[11:19:02.288] INFO: *** Welcome to pxar ***
[11:19:02.288] INFO: *** Today: 2016/09/23
[11:19:03.522] INFO: *** Version: v1.9.0-818-g96727
[11:19:03.522] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//dacParameters35_C15.dat
[11:19:03.534] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:19:03.554] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//defaultMaskFile.dat
[11:19:03.554] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C15.dat
[11:19:03.686] INFO: clk: 4
[11:19:03.686] INFO: ctr: 4
[11:19:03.686] INFO: sda: 19
[11:19:03.686] INFO: tin: 9
[11:19:03.686] INFO: level: 15
[11:19:03.686] INFO: triggerdelay: 0
[11:19:03.686] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:19:03.686] INFO: Log level: INFO
[11:19:03.705] QUIET: Connection to board DTB_WREKRL opened.
[11:19:03.709] 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:
------------------------------------------------------
[11:19:03.711] INFO: RPC call hashes of host and DTB match: 398089610
[11:19:05.263] INFO: DUT info:
[11:19:05.263] INFO: The DUT currently contains the following objects:
[11:19:05.263] INFO: 2 TBM Cores tbm08c (2 ON)
[11:19:05.263] INFO: TBM Core alpha (0): 7 registers set
[11:19:05.263] INFO: TBM Core beta (1): 7 registers set
[11:19:05.263] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:19:05.263] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.263] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:19:05.698] INFO: enter 'restricted' command line mode
[11:19:05.698] INFO: enter test to run
[11:19:27.311] INFO: test: PixelAlive no parameter change
[11:19:27.311] INFO: running: pixelalive
[11:19:27.336] INFO: ----------------------------------------------------------------------
[11:19:27.336] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:19:27.336] INFO: ----------------------------------------------------------------------
[11:19:27.661] INFO: Expecting 41600 events.
[11:19:31.954] INFO: 41600 events read in total (3575ms).
[11:19:32.116] INFO: Test took 4777ms.
[11:19:32.128] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:19:32.401] INFO: PixTestAlive::aliveTest() done
[11:19:32.401] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 0 0 0 0 1 0 0 0 0 0
[11:19:32.427] INFO: enter test to run
[11:19:41.863] INFO: test: timing no parameter change
[11:19:41.863] INFO: running: timing
[11:19:41.866] INFO: ######################################################################
[11:19:41.866] INFO: PixTestTiming::doTest()
[11:19:41.866] INFO: ######################################################################
[11:19:41.866] INFO: ----------------------------------------------------------------------
[11:19:41.866] INFO: PixTestTiming::TBMPhaseScan()
[11:19:41.866] INFO: ----------------------------------------------------------------------
[11:25:10.957] INFO: TBM Phase Settings: 240
[11:25:10.957] INFO: 400MHz Phase: 4
[11:25:10.957] INFO: 160MHz Phase: 7
[11:25:10.957] INFO: Functional Phase Area: 4
[11:25:10.960] INFO: Test took 329094 ms.
[11:25:10.960] INFO: PixTestTiming::TBMPhaseScan() done.
[11:25:10.961] INFO: ----------------------------------------------------------------------
[11:25:10.961] INFO: PixTestTiming::ROCDelayScan()
[11:25:10.961] INFO: ----------------------------------------------------------------------
[11:28:31.272] INFO: ROC Delay Settings: 228
[11:28:31.272] INFO: ROC Header-Trailer/Token Delay: 11
[11:28:31.272] INFO: ROC Port 0 Delay: 4
[11:28:31.272] INFO: ROC Port 1 Delay: 4
[11:28:31.272] INFO: Functional ROC Area: 5
[11:28:31.275] INFO: Test took 200315 ms.
[11:28:31.275] INFO: PixTestTiming::ROCDelayScan() done.
[11:28:31.275] INFO: ----------------------------------------------------------------------
[11:28:31.275] INFO: PixTestTiming::TimingTest()
[11:28:31.275] INFO: ----------------------------------------------------------------------
[11:28:47.403] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:02.368] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:17.336] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:32.309] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:47.261] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:30:02.194] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:30:17.359] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:30:32.351] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:30:47.342] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:31:02.447] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:31:02.826] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:31:02.845] INFO: ----------------------------------------------------------------------
[11:31:02.845] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:31:02.845] INFO: ----------------------------------------------------------------------
[11:31:02.845] INFO: ----------------------------------------------------------------------
[11:31:02.845] INFO: Read back bit status: 1
[11:31:02.845] INFO: ----------------------------------------------------------------------
[11:31:02.845] INFO: ----------------------------------------------------------------------
[11:31:02.845] INFO: Timings are good!
[11:31:02.845] INFO: ----------------------------------------------------------------------
[11:31:02.845] INFO: Test took 151570 ms.
[11:31:02.845] INFO: PixTestTiming::TimingTest() done.
[11:31:02.845] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:31:02.845] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:31:02.845] INFO: PixTestTiming::doTest took 680982 ms.
[11:31:02.845] INFO: PixTestTiming::doTest() done
[11:31:02.845] INFO: Write out TBMPhaseScan_0_V0
[11:31:02.846] INFO: Write out TBMPhaseScan_1_V0
[11:31:02.846] INFO: Write out CombinedTBMPhaseScan_V0
[11:31:02.847] INFO: Write out ROCDelayScan3_V0
[11:31:02.847] INFO: enter test to run
[11:32:10.346] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:32:10.346] INFO: running: highrate
[11:32:10.346] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:32:10.559] INFO: ----------------------------------------------------------------------
[11:32:10.559] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:32:10.559] INFO: ----------------------------------------------------------------------
[11:32:10.559] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:32:10.559] INFO: edge/corner pixel THR is adjusted
[11:32:10.559] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:32:11.516] INFO: Collecting data for 5 seconds...
[11:32:16.536] INFO: Done with hot pixel readout
[11:32:28.187] INFO: PixTest:: pg_setup set to default.
[11:32:28.188] INFO: 22 hot pixels found in step 0
[11:32:29.181] INFO: Collecting data for 5 seconds...
[11:32:34.199] INFO: Done with hot pixel readout
[11:32:45.895] INFO: PixTest:: pg_setup set to default.
[11:32:45.896] INFO: 28 hot pixels found in step 1
[11:32:46.890] INFO: Collecting data for 5 seconds...
[11:32:51.909] INFO: Done with hot pixel readout
[11:33:03.774] INFO: PixTest:: pg_setup set to default.
[11:33:03.775] INFO: 24 hot pixels found in step 2
[11:33:04.768] INFO: Collecting data for 5 seconds...
[11:33:09.786] INFO: Done with hot pixel readout
[11:33:21.794] INFO: PixTest:: pg_setup set to default.
[11:33:21.795] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:33:21.795] INFO: 20 hot pixels found in step 3
[11:33:22.788] INFO: Collecting data for 5 seconds...
[11:33:27.808] INFO: Done with hot pixel readout
[11:33:39.765] INFO: PixTest:: pg_setup set to default.
[11:33:39.765] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:33:39.766] INFO: 25 hot pixels found in step 4
[11:33:40.760] INFO: Collecting data for 5 seconds...
[11:33:45.777] INFO: Done with hot pixel readout
[11:33:57.678] INFO: PixTest:: pg_setup set to default.
[11:33:57.678] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:33:57.678] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:33:57.679] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:33:57.679] INFO: 21 hot pixels found in step 5
[11:33:58.673] INFO: Collecting data for 5 seconds...
[11:34:03.692] INFO: Done with hot pixel readout
[11:34:15.651] INFO: PixTest:: pg_setup set to default.
[11:34:15.651] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:34:15.651] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:34:15.651] INFO: 21 hot pixels found in step 6
[11:34:16.645] INFO: Collecting data for 5 seconds...
[11:34:21.664] INFO: Done with hot pixel readout
[11:34:33.730] INFO: PixTest:: pg_setup set to default.
[11:34:33.730] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:34:33.730] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:34:33.730] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:34:33.731] INFO: 17 hot pixels found in step 7
[11:34:34.725] INFO: Collecting data for 5 seconds...
[11:34:39.746] INFO: Done with hot pixel readout
[11:34:51.683] INFO: PixTest:: pg_setup set to default.
[11:34:51.683] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:34:51.683] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:34:51.683] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:34:51.683] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:34:51.684] INFO: 19 hot pixels found in step 8
[11:34:52.678] INFO: Collecting data for 5 seconds...
[11:34:57.698] INFO: Done with hot pixel readout
[11:35:09.520] INFO: PixTest:: pg_setup set to default.
[11:35:09.520] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:09.520] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:09.520] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:09.520] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:09.520] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:09.521] INFO: 17 hot pixels found in step 9
[11:35:10.514] INFO: Collecting data for 5 seconds...
[11:35:15.531] INFO: Done with hot pixel readout
[11:35:27.383] INFO: PixTest:: pg_setup set to default.
[11:35:27.383] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:27.383] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:27.384] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:27.384] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:27.384] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:27.384] INFO: 9 hot pixels found in step 10
[11:35:28.378] INFO: Collecting data for 5 seconds...
[11:35:33.394] INFO: Done with hot pixel readout
[11:35:45.229] INFO: PixTest:: pg_setup set to default.
[11:35:45.229] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:45.229] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:45.229] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:45.229] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:35:45.230] INFO: 10 hot pixels found in step 11
[11:35:46.222] INFO: Collecting data for 5 seconds...
[11:35:51.239] INFO: Done with hot pixel readout
[11:36:03.088] INFO: PixTest:: pg_setup set to default.
[11:36:03.088] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:03.089] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:03.089] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:03.089] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:03.089] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:03.089] INFO: 11 hot pixels found in step 12
[11:36:04.083] INFO: Collecting data for 5 seconds...
[11:36:09.100] INFO: Done with hot pixel readout
[11:36:20.859] INFO: PixTest:: pg_setup set to default.
[11:36:20.859] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:20.859] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:20.859] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:20.859] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:20.860] INFO: 7 hot pixels found in step 13
[11:36:21.854] INFO: Collecting data for 5 seconds...
[11:36:26.870] INFO: Done with hot pixel readout
[11:36:38.689] INFO: PixTest:: pg_setup set to default.
[11:36:38.689] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:38.689] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:38.689] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:36:38.689] INFO: 9 hot pixels found in step 14
[11:36:38.726] INFO: 9 hot pixels could not be trimmed and have been masked.
[11:36:38.729] INFO: PixTest::trimHotPixels() done
[11:36:38.729] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C0.dat
[11:36:38.750] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C1.dat
[11:36:38.764] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C2.dat
[11:36:38.777] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C3.dat
[11:36:38.788] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C4.dat
[11:36:38.793] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C5.dat
[11:36:38.799] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C6.dat
[11:36:38.804] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C7.dat
[11:36:38.810] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C8.dat
[11:36:38.815] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C9.dat
[11:36:38.821] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C10.dat
[11:36:38.826] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C11.dat
[11:36:38.831] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C12.dat
[11:36:38.837] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C13.dat
[11:36:38.843] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C14.dat
[11:36:38.848] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C15.dat
[11:36:38.854] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//defaultMaskFile.dat
[11:36:38.871] INFO: enter test to run
[11:37:22.344] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:37:22.344] INFO: running: highrate
[11:37:22.348] INFO: ----------------------------------------------------------------------
[11:37:22.348] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:37:22.348] INFO: ----------------------------------------------------------------------
[11:37:22.348] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:37:22.348] INFO: edge/corner pixel THR is adjusted
[11:37:22.348] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:37:23.307] INFO: Collecting data for 1 seconds...
[11:37:24.311] INFO: Done with hot pixel readout
[11:37:28.314] INFO: PixTest:: pg_setup set to default.
[11:37:28.314] INFO: 0 hot pixels found in step 0
[11:37:28.320] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:37:28.404] INFO: PixTest::trimHotPixels() done
[11:37:28.405] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C0.dat
[11:37:28.416] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C1.dat
[11:37:28.423] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C2.dat
[11:37:28.428] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C3.dat
[11:37:28.433] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C4.dat
[11:37:28.438] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C5.dat
[11:37:28.443] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C6.dat
[11:37:28.448] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C7.dat
[11:37:28.454] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C8.dat
[11:37:28.459] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C9.dat
[11:37:28.464] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C10.dat
[11:37:28.469] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C11.dat
[11:37:28.474] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C12.dat
[11:37:28.480] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C13.dat
[11:37:28.485] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C14.dat
[11:37:28.490] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//trimParameters35_C15.dat
[11:37:28.495] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-8-05_FPIXTest-17C-FNAL-160914-1251-150V_2016-09-14_12h51m_1473875478/000_FPIXTest_p17//defaultMaskFile.dat
[11:37:28.505] INFO: enter test to run
[11:38:32.399] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:38:32.399] INFO: running: xray
[11:38:32.401] INFO: ----------------------------------------------------------------------
[11:38:32.401] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:38:32.401] INFO: ----------------------------------------------------------------------
[11:38:33.364] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:38:44.820] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:39:14.225] INFO: Resuming triggers.
[11:39:25.779] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[11:39:55.197] INFO: Resuming triggers.
[11:40:06.655] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:40:36.117] INFO: Resuming triggers.
[11:40:47.576] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[11:41:16.955] INFO: Resuming triggers.
[11:41:28.414] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[11:41:57.652] INFO: Resuming triggers.
[11:42:09.116] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[11:42:38.407] INFO: Resuming triggers.
[11:42:49.871] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[11:43:19.617] INFO: Resuming triggers.
[11:43:31.079] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[11:44:00.442] INFO: Resuming triggers.
[11:44:09.091] INFO: data taking finished, elapsed time: 100 seconds.
[11:44:31.419] INFO: PixTest:: pg_setup set to default.
[11:44:31.422] INFO: PixTestXray::doPhRun() done
[11:44:31.562] INFO: enter test to run
[11:45:22.196] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:45:22.196] INFO: running: xray
[11:45:22.197] INFO: ----------------------------------------------------------------------
[11:45:22.197] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:45:22.197] INFO: ----------------------------------------------------------------------
[11:45:23.161] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:45:29.860] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:46:01.483] INFO: Resuming triggers.
[11:46:08.182] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[11:46:39.606] INFO: Resuming triggers.
[11:46:46.311] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[11:47:17.965] INFO: Resuming triggers.
[11:47:24.660] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[11:47:54.805] INFO: Resuming triggers.
[11:48:01.505] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[11:48:31.616] INFO: Resuming triggers.
[11:48:38.312] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[11:49:08.427] INFO: Resuming triggers.
[11:49:15.126] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:49:45.253] INFO: Resuming triggers.
[11:49:51.946] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[11:50:22.054] INFO: Resuming triggers.
[11:50:28.746] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[11:50:59.015] INFO: Resuming triggers.
[11:51:05.712] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[11:51:35.899] INFO: Resuming triggers.
[11:51:42.592] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[11:52:12.678] INFO: Resuming triggers.
[11:52:19.369] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:52:49.492] INFO: Resuming triggers.
[11:52:56.186] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[11:53:26.201] INFO: Resuming triggers.
[11:53:32.900] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[11:54:02.987] INFO: Resuming triggers.
[11:54:09.576] INFO: data taking finished, elapsed time: 100 seconds.
[11:54:39.429] INFO: PixTest:: pg_setup set to default.
[11:54:39.432] INFO: PixTestXray::doPhRun() done
[11:54:39.580] INFO: enter test to run
[11:55:12.640] INFO: test: HighRate no parameter change
[11:55:12.641] INFO: running: highrate
[11:55:12.657] INFO: ----------------------------------------------------------------------
[11:55:12.657] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:55:12.657] INFO: ----------------------------------------------------------------------
[11:55:12.811] INFO: Expecting 768 events.
[11:55:13.952] INFO: 768 events read in total (418ms).
[11:55:13.952] INFO: Test took 1275ms.
[11:55:14.755] INFO: Expecting 41600 events.
[11:55:17.893] INFO: 41600 events read in total (2611ms).
[11:55:17.894] INFO: Test took 3935ms.
[11:55:17.928] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:18.657] INFO: Expecting 41600 events.
[11:55:21.888] INFO: 41600 events read in total (2705ms).
[11:55:21.889] INFO: Test took 3943ms.
[11:55:21.924] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:22.644] INFO: Expecting 41600 events.
[11:55:25.861] INFO: 41600 events read in total (2690ms).
[11:55:25.862] INFO: Test took 3919ms.
[11:55:25.897] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:26.622] INFO: Expecting 41600 events.
[11:55:29.857] INFO: 41600 events read in total (2708ms).
[11:55:29.858] INFO: Test took 3943ms.
[11:55:29.892] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:30.617] INFO: Expecting 41600 events.
[11:55:33.854] INFO: 41600 events read in total (2711ms).
[11:55:33.855] INFO: Test took 3944ms.
[11:55:33.889] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:34.614] INFO: Expecting 41600 events.
[11:55:37.942] INFO: 41600 events read in total (2801ms).
[11:55:37.943] INFO: Test took 4035ms.
[11:55:37.978] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:38.697] INFO: Expecting 41600 events.
[11:55:41.968] INFO: 41600 events read in total (2744ms).
[11:55:41.969] INFO: Test took 3973ms.
[11:55:41.004] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:42.727] INFO: Expecting 41600 events.
[11:55:46.025] INFO: 41600 events read in total (2771ms).
[11:55:46.025] INFO: Test took 4003ms.
[11:55:46.061] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:46.784] INFO: Expecting 41600 events.
[11:55:50.075] INFO: 41600 events read in total (2765ms).
[11:55:50.076] INFO: Test took 3996ms.
[11:55:50.110] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:50.833] INFO: Expecting 41600 events.
[11:55:54.035] INFO: 41600 events read in total (2675ms).
[11:55:54.036] INFO: Test took 3908ms.
[11:55:54.071] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:54.790] INFO: Expecting 41600 events.
[11:55:58.079] INFO: 41600 events read in total (2762ms).
[11:55:58.080] INFO: Test took 3991ms.
[11:55:58.115] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:58.834] INFO: Expecting 41600 events.
[11:56:02.140] INFO: 41600 events read in total (2779ms).
[11:56:02.141] INFO: Test took 4008ms.
[11:56:02.177] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:56:02.894] INFO: Expecting 41600 events.
[11:56:06.183] INFO: 41600 events read in total (2762ms).
[11:56:06.184] INFO: Test took 3989ms.
[11:56:06.220] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:56:06.942] INFO: Expecting 41600 events.
[11:56:10.140] INFO: 41600 events read in total (2671ms).
[11:56:10.141] INFO: Test took 3901ms.
[11:56:10.176] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:56:10.897] INFO: Expecting 41600 events.
[11:56:14.028] INFO: 41600 events read in total (2604ms).
[11:56:14.029] INFO: Test took 3835ms.
[11:56:14.064] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:56:14.784] INFO: Expecting 41600 events.
[11:56:18.016] INFO: 41600 events read in total (2705ms).
[11:56:18.016] INFO: Test took 3933ms.
[11:56:18.051] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:56:18.775] INFO: Expecting 41600 events.
[11:56:22.046] INFO: 41600 events read in total (2745ms).
[11:56:22.047] INFO: Test took 3977ms.
[11:56:22.084] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:56:22.803] INFO: Expecting 41600 events.
[11:56:25.972] INFO: 41600 events read in total (2643ms).
[11:56:25.973] INFO: Test took 3868ms.
[11:56:26.010] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:56:26.728] INFO: Expecting 41600 events.
[11:56:29.933] INFO: 41600 events read in total (2679ms).
[11:56:29.934] INFO: Test took 3903ms.
[11:56:29.969] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:56:30.686] INFO: Expecting 41600 events.
[11:56:33.672] INFO: 41600 events read in total (2459ms).
[11:56:33.673] INFO: Test took 3686ms.
[11:56:33.707] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:56:34.069] INFO: enter test to run
[11:56:45.632] INFO: test: HighRate no parameter change
[11:56:45.632] INFO: running: highrate
[11:56:45.633] INFO: ----------------------------------------------------------------------
[11:56:45.633] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:56:45.633] INFO: ----------------------------------------------------------------------
[11:56:46.259] INFO: Expecting 208000 events.
[11:56:58.007] INFO: 208000 events read in total (11222ms).
[11:56:58.010] INFO: Test took 12368ms.
[11:56:58.160] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:56:58.413] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[11:56:58.413] INFO: number of red-efficiency pixels: 81 46 78 127 142 168 148 112 121 111 128 104 124 61 24 30
[11:56:58.413] INFO: number of X-ray hits detected: 62999 41549 67786 106635 115394 117468 116051 82019 77871 96817 96554 81872 87213 50337 21052 25104
[11:56:58.413] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:56:58.413] INFO: number of Vcal hits detected: 207917 207948 207922 207871 207858 207827 207843 207888 207877 207887 207822 207892 207875 207936 207976 207970
[11:56:58.413] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 100.0 99.9 100.0 100.0 100.0
[11:56:58.413] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[11:56:58.413] INFO: X-ray hit rate [MHz/cm2]: 18.5 12.2 19.9 31.3 33.8 34.4 34.0 24.0 22.8 28.4 28.3 24.0 25.6 14.8 6.2 7.4
[11:56:58.413] INFO: PixTestHighRate::doXPixelAlive() done
[11:56:58.460] INFO: PixTest:: pg_setup set to default.
[11:56:58.471] INFO: enter test to run
[11:57:21.296] INFO: test: HighRate no parameter change
[11:57:21.296] INFO: running: highrate
[11:57:21.297] INFO: ----------------------------------------------------------------------
[11:57:21.297] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:57:21.297] INFO: ----------------------------------------------------------------------
[11:57:21.910] INFO: Expecting 208000 events.
[11:57:35.692] INFO: 208000 events read in total (13256ms).
[11:57:35.697] INFO: Test took 14392ms.
[11:57:35.000] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:57:36.308] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[11:57:36.308] INFO: number of red-efficiency pixels: 238 120 245 500 416 576 643 379 276 319 335 338 348 203 60 64
[11:57:36.309] INFO: number of X-ray hits detected: 131570 86403 141095 221166 238501 243454 239642 170050 161831 201840 201426 171499 179842 103985 44291 52086
[11:57:36.309] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:57:36.309] INFO: number of Vcal hits detected: 207737 207873 207729 207458 207548 207342 207284 207578 207704 207661 207600 207637 207632 207780 207940 207935
[11:57:36.309] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.7 99.7 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[11:57:36.309] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.7 99.8 99.7 99.7 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[11:57:36.309] INFO: X-ray hit rate [MHz/cm2]: 38.6 25.3 41.4 64.8 69.9 71.4 70.2 49.8 47.4 59.2 59.0 50.3 52.7 30.5 13.0 15.3
[11:57:36.309] INFO: PixTestHighRate::doXPixelAlive() done
[11:57:36.354] INFO: PixTest:: pg_setup set to default.
[11:57:36.367] INFO: enter test to run
[11:57:58.695] INFO: test: HighRate no parameter change
[11:57:58.695] INFO: running: highrate
[11:57:58.696] INFO: ----------------------------------------------------------------------
[11:57:58.696] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:57:58.696] INFO: ----------------------------------------------------------------------
[11:57:59.310] INFO: Expecting 208000 events.
[11:58:14.970] INFO: 208000 events read in total (15133ms).
[11:58:14.977] INFO: Test took 16273ms.
[11:58:15.436] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:58:15.788] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[11:58:15.788] INFO: number of red-efficiency pixels: 542 220 515 1183 988 1382 1396 850 663 768 793 714 743 417 63 93
[11:58:15.789] INFO: number of X-ray hits detected: 195372 129714 211798 330278 356158 362722 358683 254463 243027 302299 302260 256793 270256 155750 66608 78113
[11:58:15.789] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:58:15.789] INFO: number of Vcal hits detected: 207345 207753 207330 206503 206794 206039 206127 206904 207236 207117 206997 207175 207142 207519 207936 207906
[11:58:15.789] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.7 99.3 99.5 99.2 99.2 99.5 99.7 99.6 99.6 99.6 99.6 99.8 100.0 100.0
[11:58:15.789] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.3 99.4 99.1 99.1 99.5 99.6 99.6 99.5 99.6 99.6 99.8 100.0 100.0
[11:58:15.789] INFO: X-ray hit rate [MHz/cm2]: 57.3 38.0 62.1 96.8 104.4 106.3 105.1 74.6 71.2 88.6 88.6 75.3 79.2 45.7 19.5 22.9
[11:58:15.789] INFO: PixTestHighRate::doXPixelAlive() done
[11:58:15.834] INFO: PixTest:: pg_setup set to default.
[11:58:15.848] INFO: enter test to run
[11:58:45.751] INFO: test: exit no parameter change
[11:58:46.101] QUIET: Connection to board 33 closed.
[11:58:46.110] INFO: pXar: this is the end, my friend