[15:41:07.170] INFO: *** Welcome to pxar ***
[15:41:07.170] INFO: *** Today: 2016/05/02
[15:41:07.187] INFO: *** Version: v1.9.0-796-gef167-dirty
[15:41:07.187] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//dacParameters35_C15.dat
[15:41:07.188] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:41:07.188] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//defaultMaskFile.dat
[15:41:07.188] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C15.dat
[15:41:07.258] INFO: clk: 4
[15:41:07.259] INFO: ctr: 4
[15:41:07.259] INFO: sda: 19
[15:41:07.259] INFO: tin: 9
[15:41:07.259] INFO: level: 15
[15:41:07.259] INFO: triggerdelay: 0
[15:41:07.259] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[15:41:07.259] INFO: Log level: INFO
[15:41:07.277] QUIET: Connection to board DTB_WREK4U opened.
[15:41:07.280] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 32
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREK4U
MAC address: 40D855118020
Hostname: pixelDTB032
Comment:
------------------------------------------------------
[15:41:07.283] INFO: RPC call hashes of host and DTB match: 398089610
[15:41:08.813] INFO: DUT info:
[15:41:08.813] INFO: The DUT currently contains the following objects:
[15:41:08.813] INFO: 2 TBM Cores tbm08c (2 ON)
[15:41:08.813] INFO: TBM Core alpha (0): 7 registers set
[15:41:08.813] INFO: TBM Core beta (1): 7 registers set
[15:41:08.813] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:41:08.813] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.813] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.813] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.813] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.813] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.813] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.814] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.814] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.814] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.814] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.814] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.814] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.814] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.814] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.814] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:08.814] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:41:09.217] INFO: enter 'restricted' command line mode
[15:41:09.217] INFO: enter test to run
[15:41:15.357] INFO: test: timing no parameter change
[15:41:15.357] INFO: running: timing
[15:41:15.364] INFO: ######################################################################
[15:41:15.364] INFO: PixTestTiming::doTest()
[15:41:15.364] INFO: ######################################################################
[15:41:15.364] INFO: ----------------------------------------------------------------------
[15:41:15.364] INFO: PixTestTiming::TBMPhaseScan()
[15:41:15.364] INFO: ----------------------------------------------------------------------
[15:46:44.938] INFO: TBM Phase Settings: 232
[15:46:44.939] INFO: 400MHz Phase: 2
[15:46:44.939] INFO: 160MHz Phase: 7
[15:46:44.939] INFO: Functional Phase Area: 3
[15:46:44.948] INFO: Test took 329584 ms.
[15:46:44.948] INFO: PixTestTiming::TBMPhaseScan() done.
[15:46:44.948] INFO: ----------------------------------------------------------------------
[15:46:44.948] INFO: PixTestTiming::ROCDelayScan()
[15:46:44.948] INFO: ----------------------------------------------------------------------
[15:48:49.846] INFO: ROC Delay Settings: 228
[15:48:49.846] INFO: ROC Header-Trailer/Token Delay: 11
[15:48:49.846] INFO: ROC Port 0 Delay: 4
[15:48:49.847] INFO: ROC Port 1 Delay: 4
[15:48:49.847] INFO: Functional ROC Area: 5
[15:48:49.850] INFO: Test took 124902 ms.
[15:48:49.850] INFO: PixTestTiming::ROCDelayScan() done.
[15:48:49.850] INFO: ----------------------------------------------------------------------
[15:48:49.850] INFO: PixTestTiming::TimingTest()
[15:48:49.850] INFO: ----------------------------------------------------------------------
[15:49:06.040] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:21.033] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:36.073] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:51.136] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:06.132] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:21.109] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:36.084] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:51.070] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:06.049] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:21.045] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:21.422] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:21.441] INFO: ----------------------------------------------------------------------
[15:51:21.441] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:51:21.441] INFO: ----------------------------------------------------------------------
[15:51:21.441] INFO: ----------------------------------------------------------------------
[15:51:21.441] INFO: Read back bit status: 1
[15:51:21.441] INFO: ----------------------------------------------------------------------
[15:51:21.441] INFO: ----------------------------------------------------------------------
[15:51:21.441] INFO: Timings are good!
[15:51:21.441] INFO: ----------------------------------------------------------------------
[15:51:21.441] INFO: Test took 151591 ms.
[15:51:21.441] INFO: PixTestTiming::TimingTest() done.
[15:51:21.455] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:51:21.455] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:51:21.455] INFO: PixTestTiming::doTest took 606096 ms.
[15:51:21.455] INFO: PixTestTiming::doTest() done
[15:51:21.456] INFO: Write out TBMPhaseScan_0_V0
[15:51:21.481] INFO: Write out TBMPhaseScan_1_V0
[15:51:21.481] INFO: Write out CombinedTBMPhaseScan_V0
[15:51:21.512] INFO: Write out ROCDelayScan3_V0
[15:51:21.513] INFO: enter test to run
[15:51:42.953] INFO: test: timingPixelAlive no parameter change
[15:51:42.953] INFO: running: timingpixelalive
[15:51:42.973] INFO: command ->timingpixelalive<- not known, ignored
[15:51:42.973] INFO: enter test to run
[15:51:53.568] INFO: test: PixelAlive no parameter change
[15:51:53.569] INFO: running: pixelalive
[15:51:53.573] INFO: ----------------------------------------------------------------------
[15:51:53.573] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[15:51:53.573] INFO: ----------------------------------------------------------------------
[15:51:53.889] INFO: Expecting 41600 events.
[15:51:58.227] INFO: 41600 events read in total (3623ms).
[15:51:58.227] INFO: Test took 4650ms.
[15:51:58.255] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:58.627] INFO: PixTestAlive::aliveTest() done
[15:51:58.628] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0
[15:51:58.631] INFO: enter test to run
[15:52:26.440] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:52:26.440] INFO: running: highrate
[15:52:26.440] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:52:26.697] INFO: ----------------------------------------------------------------------
[15:52:26.697] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:52:26.697] INFO: ----------------------------------------------------------------------
[15:52:26.697] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:52:26.697] INFO: edge/corner pixel THR is adjusted
[15:52:26.697] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:52:27.655] INFO: Collecting data for 5 seconds...
[15:52:32.671] INFO: Done with hot pixel readout
[15:52:44.264] INFO: PixTest:: pg_setup set to default.
[15:52:44.265] INFO: 9 hot pixels found in step 0
[15:52:45.257] INFO: Collecting data for 5 seconds...
[15:52:50.274] INFO: Done with hot pixel readout
[15:53:01.944] INFO: PixTest:: pg_setup set to default.
[15:53:01.945] INFO: 9 hot pixels found in step 1
[15:53:02.939] INFO: Collecting data for 5 seconds...
[15:53:07.954] INFO: Done with hot pixel readout
[15:53:19.679] INFO: PixTest:: pg_setup set to default.
[15:53:19.680] INFO: 10 hot pixels found in step 2
[15:53:20.673] INFO: Collecting data for 5 seconds...
[15:53:25.689] INFO: Done with hot pixel readout
[15:53:36.614] INFO: PixTest:: pg_setup set to default.
[15:53:36.615] INFO: 7 hot pixels found in step 3
[15:53:37.608] INFO: Collecting data for 5 seconds...
[15:53:42.624] INFO: Done with hot pixel readout
[15:53:54.267] INFO: PixTest:: pg_setup set to default.
[15:53:54.267] INFO: 6 hot pixels found in step 4
[15:53:55.260] INFO: Collecting data for 5 seconds...
[15:54:00.275] INFO: Done with hot pixel readout
[15:54:11.907] INFO: PixTest:: pg_setup set to default.

[15:54:11.908] INFO: 6 hot pixels found in step 5
[15:54:12.901] INFO: Collecting data for 5 seconds...
[15:54:17.916] INFO: Done with hot pixel readout
[15:54:29.127] INFO: PixTest:: pg_setup set to default.


[15:54:29.128] INFO: 5 hot pixels found in step 6
[15:54:30.121] INFO: Collecting data for 5 seconds...
[15:54:35.138] INFO: Done with hot pixel readout
[15:54:46.603] INFO: PixTest:: pg_setup set to default.



[15:54:46.604] INFO: 7 hot pixels found in step 7
[15:54:47.597] INFO: Collecting data for 5 seconds...
[15:54:52.613] INFO: Done with hot pixel readout
[15:55:03.885] INFO: PixTest:: pg_setup set to default.




[15:55:03.886] INFO: 8 hot pixels found in step 8
[15:55:04.879] INFO: Collecting data for 5 seconds...
[15:55:09.895] INFO: Done with hot pixel readout
[15:55:21.283] INFO: PixTest:: pg_setup set to default.




[15:55:21.284] INFO: 4 hot pixels found in step 9
[15:55:21.320] INFO: 4 hot pixels could not be trimmed and have been masked.
[15:55:21.324] INFO: PixTest::trimHotPixels() done
[15:55:21.324] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C0.dat
[15:55:21.329] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C1.dat
[15:55:21.335] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C2.dat
[15:55:21.342] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C3.dat
[15:55:21.347] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C4.dat
[15:55:21.352] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C5.dat
[15:55:21.357] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C6.dat
[15:55:21.363] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C7.dat
[15:55:21.368] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C8.dat
[15:55:21.373] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C9.dat
[15:55:21.378] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C10.dat
[15:55:21.383] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C11.dat
[15:55:21.389] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C12.dat
[15:55:21.394] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C13.dat
[15:55:21.399] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C14.dat
[15:55:21.405] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C15.dat
[15:55:21.410] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//defaultMaskFile.dat
[15:55:21.420] INFO: enter test to run
[15:55:47.559] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:55:47.559] INFO: running: highrate
[15:55:47.563] INFO: ----------------------------------------------------------------------
[15:55:47.564] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:55:47.564] INFO: ----------------------------------------------------------------------
[15:55:47.564] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:55:47.564] INFO: edge/corner pixel THR is adjusted
[15:55:47.564] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:55:48.521] INFO: Collecting data for 1 seconds...
[15:55:49.525] INFO: Done with hot pixel readout
[15:55:53.541] INFO: PixTest:: pg_setup set to default.
[15:55:53.542] INFO: 0 hot pixels found in step 0
[15:55:53.547] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:55:53.639] INFO: PixTest::trimHotPixels() done
[15:55:53.640] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C0.dat
[15:55:53.648] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C1.dat
[15:55:53.654] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C2.dat
[15:55:53.659] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C3.dat
[15:55:53.664] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C4.dat
[15:55:53.670] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C5.dat
[15:55:53.675] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C6.dat
[15:55:53.680] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C7.dat
[15:55:53.686] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C8.dat
[15:55:53.691] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C9.dat
[15:55:53.696] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C10.dat
[15:55:53.701] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C11.dat
[15:55:53.707] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C12.dat
[15:55:53.712] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C13.dat
[15:55:53.717] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C14.dat
[15:55:53.723] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C15.dat
[15:55:53.728] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-3-41_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//defaultMaskFile.dat
[15:55:53.737] INFO: enter test to run
[15:56:20.262] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:56:20.263] INFO: running: xray
[15:56:20.264] INFO: ----------------------------------------------------------------------
[15:56:20.264] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:56:20.264] INFO: ----------------------------------------------------------------------
[15:56:21.227] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:56:32.639] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:57:01.464] INFO: Resuming triggers.
[15:57:12.976] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:57:41.879] INFO: Resuming triggers.
[15:57:53.289] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[15:58:22.046] INFO: Resuming triggers.
[15:58:33.454] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:59:02.747] INFO: Resuming triggers.
[15:59:14.157] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[15:59:43.045] INFO: Resuming triggers.
[15:59:54.458] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[16:00:23.413] INFO: Resuming triggers.
[16:00:34.822] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[16:01:03.703] INFO: Resuming triggers.
[16:01:15.113] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[16:01:43.951] INFO: Resuming triggers.
[16:01:52.991] INFO: data taking finished, elapsed time: 100 seconds.
[16:02:13.061] INFO: PixTest:: pg_setup set to default.
[16:02:13.064] INFO: PixTestXray::doPhRun() done
[16:02:13.201] INFO: enter test to run
[16:04:27.067] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:04:27.067] INFO: running: xray
[16:04:27.068] INFO: ----------------------------------------------------------------------
[16:04:27.068] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:04:27.068] INFO: ----------------------------------------------------------------------
[16:04:28.032] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:04:34.738] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[16:05:04.360] INFO: Resuming triggers.
[16:05:11.074] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[16:05:41.085] INFO: Resuming triggers.
[16:05:47.794] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[16:06:17.698] INFO: Resuming triggers.
[16:06:24.412] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[16:06:54.344] INFO: Resuming triggers.
[16:07:01.049] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[16:07:30.806] INFO: Resuming triggers.
[16:07:37.510] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[16:08:07.716] INFO: Resuming triggers.
[16:08:14.421] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[16:08:44.580] INFO: Resuming triggers.
[16:08:51.284] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[16:09:21.515] INFO: Resuming triggers.
[16:09:28.225] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[16:09:58.378] INFO: Resuming triggers.
[16:10:05.085] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[16:10:35.461] INFO: Resuming triggers.
[16:10:42.167] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[16:11:12.525] INFO: Resuming triggers.
[16:11:19.233] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[16:11:49.591] INFO: Resuming triggers.
[16:11:56.300] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[16:12:23.262] INFO: Resuming triggers.
[16:12:29.970] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[16:13:00.344] INFO: Resuming triggers.
[16:13:06.756] INFO: data taking finished, elapsed time: 100 seconds.
[16:13:35.947] INFO: PixTest:: pg_setup set to default.
[16:13:35.950] INFO: PixTestXray::doPhRun() done
[16:13:36.096] INFO: enter test to run
[16:14:58.558] INFO: test: HighRate no parameter change
[16:14:58.558] INFO: running: highrate
[16:14:58.574] INFO: ----------------------------------------------------------------------
[16:14:58.574] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:14:58.574] INFO: ----------------------------------------------------------------------
[16:14:58.730] INFO: Expecting 768 events.
[16:14:59.864] INFO: 768 events read in total (419ms).
[16:14:59.864] INFO: Test took 1269ms.
[16:15:00.667] INFO: Expecting 41600 events.
[16:15:03.817] INFO: 41600 events read in total (2623ms).
[16:15:03.818] INFO: Test took 3946ms.
[16:15:03.852] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:04.579] INFO: Expecting 41600 events.
[16:15:07.805] INFO: 41600 events read in total (2700ms).
[16:15:07.806] INFO: Test took 3936ms.
[16:15:07.840] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:08.567] INFO: Expecting 41600 events.
[16:15:11.797] INFO: 41600 events read in total (2704ms).
[16:15:11.798] INFO: Test took 3940ms.
[16:15:11.832] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:12.553] INFO: Expecting 41600 events.
[16:15:15.793] INFO: 41600 events read in total (2713ms).
[16:15:15.794] INFO: Test took 3945ms.
[16:15:15.828] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:16.549] INFO: Expecting 41600 events.
[16:15:19.783] INFO: 41600 events read in total (2707ms).
[16:15:19.784] INFO: Test took 3937ms.
[16:15:19.817] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:20.543] INFO: Expecting 41600 events.
[16:15:23.786] INFO: 41600 events read in total (2716ms).
[16:15:23.787] INFO: Test took 3951ms.
[16:15:23.821] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:24.542] INFO: Expecting 41600 events.
[16:15:27.773] INFO: 41600 events read in total (2704ms).
[16:15:27.774] INFO: Test took 3936ms.
[16:15:27.807] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:28.533] INFO: Expecting 41600 events.
[16:15:31.765] INFO: 41600 events read in total (2705ms).
[16:15:31.766] INFO: Test took 3940ms.
[16:15:31.800] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:32.521] INFO: Expecting 41600 events.
[16:15:35.739] INFO: 41600 events read in total (2691ms).
[16:15:35.740] INFO: Test took 3921ms.
[16:15:35.774] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:36.499] INFO: Expecting 41600 events.
[16:15:39.734] INFO: 41600 events read in total (2708ms).
[16:15:39.735] INFO: Test took 3943ms.
[16:15:39.768] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:40.492] INFO: Expecting 41600 events.
[16:15:43.735] INFO: 41600 events read in total (2716ms).
[16:15:43.736] INFO: Test took 3949ms.
[16:15:43.769] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:44.496] INFO: Expecting 41600 events.
[16:15:47.738] INFO: 41600 events read in total (2715ms).
[16:15:47.739] INFO: Test took 3951ms.
[16:15:47.773] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:48.495] INFO: Expecting 41600 events.
[16:15:51.733] INFO: 41600 events read in total (2711ms).
[16:15:51.734] INFO: Test took 3943ms.
[16:15:51.768] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:52.491] INFO: Expecting 41600 events.
[16:15:55.722] INFO: 41600 events read in total (2704ms).
[16:15:55.723] INFO: Test took 3936ms.
[16:15:55.756] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:56.482] INFO: Expecting 41600 events.
[16:15:59.715] INFO: 41600 events read in total (2706ms).
[16:15:59.716] INFO: Test took 3941ms.
[16:15:59.750] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:00.475] INFO: Expecting 41600 events.
[16:16:03.713] INFO: 41600 events read in total (2712ms).
[16:16:03.714] INFO: Test took 3947ms.
[16:16:03.747] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:04.475] INFO: Expecting 41600 events.
[16:16:07.720] INFO: 41600 events read in total (2718ms).
[16:16:07.721] INFO: Test took 3955ms.
[16:16:07.755] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:08.481] INFO: Expecting 41600 events.
[16:16:11.715] INFO: 41600 events read in total (2707ms).
[16:16:11.716] INFO: Test took 3942ms.
[16:16:11.750] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:12.474] INFO: Expecting 41600 events.
[16:16:15.648] INFO: 41600 events read in total (2647ms).
[16:16:15.649] INFO: Test took 3881ms.
[16:16:15.682] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:16.404] INFO: Expecting 41600 events.
[16:16:19.451] INFO: 41600 events read in total (2520ms).
[16:16:19.452] INFO: Test took 3751ms.
[16:16:19.485] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:19.849] INFO: enter test to run
[16:17:03.565] INFO: test: HighRate no parameter change
[16:17:03.565] INFO: running: highrate
[16:17:03.567] INFO: ----------------------------------------------------------------------
[16:17:03.567] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:17:03.567] INFO: ----------------------------------------------------------------------
[16:17:04.181] INFO: Expecting 208000 events.
[16:17:16.004] INFO: 208000 events read in total (11296ms).
[16:17:16.007] INFO: Test took 12430ms.
[16:17:16.148] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:17:16.400] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0
[16:17:16.400] INFO: number of red-efficiency pixels: 68 54 83 125 141 141 133 98 100 97 120 74 96 48 27 34
[16:17:16.400] INFO: number of X-ray hits detected: 61041 41068 67908 107446 118242 118729 115860 88529 77946 94655 93183 78794 80875 47280 20376 21748
[16:17:16.400] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:17:16.400] INFO: number of Vcal hits detected: 207931 207945 207916 207873 207855 207859 207864 207850 207897 207901 207879 207925 207903 207951 207973 207932
[16:17:16.400] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[16:17:16.400] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[16:17:16.400] INFO: X-ray hit rate [MHz/cm2]: 17.9 12.0 19.9 31.5 34.7 34.8 34.0 25.9 22.8 27.7 27.3 23.1 23.7 13.9 6.0 6.4
[16:17:16.400] INFO: PixTestHighRate::doXPixelAlive() done
[16:17:16.449] INFO: PixTest:: pg_setup set to default.
[16:17:16.462] INFO: enter test to run
[16:17:41.197] INFO: test: HighRate no parameter change
[16:17:41.197] INFO: running: highrate
[16:17:41.198] INFO: ----------------------------------------------------------------------
[16:17:41.198] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:17:41.198] INFO: ----------------------------------------------------------------------
[16:17:41.810] INFO: Expecting 208000 events.
[16:17:55.439] INFO: 208000 events read in total (13102ms).
[16:17:55.444] INFO: Test took 14236ms.
[16:17:55.734] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:17:56.033] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0
[16:17:56.033] INFO: number of red-efficiency pixels: 182 111 308 378 434 424 430 326 273 387 376 283 252 156 49 84
[16:17:56.033] INFO: number of X-ray hits detected: 128399 85684 141732 226077 246995 248306 244088 187071 163539 198106 195997 166800 169678 99567 43198 46416
[16:17:56.033] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:17:56.033] INFO: number of Vcal hits detected: 207810 207888 207668 207595 207530 207545 207537 207610 207715 207585 207603 207700 207730 207841 207949 207883
[16:17:56.033] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.8 99.8 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 99.9
[16:17:56.033] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.8 99.8 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 99.9
[16:17:56.033] INFO: X-ray hit rate [MHz/cm2]: 37.6 25.1 41.5 66.3 72.4 72.8 71.5 54.8 47.9 58.1 57.4 48.9 49.7 29.2 12.7 13.6
[16:17:56.033] INFO: PixTestHighRate::doXPixelAlive() done
[16:17:56.080] INFO: PixTest:: pg_setup set to default.
[16:17:56.096] INFO: enter test to run
[16:18:16.437] INFO: test: HighRate no parameter change
[16:18:16.437] INFO: running: highrate
[16:18:16.438] INFO: ----------------------------------------------------------------------
[16:18:16.438] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:18:16.438] INFO: ----------------------------------------------------------------------
[16:18:17.052] INFO: Expecting 208000 events.
[16:18:32.591] INFO: 208000 events read in total (15012ms).
[16:18:32.598] INFO: Test took 16151ms.
[16:18:33.032] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:33.378] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0
[16:18:33.378] INFO: number of red-efficiency pixels: 440 264 706 943 1068 1042 1079 683 632 929 832 615 478 315 94 116
[16:18:33.378] INFO: number of X-ray hits detected: 195502 129911 215497 341341 373910 377498 368415 283648 248824 301191 298049 252801 256616 151753 65519 70363
[16:18:33.379] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:18:33.379] INFO: number of Vcal hits detected: 207485 207716 207102 206874 206657 206677 206677 207126 207287 206895 207042 207311 207474 207656 207903 207857
[16:18:33.379] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.5 99.4 99.4 99.4 99.6 99.7 99.5 99.6 99.7 99.8 99.9 100.0 99.9
[16:18:33.379] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.6 99.5 99.4 99.4 99.4 99.6 99.7 99.5 99.5 99.7 99.7 99.8 100.0 99.9
[16:18:33.379] INFO: X-ray hit rate [MHz/cm2]: 57.3 38.1 63.2 100.0 109.6 110.6 108.0 83.1 72.9 88.3 87.4 74.1 75.2 44.5 19.2 20.6
[16:18:33.379] INFO: PixTestHighRate::doXPixelAlive() done
[16:18:33.424] INFO: PixTest:: pg_setup set to default.
[16:18:33.442] INFO: enter test to run
[16:18:37.772] INFO: test: exit no parameter change
[16:18:38.251] QUIET: Connection to board 32 closed.
[16:18:38.261] INFO: pXar: this is the end, my friend