[12:29:32.033] INFO: *** Welcome to pxar ***
[12:29:32.033] INFO: *** Today: 2016/08/09
[12:29:32.050] INFO: *** Version: v1.9.0-818-g96727
[12:29:32.051] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//dacParameters35_C15.dat
[12:29:32.099] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:29:32.099] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//defaultMaskFile.dat
[12:29:32.099] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C15.dat
[12:29:32.187] INFO: clk: 4
[12:29:32.187] INFO: ctr: 4
[12:29:32.187] INFO: sda: 19
[12:29:32.187] INFO: tin: 9
[12:29:32.187] INFO: level: 15
[12:29:32.187] INFO: triggerdelay: 0
[12:29:32.187] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[12:29:32.187] INFO: Log level: INFO
[12:29:32.205] QUIET: Connection to board DTB_WREKRL opened.
[12:29:32.208] 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:
------------------------------------------------------
[12:29:32.211] INFO: RPC call hashes of host and DTB match: 398089610
[12:29:33.739] INFO: DUT info:
[12:29:33.739] INFO: The DUT currently contains the following objects:
[12:29:33.739] INFO: 2 TBM Cores tbm08c (2 ON)
[12:29:33.739] INFO: TBM Core alpha (0): 7 registers set
[12:29:33.739] INFO: TBM Core beta (1): 7 registers set
[12:29:33.739] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:29:33.739] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.739] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:33.740] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:29:34.160] INFO: enter 'restricted' command line mode
[12:29:34.160] INFO: enter test to run
[12:29:41.295] INFO: test: PixelAlive no parameter change
[12:29:41.295] INFO: running: pixelalive
[12:29:41.304] INFO: ----------------------------------------------------------------------
[12:29:41.304] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[12:29:41.305] INFO: ----------------------------------------------------------------------
[12:29:41.623] INFO: Expecting 41600 events.
[12:29:45.947] INFO: 41600 events read in total (3606ms).
[12:29:46.108] INFO: Test took 4801ms.
[12:29:46.122] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:46.408] INFO: PixTestAlive::aliveTest() done
[12:29:46.408] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 3 0 0 0
[12:29:46.446] INFO: enter test to run
[12:29:53.191] INFO: test: timing no parameter change
[12:29:53.191] INFO: running: timing
[12:29:53.195] INFO: ######################################################################
[12:29:53.195] INFO: PixTestTiming::doTest()
[12:29:53.195] INFO: ######################################################################
[12:29:53.195] INFO: ----------------------------------------------------------------------
[12:29:53.195] INFO: PixTestTiming::TBMPhaseScan()
[12:29:53.195] INFO: ----------------------------------------------------------------------
[12:35:34.656] INFO: TBM Phase Settings: 240
[12:35:34.656] INFO: 400MHz Phase: 4
[12:35:34.656] INFO: 160MHz Phase: 7
[12:35:34.656] INFO: Functional Phase Area: 5
[12:35:34.659] INFO: Test took 341464 ms.
[12:35:34.659] INFO: PixTestTiming::TBMPhaseScan() done.
[12:35:34.659] INFO: ----------------------------------------------------------------------
[12:35:34.659] INFO: PixTestTiming::ROCDelayScan()
[12:35:34.659] INFO: ----------------------------------------------------------------------
[12:38:10.933] INFO: ROC Delay Settings: 228
[12:38:10.934] INFO: ROC Header-Trailer/Token Delay: 11
[12:38:10.934] INFO: ROC Port 0 Delay: 4
[12:38:10.934] INFO: ROC Port 1 Delay: 4
[12:38:10.934] INFO: Functional ROC Area: 6
[12:38:10.937] INFO: Test took 156278 ms.
[12:38:10.937] INFO: PixTestTiming::ROCDelayScan() done.
[12:38:10.937] INFO: ----------------------------------------------------------------------
[12:38:10.937] INFO: PixTestTiming::TimingTest()
[12:38:10.937] INFO: ----------------------------------------------------------------------
[12:38:27.440] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:38:42.909] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:38:58.231] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:39:13.576] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:39:28.636] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:39:43.700] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:39:58.768] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:40:13.830] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:40:28.889] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:40:43.951] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:40:44.329] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:40:44.346] INFO: ----------------------------------------------------------------------
[12:40:44.346] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:40:44.346] INFO: ----------------------------------------------------------------------
[12:40:44.346] INFO: ----------------------------------------------------------------------
[12:40:44.346] INFO: Read back bit status: 1
[12:40:44.346] INFO: ----------------------------------------------------------------------
[12:40:44.346] INFO: ----------------------------------------------------------------------
[12:40:44.346] INFO: Timings are good!
[12:40:44.346] INFO: ----------------------------------------------------------------------
[12:40:44.346] INFO: Test took 153409 ms.
[12:40:44.346] INFO: PixTestTiming::TimingTest() done.
[12:40:44.346] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:40:44.346] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:40:44.346] INFO: PixTestTiming::doTest took 651154 ms.
[12:40:44.346] INFO: PixTestTiming::doTest() done
[12:40:44.347] INFO: Write out TBMPhaseScan_0_V0
[12:40:44.347] INFO: Write out TBMPhaseScan_1_V0
[12:40:44.347] INFO: Write out CombinedTBMPhaseScan_V0
[12:40:44.348] INFO: Write out ROCDelayScan3_V0
[12:40:44.348] INFO: enter test to run
[12:42:36.962] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:42:36.962] INFO: running: highrate
[12:42:36.963] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:42:37.170] INFO: ----------------------------------------------------------------------
[12:42:37.170] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:42:37.170] INFO: ----------------------------------------------------------------------
[12:42:37.170] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:42:37.170] INFO: edge/corner pixel THR is adjusted
[12:42:37.170] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:42:38.129] INFO: Collecting data for 5 seconds...
[12:42:43.146] INFO: Done with hot pixel readout
[12:42:54.342] INFO: PixTest:: pg_setup set to default.
[12:42:54.343] INFO: 1 hot pixels found in step 0
[12:42:55.330] INFO: Collecting data for 5 seconds...
[12:43:00.346] INFO: Done with hot pixel readout
[12:43:11.475] INFO: PixTest:: pg_setup set to default.
[12:43:11.476] INFO: 0 hot pixels found in step 1
[12:43:11.507] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:43:11.510] INFO: PixTest::trimHotPixels() done
[12:43:11.510] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C0.dat
[12:43:11.517] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C1.dat
[12:43:11.523] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C2.dat
[12:43:11.528] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C3.dat
[12:43:11.534] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C4.dat
[12:43:11.539] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C5.dat
[12:43:11.544] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C6.dat
[12:43:11.549] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C7.dat
[12:43:11.555] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C8.dat
[12:43:11.560] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C9.dat
[12:43:11.565] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C10.dat
[12:43:11.571] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C11.dat
[12:43:11.576] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C12.dat
[12:43:11.581] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C13.dat
[12:43:11.586] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C14.dat
[12:43:11.592] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C15.dat
[12:43:11.597] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//defaultMaskFile.dat
[12:43:11.607] INFO: enter test to run
[12:44:26.465] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:44:26.465] INFO: running: highrate
[12:44:26.470] INFO: ----------------------------------------------------------------------
[12:44:26.470] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:44:26.470] INFO: ----------------------------------------------------------------------
[12:44:26.470] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:44:26.470] INFO: edge/corner pixel THR is adjusted
[12:44:26.470] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:44:27.427] INFO: Collecting data for 1 seconds...
[12:44:28.431] INFO: Done with hot pixel readout
[12:44:32.055] INFO: PixTest:: pg_setup set to default.
[12:44:32.055] INFO: 0 hot pixels found in step 0
[12:44:32.061] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:44:32.167] INFO: PixTest::trimHotPixels() done
[12:44:32.167] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C0.dat
[12:44:32.176] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C1.dat
[12:44:32.181] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C2.dat
[12:44:32.186] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C3.dat
[12:44:32.192] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C4.dat
[12:44:32.197] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C5.dat
[12:44:32.202] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C6.dat
[12:44:32.208] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C7.dat
[12:44:32.213] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C8.dat
[12:44:32.218] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C9.dat
[12:44:32.224] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C10.dat
[12:44:32.229] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C11.dat
[12:44:32.234] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C12.dat
[12:44:32.240] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C13.dat
[12:44:32.245] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C14.dat
[12:44:32.250] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//trimParameters35_C15.dat
[12:44:32.255] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-3-22_FPIXTest-17C-FNAL-160805-1320_2016-08-05_13h20m_1470421233/000_FPIXTest_p17//defaultMaskFile.dat
[12:44:32.265] INFO: enter test to run
[12:45:07.017] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:45:07.017] INFO: running: xray
[12:45:07.019] INFO: ----------------------------------------------------------------------
[12:45:07.019] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:45:07.019] INFO: ----------------------------------------------------------------------
[12:45:07.981] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:45:20.090] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[12:45:49.204] INFO: Resuming triggers.
[12:46:01.315] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[12:46:30.563] INFO: Resuming triggers.
[12:46:42.678] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[12:47:12.177] INFO: Resuming triggers.
[12:47:24.290] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[12:47:53.601] INFO: Resuming triggers.
[12:48:05.716] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[12:48:34.631] INFO: Resuming triggers.
[12:48:46.752] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[12:49:15.891] INFO: Resuming triggers.
[12:49:28.006] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[12:49:57.979] INFO: Resuming triggers.
[12:50:10.093] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[12:50:39.750] INFO: Resuming triggers.
[12:50:43.198] INFO: data taking finished, elapsed time: 100 seconds.
[12:50:52.021] INFO: PixTest:: pg_setup set to default.
[12:50:52.024] INFO: PixTestXray::doPhRun() done
[12:50:52.160] INFO: enter test to run
[12:52:36.742] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:52:36.742] INFO: running: xray
[12:52:36.743] INFO: ----------------------------------------------------------------------
[12:52:36.743] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:52:36.743] INFO: ----------------------------------------------------------------------
[12:52:37.708] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:52:45.268] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[12:53:15.250] INFO: Resuming triggers.
[12:53:22.813] INFO: run duration 15 seconds, buffer almost full (81%), pausing triggers.
[12:53:53.011] INFO: Resuming triggers.
[12:54:00.576] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[12:54:30.584] INFO: Resuming triggers.
[12:54:38.147] INFO: run duration 30 seconds, buffer almost full (81%), pausing triggers.
[12:55:08.149] INFO: Resuming triggers.
[12:55:15.713] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[12:55:45.737] INFO: Resuming triggers.
[12:55:53.304] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[12:56:23.303] INFO: Resuming triggers.
[12:56:30.867] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[12:57:00.860] INFO: Resuming triggers.
[12:57:08.423] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[12:57:38.446] INFO: Resuming triggers.
[12:57:46.012] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[12:58:15.910] INFO: Resuming triggers.
[12:58:23.479] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[12:58:53.445] INFO: Resuming triggers.
[12:59:01.016] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[12:59:32.066] INFO: Resuming triggers.
[12:59:39.632] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[13:00:10.281] INFO: Resuming triggers.
[13:00:17.849] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[13:00:48.357] INFO: Resuming triggers.
[13:00:50.344] INFO: data taking finished, elapsed time: 100 seconds.
[13:00:58.759] INFO: PixTest:: pg_setup set to default.
[13:00:58.762] INFO: PixTestXray::doPhRun() done
[13:00:58.914] INFO: enter test to run
[13:01:17.003] INFO: test: HighRate no parameter change
[13:01:17.003] INFO: running: highrate
[13:01:17.004] INFO: ----------------------------------------------------------------------
[13:01:17.004] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:01:17.004] INFO: ----------------------------------------------------------------------
[13:01:18.143] INFO: Expecting 768 events.
[13:01:19.276] INFO: 768 events read in total (417ms).
[13:01:19.276] INFO: Test took 1266ms.
[13:01:20.079] INFO: Expecting 41600 events.
[13:01:23.186] INFO: 41600 events read in total (2580ms).
[13:01:23.187] INFO: Test took 3904ms.
[13:01:23.218] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:23.936] INFO: Expecting 41600 events.
[13:01:26.996] INFO: 41600 events read in total (2533ms).
[13:01:26.996] INFO: Test took 3761ms.
[13:01:27.027] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:27.757] INFO: Expecting 41600 events.
[13:01:31.127] INFO: 41600 events read in total (2844ms).
[13:01:31.128] INFO: Test took 4084ms.
[13:01:31.158] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:31.892] INFO: Expecting 41600 events.
[13:01:35.051] INFO: 41600 events read in total (2633ms).
[13:01:35.052] INFO: Test took 3877ms.
[13:01:35.084] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:35.810] INFO: Expecting 41600 events.
[13:01:39.016] INFO: 41600 events read in total (2679ms).
[13:01:39.017] INFO: Test took 3917ms.
[13:01:39.047] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:39.771] INFO: Expecting 41600 events.
[13:01:43.011] INFO: 41600 events read in total (2714ms).
[13:01:43.012] INFO: Test took 3949ms.
[13:01:43.042] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:43.758] INFO: Expecting 41600 events.
[13:01:46.887] INFO: 41600 events read in total (2602ms).
[13:01:46.888] INFO: Test took 3830ms.
[13:01:46.919] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:47.648] INFO: Expecting 41600 events.
[13:01:50.928] INFO: 41600 events read in total (2753ms).
[13:01:50.929] INFO: Test took 3994ms.
[13:01:50.960] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:51.691] INFO: Expecting 41600 events.
[13:01:54.933] INFO: 41600 events read in total (2715ms).
[13:01:54.934] INFO: Test took 3958ms.
[13:01:54.964] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:55.693] INFO: Expecting 41600 events.
[13:01:58.918] INFO: 41600 events read in total (2698ms).
[13:01:58.919] INFO: Test took 3938ms.
[13:01:58.950] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:59.681] INFO: Expecting 41600 events.
[13:02:02.933] INFO: 41600 events read in total (2725ms).
[13:02:02.933] INFO: Test took 3967ms.
[13:02:02.966] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:03.690] INFO: Expecting 41600 events.
[13:02:06.972] INFO: 41600 events read in total (2755ms).
[13:02:06.973] INFO: Test took 3989ms.
[13:02:06.003] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:07.734] INFO: Expecting 41600 events.
[13:02:10.000] INFO: 41600 events read in total (2739ms).
[13:02:10.001] INFO: Test took 3981ms.
[13:02:11.032] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:11.758] INFO: Expecting 41600 events.
[13:02:14.904] INFO: 41600 events read in total (2619ms).
[13:02:14.905] INFO: Test took 3855ms.
[13:02:14.936] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:15.662] INFO: Expecting 41600 events.
[13:02:18.945] INFO: 41600 events read in total (2757ms).
[13:02:18.945] INFO: Test took 3993ms.
[13:02:18.976] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:19.705] INFO: Expecting 41600 events.
[13:02:22.880] INFO: 41600 events read in total (2648ms).
[13:02:22.881] INFO: Test took 3889ms.
[13:02:22.912] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:23.641] INFO: Expecting 41600 events.
[13:02:26.779] INFO: 41600 events read in total (2611ms).
[13:02:26.780] INFO: Test took 3852ms.
[13:02:26.810] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:27.538] INFO: Expecting 41600 events.
[13:02:30.811] INFO: 41600 events read in total (2746ms).
[13:02:30.812] INFO: Test took 3985ms.
[13:02:30.842] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:31.570] INFO: Expecting 41600 events.
[13:02:34.855] INFO: 41600 events read in total (2758ms).
[13:02:34.856] INFO: Test took 3997ms.
[13:02:34.886] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:35.615] INFO: Expecting 41600 events.
[13:02:38.692] INFO: 41600 events read in total (2551ms).
[13:02:38.693] INFO: Test took 3790ms.
[13:02:38.722] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:39.085] INFO: enter test to run
[13:02:47.402] INFO: test: HighRate no parameter change
[13:02:47.402] INFO: running: highrate
[13:02:47.403] INFO: ----------------------------------------------------------------------
[13:02:47.403] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:02:47.403] INFO: ----------------------------------------------------------------------
[13:02:48.023] INFO: Expecting 208000 events.
[13:02:59.733] INFO: 208000 events read in total (11183ms).
[13:02:59.736] INFO: Test took 12326ms.
[13:02:59.861] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:00.107] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 3 0 0 0
[13:03:00.107] INFO: number of red-efficiency pixels: 49 45 52 93 106 133 124 64 68 82 94 62 94 47 19 23
[13:03:00.107] INFO: number of X-ray hits detected: 50975 35048 56234 94305 98632 96419 94409 65431 62050 81879 80757 69620 75550 44127 16838 21000
[13:03:00.107] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:03:00.107] INFO: number of Vcal hits detected: 207951 207950 207947 207907 207875 207864 207873 207936 207932 207918 207905 207936 207758 207951 207981 207977
[13:03:00.107] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[13:03:00.107] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 99.9 100.0 100.0 100.0
[13:03:00.107] INFO: X-ray hit rate [MHz/cm2]: 14.9 10.3 16.5 27.6 28.9 28.3 27.7 19.2 18.2 24.0 23.7 20.4 22.1 12.9 4.9 6.2
[13:03:00.107] INFO: PixTestHighRate::doXPixelAlive() done
[13:03:00.153] INFO: PixTest:: pg_setup set to default.
[13:03:00.163] INFO: enter test to run
[13:03:24.970] INFO: test: HighRate no parameter change
[13:03:24.970] INFO: running: highrate
[13:03:24.971] INFO: ----------------------------------------------------------------------
[13:03:24.971] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:03:24.971] INFO: ----------------------------------------------------------------------
[13:03:25.581] INFO: Expecting 208000 events.
[13:03:38.620] INFO: 208000 events read in total (12512ms).
[13:03:38.625] INFO: Test took 13645ms.
[13:03:38.862] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:39.144] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 3 0 0 0
[13:03:39.144] INFO: number of red-efficiency pixels: 149 82 155 288 309 335 338 192 201 267 284 193 263 110 36 53
[13:03:39.144] INFO: number of X-ray hits detected: 102123 69931 112145 187641 196539 190280 189715 130804 125263 164195 160466 138800 151815 87921 33560 41917
[13:03:39.144] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:03:39.144] INFO: number of Vcal hits detected: 207842 207909 207842 207694 207654 207644 207635 207794 207795 207724 207705 207801 207576 207886 207963 207946
[13:03:39.144] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.9 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[13:03:39.144] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.9 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.8 99.9 100.0 100.0
[13:03:39.144] INFO: X-ray hit rate [MHz/cm2]: 29.9 20.5 32.9 55.0 57.6 55.8 55.6 38.3 36.7 48.1 47.0 40.7 44.5 25.8 9.8 12.3
[13:03:39.144] INFO: PixTestHighRate::doXPixelAlive() done
[13:03:39.196] INFO: PixTest:: pg_setup set to default.
[13:03:39.214] INFO: enter test to run
[13:03:53.322] INFO: test: HighRate no parameter change
[13:03:53.322] INFO: running: highrate
[13:03:53.323] INFO: ----------------------------------------------------------------------
[13:03:53.323] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:03:53.323] INFO: ----------------------------------------------------------------------
[13:03:53.937] INFO: Expecting 208000 events.
[13:04:08.455] INFO: 208000 events read in total (13991ms).
[13:04:08.462] INFO: Test took 15131ms.
[13:04:08.822] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:04:09.145] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 3 0 0 0
[13:04:09.145] INFO: number of red-efficiency pixels: 293 150 336 542 623 789 836 435 384 603 573 364 568 230 61 88
[13:04:09.145] INFO: number of X-ray hits detected: 153826 105741 169793 282224 296134 288763 286935 198661 190235 248055 243709 211214 230066 133649 51248 63963
[13:04:09.145] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:04:09.145] INFO: number of Vcal hits detected: 207672 207832 207626 207399 207275 207073 207013 207503 207587 207338 207360 207606 207231 207754 207937 207910
[13:04:09.145] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.6 99.6 99.8 99.8 99.7 99.7 99.8 99.7 99.9 100.0 100.0
[13:04:09.145] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.7 99.7 99.6 99.5 99.8 99.8 99.7 99.7 99.8 99.6 99.9 100.0 100.0
[13:04:09.145] INFO: X-ray hit rate [MHz/cm2]: 45.1 31.0 49.8 82.7 86.8 84.6 84.1 58.2 55.8 72.7 71.4 61.9 67.4 39.2 15.0 18.7
[13:04:09.145] INFO: PixTestHighRate::doXPixelAlive() done
[13:04:09.199] INFO: PixTest:: pg_setup set to default.
[13:04:09.212] INFO: enter test to run
[13:04:44.177] INFO: test: exit no parameter change
[13:04:44.496] QUIET: Connection to board 33 closed.
[13:04:44.497] INFO: pXar: this is the end, my friend