[13:44:35.353] INFO: *** Welcome to pxar ***
[13:44:35.353] INFO: *** Today: 2016/04/29
[13:44:35.374] INFO: *** Version: v1.9.0-796-gef167-dirty
[13:44:35.374] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//dacParameters35_C15.dat
[13:44:35.396] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:44:35.396] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//defaultMaskFile.dat
[13:44:35.396] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C15.dat
[13:44:35.469] INFO: clk: 4
[13:44:35.469] INFO: ctr: 4
[13:44:35.469] INFO: sda: 19
[13:44:35.469] INFO: tin: 9
[13:44:35.469] INFO: level: 15
[13:44:35.469] INFO: triggerdelay: 0
[13:44:35.469] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[13:44:35.469] INFO: Log level: INFO
[13:44:35.488] QUIET: Connection to board DTB_WREKRL opened.
[13:44:35.491] 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:44:35.494] INFO: RPC call hashes of host and DTB match: 398089610
[13:44:37.028] INFO: DUT info:
[13:44:37.028] INFO: The DUT currently contains the following objects:
[13:44:37.028] INFO: 2 TBM Cores tbm08c (2 ON)
[13:44:37.028] INFO: TBM Core alpha (0): 7 registers set
[13:44:37.028] INFO: TBM Core beta (1): 7 registers set
[13:44:37.028] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:44:37.028] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.028] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.028] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.028] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.028] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.028] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.029] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.029] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.029] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.029] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.029] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.029] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.029] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.029] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.029] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.029] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:44:37.432] INFO: enter 'restricted' command line mode
[13:44:37.432] INFO: enter test to run
[13:44:50.722] INFO: test: PixelAlive no parameter change
[13:44:50.722] INFO: running: pixelalive
[13:44:50.732] INFO: ----------------------------------------------------------------------
[13:44:50.732] 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:44:50.732] INFO: ----------------------------------------------------------------------
[13:44:51.048] INFO: Expecting 41600 events.
[13:44:55.386] INFO: 41600 events read in total (3620ms).
[13:44:55.554] INFO: Test took 4819ms.
[13:44:55.564] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:44:55.826] INFO: PixTestAlive::aliveTest() done
[13:44:55.826] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:44:55.854] INFO: enter test to run
[13:45:20.338] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:45:20.338] INFO: running: highrate
[13:45:20.338] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:45:20.658] INFO: ----------------------------------------------------------------------
[13:45:20.658] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:45:20.658] INFO: ----------------------------------------------------------------------
[13:45:20.658] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:45:20.658] INFO: edge/corner pixel THR is adjusted
[13:45:20.658] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:45:21.617] INFO: Collecting data for 5 seconds...
[13:45:26.634] INFO: Done with hot pixel readout
[13:45:38.453] INFO: PixTest:: pg_setup set to default.
[13:45:38.454] INFO: 0 hot pixels found in step 0
[13:45:38.466] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:45:38.470] INFO: PixTest::trimHotPixels() done
[13:45:38.492] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C0.dat
[13:45:38.497] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C1.dat
[13:45:38.502] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C2.dat
[13:45:38.508] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C3.dat
[13:45:38.513] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C4.dat
[13:45:38.518] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C5.dat
[13:45:38.523] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C6.dat
[13:45:38.528] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C7.dat
[13:45:38.534] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C8.dat
[13:45:38.539] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C9.dat
[13:45:38.544] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C10.dat
[13:45:38.549] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C11.dat
[13:45:38.555] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C12.dat
[13:45:38.560] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C13.dat
[13:45:38.565] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C14.dat
[13:45:38.570] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C15.dat
[13:45:38.575] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//defaultMaskFile.dat
[13:45:38.585] INFO: enter test to run
[13:46:05.722] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[13:46:05.722] INFO: running: highrate
[13:46:05.726] INFO: ----------------------------------------------------------------------
[13:46:05.726] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[13:46:05.726] INFO: ----------------------------------------------------------------------
[13:46:05.726] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[13:46:05.726] INFO: edge/corner pixel THR is adjusted
[13:46:05.726] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:46:06.685] INFO: Collecting data for 1 seconds...
[13:46:07.689] INFO: Done with hot pixel readout
[13:46:11.714] INFO: PixTest:: pg_setup set to default.
[13:46:11.715] INFO: 0 hot pixels found in step 0
[13:46:11.721] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:46:11.809] INFO: PixTest::trimHotPixels() done
[13:46:11.809] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C0.dat
[13:46:11.817] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C1.dat
[13:46:11.823] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C2.dat
[13:46:11.828] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C3.dat
[13:46:11.833] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C4.dat
[13:46:11.839] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C5.dat
[13:46:11.844] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C6.dat
[13:46:11.850] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C7.dat
[13:46:11.855] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C8.dat
[13:46:11.860] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C9.dat
[13:46:11.866] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C10.dat
[13:46:11.872] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C11.dat
[13:46:11.877] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C12.dat
[13:46:11.883] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C13.dat
[13:46:11.888] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C14.dat
[13:46:11.893] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C15.dat
[13:46:11.899] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//defaultMaskFile.dat
[13:46:11.909] INFO: enter test to run
[13:46:39.650] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:46:39.650] INFO: running: xray
[13:46:39.651] INFO: ----------------------------------------------------------------------
[13:46:39.651] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:46:39.651] INFO: ----------------------------------------------------------------------
[13:46:40.616] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:46:52.102] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[13:47:21.589] INFO: Resuming triggers.
[13:47:33.074] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[13:47:58.656] INFO: Resuming triggers.
[13:48:10.140] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[13:48:39.607] INFO: Resuming triggers.
[13:48:51.092] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.









[13:49:20.647] INFO: Resuming triggers.
[13:49:32.133] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[13:50:01.369] INFO: Resuming triggers.
[13:50:12.859] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[13:50:42.236] INFO: Resuming triggers.
[13:50:53.720] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[13:51:21.183] INFO: Resuming triggers.
[13:51:32.667] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[13:52:01.539] INFO: Resuming triggers.
[13:52:09.983] INFO: data taking finished, elapsed time: 100 seconds.
[13:52:31.766] INFO: PixTest:: pg_setup set to default.
[13:52:31.769] INFO: PixTestXray::doPhRun() done
[13:52:31.909] INFO: enter test to run
[13:52:59.287] INFO: test: timing no parameter change
[13:52:59.287] INFO: running: timing
[13:52:59.290] INFO: ######################################################################
[13:52:59.290] INFO: PixTestTiming::doTest()
[13:52:59.291] INFO: ######################################################################
[13:52:59.291] INFO: ----------------------------------------------------------------------
[13:52:59.291] INFO: PixTestTiming::TBMPhaseScan()
[13:52:59.291] INFO: ----------------------------------------------------------------------
[13:57:32.639] INFO: TBM Phase Settings: 248
[13:57:32.639] INFO: 400MHz Phase: 6
[13:57:32.639] INFO: 160MHz Phase: 7
[13:57:32.639] INFO: Functional Phase Area: 4
[13:57:32.642] INFO: Test took 273351 ms.
[13:57:32.642] INFO: PixTestTiming::TBMPhaseScan() done.
[13:57:32.642] INFO: ----------------------------------------------------------------------
[13:57:32.642] INFO: PixTestTiming::ROCDelayScan()
[13:57:32.642] INFO: ----------------------------------------------------------------------
[13:59:55.003] INFO: ROC Delay Settings: 228
[13:59:55.003] INFO: ROC Header-Trailer/Token Delay: 11
[13:59:55.003] INFO: ROC Port 0 Delay: 4
[13:59:55.004] INFO: ROC Port 1 Delay: 4
[13:59:55.004] INFO: Functional ROC Area: 5
[13:59:55.007] INFO: Test took 142365 ms.
[13:59:55.007] INFO: PixTestTiming::ROCDelayScan() done.
[13:59:55.007] INFO: ----------------------------------------------------------------------
[13:59:55.007] INFO: PixTestTiming::TimingTest()
[13:59:55.007] INFO: ----------------------------------------------------------------------
[14:00:11.112] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:00:26.064] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:00:41.022] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:00:55.964] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:10.903] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:25.849] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:40.815] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:01:55.750] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:10.704] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:25.656] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:26.039] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:02:26.052] INFO: ----------------------------------------------------------------------
[14:02:26.052] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:02:26.052] INFO: ----------------------------------------------------------------------
[14:02:26.052] INFO: ----------------------------------------------------------------------
[14:02:26.052] INFO: Read back bit status: 1
[14:02:26.052] INFO: ----------------------------------------------------------------------
[14:02:26.052] INFO: ----------------------------------------------------------------------
[14:02:26.052] INFO: Timings are good!
[14:02:26.052] INFO: ----------------------------------------------------------------------
[14:02:26.052] INFO: Test took 151045 ms.
[14:02:26.052] INFO: PixTestTiming::TimingTest() done.
[14:02:26.052] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:02:26.052] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-48_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:02:26.052] INFO: PixTestTiming::doTest took 566765 ms.
[14:02:26.052] INFO: PixTestTiming::doTest() done
[14:02:26.052] INFO: Write out TBMPhaseScan_0_V0
[14:02:26.053] INFO: Write out TBMPhaseScan_1_V0
[14:02:26.053] INFO: Write out CombinedTBMPhaseScan_V0
[14:02:26.074] INFO: Write out ROCDelayScan3_V0
[14:02:26.075] INFO: enter test to run
[14:03:01.442] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:03:01.443] INFO: running: xray
[14:03:01.444] INFO: ----------------------------------------------------------------------
[14:03:01.444] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:03:01.444] INFO: ----------------------------------------------------------------------
[14:03:02.408] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:03:13.895] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[14:03:43.359] INFO: Resuming triggers.
[14:03:54.845] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[14:04:24.310] INFO: Resuming triggers.
[14:04:35.794] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[14:05:05.189] INFO: Resuming triggers.
[14:05:16.669] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[14:05:46.163] INFO: Resuming triggers.
[14:05:57.649] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[14:06:27.242] INFO: Resuming triggers.
[14:06:38.728] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[14:07:08.256] INFO: Resuming triggers.
[14:07:19.737] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[14:07:49.162] INFO: Resuming triggers.
[14:08:00.643] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[14:08:27.737] INFO: Resuming triggers.
[14:08:36.181] INFO: data taking finished, elapsed time: 100 seconds.
[14:08:57.992] INFO: PixTest:: pg_setup set to default.
[14:08:57.995] INFO: PixTestXray::doPhRun() done
[14:08:58.129] INFO: enter test to run
[14:09:50.679] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:09:50.679] INFO: running: xray
[14:09:50.681] INFO: ----------------------------------------------------------------------
[14:09:50.681] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:09:50.681] INFO: ----------------------------------------------------------------------
[14:09:51.645] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:09:58.275] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[14:10:28.391] INFO: Resuming triggers.
[14:10:35.025] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[14:11:05.182] INFO: Resuming triggers.
[14:11:11.808] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[14:11:42.073] INFO: Resuming triggers.
[14:11:48.704] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[14:12:18.786] INFO: Resuming triggers.
[14:12:25.414] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[14:12:55.602] INFO: Resuming triggers.
[14:13:02.229] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[14:13:32.409] INFO: Resuming triggers.
[14:13:39.034] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[14:14:09.883] INFO: Resuming triggers.
[14:14:16.511] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[14:14:46.151] INFO: Resuming triggers.
[14:14:52.779] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[14:15:22.729] INFO: Resuming triggers.
[14:15:29.355] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[14:15:59.481] INFO: Resuming triggers.
[14:16:06.109] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[14:16:36.281] INFO: Resuming triggers.
[14:16:42.908] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[14:17:13.064] INFO: Resuming triggers.
[14:17:19.689] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[14:17:49.837] INFO: Resuming triggers.
[14:17:56.460] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[14:18:22.620] INFO: Resuming triggers.
[14:18:29.245] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[14:18:59.355] INFO: Resuming triggers.
[14:19:00.266] INFO: data taking finished, elapsed time: 100 seconds.
[14:19:04.793] INFO: PixTest:: pg_setup set to default.
[14:19:04.796] INFO: PixTestXray::doPhRun() done
[14:19:04.944] INFO: enter test to run
[14:19:40.859] INFO: test: HighRate no parameter change
[14:19:40.859] INFO: running: highrate
[14:19:40.860] INFO: ----------------------------------------------------------------------
[14:19:40.860] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[14:19:40.860] INFO: ----------------------------------------------------------------------
[14:19:40.001] INFO: Expecting 768 events.
[14:19:42.136] INFO: 768 events read in total (419ms).
[14:19:42.136] INFO: Test took 1269ms.
[14:19:42.939] INFO: Expecting 41600 events.
[14:19:46.073] INFO: 41600 events read in total (2607ms).
[14:19:46.074] INFO: Test took 3930ms.
[14:19:46.108] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:19:46.836] INFO: Expecting 41600 events.
[14:19:50.040] INFO: 41600 events read in total (2677ms).
[14:19:50.041] INFO: Test took 3915ms.
[14:19:50.075] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:19:50.797] INFO: Expecting 41600 events.
[14:19:54.016] INFO: 41600 events read in total (2692ms).
[14:19:54.017] INFO: Test took 3925ms.
[14:19:54.051] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:19:54.776] INFO: Expecting 41600 events.
[14:19:58.011] INFO: 41600 events read in total (2709ms).
[14:19:58.012] INFO: Test took 3943ms.
[14:19:58.046] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:19:58.770] INFO: Expecting 41600 events.
[14:20:01.954] INFO: 41600 events read in total (2657ms).
[14:20:01.955] INFO: Test took 3890ms.
[14:20:01.988] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:02.713] INFO: Expecting 41600 events.
[14:20:05.933] INFO: 41600 events read in total (2693ms).
[14:20:05.934] INFO: Test took 3927ms.
[14:20:05.967] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:06.695] INFO: Expecting 41600 events.
[14:20:09.930] INFO: 41600 events read in total (2708ms).
[14:20:09.931] INFO: Test took 3945ms.
[14:20:09.965] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:10.691] INFO: Expecting 41600 events.
[14:20:13.938] INFO: 41600 events read in total (2720ms).
[14:20:13.939] INFO: Test took 3955ms.
[14:20:13.973] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:14.700] INFO: Expecting 41600 events.
[14:20:17.943] INFO: 41600 events read in total (2716ms).
[14:20:17.944] INFO: Test took 3953ms.
[14:20:17.978] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:18.701] INFO: Expecting 41600 events.
[14:20:21.938] INFO: 41600 events read in total (2710ms).
[14:20:21.939] INFO: Test took 3942ms.
[14:20:21.972] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:22.695] INFO: Expecting 41600 events.
[14:20:25.935] INFO: 41600 events read in total (2713ms).
[14:20:25.936] INFO: Test took 3946ms.
[14:20:25.970] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:26.694] INFO: Expecting 41600 events.
[14:20:29.929] INFO: 41600 events read in total (2708ms).
[14:20:29.930] INFO: Test took 3941ms.
[14:20:29.964] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:30.684] INFO: Expecting 41600 events.
[14:20:33.927] INFO: 41600 events read in total (2716ms).
[14:20:33.927] INFO: Test took 3944ms.
[14:20:33.961] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:34.684] INFO: Expecting 41600 events.
[14:20:37.935] INFO: 41600 events read in total (2724ms).
[14:20:37.936] INFO: Test took 3955ms.
[14:20:37.969] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:38.694] INFO: Expecting 41600 events.
[14:20:41.953] INFO: 41600 events read in total (2732ms).
[14:20:41.954] INFO: Test took 3966ms.
[14:20:41.987] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:42.709] INFO: Expecting 41600 events.
[14:20:45.943] INFO: 41600 events read in total (2707ms).
[14:20:45.944] INFO: Test took 3938ms.
[14:20:45.978] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:46.704] INFO: Expecting 41600 events.
[14:20:49.937] INFO: 41600 events read in total (2706ms).
[14:20:49.938] INFO: Test took 3942ms.
[14:20:49.971] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:50.698] INFO: Expecting 41600 events.
[14:20:53.943] INFO: 41600 events read in total (2718ms).
[14:20:53.944] INFO: Test took 3955ms.
[14:20:53.978] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:54.703] INFO: Expecting 41600 events.
[14:20:57.940] INFO: 41600 events read in total (2710ms).
[14:20:57.941] INFO: Test took 3944ms.
[14:20:57.976] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:58.701] INFO: Expecting 41600 events.
[14:21:01.800] INFO: 41600 events read in total (2572ms).
[14:21:01.801] INFO: Test took 3806ms.
[14:21:01.834] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:02.198] INFO: enter test to run
[14:21:10.354] INFO: test: HighRate no parameter change
[14:21:10.354] INFO: running: highrate
[14:21:10.356] INFO: ----------------------------------------------------------------------
[14:21:10.356] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:21:10.356] INFO: ----------------------------------------------------------------------
[14:21:10.968] INFO: Expecting 208000 events.
[14:21:22.849] INFO: 208000 events read in total (11354ms).
[14:21:22.852] INFO: Test took 12490ms.
[14:21:22.992] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:23.243] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[14:21:23.243] INFO: number of red-efficiency pixels: 65 39 86 141 137 177 127 88 90 96 139 83 90 58 26 19
[14:21:23.243] INFO: number of X-ray hits detected: 62654 43891 67204 106859 112915 122834 112376 77041 72946 93185 98412 81474 87627 51535 21878 23144
[14:21:23.243] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:21:23.243] INFO: number of Vcal hits detected: 207935 207961 207913 207856 207861 207817 207873 207911 207908 207903 207857 207916 207908 207940 207974 207981
[14:21:23.243] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[14:21:23.243] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[14:21:23.243] INFO: X-ray hit rate [MHz/cm2]: 18.4 12.9 19.7 31.3 33.1 36.0 32.9 22.6 21.4 27.3 28.8 23.9 25.7 15.1 6.4 6.8
[14:21:23.243] INFO: PixTestHighRate::doXPixelAlive() done
[14:21:23.290] INFO: PixTest:: pg_setup set to default.
[14:21:23.307] INFO: enter test to run
[14:21:42.338] INFO: test: HighRate no parameter change
[14:21:42.338] INFO: running: highrate
[14:21:42.339] INFO: ----------------------------------------------------------------------
[14:21:42.339] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:21:42.339] INFO: ----------------------------------------------------------------------
[14:21:42.958] INFO: Expecting 208000 events.
[14:21:56.634] INFO: 208000 events read in total (13149ms).
[14:21:56.640] INFO: Test took 14292ms.
[14:21:56.932] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:57.232] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[14:21:57.232] INFO: number of red-efficiency pixels: 243 133 310 487 490 703 388 304 252 410 425 333 351 182 63 58
[14:21:57.232] INFO: number of X-ray hits detected: 132272 92276 143218 226332 238008 259962 237556 163005 154804 196537 207843 172720 184892 107392 46308 48646
[14:21:57.232] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:21:57.232] INFO: number of Vcal hits detected: 207750 207860 207661 207463 207471 207196 207596 207677 207736 207563 207534 207648 207628 207808 207934 207939
[14:21:57.232] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.6 99.8 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[14:21:57.232] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.6 99.8 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[14:21:57.232] INFO: X-ray hit rate [MHz/cm2]: 38.8 27.0 42.0 66.3 69.8 76.2 69.6 47.8 45.4 57.6 60.9 50.6 54.2 31.5 13.6 14.3
[14:21:57.232] INFO: PixTestHighRate::doXPixelAlive() done
[14:21:57.277] INFO: PixTest:: pg_setup set to default.
[14:21:57.288] INFO: enter test to run
[14:22:18.170] INFO: test: HighRate no parameter change
[14:22:18.170] INFO: running: highrate
[14:22:18.171] INFO: ----------------------------------------------------------------------
[14:22:18.171] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:22:18.171] INFO: ----------------------------------------------------------------------
[14:22:18.783] INFO: Expecting 208000 events.
[14:22:34.331] INFO: 208000 events read in total (15021ms).
[14:22:34.338] INFO: Test took 16158ms.
[14:22:34.786] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:35.137] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[14:22:35.137] INFO: number of red-efficiency pixels: 497 296 689 1162 995 1636 995 739 554 859 1026 751 791 460 80 80
[14:22:35.137] INFO: number of X-ray hits detected: 199827 139170 216431 342950 362042 392499 361184 247250 233637 297204 315612 261513 280348 163726 70832 74126
[14:22:35.137] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:22:35.137] INFO: number of Vcal hits detected: 207426 207665 207084 206525 206785 205712 206809 207068 207381 206984 206733 207127 207032 207464 207918 207918
[14:22:35.137] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.4 99.5 99.0 99.5 99.6 99.7 99.6 99.4 99.6 99.6 99.8 100.0 100.0
[14:22:35.137] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.6 99.3 99.4 98.9 99.4 99.6 99.7 99.5 99.4 99.6 99.5 99.7 100.0 100.0
[14:22:35.137] INFO: X-ray hit rate [MHz/cm2]: 58.6 40.8 63.4 100.5 106.1 115.0 105.9 72.5 68.5 87.1 92.5 76.7 82.2 48.0 20.8 21.7
[14:22:35.137] INFO: PixTestHighRate::doXPixelAlive() done
[14:22:35.187] INFO: PixTest:: pg_setup set to default.
[14:22:35.205] INFO: enter test to run
[14:22:38.122] INFO: test: exit no parameter change
[14:22:38.513] QUIET: Connection to board 33 closed.
[14:22:38.515] INFO: pXar: this is the end, my friend