[14:09:55.198] INFO: *** Welcome to pxar ***
[14:09:55.198] INFO: *** Today: 2016/07/18
[14:09:55.213] INFO: *** Version: v1.9.0-814-g7497
[14:09:55.213] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//dacParameters35_C15.dat
[14:09:55.214] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:09:55.214] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//defaultMaskFile.dat
[14:09:55.214] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C15.dat
[14:09:55.288] INFO: clk: 4
[14:09:55.288] INFO: ctr: 4
[14:09:55.288] INFO: sda: 19
[14:09:55.288] INFO: tin: 9
[14:09:55.288] INFO: level: 15
[14:09:55.288] INFO: triggerdelay: 0
[14:09:55.288] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[14:09:55.288] INFO: Log level: INFO
[14:09:55.304] QUIET: Connection to board DTB_WREKRL opened.
[14:09:55.307] 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:
------------------------------------------------------
[14:09:55.310] INFO: RPC call hashes of host and DTB match: 398089610
[14:09:56.841] INFO: DUT info:
[14:09:56.841] INFO: The DUT currently contains the following objects:
[14:09:56.841] INFO: 2 TBM Cores tbm08c (2 ON)
[14:09:56.841] INFO: TBM Core alpha (0): 7 registers set
[14:09:56.841] INFO: TBM Core beta (1): 7 registers set
[14:09:56.841] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[14:09:56.841] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:56.841] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[14:09:57.245] INFO: enter 'restricted' command line mode
[14:09:57.245] INFO: enter test to run
[14:09:58.317] INFO: test: timing no parameter change
[14:09:58.317] INFO: running: timing
[14:09:58.329] INFO: ######################################################################
[14:09:58.329] INFO: PixTestTiming::doTest()
[14:09:58.329] INFO: ######################################################################
[14:09:58.329] INFO: ----------------------------------------------------------------------
[14:09:58.329] INFO: PixTestTiming::TBMPhaseScan()
[14:09:58.329] INFO: ----------------------------------------------------------------------
[14:15:31.996] INFO: TBM Phase Settings: 232
[14:15:31.996] INFO: 400MHz Phase: 2
[14:15:31.996] INFO: 160MHz Phase: 7
[14:15:31.996] INFO: Functional Phase Area: 5
[14:15:31.999] INFO: Test took 333670 ms.
[14:15:31.999] INFO: PixTestTiming::TBMPhaseScan() done.
[14:15:31.999] INFO: ----------------------------------------------------------------------
[14:15:31.999] INFO: PixTestTiming::ROCDelayScan()
[14:15:31.000] INFO: ----------------------------------------------------------------------
[14:17:44.490] INFO: ROC Delay Settings: 228
[14:17:44.491] INFO: ROC Header-Trailer/Token Delay: 11
[14:17:44.491] INFO: ROC Port 0 Delay: 4
[14:17:44.491] INFO: ROC Port 1 Delay: 4
[14:17:44.491] INFO: Functional ROC Area: 6
[14:17:44.494] INFO: Test took 132495 ms.
[14:17:44.494] INFO: PixTestTiming::ROCDelayScan() done.
[14:17:44.494] INFO: ----------------------------------------------------------------------
[14:17:44.494] INFO: PixTestTiming::TimingTest()
[14:17:44.494] INFO: ----------------------------------------------------------------------
[14:18:00.557] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:18:15.442] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:18:30.293] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:18:45.128] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:19:00.056] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:19:14.911] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:19:29.754] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:19:44.721] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:19:59.605] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:14.454] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:14.832] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:14.850] INFO: ----------------------------------------------------------------------
[14:20:14.850] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:20:14.850] INFO: ----------------------------------------------------------------------
[14:20:14.850] INFO: ----------------------------------------------------------------------
[14:20:14.850] INFO: Read back bit status: 1
[14:20:14.850] INFO: ----------------------------------------------------------------------
[14:20:14.850] INFO: ----------------------------------------------------------------------
[14:20:14.850] INFO: Timings are good!
[14:20:14.850] INFO: ----------------------------------------------------------------------
[14:20:14.850] INFO: Test took 150356 ms.
[14:20:14.850] INFO: PixTestTiming::TimingTest() done.
[14:20:14.862] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:20:14.862] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:20:14.862] INFO: PixTestTiming::doTest took 616538 ms.
[14:20:14.862] INFO: PixTestTiming::doTest() done
[14:20:14.862] INFO: Write out TBMPhaseScan_0_V0
[14:20:14.890] INFO: Write out TBMPhaseScan_1_V0
[14:20:14.890] INFO: Write out CombinedTBMPhaseScan_V0
[14:20:14.917] INFO: Write out ROCDelayScan3_V0
[14:20:14.918] INFO: enter test to run
[14:20:27.281] INFO: test: PixelAlive no parameter change
[14:20:27.281] INFO: running: pixelalive
[14:20:27.285] INFO: ----------------------------------------------------------------------
[14:20:27.285] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[14:20:27.285] INFO: ----------------------------------------------------------------------
[14:20:27.606] INFO: Expecting 41600 events.
[14:20:31.944] INFO: 41600 events read in total (3622ms).
[14:20:31.945] INFO: Test took 4656ms.
[14:20:31.951] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:32.347] INFO: PixTestAlive::aliveTest() done
[14:20:32.347] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 1 53 52 52 53 43 0 30 61
[14:20:32.351] INFO: enter test to run
[14:21:09.576] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[14:21:09.576] INFO: running: highrate
[14:21:09.577] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:21:09.783] INFO: ----------------------------------------------------------------------
[14:21:09.783] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[14:21:09.783] INFO: ----------------------------------------------------------------------
[14:21:09.783] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[14:21:09.783] INFO: edge/corner pixel THR is adjusted
[14:21:09.783] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:21:10.743] INFO: Collecting data for 5 seconds...
[14:21:15.759] INFO: Done with hot pixel readout
[14:21:27.196] INFO: PixTest:: pg_setup set to default.
[14:21:27.197] INFO: 0 hot pixels found in step 0
[14:21:27.232] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:21:27.236] INFO: PixTest::trimHotPixels() done
[14:21:27.236] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C0.dat
[14:21:27.241] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C1.dat
[14:21:27.248] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C2.dat
[14:21:27.254] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C3.dat
[14:21:27.260] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C4.dat
[14:21:27.265] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C5.dat
[14:21:27.271] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C6.dat
[14:21:27.276] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C7.dat
[14:21:27.281] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C8.dat
[14:21:27.286] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C9.dat
[14:21:27.292] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C10.dat
[14:21:27.297] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C11.dat
[14:21:27.302] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C12.dat
[14:21:27.307] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C13.dat
[14:21:27.312] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C14.dat
[14:21:27.318] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C15.dat
[14:21:27.323] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//defaultMaskFile.dat
[14:21:27.334] INFO: enter test to run
[14:21:54.056] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:21:54.056] INFO: running: highrate
[14:21:54.061] INFO: ----------------------------------------------------------------------
[14:21:54.061] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:21:54.061] INFO: ----------------------------------------------------------------------
[14:21:54.061] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:21:54.061] INFO: edge/corner pixel THR is adjusted
[14:21:54.061] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:21:55.018] INFO: Collecting data for 1 seconds...
[14:21:56.022] INFO: Done with hot pixel readout
[14:21:59.870] INFO: PixTest:: pg_setup set to default.
[14:21:59.870] INFO: 0 hot pixels found in step 0
[14:21:59.876] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:21:59.966] INFO: PixTest::trimHotPixels() done
[14:21:59.967] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C0.dat
[14:21:59.972] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C1.dat
[14:21:59.977] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C2.dat
[14:21:59.984] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C3.dat
[14:21:59.989] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C4.dat
[14:21:59.995] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C5.dat
[14:21:59.000] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C6.dat
[14:22:00.006] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C7.dat
[14:22:00.011] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C8.dat
[14:22:00.017] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C9.dat
[14:22:00.022] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C10.dat
[14:22:00.028] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C11.dat
[14:22:00.033] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C12.dat
[14:22:00.039] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C13.dat
[14:22:00.044] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C14.dat
[14:22:00.049] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//trimParameters35_C15.dat
[14:22:00.055] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-G-1-23_FPIXTest-17C-FNAL-160701-1310_2016-07-01_13h10m_1467396654/000_FPIXTest_p17//defaultMaskFile.dat
[14:22:00.064] INFO: enter test to run
[14:22:28.360] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:22:28.360] INFO: running: xray
[14:22:28.361] INFO: ----------------------------------------------------------------------
[14:22:28.361] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:22:28.361] INFO: ----------------------------------------------------------------------
[14:22:29.325] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:22:40.791] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[14:23:08.969] INFO: Resuming triggers.
[14:23:20.535] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[14:23:49.891] INFO: Resuming triggers.
[14:24:01.352] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[14:24:31.791] INFO: Resuming triggers.
[14:24:43.251] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[14:25:13.367] INFO: Resuming triggers.
[14:25:24.829] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[14:25:54.269] INFO: Resuming triggers.
[14:26:05.728] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[14:26:35.026] INFO: Resuming triggers.
[14:26:46.482] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[14:27:15.719] INFO: Resuming triggers.
[14:27:27.175] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[14:27:56.442] INFO: Resuming triggers.
[14:28:05.119] INFO: data taking finished, elapsed time: 100 seconds.
[14:28:27.474] INFO: PixTest:: pg_setup set to default.
[14:28:27.478] INFO: PixTestXray::doPhRun() done
[14:28:27.614] INFO: enter test to run
[14:30:08.173] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:30:08.173] INFO: running: xray
[14:30:08.174] INFO: ----------------------------------------------------------------------
[14:30:08.174] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:30:08.174] INFO: ----------------------------------------------------------------------
[14:30:09.138] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:30:15.972] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[14:30:45.450] INFO: Resuming triggers.
[14:30:52.292] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[14:31:22.413] INFO: Resuming triggers.
[14:31:29.255] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[14:31:59.155] INFO: Resuming triggers.
[14:32:05.998] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[14:32:35.575] INFO: Resuming triggers.
[14:32:42.417] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[14:33:11.872] INFO: Resuming triggers.
[14:33:18.720] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[14:33:48.958] INFO: Resuming triggers.
[14:33:55.797] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[14:34:26.438] INFO: Resuming triggers.
[14:34:33.283] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[14:35:02.956] INFO: Resuming triggers.
[14:35:09.799] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[14:35:39.407] INFO: Resuming triggers.
[14:35:46.249] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[14:36:16.773] INFO: Resuming triggers.
[14:36:23.608] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[14:36:53.774] INFO: Resuming triggers.
[14:37:00.605] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[14:37:29.944] INFO: Resuming triggers.
[14:37:36.778] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[14:38:05.907] INFO: Resuming triggers.
[14:38:12.737] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[14:38:41.921] INFO: Resuming triggers.
[14:38:46.524] INFO: data taking finished, elapsed time: 100 seconds.
[14:39:06.798] INFO: PixTest:: pg_setup set to default.
[14:39:06.801] INFO: PixTestXray::doPhRun() done
[14:39:06.951] INFO: enter test to run
[14:40:23.641] INFO: test: HighRate no parameter change
[14:40:23.641] INFO: running: highrate
[14:40:23.687] INFO: ----------------------------------------------------------------------
[14:40:23.687] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[14:40:23.687] INFO: ----------------------------------------------------------------------
[14:40:23.850] INFO: Expecting 768 events.
[14:40:24.984] INFO: 768 events read in total (418ms).
[14:40:24.984] INFO: Test took 1268ms.
[14:40:25.787] INFO: Expecting 41600 events.
[14:40:28.738] INFO: 41600 events read in total (2424ms).
[14:40:28.739] INFO: Test took 3747ms.
[14:40:28.772] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:40:29.503] INFO: Expecting 41600 events.
[14:40:32.661] INFO: 41600 events read in total (2631ms).
[14:40:32.662] INFO: Test took 3873ms.
[14:40:32.697] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:40:33.417] INFO: Expecting 41600 events.
[14:40:36.590] INFO: 41600 events read in total (2646ms).
[14:40:36.591] INFO: Test took 3876ms.
[14:40:36.625] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:40:37.350] INFO: Expecting 41600 events.
[14:40:40.558] INFO: 41600 events read in total (2681ms).
[14:40:40.559] INFO: Test took 3916ms.
[14:40:40.593] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:40:41.313] INFO: Expecting 41600 events.
[14:40:44.530] INFO: 41600 events read in total (2690ms).
[14:40:44.531] INFO: Test took 3921ms.
[14:40:44.564] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:40:45.286] INFO: Expecting 41600 events.
[14:40:48.397] INFO: 41600 events read in total (2584ms).
[14:40:48.398] INFO: Test took 3816ms.
[14:40:48.432] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:40:49.156] INFO: Expecting 41600 events.
[14:40:52.391] INFO: 41600 events read in total (2708ms).
[14:40:52.392] INFO: Test took 3941ms.
[14:40:52.426] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:40:53.147] INFO: Expecting 41600 events.
[14:40:56.331] INFO: 41600 events read in total (2658ms).
[14:40:56.332] INFO: Test took 3888ms.
[14:40:56.366] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:40:57.092] INFO: Expecting 41600 events.
[14:41:00.303] INFO: 41600 events read in total (2684ms).
[14:41:00.304] INFO: Test took 3919ms.
[14:41:00.337] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:01.064] INFO: Expecting 41600 events.
[14:41:04.284] INFO: 41600 events read in total (2693ms).
[14:41:04.285] INFO: Test took 3930ms.
[14:41:04.319] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:05.042] INFO: Expecting 41600 events.
[14:41:08.110] INFO: 41600 events read in total (2542ms).
[14:41:08.111] INFO: Test took 3774ms.
[14:41:08.145] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:08.867] INFO: Expecting 41600 events.
[14:41:12.099] INFO: 41600 events read in total (2705ms).
[14:41:12.100] INFO: Test took 3936ms.
[14:41:12.134] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:12.859] INFO: Expecting 41600 events.
[14:41:16.082] INFO: 41600 events read in total (2696ms).
[14:41:16.083] INFO: Test took 3931ms.
[14:41:16.117] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:16.844] INFO: Expecting 41600 events.
[14:41:20.042] INFO: 41600 events read in total (2671ms).
[14:41:20.043] INFO: Test took 3907ms.
[14:41:20.077] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:20.802] INFO: Expecting 41600 events.
[14:41:24.037] INFO: 41600 events read in total (2709ms).
[14:41:24.038] INFO: Test took 3944ms.
[14:41:24.073] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:24.797] INFO: Expecting 41600 events.
[14:41:28.033] INFO: 41600 events read in total (2709ms).
[14:41:28.034] INFO: Test took 3943ms.
[14:41:28.068] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:28.792] INFO: Expecting 41600 events.
[14:41:32.050] INFO: 41600 events read in total (2732ms).
[14:41:32.051] INFO: Test took 3966ms.
[14:41:32.084] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:32.808] INFO: Expecting 41600 events.
[14:41:36.048] INFO: 41600 events read in total (2713ms).
[14:41:36.049] INFO: Test took 3947ms.
[14:41:36.083] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:36.805] INFO: Expecting 41600 events.
[14:41:40.019] INFO: 41600 events read in total (2688ms).
[14:41:40.020] INFO: Test took 3920ms.
[14:41:40.054] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:40.776] INFO: Expecting 41600 events.
[14:41:43.870] INFO: 41600 events read in total (2567ms).
[14:41:43.871] INFO: Test took 3800ms.
[14:41:43.904] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:41:44.267] INFO: enter test to run
[14:41:59.600] INFO: test: HighRate no parameter change
[14:41:59.600] INFO: running: highrate
[14:41:59.601] INFO: ----------------------------------------------------------------------
[14:41:59.601] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:41:59.601] INFO: ----------------------------------------------------------------------
[14:42:00.219] INFO: Expecting 208000 events.
[14:42:11.931] INFO: 208000 events read in total (11185ms).
[14:42:11.934] INFO: Test took 12324ms.
[14:42:12.076] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:42:12.328] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 1 53 52 52 53 43 0 30 61
[14:42:12.328] INFO: number of red-efficiency pixels: 71 45 76 142 165 147 158 102 141 177 197 193 144 52 57 107
[14:42:12.328] INFO: number of X-ray hits detected: 65612 43527 67331 107938 117049 116033 113507 76627 72989 96059 95000 84785 82241 53238 20939 26857
[14:42:12.328] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:42:12.328] INFO: number of Vcal hits detected: 207879 207954 207924 207852 207833 207851 207838 207846 205262 205272 205241 205207 205744 207948 206393 204813
[14:42:12.328] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 99.9 100.0
[14:42:12.328] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.9 99.9 98.7 98.7 98.7 98.7 98.9 100.0 99.2 98.5
[14:42:12.328] INFO: X-ray hit rate [MHz/cm2]: 19.2 12.8 19.7 31.6 34.3 34.0 33.3 22.5 21.4 28.2 27.8 24.9 24.1 15.6 6.1 7.9
[14:42:12.328] INFO: PixTestHighRate::doXPixelAlive() done
[14:42:12.373] INFO: PixTest:: pg_setup set to default.
[14:42:12.388] INFO: enter test to run
[14:42:46.568] INFO: test: HighRate no parameter change
[14:42:46.568] INFO: running: highrate
[14:42:46.569] INFO: ----------------------------------------------------------------------
[14:42:46.569] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:42:46.569] INFO: ----------------------------------------------------------------------
[14:42:47.187] INFO: Expecting 208000 events.
[14:43:00.658] INFO: 208000 events read in total (12944ms).
[14:43:00.664] INFO: Test took 14084ms.
[14:43:00.952] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:43:01.249] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 1 53 52 52 53 43 0 30 61
[14:43:01.249] INFO: number of red-efficiency pixels: 220 133 228 453 524 423 530 279 321 481 420 400 374 156 73 141
[14:43:01.249] INFO: number of X-ray hits detected: 132789 88458 136333 217579 235471 232885 229093 154323 147679 192862 189187 169965 165466 107659 42304 53921
[14:43:01.249] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:43:01.249] INFO: number of Vcal hits detected: 207716 207857 207753 207504 207414 207543 207432 207643 205070 204944 204989 204982 205495 207839 206379 204763
[14:43:01.249] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.8 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 100.0
[14:43:01.249] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.7 99.8 98.6 98.5 98.6 98.5 98.8 99.9 99.2 98.4
[14:43:01.249] INFO: X-ray hit rate [MHz/cm2]: 38.9 25.9 40.0 63.8 69.0 68.3 67.1 45.2 43.3 56.5 55.5 49.8 48.5 31.6 12.4 15.8
[14:43:01.249] INFO: PixTestHighRate::doXPixelAlive() done
[14:43:01.298] INFO: PixTest:: pg_setup set to default.
[14:43:01.313] INFO: enter test to run
[14:43:25.879] INFO: test: HighRate no parameter change
[14:43:25.880] INFO: running: highrate
[14:43:25.881] INFO: ----------------------------------------------------------------------
[14:43:25.881] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:43:25.881] INFO: ----------------------------------------------------------------------
[14:43:26.504] INFO: Expecting 208000 events.
[14:43:41.510] INFO: 208000 events read in total (14479ms).
[14:43:41.517] INFO: Test took 15625ms.
[14:43:41.940] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:43:42.285] INFO: number of dead pixels (per ROC): 1 0 0 0 0 0 0 1 53 52 52 53 43 0 31 60
[14:43:42.285] INFO: number of red-efficiency pixels: 453 284 459 1156 1284 952 1240 677 598 915 943 791 664 288 124 201
[14:43:42.285] INFO: number of X-ray hits detected: 199810 134962 206148 330047 355349 353199 345829 234178 224055 291641 285100 257205 250791 161796 64529 81623
[14:43:42.285] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:43:42.285] INFO: number of Vcal hits detected: 207417 207684 207447 206506 206316 206819 206376 207106 204724 204385 204319 204476 205143 207673 206324 204708
[14:43:42.285] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.4 99.3 99.5 99.3 99.6 99.7 99.5 99.5 99.6 99.7 99.9 99.9 99.9
[14:43:42.285] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.7 99.3 99.2 99.4 99.2 99.6 98.4 98.3 98.2 98.3 98.6 99.8 99.2 98.4
[14:43:42.286] INFO: X-ray hit rate [MHz/cm2]: 58.6 39.6 60.4 96.7 104.2 103.5 101.4 68.6 65.7 85.5 83.6 75.4 73.5 47.4 18.9 23.9
[14:43:42.286] INFO: PixTestHighRate::doXPixelAlive() done
[14:43:42.335] INFO: PixTest:: pg_setup set to default.
[14:43:42.353] INFO: enter test to run
[14:44:40.855] INFO: test: exit no parameter change
[14:44:41.216] QUIET: Connection to board 33 closed.
[14:44:41.217] INFO: pXar: this is the end, my friend