[11:08:09.157] INFO: *** Welcome to pxar ***
[11:08:09.157] INFO: *** Today: 2016/11/11
[11:08:12.995] INFO: *** Version: v1.9.0-818-g96727
[11:08:12.995] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//dacParameters35_C15.dat
[11:08:13.198] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:08:13.198] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//defaultMaskFile.dat
[11:08:13.200] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C15.dat
[11:08:14.036] INFO: clk: 4
[11:08:14.036] INFO: ctr: 4
[11:08:14.036] INFO: sda: 19
[11:08:14.036] INFO: tin: 9
[11:08:14.036] INFO: level: 15
[11:08:14.036] INFO: triggerdelay: 0
[11:08:14.036] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:08:14.036] INFO: Log level: INFO
[11:08:14.074] QUIET: Connection to board DTB_WREHUL opened.
[11:08:14.077] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 30
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREHUL
MAC address: 40D85511801E
Hostname: pixelDTB030
Comment:
------------------------------------------------------
[11:08:14.080] INFO: RPC call hashes of host and DTB match: 398089610
[11:08:15.641] INFO: DUT info:
[11:08:15.641] INFO: The DUT currently contains the following objects:
[11:08:15.641] INFO: 2 TBM Cores tbm08c (2 ON)
[11:08:15.661] INFO: TBM Core alpha (0): 7 registers set
[11:08:15.661] INFO: TBM Core beta (1): 7 registers set
[11:08:15.661] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:08:15.661] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.661] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.661] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:15.662] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:08:16.240] INFO: enter 'restricted' command line mode
[11:08:16.240] INFO: enter test to run
[11:08:20.674] INFO: test: PixelAlive no parameter change
[11:08:20.674] INFO: running: pixelalive
[11:08:20.775] INFO: ----------------------------------------------------------------------
[11:08:20.775] 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:08:20.775] INFO: ----------------------------------------------------------------------
[11:08:21.099] INFO: Expecting 41600 events.
[11:08:25.371] INFO: 41600 events read in total (3554ms).
[11:08:25.540] INFO: Test took 4761ms.
[11:08:25.552] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:08:27.085] INFO: PixTestAlive::aliveTest() done
[11:08:27.085] INFO: number of dead pixels (per ROC): 0 0 0 3 0 0 36 0 0 0 0 0 2 0 0 0
[11:08:27.462] INFO: enter test to run
[11:08:31.009] INFO: test: timing no parameter change
[11:08:31.010] INFO: running: timing
[11:08:31.013] INFO: ######################################################################
[11:08:31.053] INFO: PixTestTiming::doTest()
[11:08:31.053] INFO: ######################################################################
[11:08:31.053] INFO: ----------------------------------------------------------------------
[11:08:31.053] INFO: PixTestTiming::TBMPhaseScan()
[11:08:31.053] INFO: ----------------------------------------------------------------------
[11:14:06.986] INFO: TBM Phase Settings: 236
[11:14:06.986] INFO: 400MHz Phase: 3
[11:14:06.986] INFO: 160MHz Phase: 7
[11:14:06.986] INFO: Functional Phase Area: 3
[11:14:07.014] INFO: Test took 335961 ms.
[11:14:07.014] INFO: PixTestTiming::TBMPhaseScan() done.
[11:14:07.014] INFO: ----------------------------------------------------------------------
[11:14:07.014] INFO: PixTestTiming::ROCDelayScan()
[11:14:07.014] INFO: ----------------------------------------------------------------------
[11:15:58.762] INFO: ROC Delay Settings: 228
[11:15:58.762] INFO: ROC Header-Trailer/Token Delay: 11
[11:15:58.762] INFO: ROC Port 0 Delay: 4
[11:15:58.762] INFO: ROC Port 1 Delay: 4
[11:15:58.762] INFO: Functional ROC Area: 3
[11:15:58.765] INFO: Test took 111751 ms.
[11:15:58.765] INFO: PixTestTiming::ROCDelayScan() done.
[11:15:58.766] INFO: ----------------------------------------------------------------------
[11:15:58.766] INFO: PixTestTiming::TimingTest()
[11:15:58.766] INFO: ----------------------------------------------------------------------
[11:16:15.077] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:16:30.220] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:16:45.357] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:00.508] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:15.631] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:30.789] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:45.946] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:18:01.088] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:18:16.233] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:18:31.361] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:18:31.739] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:18:31.757] INFO: ----------------------------------------------------------------------
[11:18:31.757] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:18:31.757] INFO: ----------------------------------------------------------------------
[11:18:31.757] INFO: ----------------------------------------------------------------------
[11:18:31.757] INFO: Read back bit status: 1
[11:18:31.757] INFO: ----------------------------------------------------------------------
[11:18:31.757] INFO: ----------------------------------------------------------------------
[11:18:31.757] INFO: Timings are good!
[11:18:31.757] INFO: ----------------------------------------------------------------------
[11:18:31.757] INFO: Test took 152992 ms.
[11:18:31.757] INFO: PixTestTiming::TimingTest() done.
[11:18:31.796] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:18:31.796] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:18:31.796] INFO: PixTestTiming::doTest took 600786 ms.
[11:18:31.796] INFO: PixTestTiming::doTest() done
[11:18:31.796] INFO: Write out TBMPhaseScan_0_V0
[11:18:31.847] INFO: Write out TBMPhaseScan_1_V0
[11:18:31.848] INFO: Write out CombinedTBMPhaseScan_V0
[11:18:31.906] INFO: Write out ROCDelayScan3_V0
[11:18:31.962] INFO: enter test to run
[11:19:21.502] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:19:21.511] INFO: running: highrate
[11:19:21.586] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:19:21.886] INFO: ----------------------------------------------------------------------
[11:19:21.886] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:19:21.886] INFO: ----------------------------------------------------------------------
[11:19:21.886] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:19:21.886] INFO: edge/corner pixel THR is adjusted
[11:19:21.886] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:19:22.874] INFO: Collecting data for 5 seconds...
[11:19:27.891] INFO: Done with hot pixel readout
[11:19:39.449] INFO: PixTest:: pg_setup set to default.
[11:19:39.450] INFO: 5 hot pixels found in step 0
[11:19:40.441] INFO: Collecting data for 5 seconds...
[11:19:45.457] INFO: Done with hot pixel readout
[11:19:56.983] INFO: PixTest:: pg_setup set to default.
[11:19:56.984] INFO: 2 hot pixels found in step 1
[11:19:57.975] INFO: Collecting data for 5 seconds...
[11:20:02.992] INFO: Done with hot pixel readout
[11:20:14.431] INFO: PixTest:: pg_setup set to default.
[11:20:14.432] INFO: 0 hot pixels found in step 2
[11:20:14.466] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:20:14.469] INFO: PixTest::trimHotPixels() done
[11:20:14.486] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C0.dat
[11:20:14.497] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C1.dat
[11:20:14.503] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C2.dat
[11:20:14.508] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C3.dat
[11:20:14.514] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C4.dat
[11:20:14.519] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C5.dat
[11:20:14.525] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C6.dat
[11:20:14.531] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C7.dat
[11:20:14.536] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C8.dat
[11:20:14.542] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C9.dat
[11:20:14.547] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C10.dat
[11:20:14.554] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C11.dat
[11:20:14.559] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C12.dat
[11:20:14.565] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C13.dat
[11:20:14.570] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C14.dat
[11:20:14.575] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C15.dat
[11:20:14.581] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//defaultMaskFile.dat
[11:20:14.596] INFO: enter test to run
[11:20:46.765] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:20:46.765] INFO: running: highrate
[11:20:46.769] INFO: ----------------------------------------------------------------------
[11:20:46.769] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:20:46.770] INFO: ----------------------------------------------------------------------
[11:20:46.770] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:20:46.770] INFO: edge/corner pixel THR is adjusted
[11:20:46.770] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:20:47.728] INFO: Collecting data for 1 seconds...
[11:20:48.732] INFO: Done with hot pixel readout
[11:20:52.615] INFO: PixTest:: pg_setup set to default.
[11:20:52.616] INFO: 0 hot pixels found in step 0
[11:20:52.622] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:20:52.721] INFO: PixTest::trimHotPixels() done
[11:20:52.721] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C0.dat
[11:20:52.731] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C1.dat
[11:20:52.743] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C2.dat
[11:20:52.748] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C3.dat
[11:20:52.754] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C4.dat
[11:20:52.759] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C5.dat
[11:20:52.764] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C6.dat
[11:20:52.770] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C7.dat
[11:20:52.775] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C8.dat
[11:20:52.780] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C9.dat
[11:20:52.786] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C10.dat
[11:20:52.791] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C11.dat
[11:20:52.796] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C12.dat
[11:20:52.802] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C13.dat
[11:20:52.807] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C14.dat
[11:20:52.813] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C15.dat
[11:20:52.818] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-5-21_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//defaultMaskFile.dat
[11:20:52.835] INFO: enter test to run
[11:21:22.741] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:21:22.741] INFO: running: xray
[11:21:22.742] INFO: ----------------------------------------------------------------------
[11:21:22.742] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:21:22.742] INFO: ----------------------------------------------------------------------
[11:21:23.720] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:21:35.610] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:22:05.885] INFO: Resuming triggers.
[11:22:17.774] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[11:22:48.068] INFO: Resuming triggers.
[11:22:59.957] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[11:23:29.941] INFO: Resuming triggers.
[11:23:41.827] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[11:24:11.338] INFO: Resuming triggers.
[11:24:23.226] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[11:24:52.476] INFO: Resuming triggers.
[11:25:04.367] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[11:25:34.702] INFO: Resuming triggers.
[11:25:46.593] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[11:26:16.668] INFO: Resuming triggers.
[11:26:28.551] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[11:26:58.671] INFO: Resuming triggers.
[11:27:03.936] INFO: data taking finished, elapsed time: 100 seconds.
[11:27:17.977] INFO: PixTest:: pg_setup set to default.
[11:27:17.981] INFO: PixTestXray::doPhRun() done
[11:27:18.469] INFO: enter test to run
[11:28:06.778] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:28:06.778] INFO: running: xray
[11:28:06.779] INFO: ----------------------------------------------------------------------
[11:28:06.779] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:28:06.779] INFO: ----------------------------------------------------------------------
[11:28:07.742] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:28:14.890] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[11:28:46.430] INFO: Resuming triggers.
[11:28:53.577] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[11:29:25.424] INFO: Resuming triggers.
[11:29:32.574] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[11:30:04.461] INFO: Resuming triggers.
[11:30:11.612] INFO: run duration 28 seconds, buffer almost full (81%), pausing triggers.
[11:30:42.934] INFO: Resuming triggers.
[11:30:50.086] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[11:31:20.715] INFO: Resuming triggers.
[11:31:27.867] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[11:31:58.501] INFO: Resuming triggers.
[11:32:05.652] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[11:32:36.525] INFO: Resuming triggers.
[11:32:43.678] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[11:33:14.602] INFO: Resuming triggers.
[11:33:21.757] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[11:33:52.369] INFO: Resuming triggers.
[11:33:59.521] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[11:34:30.115] INFO: Resuming triggers.
[11:34:37.268] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[11:35:07.934] INFO: Resuming triggers.
[11:35:15.087] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[11:35:45.682] INFO: Resuming triggers.
[11:35:52.833] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[11:36:23.455] INFO: Resuming triggers.
[11:36:30.606] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[11:37:01.849] INFO: Resuming triggers.
[11:37:02.080] INFO: data taking finished, elapsed time: 100 seconds.
[11:37:03.458] INFO: PixTest:: pg_setup set to default.
[11:37:03.461] INFO: PixTestXray::doPhRun() done
[11:37:03.645] INFO: enter test to run
[11:37:45.174] INFO: test: HighRate no parameter change
[11:37:45.174] INFO: running: highrate
[11:37:45.196] INFO: ----------------------------------------------------------------------
[11:37:45.196] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:37:45.196] INFO: ----------------------------------------------------------------------
[11:37:45.400] INFO: Expecting 768 events.
[11:37:46.542] INFO: 768 events read in total (426ms).
[11:37:46.542] INFO: Test took 1275ms.
[11:37:47.345] INFO: Expecting 41600 events.
[11:37:50.477] INFO: 41600 events read in total (2606ms).
[11:37:50.478] INFO: Test took 3817ms.
[11:37:50.511] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:37:51.237] INFO: Expecting 41600 events.
[11:37:54.437] INFO: 41600 events read in total (2674ms).
[11:37:54.438] INFO: Test took 3910ms.
[11:37:54.469] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:37:55.196] INFO: Expecting 41600 events.
[11:37:58.424] INFO: 41600 events read in total (2701ms).
[11:37:58.425] INFO: Test took 3939ms.
[11:37:58.457] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:37:59.182] INFO: Expecting 41600 events.
[11:38:02.435] INFO: 41600 events read in total (2726ms).
[11:38:02.436] INFO: Test took 3963ms.
[11:38:02.471] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:03.193] INFO: Expecting 41600 events.
[11:38:06.421] INFO: 41600 events read in total (2702ms).
[11:38:06.422] INFO: Test took 3927ms.
[11:38:06.454] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:07.173] INFO: Expecting 41600 events.
[11:38:10.461] INFO: 41600 events read in total (2761ms).
[11:38:10.462] INFO: Test took 3991ms.
[11:38:10.495] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:11.219] INFO: Expecting 41600 events.
[11:38:14.556] INFO: 41600 events read in total (2810ms).
[11:38:14.557] INFO: Test took 4045ms.
[11:38:14.590] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:15.318] INFO: Expecting 41600 events.
[11:38:18.573] INFO: 41600 events read in total (2728ms).
[11:38:18.574] INFO: Test took 3966ms.
[11:38:18.606] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:19.332] INFO: Expecting 41600 events.
[11:38:22.533] INFO: 41600 events read in total (2674ms).
[11:38:22.534] INFO: Test took 3912ms.
[11:38:22.566] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:23.291] INFO: Expecting 41600 events.
[11:38:26.422] INFO: 41600 events read in total (2604ms).
[11:38:26.423] INFO: Test took 3841ms.
[11:38:26.456] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:27.187] INFO: Expecting 41600 events.
[11:38:30.155] INFO: 41600 events read in total (2442ms).
[11:38:30.156] INFO: Test took 3683ms.
[11:38:30.190] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:30.918] INFO: Expecting 41600 events.
[11:38:34.123] INFO: 41600 events read in total (2678ms).
[11:38:34.124] INFO: Test took 3915ms.
[11:38:34.157] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:34.882] INFO: Expecting 41600 events.
[11:38:38.032] INFO: 41600 events read in total (2624ms).
[11:38:38.033] INFO: Test took 3860ms.
[11:38:38.065] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:38.796] INFO: Expecting 41600 events.
[11:38:42.025] INFO: 41600 events read in total (2703ms).
[11:38:42.026] INFO: Test took 3942ms.
[11:38:42.058] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:42.788] INFO: Expecting 41600 events.
[11:38:46.007] INFO: 41600 events read in total (2692ms).
[11:38:46.008] INFO: Test took 3933ms.
[11:38:46.039] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:46.769] INFO: Expecting 41600 events.
[11:38:49.002] INFO: 41600 events read in total (2706ms).
[11:38:49.003] INFO: Test took 3946ms.
[11:38:50.035] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:50.763] INFO: Expecting 41600 events.
[11:38:53.004] INFO: 41600 events read in total (2714ms).
[11:38:53.005] INFO: Test took 3953ms.
[11:38:54.038] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:54.760] INFO: Expecting 41600 events.
[11:38:57.983] INFO: 41600 events read in total (2696ms).
[11:38:57.984] INFO: Test took 3926ms.
[11:38:58.015] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:58.744] INFO: Expecting 41600 events.
[11:39:01.861] INFO: 41600 events read in total (2590ms).
[11:39:01.862] INFO: Test took 3828ms.
[11:39:01.893] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:02.622] INFO: Expecting 41600 events.
[11:39:05.719] INFO: 41600 events read in total (2570ms).
[11:39:05.888] INFO: Test took 3977ms.
[11:39:06.531] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:06.794] INFO: enter test to run
[11:39:13.053] INFO: test: HighRate no parameter change
[11:39:13.053] INFO: running: highrate
[11:39:13.070] INFO: ----------------------------------------------------------------------
[11:39:13.070] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:39:13.070] INFO: ----------------------------------------------------------------------
[11:39:13.742] INFO: Expecting 208000 events.
[11:39:25.452] INFO: 208000 events read in total (11183ms).
[11:39:25.455] INFO: Test took 12319ms.
[11:39:25.586] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:25.840] INFO: number of dead pixels (per ROC): 0 0 0 3 0 0 37 0 0 0 0 0 162 0 0 0
[11:39:25.890] INFO: number of red-efficiency pixels: 61 41 68 110 118 139 172 96 73 112 121 106 273 72 14 25
[11:39:25.890] INFO: number of X-ray hits detected: 51077 33592 57889 89675 95577 103619 98059 72742 69940 94720 92863 77991 79162 50538 19345 20977
[11:39:25.890] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:39:25.890] INFO: number of Vcal hits detected: 207938 207958 207930 207737 207879 207857 206011 207903 207926 207884 207877 207893 199785 207926 207986 207975
[11:39:25.890] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[11:39:25.890] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.0 100.0 100.0 99.9 99.9 99.9 96.1 100.0 100.0 100.0
[11:39:25.890] INFO: X-ray hit rate [MHz/cm2]: 15.0 9.8 17.0 26.3 28.0 30.4 28.7 21.3 20.5 27.8 27.2 22.9 23.2 14.8 5.7 6.1
[11:39:25.890] INFO: PixTestHighRate::doXPixelAlive() done
[11:39:25.937] INFO: PixTest:: pg_setup set to default.
[11:39:25.953] INFO: enter test to run
[11:40:03.189] INFO: test: HighRate no parameter change
[11:40:03.189] INFO: running: highrate
[11:40:03.190] INFO: ----------------------------------------------------------------------
[11:40:03.190] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:40:03.190] INFO: ----------------------------------------------------------------------
[11:40:03.812] INFO: Expecting 208000 events.
[11:40:17.094] INFO: 208000 events read in total (12755ms).
[11:40:17.099] INFO: Test took 13900ms.
[11:40:17.363] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:17.657] INFO: number of dead pixels (per ROC): 0 0 0 3 0 0 36 0 0 0 0 0 162 0 0 0
[11:40:17.657] INFO: number of red-efficiency pixels: 155 100 231 336 317 490 430 316 191 318 369 297 460 207 44 46
[11:40:17.657] INFO: number of X-ray hits detected: 106670 69547 120431 186423 198223 215106 204935 151553 146983 196651 192132 161962 164272 107215 40898 44156
[11:40:17.657] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:40:17.657] INFO: number of Vcal hits detected: 207841 207897 207753 207503 207664 207467 205733 207667 207800 207664 207607 207685 199584 207781 207956 207953
[11:40:17.657] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.8 99.9 99.8 99.8 99.8 99.9 99.9 99.8 99.9 99.9 99.9 100.0 100.0
[11:40:17.657] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.7 98.9 99.8 99.9 99.8 99.8 99.8 96.0 99.9 100.0 100.0
[11:40:17.657] INFO: X-ray hit rate [MHz/cm2]: 31.3 20.4 35.3 54.6 58.1 63.0 60.1 44.4 43.1 57.6 56.3 47.5 48.1 31.4 12.0 12.9
[11:40:17.657] INFO: PixTestHighRate::doXPixelAlive() done
[11:40:17.704] INFO: PixTest:: pg_setup set to default.
[11:40:17.724] INFO: enter test to run
[11:40:43.285] INFO: test: HighRate no parameter change
[11:40:43.285] INFO: running: highrate
[11:40:43.286] INFO: ----------------------------------------------------------------------
[11:40:43.286] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:40:43.286] INFO: ----------------------------------------------------------------------
[11:40:43.906] INFO: Expecting 208000 events.
[11:40:58.806] INFO: 208000 events read in total (14373ms).
[11:40:58.813] INFO: Test took 15518ms.
[11:40:59.211] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:59.548] INFO: number of dead pixels (per ROC): 0 0 0 3 0 0 35 0 0 0 0 0 162 0 0 0
[11:40:59.548] INFO: number of red-efficiency pixels: 362 156 501 781 872 1135 988 662 418 761 918 693 802 429 70 58
[11:40:59.548] INFO: number of X-ray hits detected: 161344 105322 184225 283057 299367 326007 309886 229713 222464 296835 293664 245184 249040 161742 62168 66667
[11:40:59.548] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:40:59.548] INFO: number of Vcal hits detected: 207599 207841 207386 206927 206999 206585 205043 207201 207533 207125 206886 207198 199181 207480 207929 207939
[11:40:59.548] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.6 99.6 99.4 99.5 99.7 99.8 99.6 99.5 99.7 99.7 99.8 100.0 100.0
[11:40:59.548] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.5 99.5 99.3 98.6 99.6 99.8 99.6 99.5 99.6 95.8 99.8 100.0 100.0
[11:40:59.548] INFO: X-ray hit rate [MHz/cm2]: 47.3 30.9 54.0 83.0 87.7 95.6 90.8 67.3 65.2 87.0 86.1 71.9 73.0 47.4 18.2 19.5
[11:40:59.548] INFO: PixTestHighRate::doXPixelAlive() done
[11:40:59.596] INFO: PixTest:: pg_setup set to default.
[11:40:59.611] INFO: enter test to run
[11:41:18.413] INFO: test: exit no parameter change
[11:41:19.679] QUIET: Connection to board 30 closed.
[11:41:19.974] INFO: pXar: this is the end, my friend