[13:13:17.331] INFO: *** Welcome to pxar ***
[13:13:17.331] INFO: *** Today: 2016/04/11
[13:13:17.366] INFO: *** Version: v1.9.0-796-gef167-dirty
[13:13:17.367] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//dacParameters35_C15.dat
[13:13:17.388] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:13:17.388] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//defaultMaskFile.dat
[13:13:17.393] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C15.dat
[13:13:17.481] INFO: clk: 4
[13:13:17.481] INFO: ctr: 4
[13:13:17.481] INFO: sda: 19
[13:13:17.481] INFO: tin: 9
[13:13:17.481] INFO: level: 15
[13:13:17.481] INFO: triggerdelay: 0
[13:13:17.481] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[13:13:17.481] INFO: Log level: INFO
[13:13:17.498] QUIET: Connection to board DTB_WREKRL opened.
[13:13:17.502] 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:
------------------------------------------------------
[13:13:17.504] INFO: RPC call hashes of host and DTB match: 398089610
[13:13:19.039] INFO: DUT info:
[13:13:19.039] INFO: The DUT currently contains the following objects:
[13:13:19.039] INFO: 2 TBM Cores tbm08c (2 ON)
[13:13:19.039] INFO: TBM Core alpha (0): 7 registers set
[13:13:19.039] INFO: TBM Core beta (1): 7 registers set
[13:13:19.039] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:13:19.039] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.039] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.039] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.039] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.039] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.039] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.039] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.039] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.040] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.040] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.040] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.040] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.040] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.040] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.040] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.040] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:13:19.462] INFO: enter 'restricted' command line mode
[13:13:19.462] INFO: enter test to run
[13:13:25.244] INFO: test: timing no parameter change
[13:13:25.244] INFO: running: timing
[13:13:25.253] INFO: ######################################################################
[13:13:25.253] INFO: PixTestTiming::doTest()
[13:13:25.253] INFO: ######################################################################
[13:13:25.253] INFO: ----------------------------------------------------------------------
[13:13:25.253] INFO: PixTestTiming::TBMPhaseScan()
[13:13:25.253] INFO: ----------------------------------------------------------------------
[13:18:00.281] INFO: TBM Phase Settings: 236
[13:18:00.281] INFO: 400MHz Phase: 3
[13:18:00.281] INFO: 160MHz Phase: 7
[13:18:00.281] INFO: Functional Phase Area: 4
[13:18:00.284] INFO: Test took 275031 ms.
[13:18:00.284] INFO: PixTestTiming::TBMPhaseScan() done.
[13:18:00.285] INFO: ----------------------------------------------------------------------
[13:18:00.285] INFO: PixTestTiming::ROCDelayScan()
[13:18:00.285] INFO: ----------------------------------------------------------------------
[13:20:00.481] INFO: ROC Delay Settings: 228
[13:20:00.481] INFO: ROC Header-Trailer/Token Delay: 11
[13:20:00.481] INFO: ROC Port 0 Delay: 4
[13:20:00.481] INFO: ROC Port 1 Delay: 4
[13:20:00.481] INFO: Functional ROC Area: 5
[13:20:00.485] INFO: Test took 120201 ms.
[13:20:00.485] INFO: PixTestTiming::ROCDelayScan() done.
[13:20:00.485] INFO: ----------------------------------------------------------------------
[13:20:00.485] INFO: PixTestTiming::TimingTest()
[13:20:00.485] INFO: ----------------------------------------------------------------------
[13:20:16.640] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:20:31.620] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:20:46.606] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:01.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:16.562] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:31.536] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:21:46.520] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:01.500] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:16.476] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:31.437] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:31.815] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:31.832] INFO: ----------------------------------------------------------------------
[13:22:31.832] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[13:22:31.832] INFO: ----------------------------------------------------------------------
[13:22:31.832] INFO: ----------------------------------------------------------------------
[13:22:31.832] INFO: Read back bit status: 1
[13:22:31.832] INFO: ----------------------------------------------------------------------
[13:22:31.832] INFO: ----------------------------------------------------------------------
[13:22:31.832] INFO: Timings are good!
[13:22:31.832] INFO: ----------------------------------------------------------------------
[13:22:31.832] INFO: Test took 151347 ms.
[13:22:31.832] INFO: PixTestTiming::TimingTest() done.
[13:22:31.832] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//tbmParameters_C0a.dat
[13:22:31.832] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:22:31.832] INFO: PixTestTiming::doTest took 546584 ms.
[13:22:31.833] INFO: PixTestTiming::doTest() done
[13:22:31.833] INFO: Write out TBMPhaseScan_0_V0
[13:22:31.858] INFO: Write out TBMPhaseScan_1_V0
[13:22:31.859] INFO: Write out CombinedTBMPhaseScan_V0
[13:22:31.859] INFO: Write out ROCDelayScan3_V0
[13:22:31.860] INFO: enter test to run
[13:24:18.824] INFO: test: PixelAlive no parameter change
[13:24:18.824] INFO: running: pixelalive
[13:24:18.828] INFO: ----------------------------------------------------------------------
[13:24:18.828] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[13:24:18.828] INFO: ----------------------------------------------------------------------
[13:24:19.149] INFO: Expecting 41600 events.
[13:24:23.477] INFO: 41600 events read in total (3613ms).
[13:24:23.477] INFO: Test took 4645ms.
[13:24:23.484] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:24:23.879] INFO: PixTestAlive::aliveTest() done
[13:24:23.879] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 3 0 0 0
[13:24:23.883] INFO: enter test to run
[13:24:51.439] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:24:51.439] INFO: running: highrate
[13:24:51.440] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:24:51.628] INFO: ----------------------------------------------------------------------
[13:24:51.628] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:24:51.628] INFO: ----------------------------------------------------------------------
[13:24:51.628] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:24:51.628] INFO: edge/corner pixel THR is adjusted
[13:24:51.628] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:24:52.586] INFO: Collecting data for 5 seconds...
[13:24:57.602] INFO: Done with hot pixel readout
[13:25:09.561] INFO: PixTest:: pg_setup set to default.
[13:25:09.562] INFO: 0 hot pixels found in step 0
[13:25:09.601] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:25:09.604] INFO: PixTest::trimHotPixels() done
[13:25:09.604] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C0.dat
[13:25:09.612] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C1.dat
[13:25:09.620] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C2.dat
[13:25:09.628] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C3.dat
[13:25:09.635] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C4.dat
[13:25:09.642] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C5.dat
[13:25:09.649] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C6.dat
[13:25:09.656] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C7.dat
[13:25:09.663] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C8.dat
[13:25:09.670] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C9.dat
[13:25:09.677] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C10.dat
[13:25:09.685] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C11.dat
[13:25:09.692] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C12.dat
[13:25:09.699] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C13.dat
[13:25:09.706] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C14.dat
[13:25:09.713] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C15.dat
[13:25:09.720] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//defaultMaskFile.dat
[13:25:09.731] INFO: enter test to run
[13:25:40.215] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[13:25:40.215] INFO: running: highrate
[13:25:40.219] INFO: ----------------------------------------------------------------------
[13:25:40.219] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[13:25:40.219] INFO: ----------------------------------------------------------------------
[13:25:40.220] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[13:25:40.220] INFO: edge/corner pixel THR is adjusted
[13:25:40.220] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:25:41.178] INFO: Collecting data for 1 seconds...
[13:25:42.181] INFO: Done with hot pixel readout
[13:25:46.357] INFO: PixTest:: pg_setup set to default.
[13:25:46.357] INFO: 0 hot pixels found in step 0
[13:25:46.363] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:25:46.449] INFO: PixTest::trimHotPixels() done
[13:25:46.449] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C0.dat
[13:25:46.461] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C1.dat
[13:25:46.468] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C2.dat
[13:25:46.475] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C3.dat
[13:25:46.482] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C4.dat
[13:25:46.489] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C5.dat
[13:25:46.496] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C6.dat
[13:25:46.503] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C7.dat
[13:25:46.511] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C8.dat
[13:25:46.518] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C9.dat
[13:25:46.525] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C10.dat
[13:25:46.532] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C11.dat
[13:25:46.539] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C12.dat
[13:25:46.547] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C13.dat
[13:25:46.554] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C14.dat
[13:25:46.561] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//trimParameters35_C15.dat
[13:25:46.568] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-G-1-49_FPIXTest-17C-FNAL-160125-0956_2016-01-25_09h57m_1453737426/000_FPIXTest_p17//defaultMaskFile.dat
[13:25:46.578] INFO: enter test to run
[13:26:09.511] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:26:09.511] INFO: running: xray
[13:26:09.512] INFO: ----------------------------------------------------------------------
[13:26:09.512] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:26:09.512] INFO: ----------------------------------------------------------------------
[13:26:10.475] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:26:21.669] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[13:26:51.056] INFO: Resuming triggers.
[13:27:02.250] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[13:27:31.746] INFO: Resuming triggers.
[13:27:42.948] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[13:28:09.319] INFO: Resuming triggers.
[13:28:20.518] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[13:28:49.831] INFO: Resuming triggers.
[13:29:01.027] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[13:29:30.398] INFO: Resuming triggers.
[13:29:41.591] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[13:30:10.936] INFO: Resuming triggers.
[13:30:22.129] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[13:30:51.434] INFO: Resuming triggers.
[13:31:02.631] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[13:31:32.068] INFO: Resuming triggers.
[13:31:42.820] INFO: data taking finished, elapsed time: 100 seconds.
[13:32:11.222] INFO: PixTest:: pg_setup set to default.
[13:32:11.226] INFO: PixTestXray::doPhRun() done
[13:32:11.363] INFO: enter test to run
[13:33:26.731] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[13:33:26.732] INFO: running: xray
[13:33:26.733] INFO: ----------------------------------------------------------------------
[13:33:26.733] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:33:26.733] INFO: ----------------------------------------------------------------------
[13:33:27.713] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:33:34.052] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[13:34:05.159] INFO: Resuming triggers.
[13:34:11.503] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[13:34:41.687] INFO: Resuming triggers.
[13:34:48.031] INFO: run duration 18 seconds, buffer almost full (81%), pausing triggers.
[13:35:19.014] INFO: Resuming triggers.
[13:35:25.362] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[13:35:55.785] INFO: Resuming triggers.
[13:36:02.127] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[13:36:32.166] INFO: Resuming triggers.
[13:36:38.509] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[13:37:08.565] INFO: Resuming triggers.
[13:37:14.908] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[13:37:45.038] INFO: Resuming triggers.
[13:37:51.380] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[13:38:19.067] INFO: Resuming triggers.
[13:38:25.410] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[13:38:55.449] INFO: Resuming triggers.
[13:39:01.790] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[13:39:31.832] INFO: Resuming triggers.
[13:39:38.171] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[13:40:08.242] INFO: Resuming triggers.
[13:40:14.583] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[13:40:44.626] INFO: Resuming triggers.
[13:40:50.968] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[13:41:20.965] INFO: Resuming triggers.
[13:41:27.305] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[13:41:57.341] INFO: Resuming triggers.
[13:42:03.681] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[13:42:33.708] INFO: Resuming triggers.
[13:42:38.893] INFO: data taking finished, elapsed time: 100 seconds.
[13:43:03.592] INFO: PixTest:: pg_setup set to default.
[13:43:03.595] INFO: PixTestXray::doPhRun() done
[13:43:03.742] INFO: enter test to run
[13:43:33.647] INFO: test: HighRate no parameter change
[13:43:33.647] INFO: running: highrate
[13:43:33.648] INFO: ----------------------------------------------------------------------
[13:43:33.648] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:43:33.648] INFO: ----------------------------------------------------------------------
[13:43:33.788] INFO: Expecting 768 events.
[13:43:34.922] INFO: 768 events read in total (418ms).
[13:43:34.923] INFO: Test took 1269ms.
[13:43:35.726] INFO: Expecting 41600 events.
[13:43:38.835] INFO: 41600 events read in total (2582ms).
[13:43:38.836] INFO: Test took 3904ms.
[13:43:38.872] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:39.598] INFO: Expecting 41600 events.
[13:43:42.810] INFO: 41600 events read in total (2685ms).
[13:43:42.811] INFO: Test took 3920ms.
[13:43:42.848] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:43.570] INFO: Expecting 41600 events.
[13:43:46.818] INFO: 41600 events read in total (2722ms).
[13:43:46.819] INFO: Test took 3952ms.
[13:43:46.856] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:47.575] INFO: Expecting 41600 events.
[13:43:50.816] INFO: 41600 events read in total (2714ms).
[13:43:50.817] INFO: Test took 3943ms.
[13:43:50.854] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:51.575] INFO: Expecting 41600 events.
[13:43:54.837] INFO: 41600 events read in total (2735ms).
[13:43:54.838] INFO: Test took 3965ms.
[13:43:54.875] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:55.595] INFO: Expecting 41600 events.
[13:43:58.853] INFO: 41600 events read in total (2731ms).
[13:43:58.854] INFO: Test took 3960ms.
[13:43:58.891] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:43:59.609] INFO: Expecting 41600 events.
[13:44:02.883] INFO: 41600 events read in total (2747ms).
[13:44:02.884] INFO: Test took 3973ms.
[13:44:02.921] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:03.637] INFO: Expecting 41600 events.
[13:44:06.908] INFO: 41600 events read in total (2744ms).
[13:44:06.909] INFO: Test took 3969ms.
[13:44:06.946] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:07.666] INFO: Expecting 41600 events.
[13:44:10.917] INFO: 41600 events read in total (2724ms).
[13:44:10.918] INFO: Test took 3952ms.
[13:44:10.955] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:11.677] INFO: Expecting 41600 events.
[13:44:14.949] INFO: 41600 events read in total (2746ms).
[13:44:14.950] INFO: Test took 3976ms.
[13:44:14.987] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:15.708] INFO: Expecting 41600 events.
[13:44:18.981] INFO: 41600 events read in total (2746ms).
[13:44:18.982] INFO: Test took 3976ms.
[13:44:19.018] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:19.740] INFO: Expecting 41600 events.
[13:44:22.989] INFO: 41600 events read in total (2722ms).
[13:44:22.990] INFO: Test took 3953ms.
[13:44:23.027] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:23.749] INFO: Expecting 41600 events.
[13:44:27.017] INFO: 41600 events read in total (2741ms).
[13:44:27.018] INFO: Test took 3972ms.
[13:44:27.055] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:27.772] INFO: Expecting 41600 events.
[13:44:31.029] INFO: 41600 events read in total (2730ms).
[13:44:31.030] INFO: Test took 3955ms.
[13:44:31.066] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:31.788] INFO: Expecting 41600 events.
[13:44:35.055] INFO: 41600 events read in total (2740ms).
[13:44:35.056] INFO: Test took 3970ms.
[13:44:35.092] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:35.814] INFO: Expecting 41600 events.
[13:44:39.081] INFO: 41600 events read in total (2740ms).
[13:44:39.083] INFO: Test took 3972ms.
[13:44:39.119] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:39.841] INFO: Expecting 41600 events.
[13:44:43.108] INFO: 41600 events read in total (2740ms).
[13:44:43.109] INFO: Test took 3971ms.
[13:44:43.145] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:43.861] INFO: Expecting 41600 events.
[13:44:47.127] INFO: 41600 events read in total (2740ms).
[13:44:47.129] INFO: Test took 3965ms.
[13:44:47.166] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:47.882] INFO: Expecting 41600 events.
[13:44:51.113] INFO: 41600 events read in total (2704ms).
[13:44:51.114] INFO: Test took 3928ms.
[13:44:51.150] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:51.870] INFO: Expecting 41600 events.
[13:44:54.953] INFO: 41600 events read in total (2556ms).
[13:44:54.954] INFO: Test took 3785ms.
[13:44:54.990] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:55.350] INFO: enter test to run
[13:54:26.578] INFO: test: HighRate no parameter change
[13:54:26.578] INFO: running: highrate
[13:54:26.579] INFO: ----------------------------------------------------------------------
[13:54:26.579] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:54:26.580] INFO: ----------------------------------------------------------------------
[13:54:27.192] INFO: Expecting 208000 events.
[13:54:39.137] INFO: 208000 events read in total (11418ms).
[13:54:39.141] INFO: Test took 12553ms.
[13:54:39.299] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:54:39.557] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 3 0 0 0
[13:54:39.557] INFO: number of red-efficiency pixels: 77 73 96 149 145 185 195 113 108 137 123 128 126 66 31 21
[13:54:39.557] INFO: number of X-ray hits detected: 64309 51261 78718 115003 119958 129967 125746 86273 90109 108236 106580 95503 97089 57900 25467 28930
[13:54:39.557] 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:54:39.557] INFO: number of Vcal hits detected: 207922 207926 207900 207848 207850 207814 207802 207884 207889 207861 207874 207869 207723 207933 207969 207979
[13:54:39.557] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[13:54:39.557] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[13:54:39.557] INFO: X-ray hit rate [MHz/cm2]: 18.8 15.0 23.1 33.7 35.2 38.1 36.9 25.3 26.4 31.7 31.2 28.0 28.5 17.0 7.5 8.5
[13:54:39.557] INFO: PixTestHighRate::doXPixelAlive() done
[13:54:39.602] INFO: PixTest:: pg_setup set to default.
[13:54:39.612] INFO: enter test to run
[13:55:01.026] INFO: test: HighRate no parameter change
[13:55:01.026] INFO: running: highrate
[13:55:01.027] INFO: ----------------------------------------------------------------------
[13:55:01.027] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:55:01.027] INFO: ----------------------------------------------------------------------
[13:55:01.644] INFO: Expecting 208000 events.
[13:55:15.580] INFO: 208000 events read in total (13409ms).
[13:55:15.585] INFO: Test took 14547ms.
[13:55:15.902] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:55:16.210] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 3 0 0 0
[13:55:16.211] INFO: number of red-efficiency pixels: 203 179 360 539 468 647 585 272 299 512 468 444 424 182 75 63
[13:55:16.211] INFO: number of X-ray hits detected: 129763 103725 160143 233469 243437 262536 256154 175105 184225 219186 217145 193973 198256 117759 52513 59236
[13:55:16.211] 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:55:16.211] INFO: number of Vcal hits detected: 207783 207812 207607 207406 207499 207277 207341 207702 207684 207431 207498 207505 207399 207810 207924 207937
[13:55:16.211] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.8 99.7 99.7 99.9 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[13:55:16.211] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.8 99.7 99.7 99.9 99.8 99.7 99.8 99.8 99.7 99.9 100.0 100.0
[13:55:16.211] INFO: X-ray hit rate [MHz/cm2]: 38.0 30.4 46.9 68.4 71.4 77.0 75.1 51.3 54.0 64.2 63.6 56.9 58.1 34.5 15.4 17.4
[13:55:16.211] INFO: PixTestHighRate::doXPixelAlive() done
[13:55:16.257] INFO: PixTest:: pg_setup set to default.
[13:55:16.271] INFO: enter test to run
[13:55:30.410] INFO: test: HighRate no parameter change
[13:55:30.410] INFO: running: highrate
[13:55:30.411] INFO: ----------------------------------------------------------------------
[13:55:30.411] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:55:30.411] INFO: ----------------------------------------------------------------------
[13:55:31.021] INFO: Expecting 208000 events.
[13:55:47.158] INFO: 208000 events read in total (15610ms).
[13:55:47.166] INFO: Test took 16746ms.
[13:55:47.698] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:55:48.067] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 3 0 0 0
[13:55:48.067] INFO: number of red-efficiency pixels: 449 361 847 1351 1089 1704 1405 654 681 1186 1195 978 1018 394 128 109
[13:55:48.067] INFO: number of X-ray hits detected: 203756 162706 250534 363650 379312 408973 401350 274351 288783 341822 338642 303618 309749 184565 82154 93692
[13:55:48.067] 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:55:48.067] INFO: number of Vcal hits detected: 207509 207593 206770 206250 206604 205572 206080 207201 207212 206490 206489 206761 206612 207539 207862 207890
[13:55:48.067] INFO: Vcal hit fiducial efficiency (%): 99.8 99.8 99.5 99.2 99.4 98.9 99.2 99.6 99.7 99.3 99.3 99.5 99.5 99.8 99.9 99.9
[13:55:48.067] INFO: Vcal hit overall efficiency (%): 99.8 99.8 99.4 99.2 99.3 98.8 99.1 99.6 99.6 99.3 99.3 99.4 99.3 99.8 99.9 99.9
[13:55:48.067] INFO: X-ray hit rate [MHz/cm2]: 59.7 47.7 73.4 106.6 111.2 119.9 117.6 80.4 84.6 100.2 99.3 89.0 90.8 54.1 24.1 27.5
[13:55:48.067] INFO: PixTestHighRate::doXPixelAlive() done
[13:55:48.116] INFO: PixTest:: pg_setup set to default.
[13:55:48.131] INFO: enter test to run
[13:56:28.657] INFO: test: exit no parameter change
[13:56:29.036] QUIET: Connection to board 33 closed.
[13:56:29.038] INFO: pXar: this is the end, my friend