[09:16:02.091] INFO: *** Welcome to pxar ***
[09:16:02.091] INFO: *** Today: 2016/09/09
[09:16:03.133] INFO: *** Version: v1.9.0-818-g96727
[09:16:03.133] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//dacParameters35_C15.dat
[09:16:03.188] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:16:03.189] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//defaultMaskFile.dat
[09:16:03.193] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C15.dat
[09:16:03.341] INFO: clk: 4
[09:16:03.341] INFO: ctr: 4
[09:16:03.341] INFO: sda: 19
[09:16:03.341] INFO: tin: 9
[09:16:03.341] INFO: level: 15
[09:16:03.341] INFO: triggerdelay: 0
[09:16:03.341] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[09:16:03.341] INFO: Log level: INFO
[09:16:03.358] QUIET: Connection to board DTB_WREKRL opened.
[09:16:03.361] 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:
------------------------------------------------------
[09:16:03.364] INFO: RPC call hashes of host and DTB match: 398089610
[09:16:04.907] INFO: DUT info:
[09:16:04.907] INFO: The DUT currently contains the following objects:
[09:16:04.907] INFO: 2 TBM Cores tbm08c (2 ON)
[09:16:04.907] INFO: TBM Core alpha (0): 7 registers set
[09:16:04.907] INFO: TBM Core beta (1): 7 registers set
[09:16:04.907] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[09:16:04.907] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.907] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.907] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:04.908] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[09:16:05.338] INFO: enter 'restricted' command line mode
[09:16:05.339] INFO: enter test to run
[09:16:15.156] INFO: test: PixelAlive no parameter change
[09:16:15.156] INFO: running: pixelalive
[09:16:15.217] INFO: ----------------------------------------------------------------------
[09:16:15.217] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[09:16:15.217] INFO: ----------------------------------------------------------------------
[09:16:15.537] INFO: Expecting 41600 events.
[09:16:19.887] INFO: 41600 events read in total (3632ms).
[09:16:20.056] INFO: Test took 4836ms.
[09:16:20.066] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:16:20.571] INFO: PixTestAlive::aliveTest() done
[09:16:20.571] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 2 0 0 1 0 0 0 0
[09:16:20.724] INFO: enter test to run
[09:16:35.884] INFO: test: timing no parameter change
[09:16:35.884] INFO: running: timing
[09:16:35.887] INFO: ######################################################################
[09:16:35.887] INFO: PixTestTiming::doTest()
[09:16:35.887] INFO: ######################################################################
[09:16:35.887] INFO: ----------------------------------------------------------------------
[09:16:35.887] INFO: PixTestTiming::TBMPhaseScan()
[09:16:35.887] INFO: ----------------------------------------------------------------------
[09:21:14.055] INFO: TBM Phase Settings: 236
[09:21:14.055] INFO: 400MHz Phase: 3
[09:21:14.055] INFO: 160MHz Phase: 7
[09:21:14.055] INFO: Functional Phase Area: 3
[09:21:14.073] INFO: Test took 278186 ms.
[09:21:14.073] INFO: PixTestTiming::TBMPhaseScan() done.
[09:21:14.073] INFO: ----------------------------------------------------------------------
[09:21:14.073] INFO: PixTestTiming::ROCDelayScan()
[09:21:14.073] INFO: ----------------------------------------------------------------------
[09:23:12.967] INFO: ROC Delay Settings: 228
[09:23:12.967] INFO: ROC Header-Trailer/Token Delay: 11
[09:23:12.967] INFO: ROC Port 0 Delay: 4
[09:23:12.967] INFO: ROC Port 1 Delay: 4
[09:23:12.967] INFO: Functional ROC Area: 3
[09:23:12.970] INFO: Test took 118897 ms.
[09:23:12.970] INFO: PixTestTiming::ROCDelayScan() done.
[09:23:12.970] INFO: ----------------------------------------------------------------------
[09:23:12.970] INFO: PixTestTiming::TimingTest()
[09:23:12.970] INFO: ----------------------------------------------------------------------
[09:23:29.114] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:23:44.083] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:23:59.059] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:24:14.021] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:24:28.997] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:24:43.975] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:24:58.924] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:25:13.831] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:25:28.792] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:25:43.770] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:25:44.148] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:25:44.165] INFO: ----------------------------------------------------------------------
[09:25:44.165] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[09:25:44.165] INFO: ----------------------------------------------------------------------
[09:25:44.165] INFO: ----------------------------------------------------------------------
[09:25:44.165] INFO: Read back bit status: 1
[09:25:44.165] INFO: ----------------------------------------------------------------------
[09:25:44.165] INFO: ----------------------------------------------------------------------
[09:25:44.165] INFO: Timings are good!
[09:25:44.165] INFO: ----------------------------------------------------------------------
[09:25:44.165] INFO: Test took 151195 ms.
[09:25:44.165] INFO: PixTestTiming::TimingTest() done.
[09:25:44.165] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//tbmParameters_C0a.dat
[09:25:44.165] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:25:44.166] INFO: PixTestTiming::doTest took 548282 ms.
[09:25:44.166] INFO: PixTestTiming::doTest() done
[09:25:44.166] INFO: Write out TBMPhaseScan_0_V0
[09:25:44.166] INFO: Write out TBMPhaseScan_1_V0
[09:25:44.166] INFO: Write out CombinedTBMPhaseScan_V0
[09:25:44.167] INFO: Write out ROCDelayScan3_V0
[09:25:44.167] INFO: enter test to run
[09:29:55.879] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[09:29:55.879] INFO: running: highrate
[09:29:55.892] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[09:29:56.158] INFO: ----------------------------------------------------------------------
[09:29:56.159] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[09:29:56.159] INFO: ----------------------------------------------------------------------
[09:29:56.159] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[09:29:56.159] INFO: edge/corner pixel THR is adjusted
[09:29:56.159] INFO: PixTestHighRate::trimHotPixels: step 0...
[09:29:57.117] INFO: Collecting data for 5 seconds...
[09:30:02.133] INFO: Done with hot pixel readout
[09:30:13.342] INFO: PixTest:: pg_setup set to default.
[09:30:13.343] INFO: 0 hot pixels found in step 0
[09:30:13.375] INFO: 0 hot pixels could not be trimmed and have been masked.
[09:30:13.378] INFO: PixTest::trimHotPixels() done
[09:30:13.378] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C0.dat
[09:30:13.384] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C1.dat
[09:30:13.390] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C2.dat
[09:30:13.396] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C3.dat
[09:30:13.401] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C4.dat
[09:30:13.407] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C5.dat
[09:30:13.412] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C6.dat
[09:30:13.417] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C7.dat
[09:30:13.422] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C8.dat
[09:30:13.427] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C9.dat
[09:30:13.432] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C10.dat
[09:30:13.438] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C11.dat
[09:30:13.443] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C12.dat
[09:30:13.448] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C13.dat
[09:30:13.453] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C14.dat
[09:30:13.458] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C15.dat
[09:30:13.463] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//defaultMaskFile.dat
[09:30:13.477] INFO: enter test to run
[09:30:31.662] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[09:30:31.662] INFO: running: highrate
[09:30:31.667] INFO: ----------------------------------------------------------------------
[09:30:31.667] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[09:30:31.667] INFO: ----------------------------------------------------------------------
[09:30:31.667] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[09:30:31.667] INFO: edge/corner pixel THR is adjusted
[09:30:31.667] INFO: PixTestHighRate::trimHotPixels: step 0...
[09:30:32.624] INFO: Collecting data for 1 seconds...
[09:30:33.628] INFO: Done with hot pixel readout
[09:30:37.314] INFO: PixTest:: pg_setup set to default.
[09:30:37.315] INFO: 0 hot pixels found in step 0
[09:30:37.321] INFO: 0 hot pixels could not be trimmed and have been masked.
[09:30:37.411] INFO: PixTest::trimHotPixels() done
[09:30:37.411] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C0.dat
[09:30:37.418] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C1.dat
[09:30:37.423] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C2.dat
[09:30:37.429] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C3.dat
[09:30:37.435] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C4.dat
[09:30:37.440] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C5.dat
[09:30:37.445] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C6.dat
[09:30:37.451] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C7.dat
[09:30:37.456] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C8.dat
[09:30:37.461] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C9.dat
[09:30:37.467] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C10.dat
[09:30:37.472] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C11.dat
[09:30:37.478] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C12.dat
[09:30:37.483] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C13.dat
[09:30:37.488] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C14.dat
[09:30:37.494] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C15.dat
[09:30:37.499] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-6-27_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//defaultMaskFile.dat
[09:30:37.510] INFO: enter test to run
[09:30:57.686] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[09:30:57.687] INFO: running: xray
[09:30:57.688] INFO: ----------------------------------------------------------------------
[09:30:57.688] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[09:30:57.688] INFO: ----------------------------------------------------------------------
[09:30:58.668] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[09:31:10.809] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[09:31:39.951] INFO: Resuming triggers.
[09:31:52.095] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[09:32:21.542] INFO: Resuming triggers.
[09:32:33.688] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[09:33:03.206] INFO: Resuming triggers.
[09:33:15.347] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[09:33:45.530] INFO: Resuming triggers.
[09:33:57.684] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[09:34:27.305] INFO: Resuming triggers.
[09:34:39.458] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[09:35:08.650] INFO: Resuming triggers.
[09:35:20.820] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[09:35:49.998] INFO: Resuming triggers.
[09:36:02.165] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[09:36:31.337] INFO: Resuming triggers.
[09:36:34.482] INFO: data taking finished, elapsed time: 100 seconds.
[09:36:42.355] INFO: PixTest:: pg_setup set to default.
[09:36:42.358] INFO: PixTestXray::doPhRun() done
[09:36:42.545] INFO: enter test to run
[09:37:23.884] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[09:37:23.884] INFO: running: xray
[09:37:23.885] INFO: ----------------------------------------------------------------------
[09:37:23.885] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[09:37:23.885] INFO: ----------------------------------------------------------------------
[09:37:24.849] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[09:37:32.301] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[09:38:02.412] INFO: Resuming triggers.
[09:38:09.869] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[09:38:39.971] INFO: Resuming triggers.
[09:38:47.426] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[09:39:17.524] INFO: Resuming triggers.
[09:39:24.969] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[09:39:55.042] INFO: Resuming triggers.
[09:40:02.488] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[09:40:32.579] INFO: Resuming triggers.
[09:40:40.021] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[09:41:10.130] INFO: Resuming triggers.
[09:41:17.560] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[09:41:47.701] INFO: Resuming triggers.
[09:41:55.117] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[09:42:25.276] INFO: Resuming triggers.
[09:42:32.690] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[09:43:03.599] INFO: Resuming triggers.
[09:43:10.003] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[09:43:41.336] INFO: Resuming triggers.
[09:43:48.737] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[09:44:19.360] INFO: Resuming triggers.
[09:44:26.768] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[09:44:57.434] INFO: Resuming triggers.
[09:45:04.852] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[09:45:35.638] INFO: Resuming triggers.
[09:45:39.388] INFO: data taking finished, elapsed time: 100 seconds.
[09:45:55.481] INFO: PixTest:: pg_setup set to default.
[09:45:55.485] INFO: PixTestXray::doPhRun() done
[09:45:55.635] INFO: enter test to run
[09:47:02.040] INFO: test: HighRate no parameter change
[09:47:02.040] INFO: running: highrate
[09:47:02.052] INFO: ----------------------------------------------------------------------
[09:47:02.052] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[09:47:02.052] INFO: ----------------------------------------------------------------------
[09:47:02.198] INFO: Expecting 768 events.
[09:47:03.332] INFO: 768 events read in total (419ms).
[09:47:03.332] INFO: Test took 1268ms.
[09:47:04.135] INFO: Expecting 41600 events.
[09:47:07.157] INFO: 41600 events read in total (2496ms).
[09:47:07.158] INFO: Test took 3820ms.
[09:47:07.188] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:07.922] INFO: Expecting 41600 events.
[09:47:11.127] INFO: 41600 events read in total (2678ms).
[09:47:11.128] INFO: Test took 3924ms.
[09:47:11.159] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:11.878] INFO: Expecting 41600 events.
[09:47:15.140] INFO: 41600 events read in total (2736ms).
[09:47:15.141] INFO: Test took 3965ms.
[09:47:15.172] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:15.891] INFO: Expecting 41600 events.
[09:47:19.089] INFO: 41600 events read in total (2671ms).
[09:47:19.090] INFO: Test took 3901ms.
[09:47:19.120] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:19.850] INFO: Expecting 41600 events.
[09:47:23.046] INFO: 41600 events read in total (2669ms).
[09:47:23.047] INFO: Test took 3911ms.
[09:47:23.077] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:23.806] INFO: Expecting 41600 events.
[09:47:26.996] INFO: 41600 events read in total (2663ms).
[09:47:26.997] INFO: Test took 3903ms.
[09:47:27.028] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:27.756] INFO: Expecting 41600 events.
[09:47:30.947] INFO: 41600 events read in total (2665ms).
[09:47:30.948] INFO: Test took 3903ms.
[09:47:30.979] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:31.711] INFO: Expecting 41600 events.
[09:47:34.916] INFO: 41600 events read in total (2678ms).
[09:47:34.917] INFO: Test took 3921ms.
[09:47:34.947] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:35.677] INFO: Expecting 41600 events.
[09:47:38.866] INFO: 41600 events read in total (2662ms).
[09:47:38.867] INFO: Test took 3903ms.
[09:47:38.897] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:39.630] INFO: Expecting 41600 events.
[09:47:42.822] INFO: 41600 events read in total (2666ms).
[09:47:42.823] INFO: Test took 3910ms.
[09:47:42.853] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:43.581] INFO: Expecting 41600 events.
[09:47:46.773] INFO: 41600 events read in total (2665ms).
[09:47:46.774] INFO: Test took 3904ms.
[09:47:46.805] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:47.537] INFO: Expecting 41600 events.
[09:47:50.744] INFO: 41600 events read in total (2680ms).
[09:47:50.745] INFO: Test took 3924ms.
[09:47:50.775] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:51.506] INFO: Expecting 41600 events.
[09:47:54.660] INFO: 41600 events read in total (2627ms).
[09:47:54.661] INFO: Test took 3869ms.
[09:47:54.691] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:55.425] INFO: Expecting 41600 events.
[09:47:58.615] INFO: 41600 events read in total (2663ms).
[09:47:58.616] INFO: Test took 3908ms.
[09:47:58.646] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:47:59.375] INFO: Expecting 41600 events.
[09:48:02.578] INFO: 41600 events read in total (2676ms).
[09:48:02.579] INFO: Test took 3915ms.
[09:48:02.609] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:48:03.341] INFO: Expecting 41600 events.
[09:48:06.540] INFO: 41600 events read in total (2672ms).
[09:48:06.541] INFO: Test took 3913ms.
[09:48:06.571] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:48:07.304] INFO: Expecting 41600 events.
[09:48:10.498] INFO: 41600 events read in total (2667ms).
[09:48:10.499] INFO: Test took 3910ms.
[09:48:10.529] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:48:11.261] INFO: Expecting 41600 events.
[09:48:14.447] INFO: 41600 events read in total (2659ms).
[09:48:14.448] INFO: Test took 3902ms.
[09:48:14.478] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:48:15.211] INFO: Expecting 41600 events.
[09:48:18.402] INFO: 41600 events read in total (2664ms).
[09:48:18.403] INFO: Test took 3908ms.
[09:48:18.433] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:48:19.161] INFO: Expecting 41600 events.
[09:48:22.207] INFO: 41600 events read in total (2519ms).
[09:48:22.209] INFO: Test took 3759ms.
[09:48:22.238] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:48:22.608] INFO: enter test to run
[09:48:47.439] INFO: test: HighRate no parameter change
[09:48:47.439] INFO: running: highrate
[09:48:47.440] INFO: ----------------------------------------------------------------------
[09:48:47.440] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[09:48:47.440] INFO: ----------------------------------------------------------------------
[09:48:48.057] INFO: Expecting 208000 events.
[09:48:59.707] INFO: 208000 events read in total (11123ms).
[09:48:59.710] INFO: Test took 12259ms.
[09:48:59.834] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:49:00.079] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 9 0 0 1 0 0 0 0
[09:49:00.080] INFO: number of red-efficiency pixels: 86 39 77 98 107 129 124 93 106 100 132 91 78 47 18 25
[09:49:00.080] INFO: number of X-ray hits detected: 61489 37368 59349 92917 96173 98340 91773 68784 63783 78819 82240 71901 73527 44996 18224 22007
[09:49:00.080] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[09:49:00.080] INFO: number of Vcal hits detected: 207912 207960 207922 207901 207890 207867 207873 207857 207430 207900 207864 207858 207922 207952 207982 207974
[09:49:00.080] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 100.0 99.9 99.9 100.0 99.9 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[09:49:00.080] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.7 100.0 99.9 99.9 100.0 100.0 100.0 100.0
[09:49:00.080] INFO: X-ray hit rate [MHz/cm2]: 18.0 11.0 17.4 27.2 28.2 28.8 26.9 20.2 18.7 23.1 24.1 21.1 21.6 13.2 5.3 6.5
[09:49:00.080] INFO: PixTestHighRate::doXPixelAlive() done
[09:49:00.135] INFO: PixTest:: pg_setup set to default.
[09:49:00.148] INFO: enter test to run
[09:49:26.735] INFO: test: HighRate no parameter change
[09:49:26.735] INFO: running: highrate
[09:49:26.736] INFO: ----------------------------------------------------------------------
[09:49:26.736] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[09:49:26.736] INFO: ----------------------------------------------------------------------
[09:49:27.354] INFO: Expecting 208000 events.
[09:49:40.453] INFO: 208000 events read in total (12572ms).
[09:49:40.458] INFO: Test took 13712ms.
[09:49:40.711] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:49:40.999] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 8 0 0 1 0 0 0 0
[09:49:40.999] INFO: number of red-efficiency pixels: 231 119 202 396 329 431 380 224 233 310 320 190 185 161 53 64
[09:49:40.999] INFO: number of X-ray hits detected: 128192 78608 125044 193045 200087 205814 192133 143572 133237 165436 172477 149670 153940 94328 38341 45851
[09:49:40.999] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[09:49:40.999] INFO: number of Vcal hits detected: 207751 207876 207785 207577 207644 207528 207594 207712 207302 207674 207662 207756 207812 207824 207947 207935
[09:49:40.999] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.9 99.8 99.9 99.9 99.9 100.0 100.0
[09:49:40.999] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.7 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[09:49:40.999] INFO: X-ray hit rate [MHz/cm2]: 37.6 23.0 36.7 56.6 58.6 60.3 56.3 42.1 39.1 48.5 50.6 43.9 45.1 27.6 11.2 13.4
[09:49:40.999] INFO: PixTestHighRate::doXPixelAlive() done
[09:49:41.050] INFO: PixTest:: pg_setup set to default.
[09:49:41.067] INFO: enter test to run
[09:50:14.198] INFO: test: HighRate no parameter change
[09:50:14.199] INFO: running: highrate
[09:50:14.200] INFO: ----------------------------------------------------------------------
[09:50:14.200] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[09:50:14.200] INFO: ----------------------------------------------------------------------
[09:50:14.815] INFO: Expecting 208000 events.
[09:50:29.580] INFO: 208000 events read in total (14238ms).
[09:50:29.587] INFO: Test took 15377ms.
[09:50:29.964] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:50:30.293] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 9 0 0 1 0 0 0 0
[09:50:30.293] INFO: number of red-efficiency pixels: 503 223 395 905 736 1069 889 442 517 665 745 487 465 347 73 90
[09:50:30.293] INFO: number of X-ray hits detected: 195576 119330 189998 294303 306245 312471 291485 218012 203586 251786 263561 227339 234840 143779 58514 70842
[09:50:30.293] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[09:50:30.293] INFO: number of Vcal hits detected: 207377 207766 207538 206933 207157 206664 206925 207449 206968 207265 207143 207406 207485 207598 207925 207908
[09:50:30.293] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.8 99.5 99.6 99.4 99.5 99.8 99.7 99.7 99.6 99.8 99.8 99.8 100.0 100.0
[09:50:30.293] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.8 99.5 99.6 99.4 99.5 99.7 99.5 99.6 99.6 99.7 99.8 99.8 100.0 100.0
[09:50:30.293] INFO: X-ray hit rate [MHz/cm2]: 57.3 35.0 55.7 86.3 89.8 91.6 85.4 63.9 59.7 73.8 77.3 66.6 68.8 42.1 17.2 20.8
[09:50:30.293] INFO: PixTestHighRate::doXPixelAlive() done
[09:50:30.341] INFO: PixTest:: pg_setup set to default.
[09:50:30.355] INFO: enter test to run
[09:51:01.454] INFO: test: exit no parameter change
[09:51:01.868] QUIET: Connection to board 33 closed.
[09:51:01.880] INFO: pXar: this is the end, my friend