[12:00:51.190] INFO: *** Welcome to pxar ***
[12:00:51.190] INFO: *** Today: 2016/09/26
[12:00:52.322] INFO: *** Version: v1.9.0-818-g96727
[12:00:52.322] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//dacParameters35_C15.dat
[12:00:52.382] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:00:52.383] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//defaultMaskFile.dat
[12:00:52.386] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C15.dat
[12:00:52.518] INFO: clk: 4
[12:00:52.518] INFO: ctr: 4
[12:00:52.518] INFO: sda: 19
[12:00:52.518] INFO: tin: 9
[12:00:52.518] INFO: level: 15
[12:00:52.518] INFO: triggerdelay: 0
[12:00:52.518] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[12:00:52.518] INFO: Log level: INFO
[12:00:52.553] QUIET: Connection to board DTB_WREKRL opened.
[12:00:52.556] 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:
------------------------------------------------------
[12:00:52.559] INFO: RPC call hashes of host and DTB match: 398089610
[12:00:54.102] INFO: DUT info:
[12:00:54.102] INFO: The DUT currently contains the following objects:
[12:00:54.102] INFO: 2 TBM Cores tbm08c (2 ON)
[12:00:54.102] INFO: TBM Core alpha (0): 7 registers set
[12:00:54.102] INFO: TBM Core beta (1): 7 registers set
[12:00:54.102] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:00:54.102] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.102] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:00:54.553] INFO: enter 'restricted' command line mode
[12:00:54.553] INFO: enter test to run
[12:00:59.641] INFO: test: PixelAlive no parameter change
[12:00:59.641] INFO: running: pixelalive
[12:00:59.714] INFO: ----------------------------------------------------------------------
[12:00:59.714] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[12:00:59.714] INFO: ----------------------------------------------------------------------
[12:01:00.032] INFO: Expecting 41600 events.
[12:01:04.372] INFO: 41600 events read in total (3621ms).
[12:01:04.541] INFO: Test took 4823ms.
[12:01:04.553] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:05.085] INFO: PixTestAlive::aliveTest() done
[12:01:05.085] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0
[12:01:05.238] INFO: enter test to run
[12:01:13.225] INFO: test: timing no parameter change
[12:01:13.225] INFO: running: timing
[12:01:13.229] INFO: ######################################################################
[12:01:13.229] INFO: PixTestTiming::doTest()
[12:01:13.229] INFO: ######################################################################
[12:01:13.229] INFO: ----------------------------------------------------------------------
[12:01:13.229] INFO: PixTestTiming::TBMPhaseScan()
[12:01:13.229] INFO: ----------------------------------------------------------------------
[12:08:39.607] INFO: TBM Phase Settings: 248
[12:08:39.607] INFO: 400MHz Phase: 6
[12:08:39.607] INFO: 160MHz Phase: 7
[12:08:39.607] INFO: Functional Phase Area: 3
[12:08:39.626] INFO: Test took 446397 ms.
[12:08:39.626] INFO: PixTestTiming::TBMPhaseScan() done.
[12:08:39.627] INFO: ----------------------------------------------------------------------
[12:08:39.627] INFO: PixTestTiming::ROCDelayScan()
[12:08:39.627] INFO: ----------------------------------------------------------------------
[12:11:22.143] INFO: ROC Delay Settings: 228
[12:11:22.143] INFO: ROC Header-Trailer/Token Delay: 11
[12:11:22.143] INFO: ROC Port 0 Delay: 4
[12:11:22.143] INFO: ROC Port 1 Delay: 4
[12:11:22.143] INFO: Functional ROC Area: 3
[12:11:22.146] INFO: Test took 162520 ms.
[12:11:22.146] INFO: PixTestTiming::ROCDelayScan() done.
[12:11:22.146] INFO: ----------------------------------------------------------------------
[12:11:22.146] INFO: PixTestTiming::TimingTest()
[12:11:22.146] INFO: ----------------------------------------------------------------------
[12:11:38.401] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:11:53.518] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:08.482] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:23.453] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:38.418] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:53.382] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:08.347] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:23.300] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:38.242] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:53.204] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:53.586] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:53.603] INFO: ----------------------------------------------------------------------
[12:13:53.603] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:13:53.603] INFO: ----------------------------------------------------------------------
[12:13:53.603] INFO: ----------------------------------------------------------------------
[12:13:53.603] INFO: Read back bit status: 1
[12:13:53.603] INFO: ----------------------------------------------------------------------
[12:13:53.603] INFO: ----------------------------------------------------------------------
[12:13:53.603] INFO: Timings are good!
[12:13:53.603] INFO: ----------------------------------------------------------------------
[12:13:53.603] INFO: Test took 151457 ms.
[12:13:53.603] INFO: PixTestTiming::TimingTest() done.
[12:13:53.604] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:13:53.604] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:13:53.604] INFO: PixTestTiming::doTest took 760379 ms.
[12:13:53.604] INFO: PixTestTiming::doTest() done
[12:13:53.604] INFO: Write out TBMPhaseScan_0_V0
[12:13:53.604] INFO: Write out TBMPhaseScan_1_V0
[12:13:53.604] INFO: Write out CombinedTBMPhaseScan_V0
[12:13:53.605] INFO: Write out ROCDelayScan3_V0
[12:13:53.605] INFO: enter test to run
[12:14:49.252] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:14:49.252] INFO: running: highrate
[12:14:49.265] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:14:49.506] INFO: ----------------------------------------------------------------------
[12:14:49.506] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:14:49.506] INFO: ----------------------------------------------------------------------
[12:14:49.506] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:14:49.506] INFO: edge/corner pixel THR is adjusted
[12:14:49.506] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:14:50.464] INFO: Collecting data for 5 seconds...
[12:14:55.482] INFO: Done with hot pixel readout
[12:15:07.171] INFO: PixTest:: pg_setup set to default.
[12:15:07.172] INFO: 0 hot pixels found in step 0
[12:15:07.209] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:15:07.213] INFO: PixTest::trimHotPixels() done
[12:15:07.213] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C0.dat
[12:15:07.220] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C1.dat
[12:15:07.225] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C2.dat
[12:15:07.230] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C3.dat
[12:15:07.236] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C4.dat
[12:15:07.241] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C5.dat
[12:15:07.246] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C6.dat
[12:15:07.252] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C7.dat
[12:15:07.257] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C8.dat
[12:15:07.262] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C9.dat
[12:15:07.267] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C10.dat
[12:15:07.272] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C11.dat
[12:15:07.278] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C12.dat
[12:15:07.283] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C13.dat
[12:15:07.288] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C14.dat
[12:15:07.293] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C15.dat
[12:15:07.299] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//defaultMaskFile.dat
[12:15:07.308] INFO: enter test to run
[12:15:29.307] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:15:29.307] INFO: running: highrate
[12:15:29.312] INFO: ----------------------------------------------------------------------
[12:15:29.312] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:15:29.312] INFO: ----------------------------------------------------------------------
[12:15:29.312] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:15:29.312] INFO: edge/corner pixel THR is adjusted
[12:15:29.312] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:15:30.271] INFO: Collecting data for 1 seconds...
[12:15:31.274] INFO: Done with hot pixel readout
[12:15:35.328] INFO: PixTest:: pg_setup set to default.
[12:15:35.328] INFO: 0 hot pixels found in step 0
[12:15:35.333] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:15:35.424] INFO: PixTest::trimHotPixels() done
[12:15:35.424] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C0.dat
[12:15:35.436] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C1.dat
[12:15:35.443] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C2.dat
[12:15:35.448] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C3.dat
[12:15:35.453] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C4.dat
[12:15:35.459] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C5.dat
[12:15:35.464] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C6.dat
[12:15:35.469] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C7.dat
[12:15:35.475] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C8.dat
[12:15:35.510] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C9.dat
[12:15:35.522] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C10.dat
[12:15:35.527] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C11.dat
[12:15:35.533] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C12.dat
[12:15:35.538] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C13.dat
[12:15:35.543] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C14.dat
[12:15:35.549] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//trimParameters35_C15.dat
[12:15:35.554] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-27_FPIXTest-17C-FNAL-160919-1337-150V_2016-09-19_13h37m_1474310246/000_FPIXTest_p17//defaultMaskFile.dat
[12:15:35.571] INFO: enter test to run
[12:19:29.714] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:19:29.714] INFO: running: xray
[12:19:29.715] INFO: ----------------------------------------------------------------------
[12:19:29.715] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:19:29.715] INFO: ----------------------------------------------------------------------
[12:19:30.695] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:19:42.064] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:20:11.646] INFO: Resuming triggers.
[12:20:23.120] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[12:20:52.434] INFO: Resuming triggers.
[12:21:03.805] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[12:21:33.740] INFO: Resuming triggers.
[12:21:45.111] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[12:22:14.422] INFO: Resuming triggers.
[12:22:25.792] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[12:22:55.381] INFO: Resuming triggers.
[12:23:06.749] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[12:23:36.778] INFO: Resuming triggers.
[12:23:48.149] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[12:24:17.619] INFO: Resuming triggers.
[12:24:28.990] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[12:24:58.311] INFO: Resuming triggers.
[12:25:07.716] INFO: data taking finished, elapsed time: 100 seconds.
[12:25:32.364] INFO: PixTest:: pg_setup set to default.
[12:25:32.367] INFO: PixTestXray::doPhRun() done
[12:25:35.013] INFO: enter test to run
[12:25:54.951] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:25:54.951] INFO: running: xray
[12:25:54.952] INFO: ----------------------------------------------------------------------
[12:25:54.952] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:25:54.952] INFO: ----------------------------------------------------------------------
[12:25:55.916] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:26:02.700] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:26:34.274] INFO: Resuming triggers.
[12:26:41.056] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[12:27:11.527] INFO: Resuming triggers.
[12:27:18.309] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[12:27:48.510] INFO: Resuming triggers.
[12:27:55.295] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[12:28:25.608] INFO: Resuming triggers.
[12:28:32.394] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[12:29:02.670] INFO: Resuming triggers.
[12:29:09.449] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[12:29:39.427] INFO: Resuming triggers.
[12:29:46.212] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[12:30:16.434] INFO: Resuming triggers.
[12:30:23.217] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[12:30:53.509] INFO: Resuming triggers.
[12:31:00.285] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[12:31:30.482] INFO: Resuming triggers.
[12:31:37.260] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[12:32:07.500] INFO: Resuming triggers.
[12:32:14.277] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[12:32:44.639] INFO: Resuming triggers.
[12:32:51.415] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[12:33:22.569] INFO: Resuming triggers.
[12:33:29.355] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[12:34:00.378] INFO: Resuming triggers.
[12:34:07.156] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[12:34:37.883] INFO: Resuming triggers.
[12:34:43.288] INFO: data taking finished, elapsed time: 100 seconds.
[12:35:08.064] INFO: PixTest:: pg_setup set to default.
[12:35:08.067] INFO: PixTestXray::doPhRun() done
[12:35:08.219] INFO: enter test to run
[12:35:44.939] INFO: test: HighRate no parameter change
[12:35:44.939] INFO: running: highrate
[12:35:44.955] INFO: ----------------------------------------------------------------------
[12:35:44.955] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:35:44.955] INFO: ----------------------------------------------------------------------
[12:35:45.109] INFO: Expecting 768 events.
[12:35:46.246] INFO: 768 events read in total (421ms).
[12:35:46.246] INFO: Test took 1271ms.
[12:35:47.049] INFO: Expecting 41600 events.
[12:35:50.170] INFO: 41600 events read in total (2594ms).
[12:35:50.171] INFO: Test took 3900ms.
[12:35:50.206] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:35:50.916] INFO: Expecting 41600 events.
[12:35:54.095] INFO: 41600 events read in total (2652ms).
[12:35:54.096] INFO: Test took 3871ms.
[12:35:54.133] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:35:54.848] INFO: Expecting 41600 events.
[12:35:58.082] INFO: 41600 events read in total (2707ms).
[12:35:58.083] INFO: Test took 3932ms.
[12:35:58.120] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:35:58.837] INFO: Expecting 41600 events.
[12:36:02.116] INFO: 41600 events read in total (2752ms).
[12:36:02.117] INFO: Test took 3978ms.
[12:36:02.153] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:02.873] INFO: Expecting 41600 events.
[12:36:06.195] INFO: 41600 events read in total (2795ms).
[12:36:06.196] INFO: Test took 4025ms.
[12:36:06.232] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:06.950] INFO: Expecting 41600 events.
[12:36:10.240] INFO: 41600 events read in total (2763ms).
[12:36:10.241] INFO: Test took 3989ms.
[12:36:10.277] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:10.997] INFO: Expecting 41600 events.
[12:36:14.385] INFO: 41600 events read in total (2861ms).
[12:36:14.386] INFO: Test took 4091ms.
[12:36:14.423] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:15.133] INFO: Expecting 41600 events.
[12:36:18.414] INFO: 41600 events read in total (2754ms).
[12:36:18.415] INFO: Test took 3974ms.
[12:36:18.452] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:19.172] INFO: Expecting 41600 events.
[12:36:22.437] INFO: 41600 events read in total (2738ms).
[12:36:22.439] INFO: Test took 3968ms.
[12:36:22.485] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:23.174] INFO: Expecting 41600 events.
[12:36:26.487] INFO: 41600 events read in total (2786ms).
[12:36:26.488] INFO: Test took 3976ms.
[12:36:26.524] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:27.243] INFO: Expecting 41600 events.
[12:36:30.558] INFO: 41600 events read in total (2789ms).
[12:36:30.559] INFO: Test took 4017ms.
[12:36:30.596] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:31.313] INFO: Expecting 41600 events.
[12:36:34.596] INFO: 41600 events read in total (2757ms).
[12:36:34.598] INFO: Test took 3983ms.
[12:36:34.644] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:35.348] INFO: Expecting 41600 events.
[12:36:38.619] INFO: 41600 events read in total (2744ms).
[12:36:38.620] INFO: Test took 3950ms.
[12:36:38.657] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:39.375] INFO: Expecting 41600 events.
[12:36:42.697] INFO: 41600 events read in total (2795ms).
[12:36:42.698] INFO: Test took 4023ms.
[12:36:42.736] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:43.450] INFO: Expecting 41600 events.
[12:36:46.826] INFO: 41600 events read in total (2849ms).
[12:36:46.827] INFO: Test took 4073ms.
[12:36:46.864] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:47.582] INFO: Expecting 41600 events.
[12:36:51.027] INFO: 41600 events read in total (2919ms).
[12:36:51.028] INFO: Test took 4142ms.
[12:36:51.065] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:51.782] INFO: Expecting 41600 events.
[12:36:55.116] INFO: 41600 events read in total (2807ms).
[12:36:55.117] INFO: Test took 4033ms.
[12:36:55.153] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:55.869] INFO: Expecting 41600 events.
[12:36:59.223] INFO: 41600 events read in total (2827ms).
[12:36:59.224] INFO: Test took 4052ms.
[12:36:59.270] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:59.970] INFO: Expecting 41600 events.
[12:37:03.257] INFO: 41600 events read in total (2760ms).
[12:37:03.258] INFO: Test took 3969ms.
[12:37:03.296] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:04.014] INFO: Expecting 41600 events.
[12:37:07.050] INFO: 41600 events read in total (2509ms).
[12:37:07.051] INFO: Test took 3735ms.
[12:37:07.086] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:07.443] INFO: enter test to run
[12:38:26.274] INFO: test: HighRate no parameter change
[12:38:26.274] INFO: running: highrate
[12:38:26.275] INFO: ----------------------------------------------------------------------
[12:38:26.275] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:38:26.275] INFO: ----------------------------------------------------------------------
[12:38:26.903] INFO: Expecting 208000 events.
[12:38:38.840] INFO: 208000 events read in total (11411ms).
[12:38:38.843] INFO: Test took 12542ms.
[12:38:38.995] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:38:39.249] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0
[12:38:39.249] INFO: number of red-efficiency pixels: 81 44 72 125 192 123 127 139 99 176 152 110 96 87 26 25
[12:38:39.249] INFO: number of X-ray hits detected: 64607 38431 62258 99106 112995 111942 114000 94161 94830 121751 117372 93722 94880 58720 20885 22889
[12:38:39.249] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:38:39.249] INFO: number of Vcal hits detected: 207918 207956 207926 207871 207799 207875 207872 207857 207899 207820 207842 207841 207903 207911 207973 207974
[12:38:39.249] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[12:38:39.249] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0
[12:38:39.249] INFO: X-ray hit rate [MHz/cm2]: 18.9 11.3 18.2 29.0 33.1 32.8 33.4 27.6 27.8 35.7 34.4 27.5 27.8 17.2 6.1 6.7
[12:38:39.249] INFO: PixTestHighRate::doXPixelAlive() done
[12:38:39.301] INFO: PixTest:: pg_setup set to default.
[12:38:39.316] INFO: enter test to run
[12:39:00.138] INFO: test: HighRate no parameter change
[12:39:00.138] INFO: running: highrate
[12:39:00.139] INFO: ----------------------------------------------------------------------
[12:39:00.139] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:39:00.139] INFO: ----------------------------------------------------------------------
[12:39:00.753] INFO: Expecting 208000 events.
[12:39:16.179] INFO: 208000 events read in total (14899ms).
[12:39:16.187] INFO: Test took 16038ms.
[12:39:16.637] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:39:16.984] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0
[12:39:16.984] INFO: number of red-efficiency pixels: 457 179 526 970 1125 746 900 830 899 1361 914 611 748 518 77 87
[12:39:16.984] INFO: number of X-ray hits detected: 188991 113342 182398 288527 330049 325265 330103 275164 277356 354952 340867 274530 277703 170604 61691 68205
[12:39:16.984] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:39:16.984] INFO: number of Vcal hits detected: 207461 207808 207342 206836 206612 207108 206908 206943 206920 206203 206908 207243 207124 207357 207919 207911
[12:39:16.984] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.5 99.4 99.6 99.5 99.5 99.6 99.2 99.5 99.7 99.6 99.7 100.0 100.0
[12:39:16.984] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.4 99.3 99.6 99.5 99.5 99.5 99.1 99.5 99.6 99.6 99.7 100.0 100.0
[12:39:16.984] INFO: X-ray hit rate [MHz/cm2]: 55.4 33.2 53.5 84.6 96.7 95.3 96.8 80.7 81.3 104.0 99.9 80.5 81.4 50.0 18.1 20.0
[12:39:16.984] INFO: PixTestHighRate::doXPixelAlive() done
[12:39:17.030] INFO: PixTest:: pg_setup set to default.
[12:39:17.046] INFO: enter test to run
[12:39:44.881] INFO: test: HighRate no parameter change
[12:39:44.882] INFO: running: highrate
[12:39:44.883] INFO: ----------------------------------------------------------------------
[12:39:44.883] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:39:44.883] INFO: ----------------------------------------------------------------------
[12:39:45.499] INFO: Expecting 208000 events.
[12:40:00.930] INFO: 208000 events read in total (14904ms).
[12:40:00.940] INFO: Test took 16048ms.
[12:40:01.374] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:40:01.720] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0
[12:40:01.721] INFO: number of red-efficiency pixels: 442 157 520 912 1093 843 927 828 835 1349 915 597 746 500 81 87
[12:40:01.721] INFO: number of X-ray hits detected: 189022 113412 181818 289291 329748 325719 331565 276367 277367 354401 340205 273751 278537 171532 61337 68172
[12:40:01.721] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:40:01.721] INFO: number of Vcal hits detected: 207494 207829 207373 206893 206606 207015 206895 206980 206993 206222 206904 207250 207126 207393 207917 207911
[12:40:01.721] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.5 99.4 99.6 99.5 99.6 99.6 99.2 99.5 99.7 99.6 99.7 100.0 100.0
[12:40:01.721] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.5 99.3 99.5 99.5 99.5 99.5 99.1 99.5 99.6 99.6 99.7 100.0 100.0
[12:40:01.721] INFO: X-ray hit rate [MHz/cm2]: 55.4 33.2 53.3 84.8 96.7 95.5 97.2 81.0 81.3 103.9 99.7 80.2 81.6 50.3 18.0 20.0
[12:40:01.721] INFO: PixTestHighRate::doXPixelAlive() done
[12:40:01.768] INFO: PixTest:: pg_setup set to default.
[12:40:01.783] INFO: enter test to run
[12:40:06.769] INFO: test: exit no parameter change
[12:40:07.248] QUIET: Connection to board 33 closed.
[12:40:07.306] INFO: pXar: this is the end, my friend