[18:27:33.041] INFO: *** Welcome to pxar ***
[18:27:33.041] INFO: *** Today: 2016/09/29
[18:27:33.079] INFO: *** Version: v1.9.0-818-g96727
[18:27:33.079] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//dacParameters35_C15.dat
[18:27:33.335] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//tbmParameters_C0b.dat
[18:27:33.336] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//defaultMaskFile.dat
[18:27:33.388] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C15.dat
[18:27:34.502] INFO: clk: 4
[18:27:34.502] INFO: ctr: 4
[18:27:34.502] INFO: sda: 19
[18:27:34.502] INFO: tin: 9
[18:27:34.502] INFO: level: 15
[18:27:34.502] INFO: triggerdelay: 0
[18:27:34.502] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[18:27:34.502] INFO: Log level: INFO
[18:27:34.518] QUIET: Connection to board DTB_WREKRL opened.
[18:27:34.521] 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:
------------------------------------------------------
[18:27:34.524] INFO: RPC call hashes of host and DTB match: 398089610
[18:27:36.057] INFO: DUT info:
[18:27:36.057] INFO: The DUT currently contains the following objects:
[18:27:36.057] INFO: 2 TBM Cores tbm08c (2 ON)
[18:27:36.057] INFO: TBM Core alpha (0): 7 registers set
[18:27:36.057] INFO: TBM Core beta (1): 7 registers set
[18:27:36.057] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[18:27:36.057] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.057] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.057] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.057] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.058] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[18:27:36.486] INFO: enter 'restricted' command line mode
[18:27:36.486] INFO: enter test to run
[18:27:43.505] INFO: test: PixelAlive no parameter change
[18:27:43.505] INFO: running: pixelalive
[18:27:43.513] INFO: ----------------------------------------------------------------------
[18:27:43.513] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[18:27:43.513] INFO: ----------------------------------------------------------------------
[18:27:43.836] INFO: Expecting 41600 events.
[18:27:48.064] INFO: 41600 events read in total (3509ms).
[18:27:48.222] INFO: Test took 4705ms.
[18:27:48.232] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:27:48.493] INFO: PixTestAlive::aliveTest() done
[18:27:48.493] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[18:27:48.526] INFO: enter test to run
[18:27:54.584] INFO: test: timing no parameter change
[18:27:54.584] INFO: running: timing
[18:27:54.608] INFO: ######################################################################
[18:27:54.608] INFO: PixTestTiming::doTest()
[18:27:54.608] INFO: ######################################################################
[18:27:54.608] INFO: ----------------------------------------------------------------------
[18:27:54.608] INFO: PixTestTiming::TBMPhaseScan()
[18:27:54.608] INFO: ----------------------------------------------------------------------
[18:32:24.051] INFO: TBM Phase Settings: 232
[18:32:24.071] INFO: 400MHz Phase: 2
[18:32:24.071] INFO: 160MHz Phase: 7
[18:32:24.071] INFO: Functional Phase Area: 4
[18:32:24.093] INFO: Test took 269485 ms.
[18:32:24.094] INFO: PixTestTiming::TBMPhaseScan() done.
[18:32:24.094] INFO: ----------------------------------------------------------------------
[18:32:24.094] INFO: PixTestTiming::ROCDelayScan()
[18:32:24.094] INFO: ----------------------------------------------------------------------
[18:34:58.739] INFO: ROC Delay Settings: 228
[18:34:58.739] INFO: ROC Header-Trailer/Token Delay: 11
[18:34:58.739] INFO: ROC Port 0 Delay: 4
[18:34:58.739] INFO: ROC Port 1 Delay: 4
[18:34:58.739] INFO: Functional ROC Area: 3
[18:34:58.742] INFO: Test took 154648 ms.
[18:34:58.742] INFO: PixTestTiming::ROCDelayScan() done.
[18:34:58.742] INFO: ----------------------------------------------------------------------
[18:34:58.742] INFO: PixTestTiming::TimingTest()
[18:34:58.742] INFO: ----------------------------------------------------------------------
[18:35:14.452] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:35:29.399] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:35:44.395] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:35:59.337] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:36:14.309] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:36:29.302] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:36:44.297] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:36:59.297] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:37:14.299] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:37:29.299] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:37:29.677] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:37:29.694] INFO: ----------------------------------------------------------------------
[18:37:29.694] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[18:37:29.694] INFO: ----------------------------------------------------------------------
[18:37:29.694] INFO: ----------------------------------------------------------------------
[18:37:29.694] INFO: Read back bit status: 1
[18:37:29.694] INFO: ----------------------------------------------------------------------
[18:37:29.694] INFO: ----------------------------------------------------------------------
[18:37:29.694] INFO: Timings are good!
[18:37:29.694] INFO: ----------------------------------------------------------------------
[18:37:29.694] INFO: Test took 150952 ms.
[18:37:29.694] INFO: PixTestTiming::TimingTest() done.
[18:37:29.737] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//tbmParameters_C0a.dat
[18:37:29.737] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//tbmParameters_C0b.dat
[18:37:29.737] INFO: PixTestTiming::doTest took 575132 ms.
[18:37:29.737] INFO: PixTestTiming::doTest() done
[18:37:29.738] INFO: Write out TBMPhaseScan_0_V0
[18:37:29.738] INFO: Write out TBMPhaseScan_1_V0
[18:37:29.738] INFO: Write out CombinedTBMPhaseScan_V0
[18:37:29.774] INFO: Write out ROCDelayScan3_V0
[18:37:29.774] INFO: enter test to run
[18:38:12.348] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[18:38:12.348] INFO: running: highrate
[18:38:12.366] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[18:38:12.648] INFO: ----------------------------------------------------------------------
[18:38:12.648] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[18:38:12.648] INFO: ----------------------------------------------------------------------
[18:38:12.648] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[18:38:12.648] INFO: edge/corner pixel THR is adjusted
[18:38:12.648] INFO: PixTestHighRate::trimHotPixels: step 0...
[18:38:13.620] INFO: Collecting data for 5 seconds...
[18:38:18.637] INFO: Done with hot pixel readout
[18:38:30.542] INFO: PixTest:: pg_setup set to default.
[18:38:30.543] INFO: 0 hot pixels found in step 0
[18:38:30.580] INFO: 0 hot pixels could not be trimmed and have been masked.
[18:38:30.584] INFO: PixTest::trimHotPixels() done
[18:38:30.584] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C0.dat
[18:38:30.589] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C1.dat
[18:38:30.596] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C2.dat
[18:38:30.603] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C3.dat
[18:38:30.608] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C4.dat
[18:38:30.614] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C5.dat
[18:38:30.619] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C6.dat
[18:38:30.637] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C7.dat
[18:38:30.643] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C8.dat
[18:38:30.648] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C9.dat
[18:38:30.653] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C10.dat
[18:38:30.658] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C11.dat
[18:38:30.664] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C12.dat
[18:38:30.669] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C13.dat
[18:38:30.674] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C14.dat
[18:38:30.680] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C15.dat
[18:38:30.685] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//defaultMaskFile.dat
[18:38:30.700] INFO: enter test to run
[18:38:55.764] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[18:38:55.764] INFO: running: highrate
[18:38:55.768] INFO: ----------------------------------------------------------------------
[18:38:55.768] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[18:38:55.768] INFO: ----------------------------------------------------------------------
[18:38:55.768] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[18:38:55.768] INFO: edge/corner pixel THR is adjusted
[18:38:55.768] INFO: PixTestHighRate::trimHotPixels: step 0...
[18:38:56.726] INFO: Collecting data for 1 seconds...
[18:38:57.730] INFO: Done with hot pixel readout
[18:39:01.975] INFO: PixTest:: pg_setup set to default.
[18:39:01.976] INFO: 0 hot pixels found in step 0
[18:39:01.981] INFO: 0 hot pixels could not be trimmed and have been masked.
[18:39:02.063] INFO: PixTest::trimHotPixels() done
[18:39:02.064] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C0.dat
[18:39:02.086] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C1.dat
[18:39:02.093] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C2.dat
[18:39:02.103] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C3.dat
[18:39:02.108] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C4.dat
[18:39:02.114] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C5.dat
[18:39:02.119] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C6.dat
[18:39:02.124] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C7.dat
[18:39:02.129] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C8.dat
[18:39:02.135] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C9.dat
[18:39:02.140] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C10.dat
[18:39:02.145] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C11.dat
[18:39:02.151] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C12.dat
[18:39:02.156] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C13.dat
[18:39:02.161] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C14.dat
[18:39:02.167] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//trimParameters35_C15.dat
[18:39:02.172] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-24_FPIXTest-17C-FNAL-160926-1425-150V_2016-09-26_15h05m_1474920344/000_FPIXTest_p17//defaultMaskFile.dat
[18:39:02.186] INFO: enter test to run
[18:39:27.868] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[18:39:27.868] INFO: running: xray
[18:39:27.869] INFO: ----------------------------------------------------------------------
[18:39:27.869] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[18:39:27.869] INFO: ----------------------------------------------------------------------
[18:39:28.832] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[18:39:40.137] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[18:40:09.138] INFO: Resuming triggers.
[18:40:20.546] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[18:40:50.310] INFO: Resuming triggers.
[18:41:01.611] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[18:41:31.506] INFO: Resuming triggers.
[18:41:42.807] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[18:42:12.650] INFO: Resuming triggers.
[18:42:23.954] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[18:42:53.547] INFO: Resuming triggers.
[18:43:04.846] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[18:43:35.210] INFO: Resuming triggers.
[18:43:46.513] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[18:44:16.809] INFO: Resuming triggers.
[18:44:28.109] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[18:44:58.928] INFO: Resuming triggers.
[18:45:08.896] INFO: data taking finished, elapsed time: 100 seconds.
[18:45:35.867] INFO: PixTest:: pg_setup set to default.
[18:45:35.870] INFO: PixTestXray::doPhRun() done
[18:45:36.091] INFO: enter test to run
[18:45:58.945] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[18:45:58.945] INFO: running: xray
[18:45:58.946] INFO: ----------------------------------------------------------------------
[18:45:58.946] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[18:45:58.946] INFO: ----------------------------------------------------------------------
[18:45:59.910] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[18:46:06.403] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[18:46:36.470] INFO: Resuming triggers.
[18:46:42.964] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[18:47:12.968] INFO: Resuming triggers.
[18:47:19.464] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[18:47:49.532] INFO: Resuming triggers.
[18:47:56.031] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[18:48:26.156] INFO: Resuming triggers.
[18:48:32.653] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[18:49:02.700] INFO: Resuming triggers.
[18:49:09.198] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[18:49:39.301] INFO: Resuming triggers.
[18:49:45.803] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[18:50:15.899] INFO: Resuming triggers.
[18:50:22.398] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[18:50:52.527] INFO: Resuming triggers.
[18:50:59.024] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[18:51:29.064] INFO: Resuming triggers.
[18:51:35.559] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[18:52:05.558] INFO: Resuming triggers.
[18:52:12.058] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[18:52:42.078] INFO: Resuming triggers.
[18:52:48.574] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[18:53:19.344] INFO: Resuming triggers.
[18:53:25.841] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[18:53:56.686] INFO: Resuming triggers.
[18:54:03.179] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[18:54:33.707] INFO: Resuming triggers.
[18:54:40.207] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[18:55:10.860] INFO: Resuming triggers.
[18:55:13.746] INFO: data taking finished, elapsed time: 100 seconds.
[18:55:27.526] INFO: PixTest:: pg_setup set to default.
[18:55:27.529] INFO: PixTestXray::doPhRun() done
[18:55:27.683] INFO: enter test to run
[18:55:51.509] INFO: test: HighRate no parameter change
[18:55:51.509] INFO: running: highrate
[18:55:51.534] INFO: ----------------------------------------------------------------------
[18:55:51.534] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[18:55:51.534] INFO: ----------------------------------------------------------------------
[18:55:51.696] INFO: Expecting 768 events.
[18:55:52.843] INFO: 768 events read in total (432ms).
[18:55:52.843] INFO: Test took 1282ms.
[18:55:53.646] INFO: Expecting 41600 events.
[18:55:56.741] INFO: 41600 events read in total (2568ms).
[18:55:56.742] INFO: Test took 3827ms.
[18:55:56.775] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:55:57.499] INFO: Expecting 41600 events.
[18:56:00.682] INFO: 41600 events read in total (2656ms).
[18:56:00.684] INFO: Test took 3892ms.
[18:56:00.719] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:01.439] INFO: Expecting 41600 events.
[18:56:04.823] INFO: 41600 events read in total (2857ms).
[18:56:04.824] INFO: Test took 4087ms.
[18:56:04.858] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:05.579] INFO: Expecting 41600 events.
[18:56:08.822] INFO: 41600 events read in total (2716ms).
[18:56:08.823] INFO: Test took 3919ms.
[18:56:08.858] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:09.580] INFO: Expecting 41600 events.
[18:56:12.805] INFO: 41600 events read in total (2698ms).
[18:56:12.806] INFO: Test took 3931ms.
[18:56:12.841] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:13.563] INFO: Expecting 41600 events.
[18:56:16.874] INFO: 41600 events read in total (2784ms).
[18:56:16.875] INFO: Test took 4016ms.
[18:56:16.910] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:17.630] INFO: Expecting 41600 events.
[18:56:20.906] INFO: 41600 events read in total (2749ms).
[18:56:20.906] INFO: Test took 3977ms.
[18:56:20.942] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:21.659] INFO: Expecting 41600 events.
[18:56:24.983] INFO: 41600 events read in total (2797ms).
[18:56:24.984] INFO: Test took 4024ms.
[18:56:25.019] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:25.739] INFO: Expecting 41600 events.
[18:56:28.979] INFO: 41600 events read in total (2713ms).
[18:56:28.980] INFO: Test took 3943ms.
[18:56:29.016] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:29.734] INFO: Expecting 41600 events.
[18:56:33.025] INFO: 41600 events read in total (2764ms).
[18:56:33.026] INFO: Test took 3990ms.
[18:56:33.061] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:33.783] INFO: Expecting 41600 events.
[18:56:37.055] INFO: 41600 events read in total (2745ms).
[18:56:37.056] INFO: Test took 3978ms.
[18:56:37.091] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:37.809] INFO: Expecting 41600 events.
[18:56:41.146] INFO: 41600 events read in total (2810ms).
[18:56:41.147] INFO: Test took 4038ms.
[18:56:41.182] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:41.900] INFO: Expecting 41600 events.
[18:56:45.146] INFO: 41600 events read in total (2719ms).
[18:56:45.147] INFO: Test took 3947ms.
[18:56:45.182] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:45.904] INFO: Expecting 41600 events.
[18:56:49.118] INFO: 41600 events read in total (2689ms).
[18:56:49.119] INFO: Test took 3918ms.
[18:56:49.155] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:49.877] INFO: Expecting 41600 events.
[18:56:53.138] INFO: 41600 events read in total (2734ms).
[18:56:53.139] INFO: Test took 3967ms.
[18:56:53.173] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:53.899] INFO: Expecting 41600 events.
[18:56:57.195] INFO: 41600 events read in total (2770ms).
[18:56:57.196] INFO: Test took 4004ms.
[18:56:57.232] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:56:57.955] INFO: Expecting 41600 events.
[18:57:01.346] INFO: 41600 events read in total (2864ms).
[18:57:01.347] INFO: Test took 4098ms.
[18:57:01.382] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:57:02.104] INFO: Expecting 41600 events.
[18:57:05.417] INFO: 41600 events read in total (2786ms).
[18:57:05.418] INFO: Test took 4018ms.
[18:57:05.453] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:57:06.176] INFO: Expecting 41600 events.
[18:57:09.451] INFO: 41600 events read in total (2748ms).
[18:57:09.452] INFO: Test took 3981ms.
[18:57:09.488] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:57:10.194] INFO: Expecting 41600 events.
[18:57:13.380] INFO: 41600 events read in total (2659ms).
[18:57:13.381] INFO: Test took 3875ms.
[18:57:13.416] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:57:13.785] INFO: enter test to run
[18:57:32.004] INFO: test: HighRate no parameter change
[18:57:32.004] INFO: running: highrate
[18:57:32.006] INFO: ----------------------------------------------------------------------
[18:57:32.006] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:57:32.006] INFO: ----------------------------------------------------------------------
[18:57:33.625] INFO: Expecting 208000 events.
[18:57:45.974] INFO: 208000 events read in total (11822ms).
[18:57:45.977] INFO: Test took 12963ms.
[18:57:46.128] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:57:46.382] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[18:57:46.382] INFO: number of red-efficiency pixels: 50 43 88 128 186 131 125 90 79 154 150 101 109 59 31 21
[18:57:46.382] INFO: number of X-ray hits detected: 64303 43315 64765 99974 109316 110659 110526 78708 78867 108624 106916 87063 92910 54367 22150 22216
[18:57:46.382] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:57:46.382] INFO: number of Vcal hits detected: 207949 207957 207909 207869 207783 207863 207872 207909 207919 207844 207846 207897 207891 207939 207969 207979
[18:57:46.382] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[18:57:46.382] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[18:57:46.382] INFO: X-ray hit rate [MHz/cm2]: 18.8 12.7 19.0 29.3 32.0 32.4 32.4 23.1 23.1 31.8 31.3 25.5 27.2 15.9 6.5 6.5
[18:57:46.382] INFO: PixTestHighRate::doXPixelAlive() done
[18:57:46.427] INFO: PixTest:: pg_setup set to default.
[18:57:46.436] INFO: enter test to run
[18:58:05.316] INFO: test: HighRate no parameter change
[18:58:05.316] INFO: running: highrate
[18:58:05.317] INFO: ----------------------------------------------------------------------
[18:58:05.317] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:58:05.317] INFO: ----------------------------------------------------------------------
[18:58:05.940] INFO: Expecting 208000 events.
[18:58:20.274] INFO: 208000 events read in total (13808ms).
[18:58:20.280] INFO: Test took 14954ms.
[18:58:20.597] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:58:20.908] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[18:58:20.908] INFO: number of red-efficiency pixels: 182 136 307 478 586 464 463 284 372 555 387 387 335 230 49 49
[18:58:20.908] INFO: number of X-ray hits detected: 142652 96287 144265 220960 241904 244291 241908 175882 175842 239987 236781 195171 205390 120054 49146 49479
[18:58:20.908] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:58:20.908] INFO: number of Vcal hits detected: 207805 207855 207665 207479 207303 207500 207497 207695 207607 207379 207579 207585 207648 207754 207947 207951
[18:58:20.908] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.8 99.9 99.8 99.7 99.8 99.8 99.8 99.9 100.0 100.0
[18:58:20.908] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.8 99.8 99.9 99.8 99.7 99.8 99.8 99.8 99.9 100.0 100.0
[18:58:20.908] INFO: X-ray hit rate [MHz/cm2]: 41.8 28.2 42.3 64.8 70.9 71.6 70.9 51.6 51.5 70.3 69.4 57.2 60.2 35.2 14.4 14.5
[18:58:20.908] INFO: PixTestHighRate::doXPixelAlive() done
[18:58:20.953] INFO: PixTest:: pg_setup set to default.
[18:58:20.969] INFO: enter test to run
[18:58:38.820] INFO: test: HighRate no parameter change
[18:58:38.820] INFO: running: highrate
[18:58:38.821] INFO: ----------------------------------------------------------------------
[18:58:38.821] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:58:38.821] INFO: ----------------------------------------------------------------------
[18:58:39.440] INFO: Expecting 208000 events.
[18:58:55.791] INFO: 208000 events read in total (15824ms).
[18:58:55.799] INFO: Test took 16969ms.
[18:58:56.277] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:58:56.644] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[18:58:56.644] INFO: number of red-efficiency pixels: 380 241 704 1140 1388 1062 990 645 668 1366 1008 897 731 558 103 97
[18:58:56.644] INFO: number of X-ray hits detected: 216840 145209 218230 334353 365473 370284 368379 264924 265998 362390 358216 293768 312132 181690 73773 74874
[18:58:56.644] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:58:56.644] INFO: number of Vcal hits detected: 207579 207730 207006 206572 206105 206652 206793 207212 207186 206208 206724 206912 207162 207307 207893 207902
[18:58:56.644] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.4 99.2 99.4 99.5 99.7 99.7 99.2 99.5 99.5 99.6 99.7 100.0 100.0
[18:58:56.644] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.5 99.3 99.1 99.4 99.4 99.6 99.6 99.1 99.4 99.5 99.6 99.7 99.9 100.0
[18:58:56.644] INFO: X-ray hit rate [MHz/cm2]: 63.6 42.6 64.0 98.0 107.1 108.5 108.0 77.7 78.0 106.2 105.0 86.1 91.5 53.3 21.6 21.9
[18:58:56.644] INFO: PixTestHighRate::doXPixelAlive() done
[18:58:56.691] INFO: PixTest:: pg_setup set to default.
[18:58:56.707] INFO: enter test to run
[18:58:59.388] INFO: test: exit no parameter change
[18:59:00.137] QUIET: Connection to board 33 closed.
[18:59:00.171] INFO: pXar: this is the end, my friend