[14:10:50.315] INFO: *** Welcome to pxar ***
[14:10:50.315] INFO: *** Today: 2016/05/05
[14:10:50.339] INFO: *** Version: v1.9.0-796-gef167-dirty
[14:10:50.339] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//dacParameters35_C15.dat
[14:10:50.339] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:10:50.339] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//defaultMaskFile.dat
[14:10:50.339] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C15.dat
[14:10:50.431] INFO: clk: 4
[14:10:50.431] INFO: ctr: 4
[14:10:50.431] INFO: sda: 19
[14:10:50.431] INFO: tin: 9
[14:10:50.431] INFO: level: 15
[14:10:50.431] INFO: triggerdelay: 0
[14:10:50.431] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[14:10:50.431] INFO: Log level: INFO
[14:10:50.449] QUIET: Connection to board DTB_WREKRL opened.
[14:10:50.452] 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:10:50.455] INFO: RPC call hashes of host and DTB match: 398089610
[14:10:51.985] INFO: DUT info:
[14:10:51.985] INFO: The DUT currently contains the following objects:
[14:10:51.985] INFO: 2 TBM Cores tbm08c (2 ON)
[14:10:51.985] INFO: TBM Core alpha (0): 7 registers set
[14:10:51.986] INFO: TBM Core beta (1): 7 registers set
[14:10:51.986] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[14:10:51.986] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:51.986] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[14:10:52.390] INFO: enter 'restricted' command line mode
[14:10:52.390] INFO: enter test to run
[14:10:59.258] INFO: test: timing no parameter change
[14:10:59.258] INFO: running: timing
[14:10:59.267] INFO: ######################################################################
[14:10:59.267] INFO: PixTestTiming::doTest()
[14:10:59.267] INFO: ######################################################################
[14:10:59.268] INFO: ----------------------------------------------------------------------
[14:10:59.268] INFO: PixTestTiming::TBMPhaseScan()
[14:10:59.268] INFO: ----------------------------------------------------------------------
[14:17:25.757] INFO: TBM Phase Settings: 224
[14:17:25.757] INFO: 400MHz Phase: 0
[14:17:25.757] INFO: 160MHz Phase: 7
[14:17:25.757] INFO: Functional Phase Area: 2
[14:17:25.760] INFO: Test took 386493 ms.
[14:17:25.760] INFO: PixTestTiming::TBMPhaseScan() done.
[14:17:25.760] INFO: ----------------------------------------------------------------------
[14:17:25.760] INFO: PixTestTiming::ROCDelayScan()
[14:17:25.760] INFO: ----------------------------------------------------------------------
[14:19:17.682] INFO: ROC Delay Settings: 228
[14:19:17.682] INFO: ROC Header-Trailer/Token Delay: 11
[14:19:17.682] INFO: ROC Port 0 Delay: 4
[14:19:17.682] INFO: ROC Port 1 Delay: 4
[14:19:17.682] INFO: Functional ROC Area: 4
[14:19:17.685] INFO: Test took 111925 ms.
[14:19:17.685] INFO: PixTestTiming::ROCDelayScan() done.
[14:19:17.686] INFO: ----------------------------------------------------------------------
[14:19:17.686] INFO: PixTestTiming::TimingTest()
[14:19:17.686] INFO: ----------------------------------------------------------------------
[14:19:33.875] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:19:48.848] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:04.042] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:19.334] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:34.612] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:49.959] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:05.229] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:20.528] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:35.721] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:50.922] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:51.298] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:51.316] INFO: ----------------------------------------------------------------------
[14:21:51.316] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:21:51.316] INFO: ----------------------------------------------------------------------
[14:21:51.316] INFO: ----------------------------------------------------------------------
[14:21:51.316] INFO: Read back bit status: 1
[14:21:51.316] INFO: ----------------------------------------------------------------------
[14:21:51.316] INFO: ----------------------------------------------------------------------
[14:21:51.316] INFO: Timings are good!
[14:21:51.316] INFO: ----------------------------------------------------------------------
[14:21:51.316] INFO: Test took 153631 ms.
[14:21:51.316] INFO: PixTestTiming::TimingTest() done.
[14:21:51.316] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:21:51.316] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:21:51.316] INFO: PixTestTiming::doTest took 652053 ms.
[14:21:51.316] INFO: PixTestTiming::doTest() done
[14:21:51.316] INFO: Write out TBMPhaseScan_0_V0
[14:21:51.348] INFO: Write out TBMPhaseScan_1_V0
[14:21:51.348] INFO: Write out CombinedTBMPhaseScan_V0
[14:21:51.349] INFO: Write out ROCDelayScan3_V0
[14:21:51.350] INFO: enter test to run
[14:34:23.840] INFO: test: PixelAlive no parameter change
[14:34:23.840] INFO: running: pixelalive
[14:34:23.845] INFO: ----------------------------------------------------------------------
[14:34:23.845] 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:34:23.845] INFO: ----------------------------------------------------------------------
[14:34:24.163] INFO: Expecting 41600 events.
[14:34:28.490] INFO: 41600 events read in total (3612ms).
[14:34:28.491] INFO: Test took 4642ms.
[14:34:28.497] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:34:28.895] INFO: PixTestAlive::aliveTest() done
[14:34:28.895] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 4 4 0 0 0 0 0 0 0 0
[14:34:28.898] INFO: enter test to run
[14:35:09.232] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[14:35:09.232] INFO: running: highrate
[14:35:09.232] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:35:09.391] INFO: ----------------------------------------------------------------------
[14:35:09.391] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[14:35:09.391] INFO: ----------------------------------------------------------------------
[14:35:09.391] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[14:35:09.391] INFO: edge/corner pixel THR is adjusted
[14:35:09.391] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:35:10.347] INFO: Collecting data for 5 seconds...
[14:35:15.366] INFO: Done with hot pixel readout
[14:35:25.946] INFO: PixTest:: pg_setup set to default.
[14:35:25.947] INFO: 0 hot pixels found in step 0
[14:35:25.971] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:35:25.986] INFO: PixTest::trimHotPixels() done
[14:35:25.986] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C0.dat
[14:35:25.994] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C1.dat
[14:35:25.999] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C2.dat
[14:35:26.005] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C3.dat
[14:35:26.010] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C4.dat
[14:35:26.016] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C5.dat
[14:35:26.021] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C6.dat
[14:35:26.026] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C7.dat
[14:35:26.032] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C8.dat
[14:35:26.037] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C9.dat
[14:35:26.043] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C10.dat
[14:35:26.048] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C11.dat
[14:35:26.053] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C12.dat
[14:35:26.059] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C13.dat
[14:35:26.064] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C14.dat
[14:35:26.069] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C15.dat
[14:35:26.074] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//defaultMaskFile.dat
[14:35:26.085] INFO: enter test to run
[14:36:01.919] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:36:01.919] INFO: running: highrate
[14:36:01.924] INFO: ----------------------------------------------------------------------
[14:36:01.924] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:36:01.924] INFO: ----------------------------------------------------------------------
[14:36:01.924] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:36:01.924] INFO: edge/corner pixel THR is adjusted
[14:36:01.924] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:36:02.881] INFO: Collecting data for 1 seconds...
[14:36:03.884] INFO: Done with hot pixel readout
[14:36:07.353] INFO: PixTest:: pg_setup set to default.
[14:36:07.354] INFO: 0 hot pixels found in step 0
[14:36:07.359] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:36:07.472] INFO: PixTest::trimHotPixels() done
[14:36:07.472] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C0.dat
[14:36:07.480] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C1.dat
[14:36:07.486] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C2.dat
[14:36:07.491] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C3.dat
[14:36:07.496] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C4.dat
[14:36:07.501] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C5.dat
[14:36:07.507] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C6.dat
[14:36:07.512] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C7.dat
[14:36:07.517] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C8.dat
[14:36:07.522] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C9.dat
[14:36:07.528] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C10.dat
[14:36:07.533] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C11.dat
[14:36:07.538] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C12.dat
[14:36:07.543] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C13.dat
[14:36:07.548] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C14.dat
[14:36:07.554] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C15.dat
[14:36:07.559] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-3-15_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//defaultMaskFile.dat
[14:36:07.568] INFO: enter test to run
[14:36:38.039] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:36:38.039] INFO: running: xray
[14:36:38.040] INFO: ----------------------------------------------------------------------
[14:36:38.040] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:36:38.040] INFO: ----------------------------------------------------------------------
[14:36:39.005] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:36:51.533] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[14:37:20.418] INFO: Resuming triggers.
[14:37:32.955] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[14:38:02.102] INFO: Resuming triggers.
[14:38:14.636] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[14:38:43.607] INFO: Resuming triggers.
[14:38:56.141] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[14:39:25.286] INFO: Resuming triggers.
[14:39:37.819] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[14:40:06.797] INFO: Resuming triggers.
[14:40:19.331] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[14:40:48.372] INFO: Resuming triggers.
[14:41:00.905] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[14:41:30.023] INFO: Resuming triggers.
[14:41:42.555] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[14:42:11.900] INFO: Resuming triggers.
[14:42:11.960] INFO: data taking finished, elapsed time: 100 seconds.
[14:42:12.674] INFO: PixTest:: pg_setup set to default.
[14:42:12.677] INFO: PixTestXray::doPhRun() done
[14:42:12.816] INFO: enter test to run
[14:42:59.661] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:42:59.661] INFO: running: xray
[14:42:59.662] INFO: ----------------------------------------------------------------------
[14:42:59.662] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:42:59.662] INFO: ----------------------------------------------------------------------
[14:43:00.625] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:43:08.599] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[14:43:39.597] INFO: Resuming triggers.
[14:43:47.569] INFO: run duration 15 seconds, buffer almost full (81%), pausing triggers.
[14:44:17.635] INFO: Resuming triggers.
[14:44:25.607] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[14:44:55.695] INFO: Resuming triggers.
[14:45:03.666] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[14:45:33.803] INFO: Resuming triggers.
[14:45:41.776] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[14:46:12.415] INFO: Resuming triggers.
[14:46:20.388] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[14:46:50.723] INFO: Resuming triggers.
[14:46:58.694] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[14:47:28.756] INFO: Resuming triggers.
[14:47:36.729] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[14:48:06.916] INFO: Resuming triggers.
[14:48:14.890] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[14:48:45.105] INFO: Resuming triggers.
[14:48:53.081] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[14:49:23.175] INFO: Resuming triggers.
[14:49:31.150] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[14:50:01.181] INFO: Resuming triggers.
[14:50:09.152] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[14:50:39.221] INFO: Resuming triggers.
[14:50:43.887] INFO: data taking finished, elapsed time: 100 seconds.
[14:51:01.744] INFO: PixTest:: pg_setup set to default.
[14:51:01.748] INFO: PixTestXray::doPhRun() done
[14:51:01.894] INFO: enter test to run
[14:52:17.072] INFO: test: HighRate no parameter change
[14:52:17.072] INFO: running: highrate
[14:52:17.073] INFO: ----------------------------------------------------------------------
[14:52:17.074] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[14:52:17.074] INFO: ----------------------------------------------------------------------
[14:52:17.216] INFO: Expecting 768 events.
[14:52:18.350] INFO: 768 events read in total (419ms).
[14:52:18.350] INFO: Test took 1269ms.
[14:52:19.153] INFO: Expecting 41600 events.
[14:52:22.176] INFO: 41600 events read in total (2496ms).
[14:52:22.177] INFO: Test took 3820ms.
[14:52:22.202] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:52:22.942] INFO: Expecting 41600 events.
[14:52:26.069] INFO: 41600 events read in total (2601ms).
[14:52:26.069] INFO: Test took 3853ms.
[14:52:26.095] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:52:26.835] INFO: Expecting 41600 events.
[14:52:29.996] INFO: 41600 events read in total (2634ms).
[14:52:29.997] INFO: Test took 3886ms.
[14:52:30.023] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:52:30.763] INFO: Expecting 41600 events.
[14:52:33.918] INFO: 41600 events read in total (2628ms).
[14:52:33.919] INFO: Test took 3879ms.
[14:52:33.945] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:52:34.686] INFO: Expecting 41600 events.
[14:52:37.851] INFO: 41600 events read in total (2638ms).
[14:52:37.851] INFO: Test took 3891ms.
[14:52:37.877] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:52:38.613] INFO: Expecting 41600 events.
[14:52:41.776] INFO: 41600 events read in total (2636ms).
[14:52:41.777] INFO: Test took 3884ms.
[14:52:41.802] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:52:42.540] INFO: Expecting 41600 events.
[14:52:45.699] INFO: 41600 events read in total (2632ms).
[14:52:45.700] INFO: Test took 3881ms.
[14:52:45.726] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:52:46.462] INFO: Expecting 41600 events.
[14:52:49.637] INFO: 41600 events read in total (2648ms).
[14:52:49.638] INFO: Test took 3896ms.
[14:52:49.664] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:52:50.403] INFO: Expecting 41600 events.
[14:52:53.572] INFO: 41600 events read in total (2642ms).
[14:52:53.573] INFO: Test took 3894ms.
[14:52:53.599] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:52:54.337] INFO: Expecting 41600 events.
[14:52:57.497] INFO: 41600 events read in total (2633ms).
[14:52:57.498] INFO: Test took 3883ms.
[14:52:57.524] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:52:58.262] INFO: Expecting 41600 events.
[14:53:01.442] INFO: 41600 events read in total (2653ms).
[14:53:01.443] INFO: Test took 3905ms.
[14:53:01.469] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:53:02.203] INFO: Expecting 41600 events.
[14:53:05.368] INFO: 41600 events read in total (2638ms).
[14:53:05.369] INFO: Test took 3884ms.
[14:53:05.395] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:53:06.134] INFO: Expecting 41600 events.
[14:53:09.295] INFO: 41600 events read in total (2634ms).
[14:53:09.296] INFO: Test took 3884ms.
[14:53:09.322] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:53:10.062] INFO: Expecting 41600 events.
[14:53:13.287] INFO: 41600 events read in total (2698ms).
[14:53:13.288] INFO: Test took 3949ms.
[14:53:13.315] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:53:14.050] INFO: Expecting 41600 events.
[14:53:17.264] INFO: 41600 events read in total (2688ms).
[14:53:17.265] INFO: Test took 3935ms.
[14:53:17.292] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:53:18.030] INFO: Expecting 41600 events.
[14:53:21.235] INFO: 41600 events read in total (2678ms).
[14:53:21.236] INFO: Test took 3929ms.
[14:53:21.263] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:53:21.001] INFO: Expecting 41600 events.
[14:53:25.275] INFO: 41600 events read in total (2747ms).
[14:53:25.276] INFO: Test took 3997ms.
[14:53:25.303] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:53:26.035] INFO: Expecting 41600 events.
[14:53:29.299] INFO: 41600 events read in total (2737ms).
[14:53:29.300] INFO: Test took 3981ms.
[14:53:29.333] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:53:30.044] INFO: Expecting 41600 events.
[14:53:33.210] INFO: 41600 events read in total (2639ms).
[14:53:33.211] INFO: Test took 3863ms.
[14:53:33.238] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:53:33.970] INFO: Expecting 41600 events.
[14:53:37.010] INFO: 41600 events read in total (2513ms).
[14:53:37.011] INFO: Test took 3757ms.
[14:53:37.038] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:53:37.413] INFO: enter test to run
[14:53:53.984] INFO: test: HighRate no parameter change
[14:53:53.984] INFO: running: highrate
[14:53:53.985] INFO: ----------------------------------------------------------------------
[14:53:53.985] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:53:53.985] INFO: ----------------------------------------------------------------------
[14:53:54.610] INFO: Expecting 208000 events.
[14:54:06.170] INFO: 208000 events read in total (11033ms).
[14:54:06.172] INFO: Test took 12177ms.
[14:54:06.280] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:54:06.520] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 4 4 0 0 0 0 0 0 0 0
[14:54:06.520] INFO: number of red-efficiency pixels: 66 33 51 90 98 85 84 65 53 90 84 68 50 44 25 26
[14:54:06.520] INFO: number of X-ray hits detected: 51771 35900 48140 77374 82093 81499 79365 57573 57019 67024 65194 59505 61965 37589 17233 21294
[14:54:06.520] 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:54:06.520] INFO: number of Vcal hits detected: 207931 207967 207948 207900 207902 207914 207719 207738 207947 207909 207915 207932 207950 207955 207974 207974
[14:54:06.520] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[14:54:06.520] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 100.0 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[14:54:06.520] INFO: X-ray hit rate [MHz/cm2]: 15.2 10.5 14.1 22.7 24.1 23.9 23.3 16.9 16.7 19.6 19.1 17.4 18.2 11.0 5.1 6.2
[14:54:06.520] INFO: PixTestHighRate::doXPixelAlive() done
[14:54:06.565] INFO: PixTest:: pg_setup set to default.
[14:54:06.579] INFO: enter test to run
[14:55:35.135] INFO: test: HighRate no parameter change
[14:55:35.135] INFO: running: highrate
[14:55:35.136] INFO: ----------------------------------------------------------------------
[14:55:35.136] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:55:35.136] INFO: ----------------------------------------------------------------------
[14:55:35.753] INFO: Expecting 208000 events.
[14:55:48.440] INFO: 208000 events read in total (12160ms).
[14:55:48.445] INFO: Test took 13299ms.
[14:55:48.660] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:55:48.935] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 4 4 0 0 0 0 0 0 0 0
[14:55:48.935] INFO: number of red-efficiency pixels: 200 121 139 246 316 258 270 206 173 204 159 174 155 94 37 51
[14:55:48.935] INFO: number of X-ray hits detected: 110116 75473 102439 165116 173831 172888 167677 121468 120645 141636 139074 125953 130290 79348 36309 44942
[14:55:48.935] 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:55:48.935] INFO: number of Vcal hits detected: 207788 207876 207852 207724 207670 207730 207524 207590 207825 207788 207836 207820 207842 207905 207963 207948
[14:55:48.935] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.9 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[14:55:48.935] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.9 99.8 99.9 99.8 99.8 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[14:55:48.935] INFO: X-ray hit rate [MHz/cm2]: 32.3 22.1 30.0 48.4 51.0 50.7 49.1 35.6 35.4 41.5 40.8 36.9 38.2 23.3 10.6 13.2
[14:55:48.935] INFO: PixTestHighRate::doXPixelAlive() done
[14:55:48.982] INFO: PixTest:: pg_setup set to default.
[14:55:48.999] INFO: enter test to run
[14:56:16.470] INFO: test: HighRate no parameter change
[14:56:16.471] INFO: running: highrate
[14:56:16.472] INFO: ----------------------------------------------------------------------
[14:56:16.472] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:56:16.472] INFO: ----------------------------------------------------------------------
[14:56:17.084] INFO: Expecting 208000 events.
[14:56:31.141] INFO: 208000 events read in total (13530ms).
[14:56:31.147] INFO: Test took 14667ms.
[14:56:31.471] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:56:31.781] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 4 4 0 0 0 0 0 0 0 0
[14:56:31.781] INFO: number of red-efficiency pixels: 351 213 302 464 676 497 619 386 380 436 351 405 291 182 66 93
[14:56:31.781] INFO: number of X-ray hits detected: 166150 114786 155654 249806 264670 261085 254329 184415 184048 215595 211315 191009 198648 120321 55325 68586
[14:56:31.781] 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:56:31.781] INFO: number of Vcal hits detected: 207612 207780 207661 207451 207217 207455 207097 207379 207603 207541 207631 207573 207688 207808 207934 207906
[14:56:31.781] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.9 99.8 99.7 99.8 99.7 99.8 99.8 99.8 99.8 99.8 99.9 99.9 100.0 100.0
[14:56:31.781] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.7 99.6 99.7 99.6 99.7 99.8 99.8 99.8 99.8 99.9 99.9 100.0 100.0
[14:56:31.781] INFO: X-ray hit rate [MHz/cm2]: 48.7 33.6 45.6 73.2 77.6 76.5 74.5 54.1 53.9 63.2 61.9 56.0 58.2 35.3 16.2 20.1
[14:56:31.781] INFO: PixTestHighRate::doXPixelAlive() done
[14:56:31.826] INFO: PixTest:: pg_setup set to default.
[14:56:31.841] INFO: enter test to run
[14:56:52.694] INFO: test: exit no parameter change
[14:56:53.068] QUIET: Connection to board 33 closed.
[14:56:53.070] INFO: pXar: this is the end, my friend