[13:15:41.573] INFO: *** Welcome to pxar ***
[13:15:41.573] INFO: *** Today: 2016/10/03
[13:15:42.376] INFO: *** Version: v1.9.0-818-g96727
[13:15:42.376] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//dacParameters35_C15.dat
[13:15:42.404] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:15:42.404] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//defaultMaskFile.dat
[13:15:42.418] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C15.dat
[13:15:42.538] INFO: clk: 4
[13:15:42.538] INFO: ctr: 4
[13:15:42.538] INFO: sda: 19
[13:15:42.538] INFO: tin: 9
[13:15:42.538] INFO: level: 15
[13:15:42.538] INFO: triggerdelay: 0
[13:15:42.538] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[13:15:42.538] INFO: Log level: INFO
[13:15:42.555] QUIET: Connection to board DTB_WREKRL opened.
[13:15:42.558] 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:15:42.561] INFO: RPC call hashes of host and DTB match: 398089610
[13:15:44.095] INFO: DUT info:
[13:15:44.095] INFO: The DUT currently contains the following objects:
[13:15:44.095] INFO: 2 TBM Cores tbm08c (2 ON)
[13:15:44.095] INFO: TBM Core alpha (0): 7 registers set
[13:15:44.095] INFO: TBM Core beta (1): 7 registers set
[13:15:44.095] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:15:44.095] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.095] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.095] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.095] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.095] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.095] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.096] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.096] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.096] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.096] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.096] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.096] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.096] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.096] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.096] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.096] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:15:44.524] INFO: enter 'restricted' command line mode
[13:15:44.524] INFO: enter test to run
[13:15:49.117] INFO: test: PixelAlive no parameter change
[13:15:49.117] INFO: running: pixelalive
[13:15:49.137] INFO: ----------------------------------------------------------------------
[13:15:49.138] 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:15:49.138] INFO: ----------------------------------------------------------------------
[13:15:49.463] INFO: Expecting 41600 events.
[13:15:53.844] INFO: 41600 events read in total (3663ms).
[13:15:54.016] INFO: Test took 4876ms.
[13:15:54.028] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:15:54.343] INFO: PixTestAlive::aliveTest() done
[13:15:54.343] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0
[13:15:54.390] INFO: enter test to run
[13:15:58.549] INFO: test: timing no parameter change
[13:15:58.549] INFO: running: timing
[13:15:58.553] INFO: ######################################################################
[13:15:58.553] INFO: PixTestTiming::doTest()
[13:15:58.553] INFO: ######################################################################
[13:15:58.553] INFO: ----------------------------------------------------------------------
[13:15:58.553] INFO: PixTestTiming::TBMPhaseScan()
[13:15:58.553] INFO: ----------------------------------------------------------------------
[13:22:15.612] INFO: TBM Phase Settings: 232
[13:22:15.613] INFO: 400MHz Phase: 2
[13:22:15.613] INFO: 160MHz Phase: 7
[13:22:15.613] INFO: Functional Phase Area: 3
[13:22:15.616] INFO: Test took 377063 ms.
[13:22:15.616] INFO: PixTestTiming::TBMPhaseScan() done.
[13:22:15.616] INFO: ----------------------------------------------------------------------
[13:22:15.616] INFO: PixTestTiming::ROCDelayScan()
[13:22:15.616] INFO: ----------------------------------------------------------------------
[13:24:23.210] INFO: ROC Delay Settings: 220
[13:24:23.210] INFO: ROC Header-Trailer/Token Delay: 11
[13:24:23.210] INFO: ROC Port 0 Delay: 4
[13:24:23.210] INFO: ROC Port 1 Delay: 3
[13:24:23.210] INFO: Functional ROC Area: 5
[13:24:23.213] INFO: Test took 127597 ms.
[13:24:23.213] INFO: PixTestTiming::ROCDelayScan() done.
[13:24:23.213] INFO: ----------------------------------------------------------------------
[13:24:23.213] INFO: PixTestTiming::TimingTest()
[13:24:23.213] INFO: ----------------------------------------------------------------------
[13:24:39.473] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:24:54.599] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:25:09.527] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:25:24.444] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:25:39.391] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:25:54.558] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:26:09.848] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:26:25.101] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:26:40.279] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:26:55.489] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:26:55.866] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:26:55.884] INFO: ----------------------------------------------------------------------
[13:26:55.884] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[13:26:55.884] INFO: ----------------------------------------------------------------------
[13:26:55.884] INFO: ----------------------------------------------------------------------
[13:26:55.884] INFO: Read back bit status: 1
[13:26:55.884] INFO: ----------------------------------------------------------------------
[13:26:55.884] INFO: ----------------------------------------------------------------------
[13:26:55.884] INFO: Timings are good!
[13:26:55.884] INFO: ----------------------------------------------------------------------
[13:26:55.884] INFO: Test took 152671 ms.
[13:26:55.884] INFO: PixTestTiming::TimingTest() done.
[13:26:55.894] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//tbmParameters_C0a.dat
[13:26:55.894] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:26:55.895] INFO: PixTestTiming::doTest took 657345 ms.
[13:26:55.895] INFO: PixTestTiming::doTest() done
[13:26:55.895] INFO: Write out TBMPhaseScan_0_V0
[13:26:55.895] INFO: Write out TBMPhaseScan_1_V0
[13:26:55.895] INFO: Write out CombinedTBMPhaseScan_V0
[13:26:55.914] INFO: Write out ROCDelayScan3_V0
[13:26:55.914] INFO: enter test to run
[13:27:28.872] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:27:28.873] INFO: running: highrate
[13:27:28.888] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:27:29.191] INFO: ----------------------------------------------------------------------
[13:27:29.191] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:27:29.191] INFO: ----------------------------------------------------------------------
[13:27:29.191] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:27:29.191] INFO: edge/corner pixel THR is adjusted
[13:27:29.191] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:27:30.166] INFO: Collecting data for 5 seconds...
[13:27:35.188] INFO: Done with hot pixel readout
[13:27:47.032] INFO: PixTest:: pg_setup set to default.
[13:27:47.033] INFO: 2 hot pixels found in step 0
[13:27:48.026] INFO: Collecting data for 5 seconds...
[13:27:53.046] INFO: Done with hot pixel readout
[13:28:04.723] INFO: PixTest:: pg_setup set to default.
[13:28:04.724] INFO: 2 hot pixels found in step 1
[13:28:05.715] INFO: Collecting data for 5 seconds...
[13:28:10.732] INFO: Done with hot pixel readout
[13:28:22.475] INFO: PixTest:: pg_setup set to default.
[13:28:22.476] INFO: 1 hot pixels found in step 2
[13:28:23.468] INFO: Collecting data for 5 seconds...
[13:28:28.485] INFO: Done with hot pixel readout
[13:28:40.210] INFO: PixTest:: pg_setup set to default.
[13:28:40.211] INFO: 1 hot pixels found in step 3
[13:28:41.203] INFO: Collecting data for 5 seconds...
[13:28:46.220] INFO: Done with hot pixel readout
[13:28:58.018] INFO: PixTest:: pg_setup set to default.
[13:28:58.018] INFO: 1 hot pixels found in step 4
[13:28:59.011] INFO: Collecting data for 5 seconds...
[13:29:04.028] INFO: Done with hot pixel readout
[13:29:15.742] INFO: PixTest:: pg_setup set to default.
[13:29:15.743] INFO: 1 hot pixels found in step 5
[13:29:16.735] INFO: Collecting data for 5 seconds...
[13:29:21.752] INFO: Done with hot pixel readout
[13:29:33.467] INFO: PixTest:: pg_setup set to default.
[13:29:33.468] INFO: 0 hot pixels found in step 6
[13:29:33.504] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:29:33.507] INFO: PixTest::trimHotPixels() done
[13:29:33.507] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C0.dat
[13:29:33.513] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C1.dat
[13:29:33.518] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C2.dat
[13:29:33.523] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C3.dat
[13:29:33.529] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C4.dat
[13:29:33.534] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C5.dat
[13:29:33.539] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C6.dat
[13:29:33.544] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C7.dat
[13:29:33.549] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C8.dat
[13:29:33.555] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C9.dat
[13:29:33.560] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C10.dat
[13:29:33.565] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C11.dat
[13:29:33.590] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C12.dat
[13:29:33.596] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C13.dat
[13:29:33.605] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C14.dat
[13:29:33.610] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C15.dat
[13:29:33.635] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//defaultMaskFile.dat
[13:29:33.650] INFO: enter test to run
[13:29:59.623] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[13:29:59.623] INFO: running: highrate
[13:29:59.628] INFO: ----------------------------------------------------------------------
[13:29:59.628] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[13:29:59.628] INFO: ----------------------------------------------------------------------
[13:29:59.628] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[13:29:59.628] INFO: edge/corner pixel THR is adjusted
[13:29:59.628] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:30:00.586] INFO: Collecting data for 1 seconds...
[13:30:01.590] INFO: Done with hot pixel readout
[13:30:05.534] INFO: PixTest:: pg_setup set to default.
[13:30:05.535] INFO: 0 hot pixels found in step 0
[13:30:05.540] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:30:05.633] INFO: PixTest::trimHotPixels() done
[13:30:05.633] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C0.dat
[13:30:05.643] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C1.dat
[13:30:05.648] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C2.dat
[13:30:05.653] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C3.dat
[13:30:05.658] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C4.dat
[13:30:05.664] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C5.dat
[13:30:05.669] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C6.dat
[13:30:05.674] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C7.dat
[13:30:05.679] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C8.dat
[13:30:05.685] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C9.dat
[13:30:05.690] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C10.dat
[13:30:05.695] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C11.dat
[13:30:05.700] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C12.dat
[13:30:05.705] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C13.dat
[13:30:05.711] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C14.dat
[13:30:05.716] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//trimParameters35_C15.dat
[13:30:05.721] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-01_FPIXTest-17C-FNAL-160928-1256-150V_2016-09-28_12h56m_1475085375/000_FPIXTest_p17//defaultMaskFile.dat
[13:30:05.731] INFO: enter test to run
[13:30:21.031] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:30:21.031] INFO: running: xray
[13:30:21.033] INFO: ----------------------------------------------------------------------
[13:30:21.033] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:30:21.033] INFO: ----------------------------------------------------------------------
[13:30:21.997] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:30:33.639] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[13:31:03.234] INFO: Resuming triggers.
[13:31:14.875] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[13:31:44.524] INFO: Resuming triggers.
[13:31:56.163] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[13:32:25.674] INFO: Resuming triggers.
[13:32:37.309] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[13:33:06.772] INFO: Resuming triggers.
[13:33:18.414] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[13:33:47.834] INFO: Resuming triggers.
[13:33:59.474] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[13:34:29.020] INFO: Resuming triggers.
[13:34:40.657] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[13:35:10.091] INFO: Resuming triggers.
[13:35:21.727] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[13:35:51.482] INFO: Resuming triggers.
[13:35:58.714] INFO: data taking finished, elapsed time: 100 seconds.
[13:36:17.304] INFO: PixTest:: pg_setup set to default.
[13:36:17.307] INFO: PixTestXray::doPhRun() done
[13:36:17.512] INFO: enter test to run
[13:36:40.653] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[13:36:40.653] INFO: running: xray
[13:36:40.654] INFO: ----------------------------------------------------------------------
[13:36:40.654] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:36:40.654] INFO: ----------------------------------------------------------------------
[13:36:41.616] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:36:48.323] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[13:37:18.989] INFO: Resuming triggers.
[13:37:25.690] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[13:37:56.845] INFO: Resuming triggers.
[13:38:03.551] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[13:38:34.538] INFO: Resuming triggers.
[13:38:41.239] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[13:39:11.759] INFO: Resuming triggers.
[13:39:18.462] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[13:39:50.334] INFO: Resuming triggers.
[13:39:57.037] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[13:40:28.119] INFO: Resuming triggers.
[13:40:34.819] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[13:41:06.261] INFO: Resuming triggers.
[13:41:12.960] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[13:41:44.095] INFO: Resuming triggers.
[13:41:50.793] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[13:42:21.871] INFO: Resuming triggers.
[13:42:28.572] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[13:42:57.210] INFO: Resuming triggers.
[13:43:03.907] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[13:43:33.234] INFO: Resuming triggers.
[13:43:39.928] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[13:44:09.854] INFO: Resuming triggers.
[13:44:16.549] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[13:44:47.355] INFO: Resuming triggers.
[13:44:54.052] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[13:45:23.992] INFO: Resuming triggers.
[13:45:30.553] INFO: data taking finished, elapsed time: 100 seconds.
[13:45:59.109] INFO: PixTest:: pg_setup set to default.
[13:45:59.112] INFO: PixTestXray::doPhRun() done
[13:45:59.263] INFO: enter test to run
[13:46:39.113] INFO: test: HighRate no parameter change
[13:46:39.113] INFO: running: highrate
[13:46:39.162] INFO: ----------------------------------------------------------------------
[13:46:39.162] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:46:39.162] INFO: ----------------------------------------------------------------------
[13:46:39.354] INFO: Expecting 768 events.
[13:46:40.489] INFO: 768 events read in total (420ms).
[13:46:40.489] INFO: Test took 1270ms.
[13:46:41.292] INFO: Expecting 41600 events.
[13:46:44.421] INFO: 41600 events read in total (2602ms).
[13:46:44.422] INFO: Test took 3878ms.
[13:46:44.456] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:46:45.180] INFO: Expecting 41600 events.
[13:46:48.396] INFO: 41600 events read in total (2689ms).
[13:46:48.397] INFO: Test took 3924ms.
[13:46:48.431] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:46:49.155] INFO: Expecting 41600 events.
[13:46:52.381] INFO: 41600 events read in total (2699ms).
[13:46:52.382] INFO: Test took 3932ms.
[13:46:52.418] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:46:53.143] INFO: Expecting 41600 events.
[13:46:56.387] INFO: 41600 events read in total (2717ms).
[13:46:56.388] INFO: Test took 3952ms.
[13:46:56.424] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:46:57.146] INFO: Expecting 41600 events.
[13:47:00.376] INFO: 41600 events read in total (2703ms).
[13:47:00.377] INFO: Test took 3936ms.
[13:47:00.413] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:01.137] INFO: Expecting 41600 events.
[13:47:04.354] INFO: 41600 events read in total (2690ms).
[13:47:04.355] INFO: Test took 3924ms.
[13:47:04.389] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:05.112] INFO: Expecting 41600 events.
[13:47:08.363] INFO: 41600 events read in total (2725ms).
[13:47:08.364] INFO: Test took 3956ms.
[13:47:08.399] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:09.119] INFO: Expecting 41600 events.
[13:47:12.360] INFO: 41600 events read in total (2714ms).
[13:47:12.361] INFO: Test took 3944ms.
[13:47:12.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:13.117] INFO: Expecting 41600 events.
[13:47:16.367] INFO: 41600 events read in total (2723ms).
[13:47:16.368] INFO: Test took 3955ms.
[13:47:16.402] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:17.122] INFO: Expecting 41600 events.
[13:47:20.321] INFO: 41600 events read in total (2672ms).
[13:47:20.323] INFO: Test took 3902ms.
[13:47:20.357] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:21.080] INFO: Expecting 41600 events.
[13:47:24.337] INFO: 41600 events read in total (2730ms).
[13:47:24.338] INFO: Test took 3963ms.
[13:47:24.372] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:25.096] INFO: Expecting 41600 events.
[13:47:28.344] INFO: 41600 events read in total (2722ms).
[13:47:28.345] INFO: Test took 3954ms.
[13:47:28.379] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:29.101] INFO: Expecting 41600 events.
[13:47:32.328] INFO: 41600 events read in total (2700ms).
[13:47:32.329] INFO: Test took 3932ms.
[13:47:32.363] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:33.086] INFO: Expecting 41600 events.
[13:47:36.322] INFO: 41600 events read in total (2709ms).
[13:47:36.323] INFO: Test took 3941ms.
[13:47:36.358] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:37.079] INFO: Expecting 41600 events.
[13:47:40.318] INFO: 41600 events read in total (2712ms).
[13:47:40.319] INFO: Test took 3942ms.
[13:47:40.353] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:41.073] INFO: Expecting 41600 events.
[13:47:44.305] INFO: 41600 events read in total (2705ms).
[13:47:44.306] INFO: Test took 3934ms.
[13:47:44.340] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:45.065] INFO: Expecting 41600 events.
[13:47:48.303] INFO: 41600 events read in total (2711ms).
[13:47:48.304] INFO: Test took 3945ms.
[13:47:48.338] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:49.063] INFO: Expecting 41600 events.
[13:47:52.319] INFO: 41600 events read in total (2729ms).
[13:47:52.320] INFO: Test took 3963ms.
[13:47:52.355] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:53.075] INFO: Expecting 41600 events.
[13:47:56.291] INFO: 41600 events read in total (2689ms).
[13:47:56.292] INFO: Test took 3919ms.
[13:47:56.327] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:47:57.046] INFO: Expecting 41600 events.
[13:48:00.119] INFO: 41600 events read in total (2546ms).
[13:48:00.120] INFO: Test took 3773ms.
[13:48:00.156] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:48:00.516] INFO: enter test to run
[13:48:55.447] INFO: test: HighRate no parameter change
[13:48:55.447] INFO: running: highrate
[13:48:55.449] INFO: ----------------------------------------------------------------------
[13:48:55.449] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:48:55.449] INFO: ----------------------------------------------------------------------
[13:48:56.060] INFO: Expecting 208000 events.
[13:49:07.882] INFO: 208000 events read in total (11295ms).
[13:49:07.885] INFO: Test took 12428ms.
[13:49:08.036] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:08.291] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0
[13:49:08.291] INFO: number of red-efficiency pixels: 67 50 109 180 178 186 166 116 81 132 162 85 105 68 21 40
[13:49:08.291] INFO: number of X-ray hits detected: 64321 45105 71514 106586 120330 119272 126688 85675 79814 99746 95104 77118 83779 52126 20955 26919
[13:49:08.291] 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:49:08.291] INFO: number of Vcal hits detected: 207931 207950 207888 207766 207818 207807 207809 207882 207918 207862 207832 207914 207892 207931 207979 207959
[13:49:08.291] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[13:49:08.291] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[13:49:08.291] INFO: X-ray hit rate [MHz/cm2]: 18.9 13.2 21.0 31.2 35.3 35.0 37.1 25.1 23.4 29.2 27.9 22.6 24.6 15.3 6.1 7.9
[13:49:08.291] INFO: PixTestHighRate::doXPixelAlive() done
[13:49:08.336] INFO: PixTest:: pg_setup set to default.
[13:49:08.348] INFO: enter test to run
[13:49:21.472] INFO: test: HighRate no parameter change
[13:49:21.472] INFO: running: highrate
[13:49:21.473] INFO: ----------------------------------------------------------------------
[13:49:21.473] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:49:21.473] INFO: ----------------------------------------------------------------------
[13:49:22.093] INFO: Expecting 208000 events.
[13:49:35.721] INFO: 208000 events read in total (13101ms).
[13:49:35.726] INFO: Test took 14244ms.
[13:49:36.023] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:36.326] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0
[13:49:36.326] INFO: number of red-efficiency pixels: 222 139 279 444 621 597 576 313 259 413 453 280 268 217 71 78
[13:49:36.326] INFO: number of X-ray hits detected: 130226 91466 145152 216397 243087 240729 255648 172519 161718 201145 193107 155449 169011 104334 42910 54932
[13:49:36.326] 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:49:36.327] INFO: number of Vcal hits detected: 207759 207855 207683 207469 207302 207327 207292 207662 207723 207549 207517 207707 207723 207762 207928 207918
[13:49:36.327] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.7 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[13:49:36.327] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.7 99.7 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[13:49:36.327] INFO: X-ray hit rate [MHz/cm2]: 38.2 26.8 42.5 63.4 71.3 70.6 74.9 50.6 47.4 59.0 56.6 45.6 49.5 30.6 12.6 16.1
[13:49:36.327] INFO: PixTestHighRate::doXPixelAlive() done
[13:49:36.372] INFO: PixTest:: pg_setup set to default.
[13:49:36.389] INFO: enter test to run
[13:49:50.415] INFO: test: HighRate no parameter change
[13:49:50.415] INFO: running: highrate
[13:49:50.417] INFO: ----------------------------------------------------------------------
[13:49:50.417] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:49:50.417] INFO: ----------------------------------------------------------------------
[13:49:51.037] INFO: Expecting 208000 events.
[13:50:06.694] INFO: 208000 events read in total (15130ms).
[13:50:06.701] INFO: Test took 16275ms.
[13:50:07.138] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:07.491] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0
[13:50:07.491] INFO: number of red-efficiency pixels: 461 292 632 1215 1394 1361 1248 688 503 1007 911 620 534 468 79 117
[13:50:07.491] INFO: number of X-ray hits detected: 196919 137286 218533 325917 365434 362971 384572 260259 245184 304438 291382 235479 255063 158367 64600 83135
[13:50:07.491] 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:50:07.491] INFO: number of Vcal hits detected: 207478 207670 207145 206381 206112 206140 206168 207116 207438 206764 206936 207283 207391 207429 207921 207880
[13:50:07.491] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.3 99.2 99.2 99.2 99.6 99.7 99.5 99.5 99.7 99.7 99.8 100.0 99.9
[13:50:07.491] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.6 99.2 99.1 99.1 99.1 99.6 99.7 99.4 99.5 99.7 99.7 99.7 100.0 99.9
[13:50:07.491] INFO: X-ray hit rate [MHz/cm2]: 57.7 40.2 64.1 95.5 107.1 106.4 112.7 76.3 71.9 89.2 85.4 69.0 74.8 46.4 18.9 24.4
[13:50:07.491] INFO: PixTestHighRate::doXPixelAlive() done
[13:50:07.542] INFO: PixTest:: pg_setup set to default.
[13:50:07.556] INFO: enter test to run
[13:50:18.367] INFO: test: exit no parameter change
[13:50:19.160] QUIET: Connection to board 33 closed.
[13:50:19.216] INFO: pXar: this is the end, my friend