[15:15:11.311] INFO: *** Welcome to pxar ***
[15:15:11.311] INFO: *** Today: 2016/04/20
[15:15:11.329] INFO: *** Version: v1.9.0-796-gef167-dirty
[15:15:11.329] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//dacParameters35_C15.dat
[15:15:11.330] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:15:11.330] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//defaultMaskFile.dat
[15:15:11.330] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C15.dat
[15:15:11.405] INFO: clk: 4
[15:15:11.405] INFO: ctr: 4
[15:15:11.405] INFO: sda: 19
[15:15:11.405] INFO: tin: 9
[15:15:11.405] INFO: level: 15
[15:15:11.405] INFO: triggerdelay: 0
[15:15:11.405] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[15:15:11.405] INFO: Log level: INFO
[15:15:11.424] QUIET: Connection to board DTB_WREKRL opened.
[15:15:11.427] 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:
------------------------------------------------------
[15:15:11.430] INFO: RPC call hashes of host and DTB match: 398089610
[15:15:12.955] INFO: DUT info:
[15:15:12.955] INFO: The DUT currently contains the following objects:
[15:15:12.955] INFO: 2 TBM Cores tbm08c (2 ON)
[15:15:12.955] INFO: TBM Core alpha (0): 7 registers set
[15:15:12.955] INFO: TBM Core beta (1): 7 registers set
[15:15:12.955] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:15:12.955] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.955] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.955] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.955] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.955] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.955] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.955] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.955] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.956] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.956] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.956] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.956] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.956] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.956] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.956] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:12.956] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:15:13.359] INFO: enter 'restricted' command line mode
[15:15:13.359] INFO: enter test to run
[15:15:31.296] INFO: test: timing no parameter change
[15:15:31.297] INFO: running: timing
[15:15:31.320] INFO: ######################################################################
[15:15:31.320] INFO: PixTestTiming::doTest()
[15:15:31.324] INFO: ######################################################################
[15:15:31.324] INFO: ----------------------------------------------------------------------
[15:15:31.324] INFO: PixTestTiming::TBMPhaseScan()
[15:15:31.324] INFO: ----------------------------------------------------------------------
[15:21:34.275] INFO: TBM Phase Settings: 236
[15:21:34.275] INFO: 400MHz Phase: 3
[15:21:34.275] INFO: 160MHz Phase: 7
[15:21:34.275] INFO: Functional Phase Area: 4
[15:21:34.284] INFO: Test took 362960 ms.
[15:21:34.284] INFO: PixTestTiming::TBMPhaseScan() done.
[15:21:34.284] INFO: ----------------------------------------------------------------------
[15:21:34.284] INFO: PixTestTiming::ROCDelayScan()
[15:21:34.284] INFO: ----------------------------------------------------------------------
[15:24:57.993] INFO: ROC Delay Settings: 228
[15:24:57.993] INFO: ROC Header-Trailer/Token Delay: 11
[15:24:57.993] INFO: ROC Port 0 Delay: 4
[15:24:57.993] INFO: ROC Port 1 Delay: 4
[15:24:57.993] INFO: Functional ROC Area: 5
[15:24:57.996] INFO: Test took 203712 ms.
[15:24:57.996] INFO: PixTestTiming::ROCDelayScan() done.
[15:24:57.996] INFO: ----------------------------------------------------------------------
[15:24:57.996] INFO: PixTestTiming::TimingTest()
[15:24:57.996] INFO: ----------------------------------------------------------------------
[15:25:14.119] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:25:29.087] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:25:44.036] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:25:58.969] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:13.918] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:28.856] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:43.822] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:58.754] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:13.704] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:28.679] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:29.060] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:29.079] INFO: ----------------------------------------------------------------------
[15:27:29.079] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:27:29.079] INFO: ----------------------------------------------------------------------
[15:27:29.079] INFO: ----------------------------------------------------------------------
[15:27:29.079] INFO: Read back bit status: 1
[15:27:29.079] INFO: ----------------------------------------------------------------------
[15:27:29.079] INFO: ----------------------------------------------------------------------
[15:27:29.079] INFO: Timings are good!
[15:27:29.079] INFO: ----------------------------------------------------------------------
[15:27:29.079] INFO: Test took 151083 ms.
[15:27:29.080] INFO: PixTestTiming::TimingTest() done.
[15:27:29.099] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:27:29.099] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:27:29.099] INFO: PixTestTiming::doTest took 717784 ms.
[15:27:29.099] INFO: PixTestTiming::doTest() done
[15:27:29.099] INFO: Write out TBMPhaseScan_0_V0
[15:27:29.128] INFO: Write out TBMPhaseScan_1_V0
[15:27:29.128] INFO: Write out CombinedTBMPhaseScan_V0
[15:27:29.129] INFO: Write out ROCDelayScan3_V0
[15:27:29.130] INFO: enter test to run
[15:27:58.843] INFO: test: PixelAlive no parameter change
[15:27:58.843] INFO: running: pixelalive
[15:27:58.847] INFO: ----------------------------------------------------------------------
[15:27:58.847] 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:27:58.848] INFO: ----------------------------------------------------------------------
[15:27:59.171] INFO: Expecting 41600 events.
[15:28:03.508] INFO: 41600 events read in total (3621ms).
[15:28:03.508] INFO: Test took 4656ms.
[15:28:03.515] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:28:03.909] INFO: PixTestAlive::aliveTest() done
[15:28:03.909] INFO: number of dead pixels (per ROC): 0 0 0 2 0 0 0 0 0 0 0 1 0 0 0 0
[15:28:03.912] INFO: enter test to run
[15:28:27.635] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:28:27.635] INFO: running: highrate
[15:28:27.635] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:28:27.786] INFO: ----------------------------------------------------------------------
[15:28:27.786] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:28:27.786] INFO: ----------------------------------------------------------------------
[15:28:27.786] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:28:27.786] INFO: edge/corner pixel THR is adjusted
[15:28:27.786] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:28:28.745] INFO: Collecting data for 5 seconds...
[15:28:33.761] INFO: Done with hot pixel readout
[15:28:45.078] INFO: PixTest:: pg_setup set to default.
[15:28:45.079] INFO: 0 hot pixels found in step 0
[15:28:45.112] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:28:45.115] INFO: PixTest::trimHotPixels() done
[15:28:45.115] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C0.dat
[15:28:45.121] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C1.dat
[15:28:45.127] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C2.dat
[15:28:45.132] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C3.dat
[15:28:45.138] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C4.dat
[15:28:45.143] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C5.dat
[15:28:45.148] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C6.dat
[15:28:45.154] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C7.dat
[15:28:45.159] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C8.dat
[15:28:45.165] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C9.dat
[15:28:45.170] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C10.dat
[15:28:45.175] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C11.dat
[15:28:45.181] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C12.dat
[15:28:45.186] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C13.dat
[15:28:45.192] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C14.dat
[15:28:45.197] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C15.dat
[15:28:45.202] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//defaultMaskFile.dat
[15:28:45.214] INFO: enter test to run
[15:30:07.658] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:30:07.658] INFO: running: highrate
[15:30:07.662] INFO: ----------------------------------------------------------------------
[15:30:07.662] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:30:07.662] INFO: ----------------------------------------------------------------------
[15:30:07.662] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:30:07.662] INFO: edge/corner pixel THR is adjusted
[15:30:07.662] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:30:08.620] INFO: Collecting data for 1 seconds...
[15:30:09.623] INFO: Done with hot pixel readout
[15:30:13.479] INFO: PixTest:: pg_setup set to default.
[15:30:13.480] INFO: 0 hot pixels found in step 0
[15:30:13.486] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:30:13.584] INFO: PixTest::trimHotPixels() done
[15:30:13.585] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C0.dat
[15:30:13.593] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C1.dat
[15:30:13.598] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C2.dat
[15:30:13.604] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C3.dat
[15:30:13.609] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C4.dat
[15:30:13.615] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C5.dat
[15:30:13.620] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C6.dat
[15:30:13.626] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C7.dat
[15:30:13.631] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C8.dat
[15:30:13.637] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C9.dat
[15:30:13.642] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C10.dat
[15:30:13.648] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C11.dat
[15:30:13.653] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C12.dat
[15:30:13.658] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C13.dat
[15:30:13.664] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C14.dat
[15:30:13.669] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//trimParameters35_C15.dat
[15:30:13.675] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-12_FPIXTest-17C-FNAL-160415-1125_2016-04-15_11h26m_1460737568/000_FPIXTest_p17//defaultMaskFile.dat
[15:30:13.684] INFO: enter test to run
[15:30:35.154] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:30:35.154] INFO: running: xray
[15:30:35.155] INFO: ----------------------------------------------------------------------
[15:30:35.155] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:30:35.155] INFO: ----------------------------------------------------------------------
[15:30:36.119] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:30:47.949] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:31:17.258] INFO: Resuming triggers.
[15:31:29.095] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[15:31:53.193] INFO: Resuming triggers.
[15:32:05.022] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[15:32:34.066] INFO: Resuming triggers.
[15:32:45.896] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[15:33:15.063] INFO: Resuming triggers.
[15:33:26.888] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[15:33:56.040] INFO: Resuming triggers.
[15:34:07.871] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[15:34:37.012] INFO: Resuming triggers.
[15:34:48.840] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[15:35:18.035] INFO: Resuming triggers.
[15:35:29.860] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[15:35:59.058] INFO: Resuming triggers.
[15:36:04.753] INFO: data taking finished, elapsed time: 100 seconds.
[15:36:19.076] INFO: PixTest:: pg_setup set to default.
[15:36:19.079] INFO: PixTestXray::doPhRun() done
[15:36:19.213] INFO: enter test to run
[15:37:08.183] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:37:08.183] INFO: running: xray
[15:37:08.184] INFO: ----------------------------------------------------------------------
[15:37:08.184] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:37:08.184] INFO: ----------------------------------------------------------------------
[15:37:09.149] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:37:16.149] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:37:46.234] INFO: Resuming triggers.
[15:37:53.239] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[15:38:23.285] INFO: Resuming triggers.
[15:38:30.293] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[15:39:00.273] INFO: Resuming triggers.
[15:39:07.276] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[15:39:37.332] INFO: Resuming triggers.
[15:39:44.340] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[15:40:14.419] INFO: Resuming triggers.
[15:40:21.428] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[15:40:51.397] INFO: Resuming triggers.
[15:40:58.405] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[15:41:28.487] INFO: Resuming triggers.
[15:41:35.494] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[15:42:01.205] INFO: Resuming triggers.
[15:42:08.209] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[15:42:38.208] INFO: Resuming triggers.
[15:42:45.213] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[15:43:15.196] INFO: Resuming triggers.
[15:43:22.198] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[15:43:52.280] INFO: Resuming triggers.
[15:43:59.287] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[15:44:29.245] INFO: Resuming triggers.
[15:44:36.250] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[15:45:06.288] INFO: Resuming triggers.
[15:45:13.292] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[15:45:43.329] INFO: Resuming triggers.
[15:45:45.576] INFO: data taking finished, elapsed time: 100 seconds.
[15:45:55.494] INFO: PixTest:: pg_setup set to default.
[15:45:55.498] INFO: PixTestXray::doPhRun() done
[15:45:55.644] INFO: enter test to run
[15:46:44.515] INFO: test: HighRate no parameter change
[15:46:44.515] INFO: running: highrate
[15:46:44.516] INFO: ----------------------------------------------------------------------
[15:46:44.516] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:46:44.516] INFO: ----------------------------------------------------------------------
[15:46:44.656] INFO: Expecting 768 events.
[15:46:45.790] INFO: 768 events read in total (418ms).
[15:46:45.790] INFO: Test took 1268ms.
[15:46:46.594] INFO: Expecting 41600 events.
[15:46:49.643] INFO: 41600 events read in total (2522ms).
[15:46:49.644] INFO: Test took 3846ms.
[15:46:49.674] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:50.409] INFO: Expecting 41600 events.
[15:46:53.593] INFO: 41600 events read in total (2657ms).
[15:46:53.594] INFO: Test took 3903ms.
[15:46:53.625] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:54.356] INFO: Expecting 41600 events.
[15:46:57.556] INFO: 41600 events read in total (2673ms).
[15:46:57.557] INFO: Test took 3917ms.
[15:46:57.588] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:58.320] INFO: Expecting 41600 events.
[15:47:01.504] INFO: 41600 events read in total (2657ms).
[15:47:01.505] INFO: Test took 3900ms.
[15:47:01.535] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:02.268] INFO: Expecting 41600 events.
[15:47:05.483] INFO: 41600 events read in total (2689ms).
[15:47:05.484] INFO: Test took 3931ms.
[15:47:05.515] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:06.243] INFO: Expecting 41600 events.
[15:47:09.443] INFO: 41600 events read in total (2673ms).
[15:47:09.444] INFO: Test took 3911ms.
[15:47:09.475] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:10.202] INFO: Expecting 41600 events.
[15:47:13.402] INFO: 41600 events read in total (2674ms).
[15:47:13.403] INFO: Test took 3911ms.
[15:47:13.435] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:14.159] INFO: Expecting 41600 events.
[15:47:17.387] INFO: 41600 events read in total (2702ms).
[15:47:17.388] INFO: Test took 3936ms.
[15:47:17.419] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:18.147] INFO: Expecting 41600 events.
[15:47:21.359] INFO: 41600 events read in total (2685ms).
[15:47:21.360] INFO: Test took 3924ms.
[15:47:21.390] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:22.117] INFO: Expecting 41600 events.
[15:47:25.309] INFO: 41600 events read in total (2665ms).
[15:47:25.310] INFO: Test took 3902ms.
[15:47:25.340] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:26.072] INFO: Expecting 41600 events.
[15:47:29.281] INFO: 41600 events read in total (2682ms).
[15:47:29.282] INFO: Test took 3924ms.
[15:47:29.313] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:30.042] INFO: Expecting 41600 events.
[15:47:33.250] INFO: 41600 events read in total (2681ms).
[15:47:33.251] INFO: Test took 3922ms.
[15:47:33.281] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:34.009] INFO: Expecting 41600 events.
[15:47:37.223] INFO: 41600 events read in total (2687ms).
[15:47:37.224] INFO: Test took 3926ms.
[15:47:37.255] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:37.983] INFO: Expecting 41600 events.
[15:47:41.200] INFO: 41600 events read in total (2690ms).
[15:47:41.200] INFO: Test took 3928ms.
[15:47:41.231] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:41.964] INFO: Expecting 41600 events.
[15:47:45.174] INFO: 41600 events read in total (2683ms).
[15:47:45.175] INFO: Test took 3927ms.
[15:47:45.206] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:45.937] INFO: Expecting 41600 events.
[15:47:49.141] INFO: 41600 events read in total (2677ms).
[15:47:49.142] INFO: Test took 3919ms.
[15:47:49.173] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:49.904] INFO: Expecting 41600 events.
[15:47:53.114] INFO: 41600 events read in total (2684ms).
[15:47:53.114] INFO: Test took 3923ms.
[15:47:53.145] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:53.876] INFO: Expecting 41600 events.
[15:47:57.087] INFO: 41600 events read in total (2684ms).
[15:47:57.088] INFO: Test took 3925ms.
[15:47:57.119] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:57.850] INFO: Expecting 41600 events.
[15:48:01.045] INFO: 41600 events read in total (2668ms).
[15:48:01.045] INFO: Test took 3908ms.
[15:48:01.077] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:01.806] INFO: Expecting 41600 events.
[15:48:04.872] INFO: 41600 events read in total (2539ms).
[15:48:04.873] INFO: Test took 3778ms.
[15:48:04.903] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:05.272] INFO: enter test to run
[15:48:11.938] INFO: test: HighRate no parameter change
[15:48:11.938] INFO: running: highrate
[15:48:11.939] INFO: ----------------------------------------------------------------------
[15:48:11.939] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:48:11.939] INFO: ----------------------------------------------------------------------
[15:48:12.553] INFO: Expecting 208000 events.
[15:48:24.219] INFO: 208000 events read in total (11139ms).
[15:48:24.222] INFO: Test took 12276ms.
[15:48:24.347] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:24.594] INFO: number of dead pixels (per ROC): 0 0 0 2 0 0 0 0 0 0 0 1 0 0 0 0
[15:48:24.594] INFO: number of red-efficiency pixels: 66 39 69 101 116 119 134 84 73 109 89 103 83 66 23 23
[15:48:24.594] INFO: number of X-ray hits detected: 56594 39433 60475 96682 97828 102595 102780 75545 69011 81219 79113 73939 75581 44887 19440 23496
[15:48:24.594] 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:48:24.594] INFO: number of Vcal hits detected: 207932 207961 207930 207801 207882 207877 207862 207916 207926 207885 207910 207847 207915 207934 207976 207977
[15:48:24.594] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0 100.0
[15:48:24.594] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 100.0 99.9 100.0 100.0 100.0 100.0
[15:48:24.594] INFO: X-ray hit rate [MHz/cm2]: 16.6 11.6 17.7 28.3 28.7 30.1 30.1 22.1 20.2 23.8 23.2 21.7 22.2 13.2 5.7 6.9
[15:48:24.594] INFO: PixTestHighRate::doXPixelAlive() done
[15:48:24.640] INFO: PixTest:: pg_setup set to default.
[15:48:24.655] INFO: enter test to run
[15:48:37.354] INFO: test: HighRate no parameter change
[15:48:37.354] INFO: running: highrate
[15:48:37.355] INFO: ----------------------------------------------------------------------
[15:48:37.355] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:48:37.355] INFO: ----------------------------------------------------------------------
[15:48:37.971] INFO: Expecting 208000 events.
[15:48:51.245] INFO: 208000 events read in total (12748ms).
[15:48:51.250] INFO: Test took 13886ms.
[15:48:51.510] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:51.804] INFO: number of dead pixels (per ROC): 0 0 0 2 0 0 0 0 0 0 0 1 0 0 0 0
[15:48:51.804] INFO: number of red-efficiency pixels: 193 108 197 439 466 421 409 239 253 290 284 268 267 166 50 67
[15:48:51.804] INFO: number of X-ray hits detected: 120436 83613 127853 207897 208459 218928 219193 161593 147984 172988 170804 159731 160567 95948 41611 50891
[15:48:51.804] 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:48:51.804] INFO: number of Vcal hits detected: 207797 207890 207788 207435 207507 207543 207563 207746 207733 207697 207697 207673 207716 207829 207948 207932
[15:48:51.804] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[15:48:51.804] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.7 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.8 99.9 99.9 100.0 100.0
[15:48:51.804] INFO: X-ray hit rate [MHz/cm2]: 35.3 24.5 37.5 60.9 61.1 64.2 64.2 47.4 43.4 50.7 50.1 46.8 47.1 28.1 12.2 14.9
[15:48:51.804] INFO: PixTestHighRate::doXPixelAlive() done
[15:48:51.850] INFO: PixTest:: pg_setup set to default.
[15:48:51.862] INFO: enter test to run
[15:49:07.658] INFO: test: HighRate no parameter change
[15:49:07.658] INFO: running: highrate
[15:49:07.659] INFO: ----------------------------------------------------------------------
[15:49:07.659] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:49:07.659] INFO: ----------------------------------------------------------------------
[15:49:08.270] INFO: Expecting 208000 events.
[15:49:23.240] INFO: 208000 events read in total (14443ms).
[15:49:23.246] INFO: Test took 15579ms.
[15:49:23.652] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:23.983] INFO: number of dead pixels (per ROC): 0 0 0 2 0 0 0 0 0 0 0 1 0 0 0 0
[15:49:23.983] INFO: number of red-efficiency pixels: 410 193 474 871 996 1069 915 470 455 670 658 559 608 316 81 95
[15:49:23.983] INFO: number of X-ray hits detected: 182510 127794 194511 314076 316515 330405 331544 245837 225165 262553 257315 242188 244263 146156 63480 77159
[15:49:23.984] 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:49:23.984] INFO: number of Vcal hits detected: 207538 207786 207431 206857 206797 206681 206883 207472 207503 207260 207250 207322 207317 207643 207915 207903
[15:49:23.984] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.5 99.5 99.4 99.5 99.8 99.8 99.7 99.7 99.7 99.7 99.8 100.0 100.0
[15:49:23.984] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.5 99.4 99.4 99.5 99.7 99.8 99.6 99.6 99.7 99.7 99.8 100.0 100.0
[15:49:23.984] INFO: X-ray hit rate [MHz/cm2]: 53.5 37.5 57.0 92.1 92.8 96.8 97.2 72.1 66.0 77.0 75.4 71.0 71.6 42.8 18.6 22.6
[15:49:23.984] INFO: PixTestHighRate::doXPixelAlive() done
[15:49:24.032] INFO: PixTest:: pg_setup set to default.
[15:49:24.047] INFO: enter test to run
[15:49:53.137] INFO: test: exit no parameter change
[15:49:53.529] QUIET: Connection to board 33 closed.
[15:49:53.530] INFO: pXar: this is the end, my friend