[18:36:45.877] INFO: *** Welcome to pxar ***
[18:36:45.877] INFO: *** Today: 2016/09/07
[18:36:45.897] INFO: *** Version: v1.9.0-818-g96727
[18:36:45.897] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//dacParameters35_C15.dat
[18:36:45.898] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//tbmParameters_C0b.dat
[18:36:45.898] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//defaultMaskFile.dat
[18:36:45.898] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C15.dat
[18:36:45.967] INFO: clk: 4
[18:36:45.967] INFO: ctr: 4
[18:36:45.967] INFO: sda: 19
[18:36:45.967] INFO: tin: 9
[18:36:45.967] INFO: level: 15
[18:36:45.967] INFO: triggerdelay: 0
[18:36:45.967] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[18:36:45.967] INFO: Log level: INFO
[18:36:45.985] QUIET: Connection to board DTB_WREKRL opened.
[18:36:45.988] 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:36:45.991] INFO: RPC call hashes of host and DTB match: 398089610
[18:36:47.520] INFO: DUT info:
[18:36:47.520] INFO: The DUT currently contains the following objects:
[18:36:47.520] INFO: 2 TBM Cores tbm08c (2 ON)
[18:36:47.520] INFO: TBM Core alpha (0): 7 registers set
[18:36:47.520] INFO: TBM Core beta (1): 7 registers set
[18:36:47.520] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[18:36:47.520] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.520] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.520] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.520] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.520] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.520] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.521] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.521] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.521] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.521] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.521] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.521] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.521] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.521] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.521] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.521] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[18:36:47.924] INFO: enter 'restricted' command line mode
[18:36:47.924] INFO: enter test to run
[18:36:54.307] INFO: test: PixelAlive no parameter change
[18:36:54.307] INFO: running: pixelalive
[18:36:54.316] INFO: ----------------------------------------------------------------------
[18:36:54.316] 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:36:54.316] INFO: ----------------------------------------------------------------------
[18:36:54.634] INFO: Expecting 41600 events.
[18:36:58.962] INFO: 41600 events read in total (3609ms).
[18:36:59.131] INFO: Test took 4813ms.
[18:36:59.141] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:36:59.404] INFO: PixTestAlive::aliveTest() done
[18:36:59.404] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0
[18:36:59.435] INFO: enter test to run
[18:37:03.947] INFO: test: timing no parameter change
[18:37:03.947] INFO: running: timing
[18:37:03.967] INFO: ######################################################################
[18:37:03.967] INFO: PixTestTiming::doTest()
[18:37:03.967] INFO: ######################################################################
[18:37:03.967] INFO: ----------------------------------------------------------------------
[18:37:03.967] INFO: PixTestTiming::TBMPhaseScan()
[18:37:03.968] INFO: ----------------------------------------------------------------------
[18:49:02.693] INFO: TBM Phase Settings: 240
[18:49:02.693] INFO: 400MHz Phase: 4
[18:49:02.693] INFO: 160MHz Phase: 7
[18:49:02.693] INFO: Functional Phase Area: 5
[18:49:02.696] INFO: Test took 718729 ms.
[18:49:02.696] INFO: PixTestTiming::TBMPhaseScan() done.
[18:49:02.697] INFO: ----------------------------------------------------------------------
[18:49:02.697] INFO: PixTestTiming::ROCDelayScan()
[18:49:02.697] INFO: ----------------------------------------------------------------------
[18:51:21.481] INFO: ROC Delay Settings: 228
[18:51:21.481] INFO: ROC Header-Trailer/Token Delay: 11
[18:51:21.481] INFO: ROC Port 0 Delay: 4
[18:51:21.481] INFO: ROC Port 1 Delay: 4
[18:51:21.481] INFO: Functional ROC Area: 5
[18:51:21.484] INFO: Test took 138787 ms.
[18:51:21.484] INFO: PixTestTiming::ROCDelayScan() done.
[18:51:21.485] INFO: ----------------------------------------------------------------------
[18:51:21.485] INFO: PixTestTiming::TimingTest()
[18:51:21.485] INFO: ----------------------------------------------------------------------
[18:51:37.756] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:51:52.771] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:52:07.919] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:52:22.991] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:52:38.063] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:52:53.102] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:53:08.071] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:53:23.441] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:53:38.674] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:53:53.819] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:53:54.197] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:53:54.214] INFO: ----------------------------------------------------------------------
[18:53:54.214] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[18:53:54.214] INFO: ----------------------------------------------------------------------
[18:53:54.214] INFO: ----------------------------------------------------------------------
[18:53:54.214] INFO: Read back bit status: 1
[18:53:54.214] INFO: ----------------------------------------------------------------------
[18:53:54.214] INFO: ----------------------------------------------------------------------
[18:53:54.214] INFO: Timings are good!
[18:53:54.214] INFO: ----------------------------------------------------------------------
[18:53:54.214] INFO: Test took 152729 ms.
[18:53:54.214] INFO: PixTestTiming::TimingTest() done.
[18:53:54.214] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//tbmParameters_C0a.dat
[18:53:54.214] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//tbmParameters_C0b.dat
[18:53:54.214] INFO: PixTestTiming::doTest took 1010250 ms.
[18:53:54.214] INFO: PixTestTiming::doTest() done
[18:53:54.214] INFO: Write out TBMPhaseScan_0_V0
[18:53:54.214] INFO: Write out TBMPhaseScan_1_V0
[18:53:54.214] INFO: Write out CombinedTBMPhaseScan_V0
[18:53:54.216] INFO: Write out ROCDelayScan3_V0
[18:53:54.216] INFO: enter test to run
[18:54:24.692] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[18:54:24.692] INFO: running: highrate
[18:54:24.692] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[18:54:24.856] INFO: ----------------------------------------------------------------------
[18:54:24.856] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[18:54:24.856] INFO: ----------------------------------------------------------------------
[18:54:24.856] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[18:54:24.856] INFO: edge/corner pixel THR is adjusted
[18:54:24.856] INFO: PixTestHighRate::trimHotPixels: step 0...
[18:54:25.814] INFO: Collecting data for 5 seconds...
[18:54:30.834] INFO: Done with hot pixel readout
[18:54:42.612] INFO: PixTest:: pg_setup set to default.







[18:54:42.613] INFO: 7 hot pixels found in step 0
[18:54:42.649] INFO: 7 hot pixels could not be trimmed and have been masked.
[18:54:42.652] INFO: PixTest::trimHotPixels() done
[18:54:42.652] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C0.dat
[18:54:42.659] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C1.dat
[18:54:42.666] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C2.dat
[18:54:42.671] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C3.dat
[18:54:42.676] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C4.dat
[18:54:42.682] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C5.dat
[18:54:42.687] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C6.dat
[18:54:42.692] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C7.dat
[18:54:42.698] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C8.dat
[18:54:42.703] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C9.dat
[18:54:42.708] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C10.dat
[18:54:42.713] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C11.dat
[18:54:42.719] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C12.dat
[18:54:42.724] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C13.dat
[18:54:42.729] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C14.dat
[18:54:42.735] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C15.dat
[18:54:42.740] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//defaultMaskFile.dat
[18:54:42.750] INFO: enter test to run
[18:55:02.723] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[18:55:02.723] INFO: running: highrate
[18:55:02.728] INFO: ----------------------------------------------------------------------
[18:55:02.728] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[18:55:02.728] INFO: ----------------------------------------------------------------------
[18:55:02.728] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[18:55:02.728] INFO: edge/corner pixel THR is adjusted
[18:55:02.728] INFO: PixTestHighRate::trimHotPixels: step 0...
[18:55:03.686] INFO: Collecting data for 1 seconds...
[18:55:04.689] INFO: Done with hot pixel readout
[18:55:08.780] INFO: PixTest:: pg_setup set to default.
[18:55:08.781] INFO: 0 hot pixels found in step 0
[18:55:08.787] INFO: 0 hot pixels could not be trimmed and have been masked.
[18:55:08.873] INFO: PixTest::trimHotPixels() done
[18:55:08.873] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C0.dat
[18:55:08.893] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C1.dat
[18:55:08.901] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C2.dat
[18:55:08.909] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C3.dat
[18:55:08.915] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C4.dat
[18:55:08.921] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C5.dat
[18:55:08.926] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C6.dat
[18:55:08.931] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C7.dat
[18:55:08.937] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C8.dat
[18:55:08.942] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C9.dat
[18:55:08.947] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C10.dat
[18:55:08.953] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C11.dat
[18:55:08.958] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C12.dat
[18:55:08.963] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C13.dat
[18:55:08.969] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C14.dat
[18:55:08.974] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//trimParameters35_C15.dat
[18:55:08.979] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-9-09_FPIXTest-17C-FNAL-160830-1322-150V_2016-08-30_13h23m_1472581388/000_FPIXTest_p17//defaultMaskFile.dat
[18:55:08.989] INFO: enter test to run
[18:55:32.603] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[18:55:32.603] INFO: running: xray
[18:55:32.604] INFO: ----------------------------------------------------------------------
[18:55:32.604] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[18:55:32.604] INFO: ----------------------------------------------------------------------
[18:55:33.568] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[18:55:45.079] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[18:56:14.482] INFO: Resuming triggers.
[18:56:26.086] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[18:56:55.478] INFO: Resuming triggers.
[18:57:06.991] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[18:57:36.356] INFO: Resuming triggers.
[18:57:47.866] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[18:58:17.102] INFO: Resuming triggers.
[18:58:28.613] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[18:58:57.944] INFO: Resuming triggers.
[18:59:09.458] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[18:59:38.778] INFO: Resuming triggers.
[18:59:50.290] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[19:00:19.535] INFO: Resuming triggers.
[19:00:31.051] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[19:01:00.377] INFO: Resuming triggers.
[19:01:08.615] INFO: data taking finished, elapsed time: 100 seconds.
[19:01:29.870] INFO: PixTest:: pg_setup set to default.
[19:01:29.873] INFO: PixTestXray::doPhRun() done
[19:01:30.008] INFO: enter test to run
[19:02:06.241] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[19:02:06.241] INFO: running: xray
[19:02:06.242] INFO: ----------------------------------------------------------------------
[19:02:06.242] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[19:02:06.242] INFO: ----------------------------------------------------------------------
[19:02:07.206] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[19:02:13.728] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[19:02:43.945] INFO: Resuming triggers.
[19:02:50.467] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[19:03:21.401] INFO: Resuming triggers.
[19:03:27.927] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[19:03:58.205] INFO: Resuming triggers.
[19:04:04.727] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[19:04:35.532] INFO: Resuming triggers.
[19:04:42.053] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[19:05:12.577] INFO: Resuming triggers.
[19:05:19.099] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[19:05:50.474] INFO: Resuming triggers.
[19:05:56.994] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[19:06:28.401] INFO: Resuming triggers.
[19:06:34.923] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[19:07:06.211] INFO: Resuming triggers.
[19:07:12.729] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[19:07:44.473] INFO: Resuming triggers.
[19:07:50.991] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[19:08:21.177] INFO: Resuming triggers.
[19:08:27.694] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[19:08:57.854] INFO: Resuming triggers.
[19:09:04.378] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[19:09:34.524] INFO: Resuming triggers.
[19:09:41.048] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[19:10:10.908] INFO: Resuming triggers.
[19:10:17.429] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[19:10:47.624] INFO: Resuming triggers.
[19:10:54.147] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[19:11:24.296] INFO: Resuming triggers.
[19:11:26.831] INFO: data taking finished, elapsed time: 100 seconds.
[19:11:38.760] INFO: PixTest:: pg_setup set to default.
[19:11:38.764] INFO: PixTestXray::doPhRun() done
[19:11:38.912] INFO: enter test to run
[19:12:18.348] INFO: test: HighRate no parameter change
[19:12:18.348] INFO: running: highrate
[19:12:18.369] INFO: ----------------------------------------------------------------------
[19:12:18.369] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[19:12:18.369] INFO: ----------------------------------------------------------------------
[19:12:18.525] INFO: Expecting 768 events.
[19:12:19.659] INFO: 768 events read in total (419ms).
[19:12:19.659] INFO: Test took 1269ms.
[19:12:20.463] INFO: Expecting 41600 events.
[19:12:23.565] INFO: 41600 events read in total (2576ms).
[19:12:23.566] INFO: Test took 3893ms.
[19:12:23.599] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:12:24.325] INFO: Expecting 41600 events.
[19:12:27.525] INFO: 41600 events read in total (2673ms).
[19:12:27.526] INFO: Test took 3909ms.
[19:12:27.561] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:12:28.281] INFO: Expecting 41600 events.
[19:12:31.511] INFO: 41600 events read in total (2704ms).
[19:12:31.512] INFO: Test took 3933ms.
[19:12:31.547] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:12:32.268] INFO: Expecting 41600 events.
[19:12:35.511] INFO: 41600 events read in total (2716ms).
[19:12:35.512] INFO: Test took 3947ms.
[19:12:35.546] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:12:36.271] INFO: Expecting 41600 events.
[19:12:39.514] INFO: 41600 events read in total (2716ms).
[19:12:39.515] INFO: Test took 3950ms.
[19:12:39.551] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:12:40.269] INFO: Expecting 41600 events.
[19:12:43.522] INFO: 41600 events read in total (2726ms).
[19:12:43.523] INFO: Test took 3955ms.
[19:12:43.557] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:12:44.277] INFO: Expecting 41600 events.
[19:12:47.523] INFO: 41600 events read in total (2719ms).
[19:12:47.524] INFO: Test took 3949ms.
[19:12:47.559] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:12:48.284] INFO: Expecting 41600 events.
[19:12:51.519] INFO: 41600 events read in total (2708ms).
[19:12:51.520] INFO: Test took 3943ms.
[19:12:51.555] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:12:52.279] INFO: Expecting 41600 events.
[19:12:55.523] INFO: 41600 events read in total (2717ms).
[19:12:55.524] INFO: Test took 3951ms.
[19:12:55.559] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:12:56.280] INFO: Expecting 41600 events.
[19:12:59.519] INFO: 41600 events read in total (2712ms).
[19:12:59.520] INFO: Test took 3943ms.
[19:12:59.554] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:00.275] INFO: Expecting 41600 events.
[19:13:03.519] INFO: 41600 events read in total (2717ms).
[19:13:03.520] INFO: Test took 3948ms.
[19:13:03.554] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:04.278] INFO: Expecting 41600 events.
[19:13:07.516] INFO: 41600 events read in total (2711ms).
[19:13:07.517] INFO: Test took 3943ms.
[19:13:07.552] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:08.277] INFO: Expecting 41600 events.
[19:13:11.518] INFO: 41600 events read in total (2715ms).
[19:13:11.519] INFO: Test took 3949ms.
[19:13:11.553] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:12.274] INFO: Expecting 41600 events.
[19:13:15.527] INFO: 41600 events read in total (2726ms).
[19:13:15.528] INFO: Test took 3957ms.
[19:13:15.563] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:16.283] INFO: Expecting 41600 events.
[19:13:19.526] INFO: 41600 events read in total (2716ms).
[19:13:19.527] INFO: Test took 3944ms.
[19:13:19.561] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:20.285] INFO: Expecting 41600 events.
[19:13:23.530] INFO: 41600 events read in total (2718ms).
[19:13:23.531] INFO: Test took 3952ms.
[19:13:23.565] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:24.286] INFO: Expecting 41600 events.
[19:13:27.526] INFO: 41600 events read in total (2713ms).
[19:13:27.527] INFO: Test took 3943ms.
[19:13:27.561] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:28.281] INFO: Expecting 41600 events.
[19:13:31.559] INFO: 41600 events read in total (2751ms).
[19:13:31.560] INFO: Test took 3980ms.
[19:13:31.595] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:32.314] INFO: Expecting 41600 events.
[19:13:35.535] INFO: 41600 events read in total (2694ms).
[19:13:35.536] INFO: Test took 3923ms.
[19:13:35.571] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:36.296] INFO: Expecting 41600 events.
[19:13:39.369] INFO: 41600 events read in total (2547ms).
[19:13:39.371] INFO: Test took 3782ms.
[19:13:39.405] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:39.767] INFO: enter test to run
[19:13:44.540] INFO: test: HighRate no parameter change
[19:13:44.540] INFO: running: highrate
[19:13:44.541] INFO: ----------------------------------------------------------------------
[19:13:44.541] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[19:13:44.541] INFO: ----------------------------------------------------------------------
[19:13:45.162] INFO: Expecting 208000 events.
[19:13:57.055] INFO: 208000 events read in total (11366ms).
[19:13:57.058] INFO: Test took 12510ms.
[19:13:57.210] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:13:57.464] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0
[19:13:57.464] INFO: number of red-efficiency pixels: 77 56 80 110 148 164 161 112 113 140 120 87 126 64 25 22
[19:13:57.464] INFO: number of X-ray hits detected: 68369 42331 70606 109508 113120 121692 123996 89071 77237 100206 97037 83318 85261 51465 20232 23039
[19:13:57.464] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[19:13:57.464] INFO: number of Vcal hits detected: 207923 207944 207918 207885 207846 207830 207826 207886 207886 207855 207878 207911 207821 207935 207975 207978
[19:13:57.464] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[19:13:57.464] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[19:13:57.464] INFO: X-ray hit rate [MHz/cm2]: 20.0 12.4 20.7 32.1 33.2 35.7 36.3 26.1 22.6 29.4 28.4 24.4 25.0 15.1 5.9 6.8
[19:13:57.464] INFO: PixTestHighRate::doXPixelAlive() done
[19:13:57.512] INFO: PixTest:: pg_setup set to default.
[19:13:57.523] INFO: enter test to run
[19:14:15.564] INFO: test: HighRate no parameter change
[19:14:15.564] INFO: running: highrate
[19:14:15.565] INFO: ----------------------------------------------------------------------
[19:14:15.565] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[19:14:15.565] INFO: ----------------------------------------------------------------------
[19:14:16.182] INFO: Expecting 208000 events.
[19:14:29.800] INFO: 208000 events read in total (13091ms).
[19:14:29.805] INFO: Test took 14230ms.
[19:14:30.094] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:14:30.394] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 6 1 0 0 0
[19:14:30.395] INFO: number of red-efficiency pixels: 273 137 219 402 537 485 498 293 312 430 332 299 354 162 41 55
[19:14:30.395] INFO: number of X-ray hits detected: 136747 85119 143888 220368 228351 245867 248641 180118 156923 201855 195715 168471 173182 103970 41109 46889
[19:14:30.395] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[19:14:30.395] INFO: number of Vcal hits detected: 207702 207861 207766 207572 207404 207476 207451 207687 207669 207522 207651 207277 207567 207825 207958 207945
[19:14:30.395] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.8 99.9 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[19:14:30.395] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.7 99.8 99.8 99.8 99.8 99.7 99.8 99.9 100.0 100.0
[19:14:30.395] INFO: X-ray hit rate [MHz/cm2]: 40.1 24.9 42.2 64.6 66.9 72.1 72.9 52.8 46.0 59.2 57.4 49.4 50.8 30.5 12.0 13.7
[19:14:30.395] INFO: PixTestHighRate::doXPixelAlive() done
[19:14:30.443] INFO: PixTest:: pg_setup set to default.
[19:14:30.460] INFO: enter test to run
[19:14:46.603] INFO: test: HighRate no parameter change
[19:14:46.603] INFO: running: highrate
[19:14:46.604] INFO: ----------------------------------------------------------------------
[19:14:46.604] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[19:14:46.604] INFO: ----------------------------------------------------------------------
[19:14:47.218] INFO: Expecting 208000 events.
[19:15:02.866] INFO: 208000 events read in total (15121ms).
[19:15:02.874] INFO: Test took 16260ms.
[19:15:03.327] INFO: Fetched DAQ statistics. Counters are being reset now.
[19:15:03.678] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 6 1 0 0 0
[19:15:03.678] INFO: number of red-efficiency pixels: 563 320 566 879 1353 1141 1267 745 672 1085 831 773 796 356 80 72
[19:15:03.678] INFO: number of X-ray hits detected: 211571 132021 223103 338945 353150 379441 384714 279762 242936 311626 301806 259226 267500 161544 63609 72734
[19:15:03.678] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[19:15:03.678] INFO: number of Vcal hits detected: 207274 207651 207296 206936 206152 206520 206331 207072 207240 206670 207008 205849 207013 207588 207920 207928
[19:15:03.678] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.7 99.5 99.2 99.4 99.3 99.6 99.7 99.4 99.6 99.1 99.6 99.8 100.0 100.0
[19:15:03.678] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.7 99.5 99.1 99.3 99.2 99.6 99.6 99.4 99.5 99.0 99.5 99.8 100.0 100.0
[19:15:03.678] INFO: X-ray hit rate [MHz/cm2]: 62.0 38.7 65.4 99.3 103.5 111.2 112.8 82.0 71.2 91.3 88.5 76.0 78.4 47.3 18.6 21.3
[19:15:03.679] INFO: PixTestHighRate::doXPixelAlive() done
[19:15:03.724] INFO: PixTest:: pg_setup set to default.
[19:15:03.746] INFO: enter test to run
[19:15:09.251] INFO: test: exit no parameter change
[19:15:09.699] QUIET: Connection to board 33 closed.
[19:15:09.707] INFO: pXar: this is the end, my friend