[11:32:00.518] INFO: *** Welcome to pxar ***
[11:32:00.519] INFO: *** Today: 2016/10/17
[11:32:00.537] INFO: *** Version: v1.9.0-818-g96727
[11:32:00.537] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//dacParameters35_C15.dat
[11:32:00.579] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:32:00.579] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//defaultMaskFile.dat
[11:32:00.596] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C15.dat
[11:32:00.694] INFO: clk: 4
[11:32:00.694] INFO: ctr: 4
[11:32:00.694] INFO: sda: 19
[11:32:00.694] INFO: tin: 9
[11:32:00.694] INFO: level: 15
[11:32:00.694] INFO: triggerdelay: 0
[11:32:00.694] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:32:00.694] INFO: Log level: INFO
[11:32:00.713] QUIET: Connection to board DTB_WREKRL opened.
[11:32:00.717] 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:
------------------------------------------------------
[11:32:00.720] INFO: RPC call hashes of host and DTB match: 398089610
[11:32:02.253] INFO: DUT info:
[11:32:02.253] INFO: The DUT currently contains the following objects:
[11:32:02.253] INFO: 2 TBM Cores tbm08c (2 ON)
[11:32:02.253] INFO: TBM Core alpha (0): 7 registers set
[11:32:02.253] INFO: TBM Core beta (1): 7 registers set
[11:32:02.253] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:32:02.253] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.254] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:32:02.658] INFO: enter 'restricted' command line mode
[11:32:02.658] INFO: enter test to run
[11:32:10.651] INFO: test: PixelAlive no parameter change
[11:32:10.651] INFO: running: pixelalive
[11:32:10.660] INFO: ----------------------------------------------------------------------
[11:32:10.660] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:32:10.660] INFO: ----------------------------------------------------------------------
[11:32:10.978] INFO: Expecting 41600 events.
[11:32:15.302] INFO: 41600 events read in total (3605ms).
[11:32:15.469] INFO: Test took 4805ms.
[11:32:15.483] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:32:15.744] INFO: PixTestAlive::aliveTest() done
[11:32:15.744] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 160 0 0 0 0 0 0 0
[11:32:15.776] INFO: enter test to run
[11:32:22.435] INFO: test: timing no parameter change
[11:32:22.435] INFO: running: timing
[11:32:22.439] INFO: ######################################################################
[11:32:22.439] INFO: PixTestTiming::doTest()
[11:32:22.439] INFO: ######################################################################
[11:32:22.439] INFO: ----------------------------------------------------------------------
[11:32:22.439] INFO: PixTestTiming::TBMPhaseScan()
[11:32:22.439] INFO: ----------------------------------------------------------------------
[11:38:43.681] INFO: TBM Phase Settings: 8
[11:38:43.681] INFO: 400MHz Phase: 2
[11:38:43.681] INFO: 160MHz Phase: 0
[11:38:43.681] INFO: Functional Phase Area: 3
[11:38:43.684] INFO: Test took 381245 ms.
[11:38:43.684] INFO: PixTestTiming::TBMPhaseScan() done.
[11:38:43.684] INFO: ----------------------------------------------------------------------
[11:38:43.684] INFO: PixTestTiming::ROCDelayScan()
[11:38:43.684] INFO: ----------------------------------------------------------------------
[11:42:33.233] INFO: ROC Delay Settings: 219
[11:42:33.234] INFO: ROC Header-Trailer/Token Delay: 11
[11:42:33.234] INFO: ROC Port 0 Delay: 3
[11:42:33.234] INFO: ROC Port 1 Delay: 3
[11:42:33.234] INFO: Functional ROC Area: 6
[11:42:33.237] INFO: Test took 229553 ms.
[11:42:33.237] INFO: PixTestTiming::ROCDelayScan() done.
[11:42:33.237] INFO: ----------------------------------------------------------------------
[11:42:33.237] INFO: PixTestTiming::TimingTest()
[11:42:33.237] INFO: ----------------------------------------------------------------------
[11:42:49.513] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:04.522] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:19.567] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:34.568] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:49.582] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:04.612] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:19.612] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:34.647] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:49.642] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:45:04.654] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:45:05.037] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:45:05.053] INFO: ----------------------------------------------------------------------
[11:45:05.054] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:45:05.054] INFO: ----------------------------------------------------------------------
[11:45:05.054] INFO: ----------------------------------------------------------------------
[11:45:05.054] INFO: Read back bit status: 1
[11:45:05.054] INFO: ----------------------------------------------------------------------
[11:45:05.054] INFO: ----------------------------------------------------------------------
[11:45:05.054] INFO: Timings are good!
[11:45:05.054] INFO: ----------------------------------------------------------------------
[11:45:05.054] INFO: Test took 151817 ms.
[11:45:05.054] INFO: PixTestTiming::TimingTest() done.
[11:45:05.054] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:45:05.054] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:45:05.054] INFO: PixTestTiming::doTest took 762619 ms.
[11:45:05.054] INFO: PixTestTiming::doTest() done
[11:45:05.054] INFO: Write out TBMPhaseScan_0_V0
[11:45:05.054] INFO: Write out TBMPhaseScan_1_V0
[11:45:05.054] INFO: Write out CombinedTBMPhaseScan_V0
[11:45:05.055] INFO: Write out ROCDelayScan3_V0
[11:45:05.056] INFO: enter test to run
[11:47:19.629] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:47:19.629] INFO: running: highrate
[11:47:19.630] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:47:19.908] INFO: ----------------------------------------------------------------------
[11:47:19.908] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:47:19.908] INFO: ----------------------------------------------------------------------
[11:47:19.908] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:47:19.908] INFO: edge/corner pixel THR is adjusted
[11:47:19.908] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:47:20.867] INFO: Collecting data for 5 seconds...
[11:47:25.884] INFO: Done with hot pixel readout
[11:47:37.189] INFO: PixTest:: pg_setup set to default.
[11:47:37.190] INFO: 0 hot pixels found in step 0
[11:47:37.223] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:47:37.226] INFO: PixTest::trimHotPixels() done
[11:47:37.226] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C0.dat
[11:47:37.232] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C1.dat
[11:47:37.239] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C2.dat
[11:47:37.244] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C3.dat
[11:47:37.249] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C4.dat
[11:47:37.254] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C5.dat
[11:47:37.260] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C6.dat
[11:47:37.265] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C7.dat
[11:47:37.270] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C8.dat
[11:47:37.275] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C9.dat
[11:47:37.281] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C10.dat
[11:47:37.286] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C11.dat
[11:47:37.291] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C12.dat
[11:47:37.297] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C13.dat
[11:47:37.302] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C14.dat
[11:47:37.307] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C15.dat
[11:47:37.313] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//defaultMaskFile.dat
[11:47:37.326] INFO: enter test to run
[11:48:00.861] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:48:00.861] INFO: running: highrate
[11:48:00.865] INFO: ----------------------------------------------------------------------
[11:48:00.865] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:48:00.865] INFO: ----------------------------------------------------------------------
[11:48:00.865] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:48:00.865] INFO: edge/corner pixel THR is adjusted
[11:48:00.865] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:48:01.823] INFO: Collecting data for 1 seconds...
[11:48:02.827] INFO: Done with hot pixel readout
[11:48:06.777] INFO: PixTest:: pg_setup set to default.
[11:48:06.777] INFO: 0 hot pixels found in step 0
[11:48:06.783] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:48:06.875] INFO: PixTest::trimHotPixels() done
[11:48:06.875] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C0.dat
[11:48:06.887] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C1.dat
[11:48:06.894] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C2.dat
[11:48:06.899] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C3.dat
[11:48:06.905] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C4.dat
[11:48:06.910] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C5.dat
[11:48:06.915] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C6.dat
[11:48:06.920] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C7.dat
[11:48:06.925] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C8.dat
[11:48:06.931] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C9.dat
[11:48:06.936] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C10.dat
[11:48:06.941] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C11.dat
[11:48:06.946] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C12.dat
[11:48:06.952] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C13.dat
[11:48:06.957] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C14.dat
[11:48:06.962] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C15.dat
[11:48:06.967] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-A-15_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//defaultMaskFile.dat
[11:48:06.977] INFO: enter test to run
[11:48:56.572] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:48:56.572] INFO: running: xray
[11:48:56.574] INFO: ----------------------------------------------------------------------
[11:48:56.574] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:48:56.574] INFO: ----------------------------------------------------------------------
[11:48:57.537] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:49:09.198] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:49:38.639] INFO: Resuming triggers.
[11:49:50.303] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[11:50:19.654] INFO: Resuming triggers.
[11:50:31.309] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:51:00.537] INFO: Resuming triggers.
[11:51:12.195] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:51:41.345] INFO: Resuming triggers.
[11:51:53.006] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[11:52:22.085] INFO: Resuming triggers.
[11:52:33.744] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[11:53:03.069] INFO: Resuming triggers.
[11:53:14.732] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[11:53:44.552] INFO: Resuming triggers.
[11:53:56.210] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[11:54:26.253] INFO: Resuming triggers.
[11:54:33.337] INFO: data taking finished, elapsed time: 100 seconds.
[11:54:51.888] INFO: PixTest:: pg_setup set to default.
[11:54:51.891] INFO: PixTestXray::doPhRun() done
[11:54:52.030] INFO: enter test to run
[11:56:06.226] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:56:06.226] INFO: running: xray
[11:56:06.227] INFO: ----------------------------------------------------------------------
[11:56:06.227] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:56:06.227] INFO: ----------------------------------------------------------------------
[11:56:07.191] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:56:14.228] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[11:56:44.340] INFO: Resuming triggers.
[11:56:51.378] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[11:57:21.481] INFO: Resuming triggers.
[11:57:28.519] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[11:57:58.599] INFO: Resuming triggers.
[11:58:05.638] INFO: run duration 28 seconds, buffer almost full (81%), pausing triggers.
[11:58:35.836] INFO: Resuming triggers.
[11:58:42.882] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[11:59:13.039] INFO: Resuming triggers.
[11:59:20.080] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[11:59:50.187] INFO: Resuming triggers.
[11:59:57.228] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[12:00:27.350] INFO: Resuming triggers.
[12:00:34.396] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[12:01:04.513] INFO: Resuming triggers.
[12:01:11.557] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[12:01:41.590] INFO: Resuming triggers.
[12:01:48.633] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[12:02:18.719] INFO: Resuming triggers.
[12:02:25.757] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[12:02:55.995] INFO: Resuming triggers.
[12:03:03.031] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[12:03:33.969] INFO: Resuming triggers.
[12:03:41.007] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[12:04:11.446] INFO: Resuming triggers.
[12:04:18.488] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[12:04:49.362] INFO: Resuming triggers.
[12:04:51.131] INFO: data taking finished, elapsed time: 100 seconds.
[12:04:59.268] INFO: PixTest:: pg_setup set to default.
[12:04:59.271] INFO: PixTestXray::doPhRun() done
[12:04:59.425] INFO: enter test to run
[12:06:30.421] INFO: test: HighRate no parameter change
[12:06:30.421] INFO: running: highrate
[12:06:30.431] INFO: ----------------------------------------------------------------------
[12:06:30.431] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:06:30.431] INFO: ----------------------------------------------------------------------
[12:06:30.585] INFO: Expecting 768 events.
[12:06:31.721] INFO: 768 events read in total (421ms).
[12:06:31.722] INFO: Test took 1271ms.
[12:06:32.524] INFO: Expecting 41600 events.
[12:06:35.618] INFO: 41600 events read in total (2567ms).
[12:06:35.619] INFO: Test took 3889ms.
[12:06:35.657] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:36.368] INFO: Expecting 41600 events.
[12:06:39.597] INFO: 41600 events read in total (2702ms).
[12:06:39.598] INFO: Test took 3925ms.
[12:06:39.629] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:40.358] INFO: Expecting 41600 events.
[12:06:43.523] INFO: 41600 events read in total (2638ms).
[12:06:43.524] INFO: Test took 3879ms.
[12:06:43.556] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:44.276] INFO: Expecting 41600 events.
[12:06:47.535] INFO: 41600 events read in total (2732ms).
[12:06:47.536] INFO: Test took 3963ms.
[12:06:47.568] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:48.294] INFO: Expecting 41600 events.
[12:06:51.524] INFO: 41600 events read in total (2703ms).
[12:06:51.524] INFO: Test took 3941ms.
[12:06:51.556] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:52.282] INFO: Expecting 41600 events.
[12:06:55.527] INFO: 41600 events read in total (2718ms).
[12:06:55.528] INFO: Test took 3956ms.
[12:06:55.560] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:56.282] INFO: Expecting 41600 events.
[12:06:59.551] INFO: 41600 events read in total (2743ms).
[12:06:59.552] INFO: Test took 3976ms.
[12:06:59.582] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:00.309] INFO: Expecting 41600 events.
[12:07:03.609] INFO: 41600 events read in total (2773ms).
[12:07:03.610] INFO: Test took 4012ms.
[12:07:03.640] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:04.361] INFO: Expecting 41600 events.
[12:07:07.595] INFO: 41600 events read in total (2707ms).
[12:07:07.596] INFO: Test took 3940ms.
[12:07:07.627] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:08.357] INFO: Expecting 41600 events.
[12:07:11.703] INFO: 41600 events read in total (2819ms).
[12:07:11.703] INFO: Test took 4060ms.
[12:07:11.734] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:12.451] INFO: Expecting 41600 events.
[12:07:15.695] INFO: 41600 events read in total (2717ms).
[12:07:15.696] INFO: Test took 3945ms.
[12:07:15.726] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:16.456] INFO: Expecting 41600 events.
[12:07:19.751] INFO: 41600 events read in total (2768ms).
[12:07:19.751] INFO: Test took 4008ms.
[12:07:19.783] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:20.511] INFO: Expecting 41600 events.
[12:07:23.709] INFO: 41600 events read in total (2672ms).
[12:07:23.710] INFO: Test took 3911ms.
[12:07:23.741] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:24.470] INFO: Expecting 41600 events.
[12:07:27.708] INFO: 41600 events read in total (2712ms).
[12:07:27.709] INFO: Test took 3951ms.
[12:07:27.740] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:28.472] INFO: Expecting 41600 events.
[12:07:31.813] INFO: 41600 events read in total (2814ms).
[12:07:31.814] INFO: Test took 4057ms.
[12:07:31.845] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:32.576] INFO: Expecting 41600 events.
[12:07:35.757] INFO: 41600 events read in total (2654ms).
[12:07:35.758] INFO: Test took 3897ms.
[12:07:35.788] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:36.518] INFO: Expecting 41600 events.
[12:07:39.810] INFO: 41600 events read in total (2765ms).
[12:07:39.811] INFO: Test took 4007ms.
[12:07:39.841] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:40.567] INFO: Expecting 41600 events.
[12:07:43.784] INFO: 41600 events read in total (2690ms).
[12:07:43.785] INFO: Test took 3927ms.
[12:07:43.816] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:44.544] INFO: Expecting 41600 events.
[12:07:47.788] INFO: 41600 events read in total (2717ms).
[12:07:47.789] INFO: Test took 3957ms.
[12:07:47.820] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:48.544] INFO: Expecting 41600 events.
[12:07:51.645] INFO: 41600 events read in total (2574ms).
[12:07:51.646] INFO: Test took 3810ms.
[12:07:51.677] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:52.050] INFO: enter test to run
[12:08:22.812] INFO: test: HighRate no parameter change
[12:08:22.813] INFO: running: highrate
[12:08:22.814] INFO: ----------------------------------------------------------------------
[12:08:22.814] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:08:22.814] INFO: ----------------------------------------------------------------------
[12:08:23.432] INFO: Expecting 208000 events.
[12:08:35.021] INFO: 208000 events read in total (11062ms).
[12:08:35.025] INFO: Test took 12202ms.
[12:08:35.155] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:08:35.400] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0
[12:08:35.400] INFO: number of red-efficiency pixels: 55 45 64 93 144 114 101 89 234 88 99 73 81 63 25 26
[12:08:35.400] INFO: number of X-ray hits detected: 53273 37964 59826 93220 99714 98736 97947 65443 59952 80614 83799 68608 74013 45578 19487 23910
[12:08:35.400] 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:08:35.400] INFO: number of Vcal hits detected: 207941 207952 207931 207906 207853 207884 207898 207910 200701 207911 207899 207925 207919 207937 207975 207974
[12:08:35.400] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 100.0 100.0 98.2 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[12:08:35.400] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 100.0 100.0 96.5 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[12:08:35.400] INFO: X-ray hit rate [MHz/cm2]: 15.6 11.1 17.5 27.3 29.2 28.9 28.7 19.2 17.6 23.6 24.6 20.1 21.7 13.4 5.7 7.0
[12:08:35.401] INFO: PixTestHighRate::doXPixelAlive() done
[12:08:35.450] INFO: PixTest:: pg_setup set to default.
[12:08:35.464] INFO: enter test to run
[12:08:54.212] INFO: test: HighRate no parameter change
[12:08:54.212] INFO: running: highrate
[12:08:54.213] INFO: ----------------------------------------------------------------------
[12:08:54.213] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:08:54.213] INFO: ----------------------------------------------------------------------
[12:08:54.832] INFO: Expecting 208000 events.
[12:09:08.151] INFO: 208000 events read in total (12792ms).
[12:09:08.156] INFO: Test took 13934ms.
[12:09:08.429] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:09:08.722] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 144 0 0 0 0 0 0 0
[12:09:08.722] INFO: number of red-efficiency pixels: 156 112 257 361 475 426 384 278 379 342 338 232 256 181 56 74
[12:09:08.722] INFO: number of X-ray hits detected: 120016 85044 132659 207042 222480 221342 217962 147255 135424 180486 185686 153709 165835 102632 43304 53249
[12:09:08.723] 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:09:08.723] INFO: number of Vcal hits detected: 207829 207884 207729 207617 207470 207526 207580 207699 199782 207644 207645 207758 207731 207809 207942 207924
[12:09:08.723] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.6 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[12:09:08.723] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.8 99.9 96.0 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[12:09:08.723] INFO: X-ray hit rate [MHz/cm2]: 35.2 24.9 38.9 60.7 65.2 64.9 63.9 43.2 39.7 52.9 54.4 45.1 48.6 30.1 12.7 15.6
[12:09:08.723] INFO: PixTestHighRate::doXPixelAlive() done
[12:09:08.778] INFO: PixTest:: pg_setup set to default.
[12:09:08.797] INFO: enter test to run
[12:09:32.084] INFO: test: HighRate no parameter change
[12:09:32.084] INFO: running: highrate
[12:09:32.085] INFO: ----------------------------------------------------------------------
[12:09:32.085] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:09:32.085] INFO: ----------------------------------------------------------------------
[12:09:32.704] INFO: Expecting 208000 events.
[12:09:47.834] INFO: 208000 events read in total (14603ms).
[12:09:47.841] INFO: Test took 15747ms.
[12:09:48.251] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:09:48.597] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 141 0 0 0 0 0 0 0
[12:09:48.597] INFO: number of red-efficiency pixels: 332 196 590 832 1235 1088 978 646 698 877 823 457 581 435 103 106
[12:09:48.597] INFO: number of X-ray hits detected: 186036 132167 207554 322681 346701 343849 339883 228503 209967 282057 289817 238849 258280 159508 67404 83540
[12:09:48.597] 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:09:48.597] INFO: number of Vcal hits detected: 207619 207785 207241 207008 206377 206614 206790 207186 199416 206992 207045 207490 207362 207473 207890 207890
[12:09:48.597] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.6 99.3 99.4 99.5 99.7 99.5 99.6 99.6 99.8 99.7 99.8 100.0 99.9
[12:09:48.597] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.6 99.5 99.2 99.3 99.4 99.6 95.9 99.5 99.5 99.8 99.7 99.7 99.9 99.9
[12:09:48.597] INFO: X-ray hit rate [MHz/cm2]: 54.5 38.7 60.8 94.6 101.6 100.8 99.6 67.0 61.5 82.7 84.9 70.0 75.7 46.8 19.8 24.5
[12:09:48.597] INFO: PixTestHighRate::doXPixelAlive() done
[12:09:48.650] INFO: PixTest:: pg_setup set to default.
[12:09:48.666] INFO: enter test to run
[12:09:55.900] INFO: test: exit no parameter change
[12:09:56.284] QUIET: Connection to board 33 closed.
[12:09:56.285] INFO: pXar: this is the end, my friend