[09:59:17.550] INFO: *** Welcome to pxar ***
[09:59:17.550] INFO: *** Today: 2016/09/23
[09:59:17.567] INFO: *** Version: v1.9.0-818-g96727
[09:59:17.567] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//dacParameters35_C15.dat
[09:59:17.568] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:59:17.568] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//defaultMaskFile.dat
[09:59:17.568] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C15.dat
[09:59:17.643] INFO: clk: 4
[09:59:17.643] INFO: ctr: 4
[09:59:17.643] INFO: sda: 19
[09:59:17.643] INFO: tin: 9
[09:59:17.643] INFO: level: 15
[09:59:17.643] INFO: triggerdelay: 0
[09:59:17.643] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[09:59:17.643] INFO: Log level: INFO
[09:59:17.661] QUIET: Connection to board DTB_WREKRL opened.
[09:59:17.665] 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:59:17.668] INFO: RPC call hashes of host and DTB match: 398089610
[09:59:19.213] INFO: DUT info:
[09:59:19.213] INFO: The DUT currently contains the following objects:
[09:59:19.213] INFO: 2 TBM Cores tbm08c (2 ON)
[09:59:19.213] INFO: TBM Core alpha (0): 7 registers set
[09:59:19.213] INFO: TBM Core beta (1): 7 registers set
[09:59:19.213] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[09:59:19.213] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.213] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.213] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.213] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.213] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.213] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.213] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.213] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.213] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.213] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.214] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.214] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.214] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.214] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.214] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.214] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:19.645] INFO: enter 'restricted' command line mode
[09:59:19.645] INFO: enter test to run
[09:59:28.671] INFO: test: PixelAlive no parameter change
[09:59:28.671] INFO: running: pixelalive
[09:59:28.715] INFO: ----------------------------------------------------------------------
[09:59:28.715] 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:59:28.715] INFO: ----------------------------------------------------------------------
[09:59:29.034] INFO: Expecting 41600 events.
[09:59:33.362] INFO: 41600 events read in total (3610ms).
[09:59:33.527] INFO: Test took 4808ms.
[09:59:33.542] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:33.850] INFO: PixTestAlive::aliveTest() done
[09:59:33.850] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1
[09:59:33.913] INFO: enter test to run
[09:59:41.311] INFO: test: timing no parameter change
[09:59:41.311] INFO: running: timing
[09:59:41.314] INFO: ######################################################################
[09:59:41.314] INFO: PixTestTiming::doTest()
[09:59:41.314] INFO: ######################################################################
[09:59:41.314] INFO: ----------------------------------------------------------------------
[09:59:41.314] INFO: PixTestTiming::TBMPhaseScan()
[09:59:41.314] INFO: ----------------------------------------------------------------------
[10:07:15.965] INFO: TBM Phase Settings: 248
[10:07:15.965] INFO: 400MHz Phase: 6
[10:07:15.965] INFO: 160MHz Phase: 7
[10:07:15.965] INFO: Functional Phase Area: 5
[10:07:15.985] INFO: Test took 454671 ms.
[10:07:15.985] INFO: PixTestTiming::TBMPhaseScan() done.
[10:07:15.986] INFO: ----------------------------------------------------------------------
[10:07:15.986] INFO: PixTestTiming::ROCDelayScan()
[10:07:15.986] INFO: ----------------------------------------------------------------------
[10:09:23.893] INFO: ROC Delay Settings: 228
[10:09:23.893] INFO: ROC Header-Trailer/Token Delay: 11
[10:09:23.893] INFO: ROC Port 0 Delay: 4
[10:09:23.893] INFO: ROC Port 1 Delay: 4
[10:09:23.893] INFO: Functional ROC Area: 5
[10:09:23.896] INFO: Test took 127911 ms.
[10:09:23.896] INFO: PixTestTiming::ROCDelayScan() done.
[10:09:23.896] INFO: ----------------------------------------------------------------------
[10:09:23.896] INFO: PixTestTiming::TimingTest()
[10:09:23.897] INFO: ----------------------------------------------------------------------
[10:09:40.039] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:09:55.012] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:09.872] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:24.738] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:39.669] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:54.629] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:09.536] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:24.450] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:39.400] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:54.225] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:54.607] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:54.625] INFO: ----------------------------------------------------------------------
[10:11:54.625] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[10:11:54.625] INFO: ----------------------------------------------------------------------
[10:11:54.625] INFO: ----------------------------------------------------------------------
[10:11:54.625] INFO: Read back bit status: 1
[10:11:54.625] INFO: ----------------------------------------------------------------------
[10:11:54.625] INFO: ----------------------------------------------------------------------
[10:11:54.625] INFO: Timings are good!
[10:11:54.625] INFO: ----------------------------------------------------------------------
[10:11:54.625] INFO: Test took 150729 ms.
[10:11:54.625] INFO: PixTestTiming::TimingTest() done.
[10:11:54.631] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0a.dat
[10:11:54.632] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:11:54.632] INFO: PixTestTiming::doTest took 733321 ms.
[10:11:54.632] INFO: PixTestTiming::doTest() done
[10:11:54.632] INFO: Write out TBMPhaseScan_0_V0
[10:11:54.632] INFO: Write out TBMPhaseScan_1_V0
[10:11:54.632] INFO: Write out CombinedTBMPhaseScan_V0
[10:11:54.654] INFO: Write out ROCDelayScan3_V0
[10:11:54.655] INFO: enter test to run
[10:12:38.154] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:12:38.154] INFO: running: highrate
[10:12:38.174] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:12:38.357] INFO: ----------------------------------------------------------------------
[10:12:38.357] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:12:38.357] INFO: ----------------------------------------------------------------------
[10:12:38.357] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:12:38.357] INFO: edge/corner pixel THR is adjusted
[10:12:38.357] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:12:39.315] INFO: Collecting data for 5 seconds...
[10:12:44.331] INFO: Done with hot pixel readout
[10:12:55.709] INFO: PixTest:: pg_setup set to default.
[10:12:55.710] INFO: 0 hot pixels found in step 0
[10:12:55.745] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:12:55.748] INFO: PixTest::trimHotPixels() done
[10:12:55.748] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C0.dat
[10:12:55.753] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C1.dat
[10:12:55.760] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C2.dat
[10:12:55.766] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C3.dat
[10:12:55.772] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C4.dat
[10:12:55.777] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C5.dat
[10:12:55.782] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C6.dat
[10:12:55.787] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C7.dat
[10:12:55.793] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C8.dat
[10:12:55.817] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C9.dat
[10:12:55.828] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C10.dat
[10:12:55.834] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C11.dat
[10:12:55.839] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C12.dat
[10:12:55.844] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C13.dat
[10:12:55.850] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C14.dat
[10:12:55.855] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C15.dat
[10:12:55.861] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//defaultMaskFile.dat
[10:12:55.879] INFO: enter test to run
[10:13:38.633] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:13:38.633] INFO: running: highrate
[10:13:38.638] INFO: ----------------------------------------------------------------------
[10:13:38.638] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:13:38.638] INFO: ----------------------------------------------------------------------
[10:13:38.638] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:13:38.638] INFO: edge/corner pixel THR is adjusted
[10:13:38.638] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:13:39.596] INFO: Collecting data for 1 seconds...
[10:13:40.600] INFO: Done with hot pixel readout
[10:13:44.480] INFO: PixTest:: pg_setup set to default.
[10:13:44.481] INFO: 0 hot pixels found in step 0
[10:13:44.486] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:13:44.578] INFO: PixTest::trimHotPixels() done
[10:13:44.578] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C0.dat
[10:13:44.585] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C1.dat
[10:13:44.591] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C2.dat
[10:13:44.597] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C3.dat
[10:13:44.602] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C4.dat
[10:13:44.608] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C5.dat
[10:13:44.613] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C6.dat
[10:13:44.618] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C7.dat
[10:13:44.624] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C8.dat
[10:13:44.629] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C9.dat
[10:13:44.635] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C10.dat
[10:13:44.650] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C11.dat
[10:13:44.655] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C12.dat
[10:13:44.661] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C13.dat
[10:13:44.666] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C14.dat
[10:13:44.671] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C15.dat
[10:13:44.677] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-9-33_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//defaultMaskFile.dat
[10:13:44.688] INFO: enter test to run
[10:14:01.057] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:14:01.057] INFO: running: xray
[10:14:01.058] INFO: ----------------------------------------------------------------------
[10:14:01.058] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:14:01.059] INFO: ----------------------------------------------------------------------
[10:14:02.033] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:14:13.815] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[10:14:43.503] INFO: Resuming triggers.
[10:14:55.288] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[10:15:24.103] INFO: Resuming triggers.
[10:15:35.894] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[10:16:05.029] INFO: Resuming triggers.
[10:16:16.819] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[10:16:47.181] INFO: Resuming triggers.
[10:16:58.969] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[10:17:29.160] INFO: Resuming triggers.
[10:17:40.946] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[10:18:10.717] INFO: Resuming triggers.
[10:18:22.506] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[10:18:51.993] INFO: Resuming triggers.
[10:19:03.782] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[10:19:33.315] INFO: Resuming triggers.
[10:19:39.376] INFO: data taking finished, elapsed time: 100 seconds.
[10:19:54.863] INFO: PixTest:: pg_setup set to default.
[10:19:54.866] INFO: PixTestXray::doPhRun() done
[10:19:55.034] INFO: enter test to run
[10:20:33.063] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[10:20:33.063] INFO: running: xray
[10:20:33.064] INFO: ----------------------------------------------------------------------
[10:20:33.064] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:20:33.064] INFO: ----------------------------------------------------------------------
[10:20:34.039] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:20:40.965] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[10:21:11.319] INFO: Resuming triggers.
[10:21:18.242] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[10:21:48.607] INFO: Resuming triggers.
[10:21:55.531] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[10:22:25.774] INFO: Resuming triggers.
[10:22:32.698] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[10:23:03.101] INFO: Resuming triggers.
[10:23:10.028] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[10:23:40.364] INFO: Resuming triggers.
[10:23:47.285] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[10:24:17.655] INFO: Resuming triggers.
[10:24:24.574] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[10:24:54.860] INFO: Resuming triggers.
[10:25:01.778] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[10:25:32.167] INFO: Resuming triggers.
[10:25:39.086] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[10:26:10.161] INFO: Resuming triggers.
[10:26:17.079] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[10:26:48.105] INFO: Resuming triggers.
[10:26:55.022] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[10:27:26.256] INFO: Resuming triggers.
[10:27:33.175] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[10:28:03.791] INFO: Resuming triggers.
[10:28:10.711] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[10:28:42.502] INFO: Resuming triggers.
[10:28:49.425] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[10:29:20.726] INFO: Resuming triggers.
[10:29:24.170] INFO: data taking finished, elapsed time: 100 seconds.
[10:29:40.065] INFO: PixTest:: pg_setup set to default.
[10:29:40.069] INFO: PixTestXray::doPhRun() done
[10:29:40.220] INFO: enter test to run
[10:30:55.090] INFO: test: HighRate no parameter change
[10:30:55.090] INFO: running: highrate
[10:30:55.108] INFO: ----------------------------------------------------------------------
[10:30:55.108] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[10:30:55.108] INFO: ----------------------------------------------------------------------
[10:30:55.263] INFO: Expecting 768 events.
[10:30:56.397] INFO: 768 events read in total (418ms).
[10:30:56.397] INFO: Test took 1269ms.
[10:30:57.201] INFO: Expecting 41600 events.
[10:31:00.323] INFO: 41600 events read in total (2595ms).
[10:31:00.324] INFO: Test took 3920ms.
[10:31:00.356] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:01.087] INFO: Expecting 41600 events.
[10:31:04.305] INFO: 41600 events read in total (2691ms).
[10:31:04.306] INFO: Test took 3932ms.
[10:31:04.338] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:05.064] INFO: Expecting 41600 events.
[10:31:08.303] INFO: 41600 events read in total (2713ms).
[10:31:08.304] INFO: Test took 3947ms.
[10:31:08.337] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:09.063] INFO: Expecting 41600 events.
[10:31:12.284] INFO: 41600 events read in total (2694ms).
[10:31:12.285] INFO: Test took 3932ms.
[10:31:12.318] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:13.041] INFO: Expecting 41600 events.
[10:31:16.270] INFO: 41600 events read in total (2702ms).
[10:31:16.271] INFO: Test took 3936ms.
[10:31:16.304] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:17.030] INFO: Expecting 41600 events.
[10:31:20.258] INFO: 41600 events read in total (2701ms).
[10:31:20.259] INFO: Test took 3937ms.
[10:31:20.291] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:21.021] INFO: Expecting 41600 events.
[10:31:24.239] INFO: 41600 events read in total (2691ms).
[10:31:24.240] INFO: Test took 3932ms.
[10:31:24.272] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:24.999] INFO: Expecting 41600 events.
[10:31:28.234] INFO: 41600 events read in total (2708ms).
[10:31:28.235] INFO: Test took 3946ms.
[10:31:28.267] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:28.994] INFO: Expecting 41600 events.
[10:31:32.217] INFO: 41600 events read in total (2697ms).
[10:31:32.218] INFO: Test took 3933ms.
[10:31:32.251] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:32.976] INFO: Expecting 41600 events.
[10:31:36.201] INFO: 41600 events read in total (2698ms).
[10:31:36.201] INFO: Test took 3933ms.
[10:31:36.233] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:36.958] INFO: Expecting 41600 events.
[10:31:40.175] INFO: 41600 events read in total (2690ms).
[10:31:40.176] INFO: Test took 3925ms.
[10:31:40.209] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:40.935] INFO: Expecting 41600 events.
[10:31:44.180] INFO: 41600 events read in total (2718ms).
[10:31:44.181] INFO: Test took 3954ms.
[10:31:44.215] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:44.938] INFO: Expecting 41600 events.
[10:31:48.047] INFO: 41600 events read in total (2582ms).
[10:31:48.048] INFO: Test took 3815ms.
[10:31:48.080] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:48.806] INFO: Expecting 41600 events.
[10:31:52.040] INFO: 41600 events read in total (2708ms).
[10:31:52.041] INFO: Test took 3942ms.
[10:31:52.074] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:52.798] INFO: Expecting 41600 events.
[10:31:56.018] INFO: 41600 events read in total (2693ms).
[10:31:56.019] INFO: Test took 3928ms.
[10:31:56.051] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:56.781] INFO: Expecting 41600 events.
[10:32:00.012] INFO: 41600 events read in total (2704ms).
[10:32:00.013] INFO: Test took 3945ms.
[10:32:00.046] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:32:00.770] INFO: Expecting 41600 events.
[10:32:03.005] INFO: 41600 events read in total (2708ms).
[10:32:03.006] INFO: Test took 3943ms.
[10:32:04.038] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:32:04.762] INFO: Expecting 41600 events.
[10:32:07.977] INFO: 41600 events read in total (2688ms).
[10:32:07.978] INFO: Test took 3922ms.
[10:32:08.011] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:32:08.735] INFO: Expecting 41600 events.
[10:32:11.892] INFO: 41600 events read in total (2630ms).
[10:32:11.893] INFO: Test took 3863ms.
[10:32:11.925] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:32:12.656] INFO: Expecting 41600 events.
[10:32:15.678] INFO: 41600 events read in total (2496ms).
[10:32:15.679] INFO: Test took 3736ms.
[10:32:15.710] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:32:16.080] INFO: enter test to run
[10:32:31.386] INFO: test: HighRate no parameter change
[10:32:31.386] INFO: running: highrate
[10:32:31.387] INFO: ----------------------------------------------------------------------
[10:32:31.387] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:32:31.387] INFO: ----------------------------------------------------------------------
[10:32:31.001] INFO: Expecting 208000 events.
[10:32:43.760] INFO: 208000 events read in total (11232ms).
[10:32:43.763] INFO: Test took 12366ms.
[10:32:43.898] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:32:44.148] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1
[10:32:44.148] INFO: number of red-efficiency pixels: 91 41 82 101 120 156 146 84 93 140 134 107 91 89 23 25
[10:32:44.148] INFO: number of X-ray hits detected: 63365 38400 61685 88896 100249 104280 106967 69144 73610 99117 99015 86257 87908 54749 20603 23927
[10:32:44.148] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:32:44.148] INFO: number of Vcal hits detected: 207908 207959 207918 207897 207876 207840 207846 207912 207907 207859 207863 207891 207908 207909 207977 207926
[10:32:44.148] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[10:32:44.149] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0
[10:32:44.149] INFO: X-ray hit rate [MHz/cm2]: 18.6 11.3 18.1 26.1 29.4 30.6 31.4 20.3 21.6 29.1 29.0 25.3 25.8 16.0 6.0 7.0
[10:32:44.149] INFO: PixTestHighRate::doXPixelAlive() done
[10:32:44.194] INFO: PixTest:: pg_setup set to default.
[10:32:44.204] INFO: enter test to run
[10:33:05.489] INFO: test: HighRate no parameter change
[10:33:05.489] INFO: running: highrate
[10:33:05.490] INFO: ----------------------------------------------------------------------
[10:33:05.490] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:33:05.490] INFO: ----------------------------------------------------------------------
[10:33:06.104] INFO: Expecting 208000 events.
[10:33:19.341] INFO: 208000 events read in total (12711ms).
[10:33:19.346] INFO: Test took 13847ms.
[10:33:19.611] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:33:19.903] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1
[10:33:19.903] INFO: number of red-efficiency pixels: 228 116 255 298 355 415 417 256 200 419 376 271 331 201 52 55
[10:33:19.903] INFO: number of X-ray hits detected: 125418 76527 121830 177219 198137 204452 211113 136924 147246 196695 196095 170195 174145 107777 40811 47612
[10:33:19.903] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:33:19.903] INFO: number of Vcal hits detected: 207756 207880 207725 207690 207629 207555 207557 207730 207794 207550 207598 207708 207652 207790 207947 207893
[10:33:19.903] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.9 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[10:33:19.903] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.9 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 99.9
[10:33:19.903] INFO: X-ray hit rate [MHz/cm2]: 36.8 22.4 35.7 51.9 58.1 59.9 61.9 40.1 43.2 57.7 57.5 49.9 51.0 31.6 12.0 14.0
[10:33:19.903] INFO: PixTestHighRate::doXPixelAlive() done
[10:33:19.952] INFO: PixTest:: pg_setup set to default.
[10:33:19.971] INFO: enter test to run
[10:33:34.113] INFO: test: HighRate no parameter change
[10:33:34.113] INFO: running: highrate
[10:33:34.114] INFO: ----------------------------------------------------------------------
[10:33:34.114] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:33:34.115] INFO: ----------------------------------------------------------------------
[10:33:34.727] INFO: Expecting 208000 events.
[10:33:49.720] INFO: 208000 events read in total (14466ms).
[10:33:49.727] INFO: Test took 15603ms.
[10:33:50.143] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:33:50.480] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1
[10:33:50.480] INFO: number of red-efficiency pixels: 504 225 575 724 965 966 981 568 463 969 959 565 786 500 95 94
[10:33:50.480] INFO: number of X-ray hits detected: 192503 117202 187384 271225 304161 314924 324579 208829 226063 299747 299661 260899 266937 166501 63420 73755
[10:33:50.480] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:33:50.480] INFO: number of Vcal hits detected: 207397 207756 207272 207175 206816 206814 206757 207322 207463 206836 206850 207357 207096 207385 207903 207851
[10:33:50.480] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.7 99.6 99.5 99.5 99.5 99.7 99.8 99.5 99.5 99.7 99.6 99.7 100.0 100.0
[10:33:50.480] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.6 99.4 99.4 99.4 99.7 99.7 99.4 99.4 99.7 99.6 99.7 100.0 99.9
[10:33:50.480] INFO: X-ray hit rate [MHz/cm2]: 56.4 34.4 54.9 79.5 89.2 92.3 95.1 61.2 66.3 87.9 87.8 76.5 78.2 48.8 18.6 21.6
[10:33:50.480] INFO: PixTestHighRate::doXPixelAlive() done
[10:33:50.527] INFO: PixTest:: pg_setup set to default.
[10:33:50.540] INFO: enter test to run
[10:34:02.297] INFO: test: exit no parameter change
[10:34:02.774] QUIET: Connection to board 33 closed.
[10:34:02.787] INFO: pXar: this is the end, my friend