[13:07:55.367] INFO: *** Welcome to pxar ***
[13:07:55.367] INFO: *** Today: 2016/09/27
[13:07:56.439] INFO: *** Version: v1.9.0-818-g96727
[13:07:56.439] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//dacParameters35_C15.dat
[13:07:56.497] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:07:56.497] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//defaultMaskFile.dat
[13:07:56.502] INFO: MASKED Roc 0 col/row: 2 6
[13:07:56.502] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C15.dat
[13:07:56.502] INFO: masking Roc 0 col/row: 2 6
[13:07:56.638] INFO: clk: 4
[13:07:56.638] INFO: ctr: 4
[13:07:56.638] INFO: sda: 19
[13:07:56.638] INFO: tin: 9
[13:07:56.638] INFO: level: 15
[13:07:56.638] INFO: triggerdelay: 0
[13:07:56.639] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[13:07:56.639] INFO: Log level: INFO
[13:07:56.657] QUIET: Connection to board DTB_WREKRL opened.
[13:07:56.661] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[13:07:56.664] INFO: RPC call hashes of host and DTB match: 398089610
[13:07:58.198] INFO: DUT info:
[13:07:58.198] INFO: The DUT currently contains the following objects:
[13:07:58.198] INFO: 2 TBM Cores tbm08c (2 ON)
[13:07:58.198] INFO: TBM Core alpha (0): 7 registers set
[13:07:58.199] INFO: TBM Core beta (1): 7 registers set
[13:07:58.199] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:07:58.199] INFO: ROC 0: 19 DACs set, Pixels: 1 masked, 0 active.
[13:07:58.199] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.199] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:07:58.630] INFO: enter 'restricted' command line mode
[13:07:58.630] INFO: enter test to run
[13:08:16.402] INFO: test: PixelAlive no parameter change
[13:08:16.402] INFO: running: pixelalive
[13:08:16.458] INFO: ----------------------------------------------------------------------
[13:08:16.458] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[13:08:16.458] INFO: ----------------------------------------------------------------------
[13:08:16.462] INFO: ROC 0 masking pixel 2/6
[13:08:16.774] INFO: Expecting 41600 events.
[13:08:21.134] INFO: 41600 events read in total (3641ms).
[13:08:21.302] INFO: Test took 4840ms.
[13:08:21.315] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:08:21.826] INFO: PixTestAlive::aliveTest() done
[13:08:21.826] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:08:21.826] INFO: ROC 0 masking pixel 2/6
[13:08:21.998] INFO: enter test to run
[13:08:27.866] INFO: test: timing no parameter change
[13:08:27.866] INFO: running: timing
[13:08:27.869] INFO: ######################################################################
[13:08:27.869] INFO: PixTestTiming::doTest()
[13:08:27.869] INFO: ######################################################################
[13:08:27.869] INFO: ----------------------------------------------------------------------
[13:08:27.869] INFO: PixTestTiming::TBMPhaseScan()
[13:08:27.869] INFO: ----------------------------------------------------------------------
[13:13:18.784] INFO: TBM Phase Settings: 236
[13:13:18.785] INFO: 400MHz Phase: 3
[13:13:18.785] INFO: 160MHz Phase: 7
[13:13:18.785] INFO: Functional Phase Area: 4
[13:13:18.806] INFO: Test took 290937 ms.
[13:13:18.806] INFO: PixTestTiming::TBMPhaseScan() done.
[13:13:18.806] INFO: ROC 0 masking pixel 2/6
[13:13:18.806] INFO: ----------------------------------------------------------------------
[13:13:18.806] INFO: PixTestTiming::ROCDelayScan()
[13:13:18.806] INFO: ----------------------------------------------------------------------
[13:15:24.100] INFO: ROC Delay Settings: 220
[13:15:24.100] INFO: ROC Header-Trailer/Token Delay: 11
[13:15:24.100] INFO: ROC Port 0 Delay: 4
[13:15:24.100] INFO: ROC Port 1 Delay: 3
[13:15:24.100] INFO: Functional ROC Area: 4
[13:15:24.103] INFO: Test took 125297 ms.
[13:15:24.103] INFO: PixTestTiming::ROCDelayScan() done.
[13:15:24.103] INFO: ROC 0 masking pixel 2/6
[13:15:24.103] INFO: ----------------------------------------------------------------------
[13:15:24.103] INFO: PixTestTiming::TimingTest()
[13:15:24.103] INFO: ----------------------------------------------------------------------
[13:15:40.336] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:15:55.315] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:16:10.517] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:16:25.720] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:16:40.954] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:16:56.138] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:11.236] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:26.524] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:41.709] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:56.902] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:57.285] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:57.301] INFO: ----------------------------------------------------------------------
[13:17:57.301] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[13:17:57.301] INFO: ----------------------------------------------------------------------
[13:17:57.301] INFO: ----------------------------------------------------------------------
[13:17:57.301] INFO: Read back bit status: 1
[13:17:57.301] INFO: ----------------------------------------------------------------------
[13:17:57.301] INFO: ----------------------------------------------------------------------
[13:17:57.301] INFO: Timings are good!
[13:17:57.301] INFO: ----------------------------------------------------------------------
[13:17:57.301] INFO: Test took 153198 ms.
[13:17:57.301] INFO: PixTestTiming::TimingTest() done.
[13:17:57.302] INFO: ROC 0 masking pixel 2/6
[13:17:57.302] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//tbmParameters_C0a.dat
[13:17:57.302] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:17:57.302] INFO: PixTestTiming::doTest took 569436 ms.
[13:17:57.302] INFO: PixTestTiming::doTest() done
[13:17:57.302] INFO: ROC 0 masking pixel 2/6
[13:17:57.302] INFO: Write out TBMPhaseScan_0_V0
[13:17:57.302] INFO: Write out TBMPhaseScan_1_V0
[13:17:57.302] INFO: Write out CombinedTBMPhaseScan_V0
[13:17:57.303] INFO: Write out ROCDelayScan3_V0
[13:17:57.303] INFO: enter test to run
[13:18:28.902] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:18:28.902] INFO: running: highrate
[13:18:28.912] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:18:29.178] INFO: ----------------------------------------------------------------------
[13:18:29.178] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:18:29.178] INFO: ----------------------------------------------------------------------
[13:18:29.178] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:18:29.178] INFO: edge/corner pixel THR is adjusted
[13:18:29.178] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:18:30.137] INFO: Collecting data for 5 seconds...
[13:18:35.153] INFO: Done with hot pixel readout
[13:18:46.839] INFO: PixTest:: pg_setup set to default.
[13:18:46.839] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[13:18:46.839] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[13:18:46.840] INFO: 3 hot pixels found in step 0
[13:18:47.833] INFO: Collecting data for 5 seconds...
[13:18:52.850] INFO: Done with hot pixel readout
[13:19:04.614] INFO: PixTest:: pg_setup set to default.
[13:19:04.614] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[13:19:04.614] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[13:19:04.615] INFO: 2 hot pixels found in step 1
[13:19:04.651] INFO: 2 hot pixels could not be trimmed and have been masked.
[13:19:04.654] INFO: PixTest::trimHotPixels() done
[13:19:04.655] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C0.dat
[13:19:04.660] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C1.dat
[13:19:04.666] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C2.dat
[13:19:04.672] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C3.dat
[13:19:04.677] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C4.dat
[13:19:04.683] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C5.dat
[13:19:04.688] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C6.dat
[13:19:04.693] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C7.dat
[13:19:04.698] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C8.dat
[13:19:04.703] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C9.dat
[13:19:04.709] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C10.dat
[13:19:04.714] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C11.dat
[13:19:04.719] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C12.dat
[13:19:04.724] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C13.dat
[13:19:04.729] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C14.dat
[13:19:04.734] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C15.dat
[13:19:04.740] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//defaultMaskFile.dat
[13:19:04.750] INFO: enter test to run
[13:19:25.485] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[13:19:25.485] INFO: running: highrate
[13:19:25.490] INFO: ----------------------------------------------------------------------
[13:19:25.490] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[13:19:25.490] INFO: ----------------------------------------------------------------------
[13:19:25.490] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[13:19:25.490] INFO: edge/corner pixel THR is adjusted
[13:19:25.490] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:19:26.449] INFO: Collecting data for 1 seconds...
[13:19:27.452] INFO: Done with hot pixel readout
[13:19:31.401] INFO: PixTest:: pg_setup set to default.
[13:19:31.402] INFO: 0 hot pixels found in step 0
[13:19:31.407] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:19:31.498] INFO: PixTest::trimHotPixels() done
[13:19:31.498] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C0.dat
[13:19:31.510] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C1.dat
[13:19:31.517] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C2.dat
[13:19:31.523] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C3.dat
[13:19:31.528] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C4.dat
[13:19:31.533] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C5.dat
[13:19:31.538] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C6.dat
[13:19:31.544] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C7.dat
[13:19:31.549] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C8.dat
[13:19:31.554] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C9.dat
[13:19:31.559] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C10.dat
[13:19:31.565] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C11.dat
[13:19:31.570] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C12.dat
[13:19:31.575] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C13.dat
[13:19:31.580] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C14.dat
[13:19:31.585] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C15.dat
[13:19:31.591] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//defaultMaskFile.dat
[13:19:31.600] INFO: enter test to run
[13:20:23.517] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:20:23.517] INFO: running: xray
[13:20:23.518] INFO: ----------------------------------------------------------------------
[13:20:23.518] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:20:23.518] INFO: ----------------------------------------------------------------------
[13:20:23.522] INFO: ROC 0 masking hot pixel 2/6
[13:20:23.522] INFO: ROC 0 masking pixel 2/6
[13:20:24.495] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:20:36.044] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[13:21:05.546] INFO: Resuming triggers.
[13:21:17.096] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[13:21:46.071] INFO: Resuming triggers.
[13:21:57.621] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[13:22:26.603] INFO: Resuming triggers.
[13:22:38.153] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[13:23:06.712] INFO: Resuming triggers.
[13:23:18.262] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[13:23:47.423] INFO: Resuming triggers.
[13:23:58.975] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[13:24:28.202] INFO: Resuming triggers.
[13:24:39.751] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[13:25:08.949] INFO: Resuming triggers.
[13:25:20.500] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[13:25:49.622] INFO: Resuming triggers.
[13:25:57.553] INFO: data taking finished, elapsed time: 100 seconds.
[13:26:17.944] INFO: PixTest:: pg_setup set to default.
[13:26:17.947] INFO: PixTestXray::doPhRun() done
[13:26:18.144] INFO: enter test to run
[13:26:42.578] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[13:26:42.579] INFO: running: xray
[13:26:42.580] INFO: ----------------------------------------------------------------------
[13:26:42.580] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:26:42.580] INFO: ----------------------------------------------------------------------
[13:26:42.584] INFO: ROC 0 masking hot pixel 2/6
[13:26:42.584] INFO: ROC 0 masking pixel 2/6
[13:26:43.543] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:26:50.416] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[13:27:21.223] INFO: Resuming triggers.
[13:27:28.098] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[13:27:58.988] INFO: Resuming triggers.
[13:28:05.862] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[13:28:36.492] INFO: Resuming triggers.
[13:28:43.365] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[13:29:15.223] INFO: Resuming triggers.
[13:29:22.101] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[13:29:53.791] INFO: Resuming triggers.
[13:30:00.664] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[13:30:31.774] INFO: Resuming triggers.
[13:30:38.647] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[13:30:49.868] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (2) != Token Chain Length (8)
[13:30:49.868] ERROR: <datapipe.cc/CheckEventID:L463> Channel 0 Event ID mismatch: local ID (86) != TBM ID (78)
[13:30:49.869] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (4) != Token Chain Length (8)
[13:30:49.869] ERROR: <datapipe.cc/CheckEventID:L463> Channel 0 Event ID mismatch: local ID (79) != TBM ID (86)
[13:30:49.869] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[13:30:49.869] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a059 8040 483a 4838 4838 685 2447 4839 4838 53 2649 2a2 2467 519 222a 4838 8a 246d 51a 2689 71b 2442 4838 55d 284a 4838 2ca 204f e000 c000
[13:30:49.869] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a054 8000 4838 319 2060 4838 11c 2640 21d 284d 4838 4838 91 222f 35b 2261 4838 93 2065 d8 2a4b 353 2262 4839 1a 2869 4838 10d 2266 4838 10 204c e000 c000
[13:30:49.869] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a055 8040 4838 4838 31c 246d 4838
[13:30:49.869] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a04e 8081 c8 4838 51d 246f 6cd 2a44 4838 552 282e 4838 504 2045 483a 10d 264f 68c 2249 758 2026 4839 45a 2861 60a 2265 e000 c000
[13:30:49.869] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a056 80b1 4838 758 202d 4838 4838 483a 521 2a4c 483a 24c 2465 4839 11a 2649 4838 2d1 2081 70b 2242 4839 101 202d 10b 2247 48a 264f e000 c000
[13:30:49.869] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a057 80c0 4838 a2 2286 6da 2260 4838 483a 810 2225 4838 4838 451 284a 4838 31a 264a 688 2622 708 2220 84a 2243 4839 292 2664 488 2867 4839 249 2263 34a 2665 e000 c000
[13:30:49.869] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a058 8000 4838 483a 34a 264f 4838 4838 4839 254 2647 50d 224a 4838 308 2488 54c 262f 4839 55 224b 551 2042 4838 e000 c000
[13:31:10.313] INFO: Resuming triggers.
[13:31:17.186] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[13:31:48.076] INFO: Resuming triggers.
[13:31:54.948] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[13:32:25.111] INFO: Resuming triggers.
[13:32:31.984] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[13:33:02.196] INFO: Resuming triggers.
[13:33:09.069] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[13:33:39.321] INFO: Resuming triggers.
[13:33:46.189] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[13:34:16.383] INFO: Resuming triggers.
[13:34:23.252] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[13:34:53.520] INFO: Resuming triggers.
[13:35:00.391] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[13:35:22.767] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (2) != Token Chain Length (8)
[13:35:22.767] ERROR: <datapipe.cc/CheckEventID:L463> Channel 0 Event ID mismatch: local ID (83) != TBM ID (140)
[13:35:22.768] ERROR: <datapipe.cc/CheckEventValidity:L491> Channel 0 Number of ROCs (4) != Token Chain Length (8)
[13:35:22.768] ERROR: <datapipe.cc/CheckEventID:L463> Channel 0 Event ID mismatch: local ID (141) != TBM ID (83)
[13:35:22.770] ERROR: <datapipe.cc/Read:L164> Dumping the flawed event +- 3 events:
[13:35:22.770] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a056 80b1 4838 91 2062 4838 4838 4c8 286c 64c 2843 6c4 2440 483a 483a 444 2a29 4839 9 242d 203 264f 204 2242 488 2a40 812 206f 4838 255 2268 810 2a29 4839 213 246c 550 2a4f e000 c000
[13:35:22.770] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a051 8040 4838 4838 4838 612 2445 4838 68a 288f 862 264f 4838 21b 2669 642 2249 4838 65a 2a2d 4838 298 262a 4838 e000 c000
[13:35:22.770] ERROR: <datapipe.cc/Read:L166> ====== 2 ====== a052 80b1 4838 114 2848 255 224b 4838 14c 2a41 14d 224c 21a 284f 4838
[13:35:22.770] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a08c 80d0 b08 4838 4838 483a 318 2448 445 2640 4838 30a 2a44 4c2 224b 4838 302 244f e000 c000
[13:35:22.770] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a053 80c0 4838 1c 2642 85c 2a24 4838 51d 2842 4838 4838 280 2444 55d 2a4d 4838 2cb 246f 459 2445 692 284f 4838 4838 412 224f 48b 2a6f 554 2248 483a 14b 2464 50b 228d e000 c000
[13:35:22.770] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a054 8000 4838 20 2844 21b 2883 4838 4838 854 2842 4838 699 244f 4838 218 2064 4839 10c 2a44 4838 24b 2a6f 4838 e000 c000
[13:35:22.771] ERROR: <datapipe.cc/Read:L166> ====== 0 ====== a055 8040 4838 15b 244e 558 284c 4838 4838 454 284d 4838 295 204c 804 2840 4838 4c1 264d 4838 162 2468 29a 282e 483a 4839 e000 c000
[13:35:30.775] INFO: Resuming triggers.
[13:35:34.900] INFO: data taking finished, elapsed time: 100 seconds.
[13:35:53.250] INFO: PixTest:: pg_setup set to default.
[13:35:53.253] INFO: PixTestXray::doPhRun() done
[13:35:53.402] INFO: enter test to run
[13:36:46.710] INFO: test: HighRate no parameter change
[13:36:46.711] INFO: running: highrate
[13:36:46.721] INFO: ----------------------------------------------------------------------
[13:36:46.721] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:36:46.721] INFO: ----------------------------------------------------------------------
[13:36:46.867] INFO: Expecting 768 events.
[13:36:48.015] INFO: 768 events read in total (418ms).
[13:36:48.016] INFO: Test took 1283ms.
[13:36:48.020] INFO: ROC 0 masking pixel 2/6
[13:36:48.819] INFO: Expecting 41600 events.
[13:36:51.934] INFO: 41600 events read in total (2588ms).
[13:36:51.935] INFO: Test took 3912ms.
[13:36:51.967] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:36:52.698] INFO: Expecting 41600 events.
[13:36:55.882] INFO: 41600 events read in total (2657ms).
[13:36:55.883] INFO: Test took 3897ms.
[13:36:55.917] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:36:56.643] INFO: Expecting 41600 events.
[13:36:59.857] INFO: 41600 events read in total (2687ms).
[13:36:59.858] INFO: Test took 3924ms.
[13:36:59.891] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:00.619] INFO: Expecting 41600 events.
[13:37:03.841] INFO: 41600 events read in total (2695ms).
[13:37:03.842] INFO: Test took 3933ms.
[13:37:03.874] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:04.602] INFO: Expecting 41600 events.
[13:37:07.834] INFO: 41600 events read in total (2706ms).
[13:37:07.835] INFO: Test took 3944ms.
[13:37:07.867] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:08.592] INFO: Expecting 41600 events.
[13:37:11.819] INFO: 41600 events read in total (2700ms).
[13:37:11.820] INFO: Test took 3935ms.
[13:37:11.853] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:12.580] INFO: Expecting 41600 events.
[13:37:15.803] INFO: 41600 events read in total (2696ms).
[13:37:15.804] INFO: Test took 3933ms.
[13:37:15.837] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:16.563] INFO: Expecting 41600 events.
[13:37:19.786] INFO: 41600 events read in total (2697ms).
[13:37:19.787] INFO: Test took 3933ms.
[13:37:19.819] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:20.545] INFO: Expecting 41600 events.
[13:37:23.762] INFO: 41600 events read in total (2690ms).
[13:37:23.763] INFO: Test took 3926ms.
[13:37:23.796] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:24.524] INFO: Expecting 41600 events.
[13:37:27.755] INFO: 41600 events read in total (2704ms).
[13:37:27.756] INFO: Test took 3942ms.
[13:37:27.789] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:28.515] INFO: Expecting 41600 events.
[13:37:31.749] INFO: 41600 events read in total (2707ms).
[13:37:31.750] INFO: Test took 3944ms.
[13:37:31.783] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:32.507] INFO: Expecting 41600 events.
[13:37:35.769] INFO: 41600 events read in total (2735ms).
[13:37:35.770] INFO: Test took 3970ms.
[13:37:35.803] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:36.525] INFO: Expecting 41600 events.
[13:37:39.746] INFO: 41600 events read in total (2694ms).
[13:37:39.747] INFO: Test took 3927ms.
[13:37:39.781] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:40.508] INFO: Expecting 41600 events.
[13:37:43.740] INFO: 41600 events read in total (2705ms).
[13:37:43.741] INFO: Test took 3942ms.
[13:37:43.774] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:44.501] INFO: Expecting 41600 events.
[13:37:47.733] INFO: 41600 events read in total (2705ms).
[13:37:47.734] INFO: Test took 3943ms.
[13:37:47.767] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:48.491] INFO: Expecting 41600 events.
[13:37:51.718] INFO: 41600 events read in total (2700ms).
[13:37:51.719] INFO: Test took 3935ms.
[13:37:51.752] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:52.479] INFO: Expecting 41600 events.
[13:37:55.703] INFO: 41600 events read in total (2698ms).
[13:37:55.703] INFO: Test took 3933ms.
[13:37:55.736] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:37:56.462] INFO: Expecting 41600 events.
[13:37:59.690] INFO: 41600 events read in total (2701ms).
[13:37:59.691] INFO: Test took 3937ms.
[13:37:59.724] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:00.452] INFO: Expecting 41600 events.
[13:38:03.662] INFO: 41600 events read in total (2683ms).
[13:38:03.663] INFO: Test took 3920ms.
[13:38:03.696] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:04.424] INFO: Expecting 41600 events.
[13:38:07.462] INFO: 41600 events read in total (2511ms).
[13:38:07.463] INFO: Test took 3748ms.
[13:38:07.495] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:07.860] INFO: enter test to run
[13:38:37.342] INFO: test: HighRate no parameter change
[13:38:37.342] INFO: running: highrate
[13:38:37.343] INFO: ----------------------------------------------------------------------
[13:38:37.343] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:38:37.343] INFO: ----------------------------------------------------------------------
[13:38:37.351] INFO: ROC 0 masking pixel 2/6
[13:38:37.969] INFO: Expecting 208000 events.
[13:38:50.035] INFO: 208000 events read in total (11539ms).
[13:38:50.038] INFO: Test took 12687ms.
[13:38:50.178] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:38:50.431] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:38:50.431] INFO: number of red-efficiency pixels: 55 32 87 117 152 122 114 97 81 125 131 106 112 69 24 27
[13:38:50.431] INFO: number of X-ray hits detected: 57631 38584 59891 97069 100980 106121 105758 73993 73635 104020 102859 86940 87257 51631 21771 26062
[13:38:50.431] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:38:50.431] INFO: number of Vcal hits detected: 207895 207966 207913 207876 207847 207873 207883 207902 207919 207870 207867 207892 207886 207931 207976 207973
[13:38:50.431] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[13:38:50.431] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[13:38:50.431] INFO: X-ray hit rate [MHz/cm2]: 16.9 11.3 17.6 28.5 29.6 31.1 31.0 21.7 21.6 30.5 30.1 25.5 25.6 15.1 6.4 7.6
[13:38:50.431] INFO: PixTestHighRate::doXPixelAlive() done
[13:38:50.476] INFO: PixTest:: pg_setup set to default.
[13:38:50.489] INFO: enter test to run
[13:39:40.461] INFO: test: HighRate no parameter change
[13:39:40.461] INFO: running: highrate
[13:39:40.463] INFO: ----------------------------------------------------------------------
[13:39:40.463] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:39:40.463] INFO: ----------------------------------------------------------------------
[13:39:40.471] INFO: ROC 0 masking pixel 2/6
[13:39:41.089] INFO: Expecting 208000 events.
[13:39:54.796] INFO: 208000 events read in total (13180ms).
[13:39:54.801] INFO: Test took 14329ms.
[13:39:55.098] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:55.398] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:39:55.398] INFO: number of red-efficiency pixels: 155 105 226 403 473 477 376 239 294 442 412 281 342 182 45 68
[13:39:55.398] INFO: number of X-ray hits detected: 119002 80002 125285 202321 209704 221139 219986 154119 153672 215909 212963 180703 182603 107181 45403 54790
[13:39:55.398] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:39:55.398] INFO: number of Vcal hits detected: 207787 207893 207750 207568 207490 207475 207598 207742 207690 207527 207562 207708 207645 207809 207953 207932
[13:39:55.398] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[13:39:55.398] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.7 99.8 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[13:39:55.398] INFO: X-ray hit rate [MHz/cm2]: 34.9 23.4 36.7 59.3 61.5 64.8 64.5 45.2 45.0 63.3 62.4 53.0 53.5 31.4 13.3 16.1
[13:39:55.398] INFO: PixTestHighRate::doXPixelAlive() done
[13:39:55.444] INFO: PixTest:: pg_setup set to default.
[13:39:55.465] INFO: enter test to run
[13:40:29.045] INFO: test: HighRate no parameter change
[13:40:29.045] INFO: running: highrate
[13:40:29.047] INFO: ----------------------------------------------------------------------
[13:40:29.047] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:40:29.047] INFO: ----------------------------------------------------------------------
[13:40:29.055] INFO: ROC 0 masking pixel 2/6
[13:40:29.666] INFO: Expecting 208000 events.
[13:40:45.026] INFO: 208000 events read in total (14834ms).
[13:40:45.034] INFO: Test took 15979ms.
[13:40:45.471] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:45.818] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:40:45.818] INFO: number of red-efficiency pixels: 327 193 518 930 1015 1053 846 583 558 975 871 642 750 361 83 120
[13:40:45.818] INFO: number of X-ray hits detected: 179742 120993 189334 303316 316633 332259 332311 231951 233459 325046 321013 273090 275578 162264 68615 83152
[13:40:45.818] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:40:45.818] INFO: number of Vcal hits detected: 207570 207794 207367 206869 206765 206656 206995 207307 207360 206824 206987 207256 207111 207584 207913 207875
[13:40:45.818] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.5 99.5 99.4 99.6 99.7 99.7 99.5 99.5 99.7 99.6 99.8 100.0 99.9
[13:40:45.818] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.5 99.4 99.4 99.5 99.7 99.7 99.4 99.5 99.6 99.6 99.8 100.0 99.9
[13:40:45.818] INFO: X-ray hit rate [MHz/cm2]: 52.7 35.5 55.5 88.9 92.8 97.4 97.4 68.0 68.4 95.3 94.1 80.0 80.8 47.6 20.1 24.4
[13:40:45.818] INFO: PixTestHighRate::doXPixelAlive() done
[13:40:45.864] INFO: PixTest:: pg_setup set to default.
[13:40:45.881] INFO: enter test to run
[13:41:11.092] INFO: test: exit no parameter change
[13:41:11.551] QUIET: Connection to board 33 closed.
[13:41:11.565] INFO: pXar: this is the end, my friend