[11:54:43.332] INFO: *** Welcome to pxar ***
[11:54:43.332] INFO: *** Today: 2016/08/03
[11:54:43.377] INFO: *** Version: v1.9.0-818-g96727
[11:54:43.377] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//dacParameters35_C15.dat
[11:54:43.407] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:54:43.407] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//defaultMaskFile.dat
[11:54:43.412] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C15.dat
[11:54:43.513] INFO: clk: 4
[11:54:43.513] INFO: ctr: 4
[11:54:43.513] INFO: sda: 19
[11:54:43.513] INFO: tin: 9
[11:54:43.513] INFO: level: 15
[11:54:43.513] INFO: triggerdelay: 0
[11:54:43.513] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:54:43.513] INFO: Log level: INFO
[11:54:43.529] QUIET: Connection to board DTB_WREKRL opened.
[11:54:43.532] 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:54:43.535] INFO: RPC call hashes of host and DTB match: 398089610
[11:54:45.073] INFO: DUT info:
[11:54:45.073] INFO: The DUT currently contains the following objects:
[11:54:45.073] INFO: 2 TBM Cores tbm08c (2 ON)
[11:54:45.073] INFO: TBM Core alpha (0): 7 registers set
[11:54:45.073] INFO: TBM Core beta (1): 7 registers set
[11:54:45.073] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:54:45.073] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.074] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:45.478] INFO: enter 'restricted' command line mode
[11:54:45.478] INFO: enter test to run
[11:55:01.327] INFO: test: PixelAlive no parameter change
[11:55:01.327] INFO: running: pixelalive
[11:55:01.353] INFO: ----------------------------------------------------------------------
[11:55:01.353] 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:55:01.353] INFO: ----------------------------------------------------------------------
[11:55:01.721] INFO: Expecting 41600 events.
[11:55:06.077] INFO: 41600 events read in total (3638ms).
[11:55:06.205] INFO: Test took 4829ms.
[11:55:06.219] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:06.483] INFO: PixTestAlive::aliveTest() done
[11:55:06.483] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 0 1 50 4 0 0 0 0 0 0
[11:55:06.522] INFO: enter test to run
[11:56:45.542] INFO: test: timing no parameter change
[11:56:45.542] INFO: running: timing
[11:56:45.559] INFO: ######################################################################
[11:56:45.559] INFO: PixTestTiming::doTest()
[11:56:45.559] INFO: ######################################################################
[11:56:45.559] INFO: ----------------------------------------------------------------------
[11:56:45.559] INFO: PixTestTiming::TBMPhaseScan()
[11:56:45.559] INFO: ----------------------------------------------------------------------
[12:00:56.277] INFO: TBM Phase Settings: 204
[12:00:56.277] INFO: 400MHz Phase: 3
[12:00:56.277] INFO: 160MHz Phase: 6
[12:00:56.277] INFO: Functional Phase Area: 4
[12:00:56.286] INFO: Test took 250727 ms.
[12:00:56.286] INFO: PixTestTiming::TBMPhaseScan() done.
[12:00:56.286] INFO: ----------------------------------------------------------------------
[12:00:56.286] INFO: PixTestTiming::ROCDelayScan()
[12:00:56.286] INFO: ----------------------------------------------------------------------
[12:02:50.903] INFO: ROC Delay Settings: 219
[12:02:50.904] INFO: ROC Header-Trailer/Token Delay: 11
[12:02:50.904] INFO: ROC Port 0 Delay: 3
[12:02:50.904] INFO: ROC Port 1 Delay: 3
[12:02:50.904] INFO: Functional ROC Area: 3
[12:02:50.907] INFO: Test took 114621 ms.
[12:02:50.907] INFO: PixTestTiming::ROCDelayScan() done.
[12:02:50.907] INFO: ----------------------------------------------------------------------
[12:02:50.907] INFO: PixTestTiming::TimingTest()
[12:02:50.907] INFO: ----------------------------------------------------------------------
[12:03:07.069] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:22.065] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:37.052] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:52.037] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:04:06.002] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:04:21.981] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:04:36.940] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:04:51.896] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:07.054] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:22.359] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:22.737] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:22.754] INFO: ----------------------------------------------------------------------
[12:05:22.754] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:05:22.754] INFO: ----------------------------------------------------------------------
[12:05:22.754] INFO: ----------------------------------------------------------------------
[12:05:22.754] INFO: Read back bit status: 1
[12:05:22.754] INFO: ----------------------------------------------------------------------
[12:05:22.754] INFO: ----------------------------------------------------------------------
[12:05:22.754] INFO: Timings are good!
[12:05:22.754] INFO: ----------------------------------------------------------------------
[12:05:22.754] INFO: Test took 151847 ms.
[12:05:22.754] INFO: PixTestTiming::TimingTest() done.
[12:05:22.774] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:05:22.775] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:05:22.775] INFO: PixTestTiming::doTest took 517219 ms.
[12:05:22.775] INFO: PixTestTiming::doTest() done
[12:05:22.775] INFO: Write out TBMPhaseScan_0_V0
[12:05:22.775] INFO: Write out TBMPhaseScan_1_V0
[12:05:22.775] INFO: Write out CombinedTBMPhaseScan_V0
[12:05:22.790] INFO: Write out ROCDelayScan3_V0
[12:05:22.790] INFO: enter test to run
[12:07:07.514] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:07:07.514] INFO: running: highrate
[12:07:07.515] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:07:07.739] INFO: ----------------------------------------------------------------------
[12:07:07.739] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:07:07.739] INFO: ----------------------------------------------------------------------
[12:07:07.739] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:07:07.739] INFO: edge/corner pixel THR is adjusted
[12:07:07.739] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:07:08.697] INFO: Collecting data for 5 seconds...
[12:07:13.715] INFO: Done with hot pixel readout
[12:07:25.151] INFO: PixTest:: pg_setup set to default.
[12:07:25.152] INFO: 6 hot pixels found in step 0
[12:07:26.144] INFO: Collecting data for 5 seconds...
[12:07:31.164] INFO: Done with hot pixel readout
[12:07:42.460] INFO: PixTest:: pg_setup set to default.
[12:07:42.461] INFO: 7 hot pixels found in step 1
[12:07:43.451] INFO: Collecting data for 5 seconds...
[12:07:48.469] INFO: Done with hot pixel readout
[12:08:00.028] INFO: PixTest:: pg_setup set to default.
[12:08:00.029] INFO: 4 hot pixels found in step 2
[12:08:01.020] INFO: Collecting data for 5 seconds...
[12:08:06.037] INFO: Done with hot pixel readout
[12:08:17.553] INFO: PixTest:: pg_setup set to default.
[12:08:17.554] INFO: 7 hot pixels found in step 3
[12:08:18.545] INFO: Collecting data for 5 seconds...
[12:08:23.565] INFO: Done with hot pixel readout
[12:08:35.142] INFO: PixTest:: pg_setup set to default.
[12:08:35.143] INFO: 8 hot pixels found in step 4
[12:08:36.134] INFO: Collecting data for 5 seconds...
[12:08:41.153] INFO: Done with hot pixel readout
[12:08:51.904] INFO: PixTest:: pg_setup set to default.
[12:08:51.905] INFO: 8 hot pixels found in step 5
[12:08:52.897] INFO: Collecting data for 5 seconds...
[12:08:57.912] INFO: Done with hot pixel readout
[12:09:09.333] INFO: PixTest:: pg_setup set to default.
[12:09:09.334] INFO: 6 hot pixels found in step 6
[12:09:10.326] INFO: Collecting data for 5 seconds...
[12:09:15.343] INFO: Done with hot pixel readout
[12:09:26.661] INFO: PixTest:: pg_setup set to default.
[12:09:26.661] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:09:26.662] INFO: 3 hot pixels found in step 7
[12:09:27.653] INFO: Collecting data for 5 seconds...
[12:09:32.669] INFO: Done with hot pixel readout
[12:09:43.979] INFO: PixTest:: pg_setup set to default.
[12:09:43.979] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:09:43.980] INFO: 1 hot pixels found in step 8
[12:09:44.014] INFO: 1 hot pixels could not be trimmed and have been masked.
[12:09:44.018] INFO: PixTest::trimHotPixels() done
[12:09:44.018] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C0.dat
[12:09:44.024] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C1.dat
[12:09:44.030] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C2.dat
[12:09:44.036] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C3.dat
[12:09:44.041] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C4.dat
[12:09:44.046] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C5.dat
[12:09:44.051] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C6.dat
[12:09:44.056] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C7.dat
[12:09:44.061] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C8.dat
[12:09:44.067] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C9.dat
[12:09:44.072] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C10.dat
[12:09:44.077] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C11.dat
[12:09:44.082] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C12.dat
[12:09:44.087] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C13.dat
[12:09:44.093] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C14.dat
[12:09:44.098] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C15.dat
[12:09:44.103] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//defaultMaskFile.dat
[12:09:44.117] INFO: enter test to run
[12:10:28.089] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:10:28.089] INFO: running: highrate
[12:10:28.093] INFO: ----------------------------------------------------------------------
[12:10:28.093] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:10:28.093] INFO: ----------------------------------------------------------------------
[12:10:28.093] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:10:28.093] INFO: edge/corner pixel THR is adjusted
[12:10:28.093] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:10:29.052] INFO: Collecting data for 1 seconds...
[12:10:30.055] INFO: Done with hot pixel readout
[12:10:33.833] INFO: PixTest:: pg_setup set to default.
[12:10:33.834] INFO: 0 hot pixels found in step 0
[12:10:33.839] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:10:33.937] INFO: PixTest::trimHotPixels() done
[12:10:33.938] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C0.dat
[12:10:33.948] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C1.dat
[12:10:33.955] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C2.dat
[12:10:33.960] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C3.dat
[12:10:33.965] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C4.dat
[12:10:33.970] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C5.dat
[12:10:33.976] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C6.dat
[12:10:33.981] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C7.dat
[12:10:33.986] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C8.dat
[12:10:33.991] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C9.dat
[12:10:33.997] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C10.dat
[12:10:33.002] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C11.dat
[12:10:34.008] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C12.dat
[12:10:34.013] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C13.dat
[12:10:34.019] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C14.dat
[12:10:34.024] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//trimParameters35_C15.dat
[12:10:34.029] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-K-2-02_FPIXTest-17C-FNAL-160729-0950_2016-07-29_09h50m_1469803811/000_FPIXTest_p17//defaultMaskFile.dat
[12:10:34.039] INFO: enter test to run
[12:11:15.985] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:11:15.985] INFO: running: xray
[12:11:15.986] INFO: ----------------------------------------------------------------------
[12:11:15.986] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:11:15.986] INFO: ----------------------------------------------------------------------
[12:11:16.949] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:11:28.608] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:11:57.558] INFO: Resuming triggers.
[12:12:09.314] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[12:12:38.452] INFO: Resuming triggers.
[12:12:50.115] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[12:13:19.270] INFO: Resuming triggers.
[12:13:30.929] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[12:13:59.992] INFO: Resuming triggers.
[12:14:11.656] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[12:14:40.716] INFO: Resuming triggers.
[12:14:52.380] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[12:15:21.514] INFO: Resuming triggers.
[12:15:33.177] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[12:16:01.336] INFO: Resuming triggers.
[12:16:12.001] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[12:16:42.021] INFO: Resuming triggers.
[12:16:49.043] INFO: data taking finished, elapsed time: 100 seconds.
[12:17:06.966] INFO: PixTest:: pg_setup set to default.
[12:17:06.969] INFO: PixTestXray::doPhRun() done
[12:17:07.108] INFO: enter test to run
[12:18:07.454] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:18:07.454] INFO: running: xray
[12:18:07.455] INFO: ----------------------------------------------------------------------
[12:18:07.455] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:18:07.455] INFO: ----------------------------------------------------------------------
[12:18:08.419] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:18:15.420] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:18:45.080] INFO: Resuming triggers.
[12:18:52.084] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[12:19:21.934] INFO: Resuming triggers.
[12:19:28.935] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[12:19:59.378] INFO: Resuming triggers.
[12:20:06.380] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[12:20:37.867] INFO: Resuming triggers.
[12:20:44.868] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[12:21:15.584] INFO: Resuming triggers.
[12:21:22.585] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[12:21:52.981] INFO: Resuming triggers.
[12:21:59.981] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[12:22:30.534] INFO: Resuming triggers.
[12:22:37.532] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[12:23:07.973] INFO: Resuming triggers.
[12:23:14.972] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[12:23:45.469] INFO: Resuming triggers.
[12:23:52.468] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[12:24:22.922] INFO: Resuming triggers.
[12:24:29.920] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[12:25:00.375] INFO: Resuming triggers.
[12:25:07.377] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[12:25:37.794] INFO: Resuming triggers.
[12:25:44.797] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[12:26:15.178] INFO: Resuming triggers.
[12:26:22.180] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[12:26:52.709] INFO: Resuming triggers.
[12:26:55.036] INFO: data taking finished, elapsed time: 100 seconds.
[12:27:05.468] INFO: PixTest:: pg_setup set to default.
[12:27:05.471] INFO: PixTestXray::doPhRun() done
[12:27:05.621] INFO: enter test to run
[12:28:28.330] INFO: test: HighRate no parameter change
[12:28:28.330] INFO: running: highrate
[12:28:28.331] INFO: ----------------------------------------------------------------------
[12:28:28.331] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:28:28.331] INFO: ----------------------------------------------------------------------
[12:28:28.473] INFO: Expecting 768 events.
[12:28:29.606] INFO: 768 events read in total (418ms).
[12:28:29.606] INFO: Test took 1268ms.
[12:28:30.409] INFO: Expecting 41600 events.
[12:28:33.500] INFO: 41600 events read in total (2564ms).
[12:28:33.501] INFO: Test took 3887ms.
[12:28:33.536] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:34.263] INFO: Expecting 41600 events.
[12:28:37.452] INFO: 41600 events read in total (2662ms).
[12:28:37.453] INFO: Test took 3900ms.
[12:28:37.485] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:38.215] INFO: Expecting 41600 events.
[12:28:41.435] INFO: 41600 events read in total (2693ms).
[12:28:41.436] INFO: Test took 3934ms.
[12:28:41.469] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:42.196] INFO: Expecting 41600 events.
[12:28:45.444] INFO: 41600 events read in total (2721ms).
[12:28:45.445] INFO: Test took 3958ms.
[12:28:45.477] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:46.205] INFO: Expecting 41600 events.
[12:28:49.453] INFO: 41600 events read in total (2721ms).
[12:28:49.454] INFO: Test took 3959ms.
[12:28:49.487] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:50.214] INFO: Expecting 41600 events.
[12:28:53.474] INFO: 41600 events read in total (2733ms).
[12:28:53.475] INFO: Test took 3970ms.
[12:28:53.507] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:54.236] INFO: Expecting 41600 events.
[12:28:57.489] INFO: 41600 events read in total (2726ms).
[12:28:57.490] INFO: Test took 3965ms.
[12:28:57.523] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:58.247] INFO: Expecting 41600 events.
[12:29:01.503] INFO: 41600 events read in total (2729ms).
[12:29:01.503] INFO: Test took 3962ms.
[12:29:01.536] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:02.265] INFO: Expecting 41600 events.
[12:29:05.520] INFO: 41600 events read in total (2728ms).
[12:29:05.521] INFO: Test took 3969ms.
[12:29:05.554] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:06.282] INFO: Expecting 41600 events.
[12:29:09.536] INFO: 41600 events read in total (2727ms).
[12:29:09.537] INFO: Test took 3966ms.
[12:29:09.570] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:10.293] INFO: Expecting 41600 events.
[12:29:13.537] INFO: 41600 events read in total (2717ms).
[12:29:13.538] INFO: Test took 3950ms.
[12:29:13.571] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:14.297] INFO: Expecting 41600 events.
[12:29:17.565] INFO: 41600 events read in total (2741ms).
[12:29:17.566] INFO: Test took 3977ms.
[12:29:17.600] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:18.321] INFO: Expecting 41600 events.
[12:29:21.678] INFO: 41600 events read in total (2830ms).
[12:29:21.679] INFO: Test took 4062ms.
[12:29:21.713] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:22.425] INFO: Expecting 41600 events.
[12:29:25.690] INFO: 41600 events read in total (2739ms).
[12:29:25.691] INFO: Test took 3961ms.
[12:29:25.724] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:26.445] INFO: Expecting 41600 events.
[12:29:29.721] INFO: 41600 events read in total (2749ms).
[12:29:29.722] INFO: Test took 3980ms.
[12:29:29.756] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:30.478] INFO: Expecting 41600 events.
[12:29:33.835] INFO: 41600 events read in total (2831ms).
[12:29:33.837] INFO: Test took 4064ms.
[12:29:33.880] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:34.577] INFO: Expecting 41600 events.
[12:29:37.859] INFO: 41600 events read in total (2755ms).
[12:29:37.860] INFO: Test took 3958ms.
[12:29:37.893] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:38.616] INFO: Expecting 41600 events.
[12:29:41.889] INFO: 41600 events read in total (2746ms).
[12:29:41.890] INFO: Test took 3980ms.
[12:29:41.923] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:42.645] INFO: Expecting 41600 events.
[12:29:45.852] INFO: 41600 events read in total (2680ms).
[12:29:45.853] INFO: Test took 3912ms.
[12:29:45.886] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:46.612] INFO: Expecting 41600 events.
[12:29:49.731] INFO: 41600 events read in total (2593ms).
[12:29:49.732] INFO: Test took 3829ms.
[12:29:49.765] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:50.122] INFO: enter test to run
[12:30:26.345] INFO: test: HighRate no parameter change
[12:30:26.345] INFO: running: highrate
[12:30:26.354] INFO: ----------------------------------------------------------------------
[12:30:26.354] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:30:26.354] INFO: ----------------------------------------------------------------------
[12:30:26.975] INFO: Expecting 208000 events.
[12:30:38.711] INFO: 208000 events read in total (11209ms).
[12:30:38.714] INFO: Test took 12351ms.
[12:30:38.853] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:39.104] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 0 1 50 4 0 0 0 0 0 0
[12:30:39.104] INFO: number of red-efficiency pixels: 77 52 68 143 97 158 100 61 112 118 128 83 89 53 23 40
[12:30:39.104] INFO: number of X-ray hits detected: 69144 44777 64021 109188 102111 110847 105516 70545 66359 92577 90940 79139 80373 49616 21935 25234
[12:30:39.104] 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:30:39.104] INFO: number of Vcal hits detected: 207824 207947 207930 207855 207902 207840 207897 207889 205433 207681 207869 207916 207911 207947 207976 207960
[12:30:39.104] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 100.0 99.9 100.0 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[12:30:39.104] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.9 100.0 99.9 100.0 99.9 98.8 99.8 99.9 100.0 100.0 100.0 100.0 100.0
[12:30:39.104] INFO: X-ray hit rate [MHz/cm2]: 20.3 13.1 18.8 32.0 29.9 32.5 30.9 20.7 19.5 27.1 26.7 23.2 23.6 14.5 6.4 7.4
[12:30:39.104] INFO: PixTestHighRate::doXPixelAlive() done
[12:30:39.149] INFO: PixTest:: pg_setup set to default.
[12:30:39.160] INFO: enter test to run
[12:31:17.216] INFO: test: HighRate no parameter change
[12:31:17.217] INFO: running: highrate
[12:31:17.218] INFO: ----------------------------------------------------------------------
[12:31:17.218] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:31:17.218] INFO: ----------------------------------------------------------------------
[12:31:17.840] INFO: Expecting 208000 events.
[12:31:30.847] INFO: 208000 events read in total (12480ms).
[12:31:30.852] INFO: Test took 13625ms.
[12:31:31.136] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:31:31.431] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 0 1 50 4 0 0 0 0 0 0
[12:31:31.432] INFO: number of red-efficiency pixels: 214 103 187 451 333 493 402 212 218 379 331 210 225 147 55 62
[12:31:31.432] INFO: number of X-ray hits detected: 141504 90731 131061 222084 209667 226120 216121 143750 135601 188834 186116 161534 163992 101870 45200 52093
[12:31:31.432] 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:31:31.432] INFO: number of Vcal hits detected: 207676 207891 207794 207506 207643 207445 207566 207726 205318 207394 207650 207779 207769 207850 207943 207936
[12:31:31.432] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[12:31:31.432] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.9 99.8 99.8 99.7 99.8 99.9 98.7 99.7 99.8 99.9 99.9 99.9 100.0 100.0
[12:31:31.432] INFO: X-ray hit rate [MHz/cm2]: 41.5 26.6 38.4 65.1 61.5 66.3 63.3 42.1 39.7 55.3 54.6 47.3 48.1 29.9 13.2 15.3
[12:31:31.432] INFO: PixTestHighRate::doXPixelAlive() done
[12:31:31.477] INFO: PixTest:: pg_setup set to default.
[12:31:31.493] INFO: enter test to run
[12:32:22.688] INFO: test: HighRate no parameter change
[12:32:22.688] INFO: running: highrate
[12:32:22.689] INFO: ----------------------------------------------------------------------
[12:32:22.689] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:32:22.689] INFO: ----------------------------------------------------------------------
[12:32:23.314] INFO: Expecting 208000 events.
[12:32:38.211] INFO: 208000 events read in total (14371ms).
[12:32:38.218] INFO: Test took 15520ms.
[12:32:38.638] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:32:38.979] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 0 1 50 4 0 0 0 0 0 0
[12:32:38.979] INFO: number of red-efficiency pixels: 472 211 446 1121 770 1181 832 443 397 806 801 486 495 370 102 105
[12:32:38.979] INFO: number of X-ray hits detected: 212142 135755 196890 333129 313199 339121 323571 215504 204132 282470 278509 243534 246071 153192 67770 77760
[12:32:38.980] 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:32:38.980] INFO: number of Vcal hits detected: 207374 207781 207472 206594 207091 206442 207012 207435 205124 206874 207053 207470 207453 207580 207894 207892
[12:32:38.980] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.4 99.6 99.3 99.6 99.8 99.8 99.6 99.6 99.8 99.8 99.8 100.0 100.0
[12:32:38.980] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.3 99.6 99.3 99.5 99.7 98.6 99.5 99.5 99.7 99.7 99.8 99.9 99.9
[12:32:38.980] INFO: X-ray hit rate [MHz/cm2]: 62.2 39.8 57.7 97.6 91.8 99.4 94.8 63.2 59.8 82.8 81.6 71.4 72.1 44.9 19.9 22.8
[12:32:38.980] INFO: PixTestHighRate::doXPixelAlive() done
[12:32:39.024] INFO: PixTest:: pg_setup set to default.
[12:32:39.041] INFO: enter test to run
[12:32:51.567] INFO: test: exit no parameter change
[12:32:51.863] QUIET: Connection to board 33 closed.
[12:32:51.865] INFO: pXar: this is the end, my friend