[10:37:45.792] INFO: *** Welcome to pxar ***
[10:37:45.792] INFO: *** Today: 2016/09/12
[10:37:47.334] INFO: *** Version: v1.9.0-818-g96727
[10:37:47.334] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//dacParameters35_C15.dat
[10:37:47.676] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:37:47.676] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//defaultMaskFile.dat
[10:37:47.676] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C15.dat
[10:37:47.768] INFO: clk: 4
[10:37:47.768] INFO: ctr: 4
[10:37:47.768] INFO: sda: 19
[10:37:47.768] INFO: tin: 9
[10:37:47.768] INFO: level: 15
[10:37:47.768] INFO: triggerdelay: 0
[10:37:47.768] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[10:37:47.768] INFO: Log level: INFO
[10:37:47.782] QUIET: Connection to board DTB_WREKRL opened.
[10:37:47.786] 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:
------------------------------------------------------
[10:37:47.788] INFO: RPC call hashes of host and DTB match: 398089610
[10:37:49.323] INFO: DUT info:
[10:37:49.323] INFO: The DUT currently contains the following objects:
[10:37:49.323] INFO: 2 TBM Cores tbm08c (2 ON)
[10:37:49.323] INFO: TBM Core alpha (0): 7 registers set
[10:37:49.323] INFO: TBM Core beta (1): 7 registers set
[10:37:49.323] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[10:37:49.323] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.323] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.323] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.323] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.323] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.323] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.323] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.323] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.323] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.323] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.324] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.324] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.324] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.324] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.324] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.324] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[10:37:49.746] INFO: enter 'restricted' command line mode
[10:37:49.746] INFO: enter test to run
[10:37:53.806] INFO: test: PixelAlive no parameter change
[10:37:53.806] INFO: running: pixelalive
[10:37:53.815] INFO: ----------------------------------------------------------------------
[10:37:53.815] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[10:37:53.815] INFO: ----------------------------------------------------------------------
[10:37:54.141] INFO: Expecting 41600 events.
[10:37:58.513] INFO: 41600 events read in total (3654ms).
[10:37:58.677] INFO: Test took 4859ms.
[10:37:58.686] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:37:59.146] INFO: PixTestAlive::aliveTest() done
[10:37:59.146] INFO: number of dead pixels (per ROC): 0 0 0 1 0 1 0 2 0 0 0 0 0 0 0 0
[10:37:59.215] INFO: enter test to run
[10:38:03.862] INFO: test: timing no parameter change
[10:38:03.862] INFO: running: timing
[10:38:03.876] INFO: ######################################################################
[10:38:03.883] INFO: PixTestTiming::doTest()
[10:38:03.883] INFO: ######################################################################
[10:38:03.883] INFO: ----------------------------------------------------------------------
[10:38:03.883] INFO: PixTestTiming::TBMPhaseScan()
[10:38:03.883] INFO: ----------------------------------------------------------------------
[10:52:13.875] INFO: TBM Phase Settings: 240
[10:52:13.875] INFO: 400MHz Phase: 4
[10:52:13.875] INFO: 160MHz Phase: 7
[10:52:13.875] INFO: Functional Phase Area: 4
[10:52:13.886] INFO: Test took 850003 ms.
[10:52:13.886] INFO: PixTestTiming::TBMPhaseScan() done.
[10:52:13.886] INFO: ----------------------------------------------------------------------
[10:52:13.886] INFO: PixTestTiming::ROCDelayScan()
[10:52:13.886] INFO: ----------------------------------------------------------------------
[10:54:18.407] INFO: ROC Delay Settings: 227
[10:54:18.407] INFO: ROC Header-Trailer/Token Delay: 11
[10:54:18.407] INFO: ROC Port 0 Delay: 3
[10:54:18.407] INFO: ROC Port 1 Delay: 4
[10:54:18.407] INFO: Functional ROC Area: 5
[10:54:18.410] INFO: Test took 124524 ms.
[10:54:18.410] INFO: PixTestTiming::ROCDelayScan() done.
[10:54:18.410] INFO: ----------------------------------------------------------------------
[10:54:18.410] INFO: PixTestTiming::TimingTest()
[10:54:18.411] INFO: ----------------------------------------------------------------------
[10:54:34.576] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:54:49.568] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:55:04.567] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:55:19.558] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:55:34.528] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:55:49.496] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:56:04.492] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:56:19.468] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:56:34.448] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:56:49.448] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:56:49.829] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:56:49.848] INFO: ----------------------------------------------------------------------
[10:56:49.848] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[10:56:49.848] INFO: ----------------------------------------------------------------------
[10:56:49.848] INFO: ----------------------------------------------------------------------
[10:56:49.848] INFO: Read back bit status: 1
[10:56:49.848] INFO: ----------------------------------------------------------------------
[10:56:49.848] INFO: ----------------------------------------------------------------------
[10:56:49.848] INFO: Timings are good!
[10:56:49.848] INFO: ----------------------------------------------------------------------
[10:56:49.848] INFO: Test took 151438 ms.
[10:56:49.848] INFO: PixTestTiming::TimingTest() done.
[10:56:49.857] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//tbmParameters_C0a.dat
[10:56:49.857] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:56:49.857] INFO: PixTestTiming::doTest took 1125985 ms.
[10:56:49.857] INFO: PixTestTiming::doTest() done
[10:56:49.857] INFO: Write out TBMPhaseScan_0_V0
[10:56:49.857] INFO: Write out TBMPhaseScan_1_V0
[10:56:49.857] INFO: Write out CombinedTBMPhaseScan_V0
[10:56:49.883] INFO: Write out ROCDelayScan3_V0
[10:56:49.884] INFO: enter test to run
[10:57:13.111] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:57:13.111] INFO: running: highrate
[10:57:13.111] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:57:13.339] INFO: ----------------------------------------------------------------------
[10:57:13.339] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:57:13.339] INFO: ----------------------------------------------------------------------
[10:57:13.339] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:57:13.339] INFO: edge/corner pixel THR is adjusted
[10:57:13.339] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:57:14.298] INFO: Collecting data for 5 seconds...
[10:57:19.314] INFO: Done with hot pixel readout
[10:57:30.368] INFO: PixTest:: pg_setup set to default.
[10:57:30.368] INFO: 0 hot pixels found in step 0
[10:57:30.398] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:57:30.401] INFO: PixTest::trimHotPixels() done
[10:57:30.439] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C0.dat
[10:57:30.445] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C1.dat
[10:57:30.450] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C2.dat
[10:57:30.456] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C3.dat
[10:57:30.461] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C4.dat
[10:57:30.466] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C5.dat
[10:57:30.472] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C6.dat
[10:57:30.477] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C7.dat
[10:57:30.482] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C8.dat
[10:57:30.488] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C9.dat
[10:57:30.493] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C10.dat
[10:57:30.499] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C11.dat
[10:57:30.504] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C12.dat
[10:57:30.509] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C13.dat
[10:57:30.515] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C14.dat
[10:57:30.520] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C15.dat
[10:57:30.525] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//defaultMaskFile.dat
[10:57:30.542] INFO: enter test to run
[10:57:52.918] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:57:52.918] INFO: running: highrate
[10:57:52.923] INFO: ----------------------------------------------------------------------
[10:57:52.923] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:57:52.923] INFO: ----------------------------------------------------------------------
[10:57:52.923] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:57:52.923] INFO: edge/corner pixel THR is adjusted
[10:57:52.923] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:57:53.880] INFO: Collecting data for 1 seconds...
[10:57:54.885] INFO: Done with hot pixel readout
[10:57:58.598] INFO: PixTest:: pg_setup set to default.
[10:57:58.599] INFO: 0 hot pixels found in step 0
[10:57:58.605] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:57:58.703] INFO: PixTest::trimHotPixels() done
[10:57:58.703] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C0.dat
[10:57:58.715] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C1.dat
[10:57:58.722] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C2.dat
[10:57:58.728] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C3.dat
[10:57:58.733] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C4.dat
[10:57:58.738] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C5.dat
[10:57:58.744] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C6.dat
[10:57:58.749] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C7.dat
[10:57:58.754] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C8.dat
[10:57:58.759] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C9.dat
[10:57:58.765] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C10.dat
[10:57:58.770] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C11.dat
[10:57:58.775] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C12.dat
[10:57:58.780] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C13.dat
[10:57:58.786] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C14.dat
[10:57:58.791] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//trimParameters35_C15.dat
[10:57:58.796] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-6-19_FPIXTest-17C-FNAL-160907-1215-150V_2016-09-07_12h15m_1473268513/000_FPIXTest_p17//defaultMaskFile.dat
[10:57:58.816] INFO: enter test to run
[10:58:23.254] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:58:23.254] INFO: running: xray
[10:58:23.255] INFO: ----------------------------------------------------------------------
[10:58:23.255] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:58:23.255] INFO: ----------------------------------------------------------------------
[10:58:24.219] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:58:36.220] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[10:59:05.463] INFO: Resuming triggers.
[10:59:17.463] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[10:59:46.868] INFO: Resuming triggers.
[10:59:58.871] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[11:00:28.237] INFO: Resuming triggers.
[11:00:40.238] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[11:01:09.853] INFO: Resuming triggers.
[11:01:21.856] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[11:01:50.966] INFO: Resuming triggers.
[11:02:02.962] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[11:02:32.490] INFO: Resuming triggers.
[11:02:44.491] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[11:03:13.763] INFO: Resuming triggers.
[11:03:25.769] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[11:03:54.908] INFO: Resuming triggers.
[11:03:59.247] INFO: data taking finished, elapsed time: 100 seconds.
[11:04:10.408] INFO: PixTest:: pg_setup set to default.
[11:04:10.411] INFO: PixTestXray::doPhRun() done
[11:04:10.611] INFO: enter test to run
[11:04:46.844] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:04:46.844] INFO: running: xray
[11:04:46.845] INFO: ----------------------------------------------------------------------
[11:04:46.845] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:04:46.845] INFO: ----------------------------------------------------------------------
[11:04:47.808] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:04:55.284] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[11:05:25.889] INFO: Resuming triggers.
[11:05:33.374] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[11:06:01.647] INFO: Resuming triggers.
[11:06:09.128] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[11:06:39.536] INFO: Resuming triggers.
[11:06:47.019] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[11:07:17.387] INFO: Resuming triggers.
[11:07:24.867] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[11:07:56.104] INFO: Resuming triggers.
[11:08:03.591] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[11:08:34.722] INFO: Resuming triggers.
[11:08:42.204] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[11:09:11.826] INFO: Resuming triggers.
[11:09:19.308] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[11:09:49.506] INFO: Resuming triggers.
[11:09:56.989] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[11:10:27.084] INFO: Resuming triggers.
[11:10:34.571] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[11:11:04.724] INFO: Resuming triggers.
[11:11:12.204] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[11:11:42.457] INFO: Resuming triggers.
[11:11:49.943] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[11:12:20.046] INFO: Resuming triggers.
[11:12:27.535] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[11:12:57.704] INFO: Resuming triggers.
[11:13:00.761] INFO: data taking finished, elapsed time: 100 seconds.
[11:13:13.390] INFO: PixTest:: pg_setup set to default.
[11:13:13.394] INFO: PixTestXray::doPhRun() done
[11:13:13.559] INFO: enter test to run
[11:13:38.223] INFO: test: HighRate no parameter change
[11:13:38.223] INFO: running: highrate
[11:13:38.257] INFO: ----------------------------------------------------------------------
[11:13:38.257] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:13:38.257] INFO: ----------------------------------------------------------------------
[11:13:38.414] INFO: Expecting 768 events.
[11:13:39.548] INFO: 768 events read in total (419ms).
[11:13:39.549] INFO: Test took 1270ms.
[11:13:40.352] INFO: Expecting 41600 events.
[11:13:43.399] INFO: 41600 events read in total (2520ms).
[11:13:43.400] INFO: Test took 3807ms.
[11:13:43.430] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:44.167] INFO: Expecting 41600 events.
[11:13:47.335] INFO: 41600 events read in total (2641ms).
[11:13:47.336] INFO: Test took 3889ms.
[11:13:47.365] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:48.098] INFO: Expecting 41600 events.
[11:13:51.275] INFO: 41600 events read in total (2650ms).
[11:13:51.276] INFO: Test took 3893ms.
[11:13:51.306] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:52.040] INFO: Expecting 41600 events.
[11:13:55.290] INFO: 41600 events read in total (2723ms).
[11:13:55.291] INFO: Test took 3968ms.
[11:13:55.321] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:56.047] INFO: Expecting 41600 events.
[11:13:59.363] INFO: 41600 events read in total (2767ms).
[11:13:59.364] INFO: Test took 4027ms.
[11:13:59.401] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:00.125] INFO: Expecting 41600 events.
[11:14:03.333] INFO: 41600 events read in total (2681ms).
[11:14:03.333] INFO: Test took 3916ms.
[11:14:03.366] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:04.092] INFO: Expecting 41600 events.
[11:14:07.306] INFO: 41600 events read in total (2687ms).
[11:14:07.307] INFO: Test took 3925ms.
[11:14:07.338] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:08.068] INFO: Expecting 41600 events.
[11:14:11.276] INFO: 41600 events read in total (2681ms).
[11:14:11.278] INFO: Test took 3924ms.
[11:14:11.309] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:12.034] INFO: Expecting 41600 events.
[11:14:15.263] INFO: 41600 events read in total (2702ms).
[11:14:15.264] INFO: Test took 3939ms.
[11:14:15.295] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:16.025] INFO: Expecting 41600 events.
[11:14:19.243] INFO: 41600 events read in total (2691ms).
[11:14:19.244] INFO: Test took 3933ms.
[11:14:19.274] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:19.003] INFO: Expecting 41600 events.
[11:14:23.249] INFO: 41600 events read in total (2719ms).
[11:14:23.250] INFO: Test took 3958ms.
[11:14:23.281] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:24.009] INFO: Expecting 41600 events.
[11:14:27.260] INFO: 41600 events read in total (2724ms).
[11:14:27.261] INFO: Test took 3964ms.
[11:14:27.291] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:28.020] INFO: Expecting 41600 events.
[11:14:31.352] INFO: 41600 events read in total (2805ms).
[11:14:31.353] INFO: Test took 4046ms.
[11:14:31.383] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:32.110] INFO: Expecting 41600 events.
[11:14:35.328] INFO: 41600 events read in total (2691ms).
[11:14:35.329] INFO: Test took 3928ms.
[11:14:35.361] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:36.090] INFO: Expecting 41600 events.
[11:14:39.336] INFO: 41600 events read in total (2719ms).
[11:14:39.337] INFO: Test took 3960ms.
[11:14:39.368] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:40.095] INFO: Expecting 41600 events.
[11:14:43.292] INFO: 41600 events read in total (2670ms).
[11:14:43.293] INFO: Test took 3907ms.
[11:14:43.323] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:44.051] INFO: Expecting 41600 events.
[11:14:47.202] INFO: 41600 events read in total (2624ms).
[11:14:47.203] INFO: Test took 3863ms.
[11:14:47.233] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:47.961] INFO: Expecting 41600 events.
[11:14:51.102] INFO: 41600 events read in total (2614ms).
[11:14:51.103] INFO: Test took 3853ms.
[11:14:51.143] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:51.854] INFO: Expecting 41600 events.
[11:14:54.788] INFO: 41600 events read in total (2407ms).
[11:14:54.938] INFO: Test took 3779ms.
[11:14:54.969] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:55.598] INFO: Expecting 41600 events.
[11:14:58.396] INFO: 41600 events read in total (2271ms).
[11:14:58.397] INFO: Test took 3411ms.
[11:14:58.427] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:58.800] INFO: enter test to run
[11:15:05.679] INFO: test: HighRate no parameter change
[11:15:05.679] INFO: running: highrate
[11:15:05.681] INFO: ----------------------------------------------------------------------
[11:15:05.681] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:15:05.681] INFO: ----------------------------------------------------------------------
[11:15:06.381] INFO: Expecting 208000 events.
[11:15:17.898] INFO: 208000 events read in total (10990ms).
[11:15:17.901] INFO: Test took 12128ms.
[11:15:18.026] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:18.273] INFO: number of dead pixels (per ROC): 0 0 0 1 0 1 0 2 0 0 0 0 0 0 0 0
[11:15:18.273] INFO: number of red-efficiency pixels: 78 30 83 96 124 135 126 85 83 102 92 92 101 64 30 21
[11:15:18.273] INFO: number of X-ray hits detected: 58222 37629 60350 89112 93953 96914 94920 66277 65411 83392 80665 70858 72687 45562 17898 25188
[11:15:18.273] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:15:18.273] INFO: number of Vcal hits detected: 207918 207970 207915 207854 207874 207815 207872 207817 207917 207896 207907 207907 207897 207935 207968 207979
[11:15:18.273] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[11:15:18.273] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[11:15:18.273] INFO: X-ray hit rate [MHz/cm2]: 17.1 11.0 17.7 26.1 27.5 28.4 27.8 19.4 19.2 24.4 23.6 20.8 21.3 13.4 5.2 7.4
[11:15:18.273] INFO: PixTestHighRate::doXPixelAlive() done
[11:15:18.318] INFO: PixTest:: pg_setup set to default.
[11:15:18.327] INFO: enter test to run
[11:15:40.623] INFO: test: HighRate no parameter change
[11:15:40.623] INFO: running: highrate
[11:15:40.624] INFO: ----------------------------------------------------------------------
[11:15:40.625] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:15:40.625] INFO: ----------------------------------------------------------------------
[11:15:41.238] INFO: Expecting 208000 events.
[11:15:54.188] INFO: 208000 events read in total (12417ms).
[11:15:54.193] INFO: Test took 13560ms.
[11:15:54.441] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:54.725] INFO: number of dead pixels (per ROC): 0 0 0 1 0 1 0 2 0 0 0 0 0 0 0 0
[11:15:54.726] INFO: number of red-efficiency pixels: 190 110 229 272 372 437 366 197 184 302 245 242 250 138 44 56
[11:15:54.726] INFO: number of X-ray hits detected: 117118 76021 121740 179705 188805 195007 190505 133405 131350 168637 162368 143648 146146 91713 36111 51036
[11:15:54.726] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:15:54.726] INFO: number of Vcal hits detected: 207801 207883 207756 207652 207601 207468 207601 207684 207809 207678 207745 207744 207740 207855 207955 207943
[11:15:54.726] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.9 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[11:15:54.726] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.7 99.8 99.8 99.9 99.8 99.9 99.9 99.9 99.9 100.0 100.0
[11:15:54.726] INFO: X-ray hit rate [MHz/cm2]: 34.3 22.3 35.7 52.7 55.3 57.2 55.8 39.1 38.5 49.4 47.6 42.1 42.8 26.9 10.6 15.0
[11:15:54.726] INFO: PixTestHighRate::doXPixelAlive() done
[11:15:54.778] INFO: PixTest:: pg_setup set to default.
[11:15:54.789] INFO: enter test to run
[11:16:11.639] INFO: test: HighRate no parameter change
[11:16:11.639] INFO: running: highrate
[11:16:11.640] INFO: ----------------------------------------------------------------------
[11:16:11.640] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:16:11.640] INFO: ----------------------------------------------------------------------
[11:16:12.250] INFO: Expecting 208000 events.
[11:16:27.020] INFO: 208000 events read in total (14243ms).
[11:16:27.026] INFO: Test took 15377ms.
[11:16:27.401] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:16:27.727] INFO: number of dead pixels (per ROC): 0 0 0 1 0 1 0 2 0 0 0 0 0 0 0 0
[11:16:27.727] INFO: number of red-efficiency pixels: 427 214 523 623 918 929 906 479 434 725 510 534 546 356 71 89
[11:16:27.727] INFO: number of X-ray hits detected: 177416 114413 185431 271491 287873 296178 290270 202851 199983 257174 246320 218312 222206 139670 55614 77728
[11:16:27.727] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:16:27.727] INFO: number of Vcal hits detected: 207518 207770 207342 207236 206922 206802 206897 207341 207535 207165 207450 207393 207389 207589 207928 207907
[11:16:27.727] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.7 99.5 99.5 99.5 99.8 99.8 99.6 99.8 99.7 99.7 99.8 100.0 100.0
[11:16:27.727] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.6 99.5 99.4 99.5 99.7 99.8 99.6 99.7 99.7 99.7 99.8 100.0 100.0
[11:16:27.727] INFO: X-ray hit rate [MHz/cm2]: 52.0 33.5 54.4 79.6 84.4 86.8 85.1 59.5 58.6 75.4 72.2 64.0 65.1 40.9 16.3 22.8
[11:16:27.727] INFO: PixTestHighRate::doXPixelAlive() done
[11:16:27.774] INFO: PixTest:: pg_setup set to default.
[11:16:27.789] INFO: enter test to run
[11:16:47.742] INFO: test: exit no parameter change
[11:16:49.403] QUIET: Connection to board 33 closed.
[11:16:49.732] INFO: pXar: this is the end, my friend