[15:44:02.027] INFO: *** Welcome to pxar ***
[15:44:02.027] INFO: *** Today: 2016/09/21
[15:44:02.046] INFO: *** Version: v1.9.0-818-g96727
[15:44:02.046] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//dacParameters35_C15.dat
[15:44:02.047] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:44:02.047] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//defaultMaskFile.dat
[15:44:02.047] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C15.dat
[15:44:02.124] INFO: clk: 4
[15:44:02.124] INFO: ctr: 4
[15:44:02.124] INFO: sda: 19
[15:44:02.124] INFO: tin: 9
[15:44:02.124] INFO: level: 15
[15:44:02.124] INFO: triggerdelay: 0
[15:44:02.124] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:44:02.124] INFO: Log level: INFO
[15:44:02.142] QUIET: Connection to board DTB_WREKRL opened.
[15:44:02.146] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[15:44:02.148] INFO: RPC call hashes of host and DTB match: 398089610
[15:44:03.674] INFO: DUT info:
[15:44:03.674] INFO: The DUT currently contains the following objects:
[15:44:03.674] INFO: 2 TBM Cores tbm08c (2 ON)
[15:44:03.674] INFO: TBM Core alpha (0): 7 registers set
[15:44:03.674] INFO: TBM Core beta (1): 7 registers set
[15:44:03.675] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:44:03.675] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:03.675] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:44:04.078] INFO: enter 'restricted' command line mode
[15:44:04.078] INFO: enter test to run
[15:44:10.805] INFO: test: PixelAlive no parameter change
[15:44:10.805] INFO: running: pixelalive
[15:44:10.814] INFO: ----------------------------------------------------------------------
[15:44:10.814] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[15:44:10.814] INFO: ----------------------------------------------------------------------
[15:44:11.133] INFO: Expecting 41600 events.
[15:44:15.472] INFO: 41600 events read in total (3620ms).
[15:44:15.640] INFO: Test took 4823ms.
[15:44:15.652] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:15.919] INFO: PixTestAlive::aliveTest() done
[15:44:15.919] INFO: number of dead pixels (per ROC): 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:44:15.949] INFO: enter test to run
[15:44:22.396] INFO: test: timing no parameter change
[15:44:22.397] INFO: running: timing
[15:44:22.400] INFO: ######################################################################
[15:44:22.400] INFO: PixTestTiming::doTest()
[15:44:22.400] INFO: ######################################################################
[15:44:22.400] INFO: ----------------------------------------------------------------------
[15:44:22.400] INFO: PixTestTiming::TBMPhaseScan()
[15:44:22.400] INFO: ----------------------------------------------------------------------
[15:50:18.962] INFO: TBM Phase Settings: 232
[15:50:18.962] INFO: 400MHz Phase: 2
[15:50:18.962] INFO: 160MHz Phase: 7
[15:50:18.962] INFO: Functional Phase Area: 4
[15:50:18.965] INFO: Test took 356565 ms.
[15:50:18.965] INFO: PixTestTiming::TBMPhaseScan() done.
[15:50:18.965] INFO: ----------------------------------------------------------------------
[15:50:18.965] INFO: PixTestTiming::ROCDelayScan()
[15:50:18.965] INFO: ----------------------------------------------------------------------
[15:52:26.301] INFO: ROC Delay Settings: 228
[15:52:26.301] INFO: ROC Header-Trailer/Token Delay: 11
[15:52:26.301] INFO: ROC Port 0 Delay: 4
[15:52:26.301] INFO: ROC Port 1 Delay: 4
[15:52:26.301] INFO: Functional ROC Area: 5
[15:52:26.304] INFO: Test took 127339 ms.
[15:52:26.305] INFO: PixTestTiming::ROCDelayScan() done.
[15:52:26.305] INFO: ----------------------------------------------------------------------
[15:52:26.305] INFO: PixTestTiming::TimingTest()
[15:52:26.305] INFO: ----------------------------------------------------------------------
[15:52:42.612] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:52:57.593] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:53:12.641] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:53:27.788] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:53:43.169] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:53:58.362] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:54:13.531] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:54:28.773] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:54:44.055] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:54:59.147] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:54:59.530] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:54:59.546] INFO: ----------------------------------------------------------------------
[15:54:59.546] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:54:59.546] INFO: ----------------------------------------------------------------------
[15:54:59.546] INFO: ----------------------------------------------------------------------
[15:54:59.546] INFO: Read back bit status: 1
[15:54:59.546] INFO: ----------------------------------------------------------------------
[15:54:59.546] INFO: ----------------------------------------------------------------------
[15:54:59.546] INFO: Timings are good!
[15:54:59.546] INFO: ----------------------------------------------------------------------
[15:54:59.546] INFO: Test took 153241 ms.
[15:54:59.546] INFO: PixTestTiming::TimingTest() done.
[15:54:59.546] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:54:59.546] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:54:59.546] INFO: PixTestTiming::doTest took 637149 ms.
[15:54:59.546] INFO: PixTestTiming::doTest() done
[15:54:59.546] INFO: Write out TBMPhaseScan_0_V0
[15:54:59.546] INFO: Write out TBMPhaseScan_1_V0
[15:54:59.547] INFO: Write out CombinedTBMPhaseScan_V0
[15:54:59.548] INFO: Write out ROCDelayScan3_V0
[15:54:59.548] INFO: enter test to run
[15:55:46.632] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:55:46.632] INFO: running: highrate
[15:55:46.632] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:55:46.793] INFO: ----------------------------------------------------------------------
[15:55:46.794] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:55:46.794] INFO: ----------------------------------------------------------------------
[15:55:46.794] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:55:46.794] INFO: edge/corner pixel THR is adjusted
[15:55:46.794] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:55:47.752] INFO: Collecting data for 5 seconds...
[15:55:52.768] INFO: Done with hot pixel readout
[15:56:04.381] INFO: PixTest:: pg_setup set to default.
[15:56:04.382] INFO: 3 hot pixels found in step 0
[15:56:05.373] INFO: Collecting data for 5 seconds...
[15:56:10.389] INFO: Done with hot pixel readout
[15:56:21.963] INFO: PixTest:: pg_setup set to default.
[15:56:21.963] INFO: 3 hot pixels found in step 1
[15:56:22.955] INFO: Collecting data for 5 seconds...
[15:56:27.972] INFO: Done with hot pixel readout
[15:56:39.516] INFO: PixTest:: pg_setup set to default.
[15:56:39.517] INFO: 1 hot pixels found in step 2
[15:56:40.509] INFO: Collecting data for 5 seconds...
[15:56:45.525] INFO: Done with hot pixel readout
[15:56:57.096] INFO: PixTest:: pg_setup set to default.
[15:56:57.097] INFO: 1 hot pixels found in step 3
[15:56:58.089] INFO: Collecting data for 5 seconds...
[15:57:03.105] INFO: Done with hot pixel readout
[15:57:14.705] INFO: PixTest:: pg_setup set to default.
[15:57:14.705] INFO: 2 hot pixels found in step 4
[15:57:15.696] INFO: Collecting data for 5 seconds...
[15:57:20.713] INFO: Done with hot pixel readout
[15:57:32.320] INFO: PixTest:: pg_setup set to default.
[15:57:32.320] INFO: 1 hot pixels found in step 5
[15:57:33.312] INFO: Collecting data for 5 seconds...
[15:57:38.330] INFO: Done with hot pixel readout
[15:57:49.984] INFO: PixTest:: pg_setup set to default.
[15:57:49.985] INFO: 2 hot pixels found in step 6
[15:57:50.976] INFO: Collecting data for 5 seconds...
[15:57:55.993] INFO: Done with hot pixel readout
[15:58:07.582] INFO: PixTest:: pg_setup set to default.

[15:58:07.583] INFO: 1 hot pixels found in step 7
[15:58:07.618] INFO: 1 hot pixels could not be trimmed and have been masked.
[15:58:07.621] INFO: PixTest::trimHotPixels() done
[15:58:07.621] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C0.dat
[15:58:07.628] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C1.dat
[15:58:07.634] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C2.dat
[15:58:07.639] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C3.dat
[15:58:07.644] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C4.dat
[15:58:07.650] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C5.dat
[15:58:07.655] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C6.dat
[15:58:07.660] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C7.dat
[15:58:07.665] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C8.dat
[15:58:07.670] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C9.dat
[15:58:07.675] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C10.dat
[15:58:07.681] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C11.dat
[15:58:07.686] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C12.dat
[15:58:07.691] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C13.dat
[15:58:07.696] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C14.dat
[15:58:07.701] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C15.dat
[15:58:07.706] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//defaultMaskFile.dat
[15:58:07.721] INFO: enter test to run
[15:58:30.063] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:58:30.063] INFO: running: highrate
[15:58:30.067] INFO: ----------------------------------------------------------------------
[15:58:30.067] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:58:30.067] INFO: ----------------------------------------------------------------------
[15:58:30.067] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:58:30.067] INFO: edge/corner pixel THR is adjusted
[15:58:30.067] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:58:31.025] INFO: Collecting data for 1 seconds...
[15:58:32.029] INFO: Done with hot pixel readout
[15:58:35.929] INFO: PixTest:: pg_setup set to default.
[15:58:35.930] INFO: 0 hot pixels found in step 0
[15:58:35.935] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:58:36.033] INFO: PixTest::trimHotPixels() done
[15:58:36.033] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C0.dat
[15:58:36.041] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C1.dat
[15:58:36.047] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C2.dat
[15:58:36.052] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C3.dat
[15:58:36.058] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C4.dat
[15:58:36.064] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C5.dat
[15:58:36.069] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C6.dat
[15:58:36.075] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C7.dat
[15:58:36.080] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C8.dat
[15:58:36.086] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C9.dat
[15:58:36.091] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C10.dat
[15:58:36.097] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C11.dat
[15:58:36.102] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C12.dat
[15:58:36.108] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C13.dat
[15:58:36.113] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C14.dat
[15:58:36.119] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//trimParameters35_C15.dat
[15:58:36.124] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-A-38_FPIXTest-17C-FNAL-160915-1235-150V_2016-09-15_12h36m_1473960967/000_FPIXTest_p17//defaultMaskFile.dat
[15:58:36.134] INFO: enter test to run
[15:58:54.767] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:58:54.767] INFO: running: xray
[15:58:54.778] INFO: ----------------------------------------------------------------------
[15:58:54.778] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:58:54.778] INFO: ----------------------------------------------------------------------
[15:58:55.740] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:59:07.318] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:59:36.683] INFO: Resuming triggers.
[15:59:48.269] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[16:00:17.579] INFO: Resuming triggers.
[16:00:29.161] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[16:00:58.532] INFO: Resuming triggers.
[16:01:10.118] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[16:01:39.442] INFO: Resuming triggers.
[16:01:51.032] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[16:02:20.425] INFO: Resuming triggers.
[16:02:32.011] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[16:03:01.376] INFO: Resuming triggers.
[16:03:12.961] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[16:03:42.950] INFO: Resuming triggers.
[16:03:54.534] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[16:04:24.401] INFO: Resuming triggers.
[16:04:32.062] INFO: data taking finished, elapsed time: 100 seconds.
[16:04:51.530] INFO: PixTest:: pg_setup set to default.
[16:04:51.533] INFO: PixTestXray::doPhRun() done
[16:04:51.671] INFO: enter test to run
[16:05:40.300] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:05:40.300] INFO: running: xray
[16:05:40.301] INFO: ----------------------------------------------------------------------
[16:05:40.301] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:05:40.301] INFO: ----------------------------------------------------------------------
[16:05:41.264] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:05:48.101] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[16:06:19.402] INFO: Resuming triggers.
[16:06:26.235] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[16:06:57.666] INFO: Resuming triggers.
[16:07:04.496] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[16:07:36.481] INFO: Resuming triggers.
[16:07:43.317] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[16:08:14.221] INFO: Resuming triggers.
[16:08:21.059] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[16:08:51.176] INFO: Resuming triggers.
[16:08:57.005] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[16:09:28.198] INFO: Resuming triggers.
[16:09:35.028] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[16:10:05.303] INFO: Resuming triggers.
[16:10:12.137] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[16:10:42.336] INFO: Resuming triggers.
[16:10:49.167] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[16:11:19.386] INFO: Resuming triggers.
[16:11:26.216] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[16:11:56.424] INFO: Resuming triggers.
[16:12:03.255] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[16:12:33.371] INFO: Resuming triggers.
[16:12:40.200] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[16:13:10.378] INFO: Resuming triggers.
[16:13:17.205] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[16:13:47.317] INFO: Resuming triggers.
[16:13:54.150] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[16:14:23.953] INFO: Resuming triggers.
[16:14:28.656] INFO: data taking finished, elapsed time: 100 seconds.
[16:14:49.585] INFO: PixTest:: pg_setup set to default.
[16:14:49.588] INFO: PixTestXray::doPhRun() done
[16:14:49.735] INFO: enter test to run
[16:15:19.552] INFO: test: HighRate no parameter change
[16:15:19.552] INFO: running: highrate
[16:15:19.570] INFO: ----------------------------------------------------------------------
[16:15:19.570] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:15:19.570] INFO: ----------------------------------------------------------------------
[16:15:19.717] INFO: Expecting 768 events.
[16:15:20.851] INFO: 768 events read in total (419ms).
[16:15:20.851] INFO: Test took 1269ms.
[16:15:21.655] INFO: Expecting 41600 events.
[16:15:24.680] INFO: 41600 events read in total (2499ms).
[16:15:24.681] INFO: Test took 3823ms.
[16:15:24.713] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:25.447] INFO: Expecting 41600 events.
[16:15:28.620] INFO: 41600 events read in total (2647ms).
[16:15:28.621] INFO: Test took 3892ms.
[16:15:28.653] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:29.382] INFO: Expecting 41600 events.
[16:15:32.582] INFO: 41600 events read in total (2673ms).
[16:15:32.583] INFO: Test took 3912ms.
[16:15:32.615] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:33.345] INFO: Expecting 41600 events.
[16:15:36.561] INFO: 41600 events read in total (2689ms).
[16:15:36.562] INFO: Test took 3929ms.
[16:15:36.595] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:37.319] INFO: Expecting 41600 events.
[16:15:40.545] INFO: 41600 events read in total (2699ms).
[16:15:40.546] INFO: Test took 3934ms.
[16:15:40.579] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:41.303] INFO: Expecting 41600 events.
[16:15:44.532] INFO: 41600 events read in total (2702ms).
[16:15:44.533] INFO: Test took 3936ms.
[16:15:44.566] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:45.291] INFO: Expecting 41600 events.
[16:15:48.515] INFO: 41600 events read in total (2697ms).
[16:15:48.516] INFO: Test took 3932ms.
[16:15:48.549] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:49.276] INFO: Expecting 41600 events.
[16:15:52.486] INFO: 41600 events read in total (2683ms).
[16:15:52.487] INFO: Test took 3919ms.
[16:15:52.519] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:53.246] INFO: Expecting 41600 events.
[16:15:56.482] INFO: 41600 events read in total (2710ms).
[16:15:56.483] INFO: Test took 3946ms.
[16:15:56.516] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:57.241] INFO: Expecting 41600 events.
[16:16:00.621] INFO: 41600 events read in total (2853ms).
[16:16:00.622] INFO: Test took 4087ms.
[16:16:00.656] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:01.377] INFO: Expecting 41600 events.
[16:16:04.602] INFO: 41600 events read in total (2698ms).
[16:16:04.603] INFO: Test took 3930ms.
[16:16:04.637] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:05.357] INFO: Expecting 41600 events.
[16:16:08.569] INFO: 41600 events read in total (2686ms).
[16:16:08.570] INFO: Test took 3915ms.
[16:16:08.603] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:09.329] INFO: Expecting 41600 events.
[16:16:12.525] INFO: 41600 events read in total (2669ms).
[16:16:12.526] INFO: Test took 3905ms.
[16:16:12.560] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:13.285] INFO: Expecting 41600 events.
[16:16:16.499] INFO: 41600 events read in total (2687ms).
[16:16:16.499] INFO: Test took 3921ms.
[16:16:16.534] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:17.255] INFO: Expecting 41600 events.
[16:16:20.460] INFO: 41600 events read in total (2678ms).
[16:16:20.461] INFO: Test took 3909ms.
[16:16:20.495] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:21.219] INFO: Expecting 41600 events.
[16:16:24.462] INFO: 41600 events read in total (2716ms).
[16:16:24.463] INFO: Test took 3951ms.
[16:16:24.497] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:25.213] INFO: Expecting 41600 events.
[16:16:28.477] INFO: 41600 events read in total (2737ms).
[16:16:28.478] INFO: Test took 3964ms.
[16:16:28.512] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:29.235] INFO: Expecting 41600 events.
[16:16:32.485] INFO: 41600 events read in total (2724ms).
[16:16:32.486] INFO: Test took 3957ms.
[16:16:32.519] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:33.245] INFO: Expecting 41600 events.
[16:16:36.477] INFO: 41600 events read in total (2706ms).
[16:16:36.478] INFO: Test took 3941ms.
[16:16:36.512] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:37.235] INFO: Expecting 41600 events.
[16:16:40.339] INFO: 41600 events read in total (2577ms).
[16:16:40.340] INFO: Test took 3810ms.
[16:16:40.373] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:40.732] INFO: enter test to run
[16:18:20.391] INFO: test: HighRate no parameter change
[16:18:20.391] INFO: running: highrate
[16:18:20.392] INFO: ----------------------------------------------------------------------
[16:18:20.392] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:18:20.392] INFO: ----------------------------------------------------------------------
[16:18:21.013] INFO: Expecting 208000 events.
[16:18:32.881] INFO: 208000 events read in total (11341ms).
[16:18:32.885] INFO: Test took 12484ms.
[16:18:33.031] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:33.281] INFO: number of dead pixels (per ROC): 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:18:33.281] INFO: number of red-efficiency pixels: 75 48 81 161 174 172 117 95 94 91 88 93 129 54 20 29
[16:18:33.282] INFO: number of X-ray hits detected: 61364 41120 64884 102673 107303 110475 107522 76524 69415 95453 89147 77281 83872 50563 22412 25894
[16:18:33.282] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:18:33.282] INFO: number of Vcal hits detected: 207924 207952 207868 207830 207819 207826 207882 207903 207905 207907 207911 207907 207866 207945 207978 207971
[16:18:33.282] 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 100.0 100.0 99.9 100.0 100.0 100.0
[16:18:33.282] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 99.9 100.0 100.0 100.0
[16:18:33.282] INFO: X-ray hit rate [MHz/cm2]: 18.0 12.1 19.0 30.1 31.5 32.4 31.5 22.4 20.3 28.0 26.1 22.7 24.6 14.8 6.6 7.6
[16:18:33.282] INFO: PixTestHighRate::doXPixelAlive() done
[16:18:33.336] INFO: PixTest:: pg_setup set to default.
[16:18:33.352] INFO: enter test to run
[16:18:51.743] INFO: test: HighRate no parameter change
[16:18:51.743] INFO: running: highrate
[16:18:51.744] INFO: ----------------------------------------------------------------------
[16:18:51.744] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:18:51.744] INFO: ----------------------------------------------------------------------
[16:18:52.357] INFO: Expecting 208000 events.
[16:19:06.387] INFO: 208000 events read in total (13503ms).
[16:19:06.392] INFO: Test took 14639ms.
[16:19:06.689] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:19:06.992] INFO: number of dead pixels (per ROC): 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:19:06.992] INFO: number of red-efficiency pixels: 218 134 307 529 561 541 445 341 233 321 298 256 334 202 59 70
[16:19:06.992] INFO: number of X-ray hits detected: 129894 87222 137076 216608 227099 233043 227139 162639 146623 201296 189899 164309 177876 107065 47840 55039
[16:19:06.992] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:19:06.992] INFO: number of Vcal hits detected: 207765 207862 207607 207420 207376 207385 207518 207629 207757 207657 207689 207733 207638 207787 207940 207929
[16:19:06.992] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.7 99.7 99.7 99.8 99.8 99.9 99.8 99.9 99.9 99.8 99.9 100.0 100.0
[16:19:06.992] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.7 99.8 99.8 99.9 99.8 99.9 99.9 99.8 99.9 100.0 100.0
[16:19:06.992] INFO: X-ray hit rate [MHz/cm2]: 38.1 25.6 40.2 63.5 66.6 68.3 66.6 47.7 43.0 59.0 55.7 48.2 52.1 31.4 14.0 16.1
[16:19:06.992] INFO: PixTestHighRate::doXPixelAlive() done
[16:19:07.042] INFO: PixTest:: pg_setup set to default.
[16:19:07.061] INFO: enter test to run
[16:19:21.702] INFO: test: HighRate no parameter change
[16:19:21.702] INFO: running: highrate
[16:19:21.704] INFO: ----------------------------------------------------------------------
[16:19:21.704] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:19:21.704] INFO: ----------------------------------------------------------------------
[16:19:22.322] INFO: Expecting 208000 events.
[16:19:38.139] INFO: 208000 events read in total (15290ms).
[16:19:38.146] INFO: Test took 16433ms.
[16:19:38.572] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:19:38.916] INFO: number of dead pixels (per ROC): 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:19:38.916] INFO: number of red-efficiency pixels: 487 305 681 1217 1363 1360 1108 748 529 708 685 578 827 459 90 101
[16:19:38.916] INFO: number of X-ray hits detected: 197982 132931 208547 329262 346366 353519 346287 246866 223832 306882 288240 249539 269832 164121 72865 84182
[16:19:38.916] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:19:38.916] INFO: number of Vcal hits detected: 207438 207666 207005 206466 206193 206168 206600 207020 207407 207186 207208 207336 207044 207465 207905 207898
[16:19:38.916] INFO: Vcal hit fiducial efficiency (%): 99.8 99.8 99.6 99.3 99.2 99.2 99.4 99.6 99.7 99.6 99.7 99.7 99.6 99.8 100.0 99.9
[16:19:38.916] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.5 99.3 99.1 99.1 99.3 99.5 99.7 99.6 99.6 99.7 99.5 99.7 100.0 100.0
[16:19:38.916] INFO: X-ray hit rate [MHz/cm2]: 58.0 39.0 61.1 96.5 101.5 103.6 101.5 72.4 65.6 89.9 84.5 73.1 79.1 48.1 21.4 24.7
[16:19:38.916] INFO: PixTestHighRate::doXPixelAlive() done
[16:19:38.964] INFO: PixTest:: pg_setup set to default.
[16:19:38.981] INFO: enter test to run
[16:20:07.550] INFO: test: exit no parameter change
[16:20:08.045] QUIET: Connection to board 33 closed.
[16:20:08.056] INFO: pXar: this is the end, my friend