[15:07:05.349] INFO: *** Welcome to pxar ***
[15:07:05.349] INFO: *** Today: 2016/04/21
[15:07:05.379] INFO: *** Version: v1.9.0-796-gef167-dirty
[15:07:05.379] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//dacParameters35_C15.dat
[15:07:05.433] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:07:05.433] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//defaultMaskFile.dat
[15:07:05.439] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C15.dat
[15:07:05.553] INFO: clk: 4
[15:07:05.553] INFO: ctr: 4
[15:07:05.553] INFO: sda: 19
[15:07:05.553] INFO: tin: 9
[15:07:05.553] INFO: level: 15
[15:07:05.553] INFO: triggerdelay: 0
[15:07:05.553] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[15:07:05.553] INFO: Log level: INFO
[15:07:05.572] QUIET: Connection to board DTB_WREK4U opened.
[15:07:05.576] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 32
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREK4U
MAC address: 40D855118020
Hostname: pixelDTB032
Comment:
------------------------------------------------------
[15:07:05.579] INFO: RPC call hashes of host and DTB match: 398089610
[15:07:07.110] INFO: DUT info:
[15:07:07.110] INFO: The DUT currently contains the following objects:
[15:07:07.110] INFO: 2 TBM Cores tbm08c (2 ON)
[15:07:07.110] INFO: TBM Core alpha (0): 7 registers set
[15:07:07.110] INFO: TBM Core beta (1): 7 registers set
[15:07:07.110] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:07:07.110] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.110] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.110] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.110] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.110] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.110] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.110] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.110] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.110] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.111] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.111] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.111] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.111] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.111] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.111] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.111] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:07:07.514] INFO: enter 'restricted' command line mode
[15:07:07.514] INFO: enter test to run
[15:07:21.851] INFO: test: timing no parameter change
[15:07:21.852] INFO: running: timing
[15:07:21.860] INFO: ######################################################################
[15:07:21.860] INFO: PixTestTiming::doTest()
[15:07:21.860] INFO: ######################################################################
[15:07:21.861] INFO: ----------------------------------------------------------------------
[15:07:21.861] INFO: PixTestTiming::TBMPhaseScan()
[15:07:21.861] INFO: ----------------------------------------------------------------------
[15:13:24.786] INFO: TBM Phase Settings: 236
[15:13:24.786] INFO: 400MHz Phase: 3
[15:13:24.786] INFO: 160MHz Phase: 7
[15:13:24.786] INFO: Functional Phase Area: 4
[15:13:24.790] INFO: Test took 362929 ms.
[15:13:24.790] INFO: PixTestTiming::TBMPhaseScan() done.
[15:13:24.790] INFO: ----------------------------------------------------------------------
[15:13:24.790] INFO: PixTestTiming::ROCDelayScan()
[15:13:24.790] INFO: ----------------------------------------------------------------------
[15:15:35.980] INFO: ROC Delay Settings: 228
[15:15:35.980] INFO: ROC Header-Trailer/Token Delay: 11
[15:15:35.980] INFO: ROC Port 0 Delay: 4
[15:15:35.980] INFO: ROC Port 1 Delay: 4
[15:15:35.980] INFO: Functional ROC Area: 5
[15:15:35.983] INFO: Test took 131193 ms.
[15:15:35.983] INFO: PixTestTiming::ROCDelayScan() done.
[15:15:35.983] INFO: ----------------------------------------------------------------------
[15:15:35.983] INFO: PixTestTiming::TimingTest()
[15:15:35.983] INFO: ----------------------------------------------------------------------
[15:15:51.257] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:06.271] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:21.263] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:36.252] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:51.250] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:06.239] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:21.218] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:36.212] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:51.191] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:18:06.192] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:18:06.574] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:18:06.592] INFO: ----------------------------------------------------------------------
[15:18:06.592] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:18:06.592] INFO: ----------------------------------------------------------------------
[15:18:06.592] INFO: ----------------------------------------------------------------------
[15:18:06.592] INFO: Read back bit status: 1
[15:18:06.592] INFO: ----------------------------------------------------------------------
[15:18:06.592] INFO: ----------------------------------------------------------------------
[15:18:06.592] INFO: Timings are good!
[15:18:06.592] INFO: ----------------------------------------------------------------------
[15:18:06.592] INFO: Test took 150609 ms.
[15:18:06.592] INFO: PixTestTiming::TimingTest() done.
[15:18:06.592] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:18:06.593] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:18:06.593] INFO: PixTestTiming::doTest took 644737 ms.
[15:18:06.593] INFO: PixTestTiming::doTest() done
[15:18:06.593] INFO: Write out TBMPhaseScan_0_V0
[15:18:06.620] INFO: Write out TBMPhaseScan_1_V0
[15:18:06.620] INFO: Write out CombinedTBMPhaseScan_V0
[15:18:06.621] INFO: Write out ROCDelayScan3_V0
[15:18:06.621] INFO: enter test to run
[15:18:40.558] INFO: test: PixelAlive no parameter change
[15:18:40.558] INFO: running: pixelalive
[15:18:40.563] INFO: ----------------------------------------------------------------------
[15:18:40.563] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[15:18:40.563] INFO: ----------------------------------------------------------------------
[15:18:40.881] INFO: Expecting 41600 events.
[15:18:45.196] INFO: 41600 events read in total (3599ms).
[15:18:45.196] INFO: Test took 4631ms.
[15:18:45.203] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:18:45.600] INFO: PixTestAlive::aliveTest() done
[15:18:45.600] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:18:45.604] INFO: enter test to run
[15:19:15.078] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:19:15.078] INFO: running: highrate
[15:19:15.079] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:19:15.292] INFO: ----------------------------------------------------------------------
[15:19:15.292] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:19:15.292] INFO: ----------------------------------------------------------------------
[15:19:15.292] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:19:15.292] INFO: edge/corner pixel THR is adjusted
[15:19:15.292] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:19:16.249] INFO: Collecting data for 5 seconds...
[15:19:21.266] INFO: Done with hot pixel readout
[15:19:33.388] INFO: PixTest:: pg_setup set to default.
[15:19:33.388] INFO: 2 hot pixels found in step 0
[15:19:34.384] INFO: Collecting data for 5 seconds...
[15:19:39.401] INFO: Done with hot pixel readout
[15:19:51.498] INFO: PixTest:: pg_setup set to default.
[15:19:51.499] INFO: 7 hot pixels found in step 1
[15:19:52.494] INFO: Collecting data for 5 seconds...
[15:19:57.511] INFO: Done with hot pixel readout
[15:20:09.597] INFO: PixTest:: pg_setup set to default.
[15:20:09.598] INFO: 4 hot pixels found in step 2
[15:20:10.593] INFO: Collecting data for 5 seconds...
[15:20:15.610] INFO: Done with hot pixel readout
[15:20:27.685] INFO: PixTest:: pg_setup set to default.
[15:20:27.686] INFO: 4 hot pixels found in step 3
[15:20:28.680] INFO: Collecting data for 5 seconds...
[15:20:33.697] INFO: Done with hot pixel readout
[15:20:45.766] INFO: PixTest:: pg_setup set to default.
[15:20:45.767] INFO: 3 hot pixels found in step 4
[15:20:46.762] INFO: Collecting data for 5 seconds...
[15:20:51.779] INFO: Done with hot pixel readout
[15:21:03.846] INFO: PixTest:: pg_setup set to default.
[15:21:03.847] INFO: 5 hot pixels found in step 5
[15:21:04.842] INFO: Collecting data for 5 seconds...
[15:21:09.859] INFO: Done with hot pixel readout
[15:21:21.955] INFO: PixTest:: pg_setup set to default.

[15:21:21.955] INFO: 2 hot pixels found in step 6
[15:21:22.951] INFO: Collecting data for 5 seconds...
[15:21:27.967] INFO: Done with hot pixel readout
[15:21:40.089] INFO: PixTest:: pg_setup set to default.
[15:21:40.089] INFO: 2 hot pixels found in step 7
[15:21:41.085] INFO: Collecting data for 5 seconds...
[15:21:46.102] INFO: Done with hot pixel readout
[15:21:58.155] INFO: PixTest:: pg_setup set to default.
[15:21:58.155] INFO: 0 hot pixels found in step 8
[15:21:58.195] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:21:58.198] INFO: PixTest::trimHotPixels() done
[15:21:58.198] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C0.dat
[15:21:58.204] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C1.dat
[15:21:58.209] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C2.dat
[15:21:58.215] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C3.dat
[15:21:58.221] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C4.dat
[15:21:58.226] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C5.dat
[15:21:58.231] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C6.dat
[15:21:58.237] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C7.dat
[15:21:58.242] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C8.dat
[15:21:58.247] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C9.dat
[15:21:58.252] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C10.dat
[15:21:58.258] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C11.dat
[15:21:58.263] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C12.dat
[15:21:58.268] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C13.dat
[15:21:58.273] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C14.dat
[15:21:58.279] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C15.dat
[15:21:58.306] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//defaultMaskFile.dat
[15:21:58.318] INFO: enter test to run
[15:22:34.021] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:22:34.021] INFO: running: highrate
[15:22:34.025] INFO: ----------------------------------------------------------------------
[15:22:34.025] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:22:34.025] INFO: ----------------------------------------------------------------------
[15:22:34.025] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:22:34.025] INFO: edge/corner pixel THR is adjusted
[15:22:34.025] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:22:34.983] INFO: Collecting data for 1 seconds...
[15:22:35.987] INFO: Done with hot pixel readout
[15:22:40.190] INFO: PixTest:: pg_setup set to default.
[15:22:40.191] INFO: 0 hot pixels found in step 0
[15:22:40.196] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:22:40.279] INFO: PixTest::trimHotPixels() done
[15:22:40.280] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C0.dat
[15:22:40.291] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C1.dat
[15:22:40.296] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C2.dat
[15:22:40.301] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C3.dat
[15:22:40.306] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C4.dat
[15:22:40.312] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C5.dat
[15:22:40.317] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C6.dat
[15:22:40.322] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C7.dat
[15:22:40.327] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C8.dat
[15:22:40.333] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C9.dat
[15:22:40.338] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C10.dat
[15:22:40.343] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C11.dat
[15:22:40.348] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C12.dat
[15:22:40.354] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C13.dat
[15:22:40.359] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C14.dat
[15:22:40.364] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C15.dat
[15:22:40.369] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-4-22_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//defaultMaskFile.dat
[15:22:40.385] INFO: enter test to run
[15:23:10.948] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:23:10.948] INFO: running: xray
[15:23:10.950] INFO: ----------------------------------------------------------------------
[15:23:10.950] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:23:10.950] INFO: ----------------------------------------------------------------------
[15:23:11.912] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:23:23.094] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:23:52.082] INFO: Resuming triggers.
[15:24:03.264] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:24:32.746] INFO: Resuming triggers.
[15:24:43.931] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[15:25:13.295] INFO: Resuming triggers.
[15:25:24.476] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[15:25:52.938] INFO: Resuming triggers.
[15:26:04.119] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[15:26:33.386] INFO: Resuming triggers.
[15:26:44.576] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[15:27:13.962] INFO: Resuming triggers.
[15:27:25.149] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[15:27:54.603] INFO: Resuming triggers.
[15:28:05.790] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[15:28:35.129] INFO: Resuming triggers.
[15:28:45.972] INFO: data taking finished, elapsed time: 100 seconds.
[15:29:14.685] INFO: PixTest:: pg_setup set to default.
[15:29:14.688] INFO: PixTestXray::doPhRun() done
[15:29:14.826] INFO: enter test to run
[15:30:04.834] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:30:04.834] INFO: running: xray
[15:30:04.835] INFO: ----------------------------------------------------------------------
[15:30:04.835] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:30:04.835] INFO: ----------------------------------------------------------------------
[15:30:05.816] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:30:12.126] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:30:42.292] INFO: Resuming triggers.
[15:30:48.604] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[15:31:18.722] INFO: Resuming triggers.
[15:31:25.035] INFO: run duration 18 seconds, buffer almost full (81%), pausing triggers.
[15:31:55.138] INFO: Resuming triggers.
[15:32:01.451] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[15:32:31.563] INFO: Resuming triggers.
[15:32:37.877] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[15:33:07.952] INFO: Resuming triggers.
[15:33:14.267] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[15:33:44.312] INFO: Resuming triggers.
[15:33:50.626] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[15:34:20.667] INFO: Resuming triggers.
[15:34:26.981] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[15:34:57.054] INFO: Resuming triggers.
[15:35:03.367] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[15:35:33.524] INFO: Resuming triggers.
[15:35:39.837] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[15:36:08.318] INFO: Resuming triggers.
[15:36:14.631] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[15:36:44.665] INFO: Resuming triggers.
[15:36:50.977] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[15:37:21.116] INFO: Resuming triggers.
[15:37:27.430] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[15:37:57.474] INFO: Resuming triggers.
[15:38:03.787] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[15:38:33.985] INFO: Resuming triggers.
[15:38:40.297] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[15:39:10.340] INFO: Resuming triggers.
[15:39:15.973] INFO: data taking finished, elapsed time: 100 seconds.
[15:39:43.076] INFO: PixTest:: pg_setup set to default.
[15:39:43.080] INFO: PixTestXray::doPhRun() done
[15:39:43.230] INFO: enter test to run
[15:40:15.917] INFO: test: HighRate no parameter change
[15:40:15.917] INFO: running: highrate
[15:40:15.918] INFO: ----------------------------------------------------------------------
[15:40:15.918] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:40:15.918] INFO: ----------------------------------------------------------------------
[15:40:16.060] INFO: Expecting 768 events.
[15:40:17.194] INFO: 768 events read in total (418ms).
[15:40:17.194] INFO: Test took 1270ms.
[15:40:17.998] INFO: Expecting 41600 events.
[15:40:21.147] INFO: 41600 events read in total (2622ms).
[15:40:21.148] INFO: Test took 3945ms.
[15:40:21.183] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:21.907] INFO: Expecting 41600 events.
[15:40:25.146] INFO: 41600 events read in total (2712ms).
[15:40:25.147] INFO: Test took 3946ms.
[15:40:25.183] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:25.904] INFO: Expecting 41600 events.
[15:40:29.168] INFO: 41600 events read in total (2737ms).
[15:40:29.169] INFO: Test took 3968ms.
[15:40:29.206] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:29.927] INFO: Expecting 41600 events.
[15:40:33.196] INFO: 41600 events read in total (2742ms).
[15:40:33.197] INFO: Test took 3972ms.
[15:40:33.234] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:33.953] INFO: Expecting 41600 events.
[15:40:37.228] INFO: 41600 events read in total (2748ms).
[15:40:37.229] INFO: Test took 3977ms.
[15:40:37.265] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:37.983] INFO: Expecting 41600 events.
[15:40:41.249] INFO: 41600 events read in total (2739ms).
[15:40:41.250] INFO: Test took 3966ms.
[15:40:41.286] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:42.005] INFO: Expecting 41600 events.
[15:40:45.260] INFO: 41600 events read in total (2728ms).
[15:40:45.261] INFO: Test took 3956ms.
[15:40:45.298] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:46.019] INFO: Expecting 41600 events.
[15:40:49.290] INFO: 41600 events read in total (2745ms).
[15:40:49.291] INFO: Test took 3974ms.
[15:40:49.326] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:50.047] INFO: Expecting 41600 events.
[15:40:53.301] INFO: 41600 events read in total (2728ms).
[15:40:53.302] INFO: Test took 3956ms.
[15:40:53.338] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:54.060] INFO: Expecting 41600 events.
[15:40:57.307] INFO: 41600 events read in total (2720ms).
[15:40:57.308] INFO: Test took 3951ms.
[15:40:57.344] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:58.065] INFO: Expecting 41600 events.
[15:41:01.325] INFO: 41600 events read in total (2733ms).
[15:41:01.326] INFO: Test took 3964ms.
[15:41:01.363] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:02.081] INFO: Expecting 41600 events.
[15:41:05.334] INFO: 41600 events read in total (2726ms).
[15:41:05.335] INFO: Test took 3953ms.
[15:41:05.371] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:06.092] INFO: Expecting 41600 events.
[15:41:09.366] INFO: 41600 events read in total (2747ms).
[15:41:09.367] INFO: Test took 3978ms.
[15:41:09.403] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:10.124] INFO: Expecting 41600 events.
[15:41:13.372] INFO: 41600 events read in total (2721ms).
[15:41:13.373] INFO: Test took 3951ms.
[15:41:13.409] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:14.127] INFO: Expecting 41600 events.
[15:41:17.392] INFO: 41600 events read in total (2739ms).
[15:41:17.393] INFO: Test took 3965ms.
[15:41:17.429] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:18.147] INFO: Expecting 41600 events.
[15:41:21.413] INFO: 41600 events read in total (2739ms).
[15:41:21.414] INFO: Test took 3965ms.
[15:41:21.450] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:22.168] INFO: Expecting 41600 events.
[15:41:25.434] INFO: 41600 events read in total (2739ms).
[15:41:25.435] INFO: Test took 3966ms.
[15:41:25.471] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:26.192] INFO: Expecting 41600 events.
[15:41:29.444] INFO: 41600 events read in total (2725ms).
[15:41:29.445] INFO: Test took 3954ms.
[15:41:29.481] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:30.202] INFO: Expecting 41600 events.
[15:41:33.439] INFO: 41600 events read in total (2710ms).
[15:41:33.440] INFO: Test took 3940ms.
[15:41:33.476] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:34.200] INFO: Expecting 41600 events.
[15:41:37.263] INFO: 41600 events read in total (2537ms).
[15:41:37.264] INFO: Test took 3769ms.
[15:41:37.299] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:41:37.661] INFO: enter test to run
[15:42:34.092] INFO: test: HighRate no parameter change
[15:42:34.092] INFO: running: highrate
[15:42:34.093] INFO: ----------------------------------------------------------------------
[15:42:34.093] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:42:34.093] INFO: ----------------------------------------------------------------------
[15:42:34.711] INFO: Expecting 208000 events.
[15:42:46.750] INFO: 208000 events read in total (11512ms).
[15:42:46.753] INFO: Test took 12652ms.
[15:42:46.908] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:47.164] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:42:47.164] INFO: number of red-efficiency pixels: 95 65 118 147 172 156 165 112 115 170 153 118 103 54 33 26
[15:42:47.164] INFO: number of X-ray hits detected: 70326 46797 73667 111031 117182 123764 127838 90273 88401 104961 104084 88433 93771 56410 24783 28816
[15:42:47.164] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:42:47.164] INFO: number of Vcal hits detected: 207902 207933 207879 207849 207825 207840 207826 207886 207881 207827 207845 207879 207893 207945 207967 207973
[15:42:47.164] INFO: Vcal hit fiducial efficiency (%): 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 100.0
[15:42:47.164] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 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
[15:42:47.164] INFO: X-ray hit rate [MHz/cm2]: 20.6 13.7 21.6 32.5 34.3 36.3 37.5 26.5 25.9 30.8 30.5 25.9 27.5 16.5 7.3 8.4
[15:42:47.164] INFO: PixTestHighRate::doXPixelAlive() done
[15:42:47.213] INFO: PixTest:: pg_setup set to default.
[15:42:47.228] INFO: enter test to run
[15:43:15.572] INFO: test: HighRate no parameter change
[15:43:15.572] INFO: running: highrate
[15:43:15.573] INFO: ----------------------------------------------------------------------
[15:43:15.573] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:43:15.573] INFO: ----------------------------------------------------------------------
[15:43:16.189] INFO: Expecting 208000 events.
[15:43:30.207] INFO: 208000 events read in total (13492ms).
[15:43:30.212] INFO: Test took 14629ms.
[15:43:30.529] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:30.838] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:43:30.838] INFO: number of red-efficiency pixels: 243 166 407 502 607 581 598 346 339 536 510 387 341 240 60 61
[15:43:30.838] INFO: number of X-ray hits detected: 149436 97451 154418 231828 247782 259784 268162 188006 185569 220082 218634 186562 197290 119660 52440 60855
[15:43:30.838] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:43:30.839] INFO: number of Vcal hits detected: 207746 207828 207534 207439 207298 207372 207340 207632 207636 207413 207444 207595 207645 207736 207938 207937
[15:43:30.839] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.7 99.7 99.7 99.8 99.8 99.7 99.7 99.8 99.8 99.9 100.0 100.0
[15:43:30.839] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.7 99.7 99.8 99.8 99.7 99.7 99.8 99.8 99.9 100.0 100.0
[15:43:30.839] INFO: X-ray hit rate [MHz/cm2]: 43.8 28.6 45.3 68.0 72.6 76.1 78.6 55.1 54.4 64.5 64.1 54.7 57.8 35.1 15.4 17.8
[15:43:30.839] INFO: PixTestHighRate::doXPixelAlive() done
[15:43:30.888] INFO: PixTest:: pg_setup set to default.
[15:43:30.907] INFO: enter test to run
[15:43:57.403] INFO: test: HighRate no parameter change
[15:43:57.403] INFO: running: highrate
[15:43:57.405] INFO: ----------------------------------------------------------------------
[15:43:57.405] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:43:57.405] INFO: ----------------------------------------------------------------------
[15:43:58.020] INFO: Expecting 208000 events.
[15:44:14.267] INFO: 208000 events read in total (15720ms).
[15:44:14.275] INFO: Test took 16860ms.
[15:44:14.785] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:15.151] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:44:15.151] INFO: number of red-efficiency pixels: 511 349 837 1285 1463 1346 1428 704 809 1155 1204 839 710 510 110 120
[15:44:15.151] INFO: number of X-ray hits detected: 225637 149067 234472 351337 375352 393126 407382 285765 283503 335000 332411 282154 299482 181507 79835 92249
[15:44:15.151] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:44:15.151] INFO: number of Vcal hits detected: 207423 207609 206816 206294 206000 206184 206059 207135 207055 206529 206440 206997 207195 207347 207887 207874
[15:44:15.151] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.5 99.2 99.1 99.2 99.2 99.6 99.6 99.4 99.3 99.6 99.7 99.7 99.9 99.9
[15:44:15.151] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.4 99.2 99.0 99.1 99.1 99.6 99.5 99.3 99.2 99.5 99.6 99.7 99.9 99.9
[15:44:15.151] INFO: X-ray hit rate [MHz/cm2]: 66.1 43.7 68.7 103.0 110.0 115.2 119.4 83.8 83.1 98.2 97.4 82.7 87.8 53.2 23.4 27.0
[15:44:15.151] INFO: PixTestHighRate::doXPixelAlive() done
[15:44:15.196] INFO: PixTest:: pg_setup set to default.
[15:44:15.213] INFO: enter test to run
[15:44:22.195] INFO: test: exit no parameter change
[15:44:22.614] QUIET: Connection to board 32 closed.
[15:44:22.616] INFO: pXar: this is the end, my friend