[13:51:01.077] INFO: *** Welcome to pxar ***
[13:51:01.077] INFO: *** Today: 2016/09/27
[13:51:01.098] INFO: *** Version: v1.9.0-818-g96727
[13:51:01.098] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//dacParameters35_C15.dat
[13:51:01.099] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:51:01.099] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//defaultMaskFile.dat
[13:51:01.099] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C15.dat
[13:51:01.169] INFO: clk: 4
[13:51:01.169] INFO: ctr: 4
[13:51:01.169] INFO: sda: 19
[13:51:01.169] INFO: tin: 9
[13:51:01.169] INFO: level: 15
[13:51:01.169] INFO: triggerdelay: 0
[13:51:01.169] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[13:51:01.169] INFO: Log level: INFO
[13:51:01.188] QUIET: Connection to board DTB_WREKRL opened.
[13:51:01.191] 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:
------------------------------------------------------
[13:51:01.194] INFO: RPC call hashes of host and DTB match: 398089610
[13:51:02.724] INFO: DUT info:
[13:51:02.724] INFO: The DUT currently contains the following objects:
[13:51:02.724] INFO: 2 TBM Cores tbm08c (2 ON)
[13:51:02.724] INFO: TBM Core alpha (0): 7 registers set
[13:51:02.724] INFO: TBM Core beta (1): 7 registers set
[13:51:02.724] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:51:02.724] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.724] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:02.725] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:51:03.128] INFO: enter 'restricted' command line mode
[13:51:03.128] INFO: enter test to run
[13:51:20.392] INFO: test: PixelAlive no parameter change
[13:51:20.393] INFO: running: pixelalive
[13:51:20.402] INFO: ----------------------------------------------------------------------
[13:51:20.402] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[13:51:20.402] INFO: ----------------------------------------------------------------------
[13:51:20.723] INFO: Expecting 41600 events.
[13:51:25.081] INFO: 41600 events read in total (3640ms).
[13:51:25.246] INFO: Test took 4842ms.
[13:51:25.255] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:51:25.518] INFO: PixTestAlive::aliveTest() done
[13:51:25.519] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 0
[13:51:25.555] INFO: enter test to run
[13:51:30.536] INFO: test: timing no parameter change
[13:51:30.536] INFO: running: timing
[13:51:30.539] INFO: ######################################################################
[13:51:30.539] INFO: PixTestTiming::doTest()
[13:51:30.539] INFO: ######################################################################
[13:51:30.539] INFO: ----------------------------------------------------------------------
[13:51:30.539] INFO: PixTestTiming::TBMPhaseScan()
[13:51:30.539] INFO: ----------------------------------------------------------------------
[14:01:19.198] INFO: TBM Phase Settings: 232
[14:01:19.198] INFO: 400MHz Phase: 2
[14:01:19.198] INFO: 160MHz Phase: 7
[14:01:19.198] INFO: Functional Phase Area: 3
[14:01:19.201] INFO: Test took 588662 ms.
[14:01:19.201] INFO: PixTestTiming::TBMPhaseScan() done.
[14:01:19.201] INFO: ----------------------------------------------------------------------
[14:01:19.201] INFO: PixTestTiming::ROCDelayScan()
[14:01:19.201] INFO: ----------------------------------------------------------------------
[14:04:16.609] INFO: ROC Delay Settings: 228
[14:04:16.610] INFO: ROC Header-Trailer/Token Delay: 11
[14:04:16.610] INFO: ROC Port 0 Delay: 4
[14:04:16.610] INFO: ROC Port 1 Delay: 4
[14:04:16.610] INFO: Functional ROC Area: 5
[14:04:16.613] INFO: Test took 177412 ms.
[14:04:16.613] INFO: PixTestTiming::ROCDelayScan() done.
[14:04:16.613] INFO: ----------------------------------------------------------------------
[14:04:16.613] INFO: PixTestTiming::TimingTest()
[14:04:16.613] INFO: ----------------------------------------------------------------------
[14:04:32.927] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:04:48.030] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:05:03.041] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:05:18.179] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:05:33.298] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:05:48.575] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:06:03.656] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:06:18.665] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:06:33.702] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:06:48.645] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:06:49.028] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:06:49.045] INFO: ----------------------------------------------------------------------
[14:06:49.045] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:06:49.045] INFO: ----------------------------------------------------------------------
[14:06:49.045] INFO: ----------------------------------------------------------------------
[14:06:49.045] INFO: Read back bit status: 1
[14:06:49.045] INFO: ----------------------------------------------------------------------
[14:06:49.045] INFO: ----------------------------------------------------------------------
[14:06:49.045] INFO: Timings are good!
[14:06:49.045] INFO: ----------------------------------------------------------------------
[14:06:49.045] INFO: Test took 152432 ms.
[14:06:49.045] INFO: PixTestTiming::TimingTest() done.
[14:06:49.045] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:06:49.045] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:06:49.046] INFO: PixTestTiming::doTest took 918510 ms.
[14:06:49.046] INFO: PixTestTiming::doTest() done
[14:06:49.046] INFO: Write out TBMPhaseScan_0_V0
[14:06:49.046] INFO: Write out TBMPhaseScan_1_V0
[14:06:49.046] INFO: Write out CombinedTBMPhaseScan_V0
[14:06:49.047] INFO: Write out ROCDelayScan3_V0
[14:06:49.047] INFO: enter test to run
[14:07:26.498] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[14:07:26.498] INFO: running: highrate
[14:07:26.498] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:07:26.702] INFO: ----------------------------------------------------------------------
[14:07:26.702] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[14:07:26.702] INFO: ----------------------------------------------------------------------
[14:07:26.702] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[14:07:26.702] INFO: edge/corner pixel THR is adjusted
[14:07:26.702] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:07:27.660] INFO: Collecting data for 5 seconds...
[14:07:32.678] INFO: Done with hot pixel readout
[14:07:45.148] INFO: PixTest:: pg_setup set to default.
[14:07:45.148] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:07:45.148] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:07:45.148] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:07:45.148] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:07:45.149] INFO: 55 hot pixels found in step 0
[14:07:46.147] INFO: Collecting data for 5 seconds...
[14:07:51.165] INFO: Done with hot pixel readout
[14:08:03.190] INFO: PixTest:: pg_setup set to default.
[14:08:03.190] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:08:03.191] INFO: 61 hot pixels found in step 1
[14:08:04.190] INFO: Collecting data for 5 seconds...
[14:08:09.208] INFO: Done with hot pixel readout
[14:08:21.240] INFO: PixTest:: pg_setup set to default.
[14:08:21.240] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:08:21.241] INFO: 64 hot pixels found in step 2
[14:08:22.239] INFO: Collecting data for 5 seconds...
[14:08:27.259] INFO: Done with hot pixel readout
[14:08:38.815] INFO: PixTest:: pg_setup set to default.
[14:08:38.816] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:08:38.816] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:08:38.816] INFO: 68 hot pixels found in step 3
[14:08:39.815] INFO: Collecting data for 5 seconds...
[14:08:44.833] INFO: Done with hot pixel readout
[14:08:56.659] INFO: PixTest:: pg_setup set to default.
[14:08:56.659] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:08:56.660] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:08:56.660] INFO: 62 hot pixels found in step 4
[14:08:57.658] INFO: Collecting data for 5 seconds...
[14:09:02.678] INFO: Done with hot pixel readout
[14:09:14.508] INFO: PixTest:: pg_setup set to default.
[14:09:14.508] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:09:14.508] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:09:14.508] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:09:14.509] INFO: 47 hot pixels found in step 5
[14:09:15.508] INFO: Collecting data for 5 seconds...
[14:09:20.526] INFO: Done with hot pixel readout
[14:09:32.824] INFO: PixTest:: pg_setup set to default.
[14:09:32.824] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:09:32.824] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:09:32.824] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:09:32.824] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:09:32.825] INFO: 48 hot pixels found in step 6
[14:09:33.822] INFO: Collecting data for 5 seconds...
[14:09:38.839] INFO: Done with hot pixel readout
[14:09:50.826] INFO: PixTest:: pg_setup set to default.
[14:09:50.826] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:09:50.826] INFO: 44 hot pixels found in step 7
[14:09:51.825] INFO: Collecting data for 5 seconds...
[14:09:56.841] INFO: Done with hot pixel readout
[14:10:08.788] INFO: PixTest:: pg_setup set to default.
[14:10:08.788] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:10:08.788] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:10:08.789] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:10:08.789] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:10:08.789] INFO: 37 hot pixels found in step 8
[14:10:09.787] INFO: Collecting data for 5 seconds...
[14:10:14.803] INFO: Done with hot pixel readout
[14:10:26.860] INFO: PixTest:: pg_setup set to default.
[14:10:26.860] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:10:26.860] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:10:26.861] INFO: 44 hot pixels found in step 9
[14:10:27.859] INFO: Collecting data for 5 seconds...
[14:10:32.875] INFO: Done with hot pixel readout
[14:10:44.893] INFO: PixTest:: pg_setup set to default.
[14:10:44.894] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:10:44.894] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:10:44.894] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:10:44.894] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:10:44.894] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:10:44.894] INFO: 41 hot pixels found in step 10
[14:10:45.892] INFO: Collecting data for 5 seconds...
[14:10:50.909] INFO: Done with hot pixel readout
[14:11:02.990] INFO: PixTest:: pg_setup set to default.
[14:11:02.991] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:02.991] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:02.991] INFO: 39 hot pixels found in step 11
[14:11:03.989] INFO: Collecting data for 5 seconds...
[14:11:08.005] INFO: Done with hot pixel readout
[14:11:21.065] INFO: PixTest:: pg_setup set to default.
[14:11:21.065] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:21.065] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:21.066] INFO: 40 hot pixels found in step 12
[14:11:22.063] INFO: Collecting data for 5 seconds...
[14:11:27.081] INFO: Done with hot pixel readout
[14:11:39.206] INFO: PixTest:: pg_setup set to default.
[14:11:39.206] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:39.206] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:39.206] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:39.207] INFO: 35 hot pixels found in step 13
[14:11:40.205] INFO: Collecting data for 5 seconds...
[14:11:45.221] INFO: Done with hot pixel readout
[14:11:57.213] INFO: PixTest:: pg_setup set to default.
[14:11:57.213] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:57.213] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:57.213] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:57.213] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:57.214] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:11:57.214] INFO: 32 hot pixels found in step 14
[14:11:57.256] INFO: 32 hot pixels could not be trimmed and have been masked.
[14:11:57.260] INFO: PixTest::trimHotPixels() done
[14:11:57.260] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C0.dat
[14:11:57.269] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C1.dat
[14:11:57.275] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C2.dat
[14:11:57.281] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C3.dat
[14:11:57.286] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C4.dat
[14:11:57.292] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C5.dat
[14:11:57.297] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C6.dat
[14:11:57.303] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C7.dat
[14:11:57.308] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C8.dat
[14:11:57.314] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C9.dat
[14:11:57.320] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C10.dat
[14:11:57.325] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C11.dat
[14:11:57.331] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C12.dat
[14:11:57.336] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C13.dat
[14:11:57.342] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C14.dat
[14:11:57.348] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C15.dat
[14:11:57.353] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//defaultMaskFile.dat
[14:11:57.363] INFO: enter test to run
[14:14:52.663] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:14:52.663] INFO: running: highrate
[14:14:52.668] INFO: ----------------------------------------------------------------------
[14:14:52.668] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:14:52.668] INFO: ----------------------------------------------------------------------
[14:14:52.668] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:14:52.668] INFO: edge/corner pixel THR is adjusted
[14:14:52.668] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:14:53.625] INFO: Collecting data for 1 seconds...
[14:14:54.629] INFO: Done with hot pixel readout
[14:14:58.802] INFO: PixTest:: pg_setup set to default.
[14:14:58.802] INFO: 0 hot pixels found in step 0
[14:14:58.808] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:14:58.892] INFO: PixTest::trimHotPixels() done
[14:14:58.892] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C0.dat
[14:14:58.901] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C1.dat
[14:14:58.907] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C2.dat
[14:14:58.912] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C3.dat
[14:14:58.918] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C4.dat
[14:14:58.924] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C5.dat
[14:14:58.929] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C6.dat
[14:14:58.935] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C7.dat
[14:14:58.941] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C8.dat
[14:14:58.946] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C9.dat
[14:14:58.952] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C10.dat
[14:14:58.957] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C11.dat
[14:14:58.963] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C12.dat
[14:14:58.969] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C13.dat
[14:14:58.974] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C14.dat
[14:14:58.980] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C15.dat
[14:14:58.986] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-5-17_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//defaultMaskFile.dat
[14:14:59.009] INFO: enter test to run
[14:15:15.159] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:15:15.159] INFO: running: xray
[14:15:15.160] INFO: ----------------------------------------------------------------------
[14:15:15.160] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:15:15.160] INFO: ----------------------------------------------------------------------
[14:15:16.124] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:15:27.172] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[14:15:56.532] INFO: Resuming triggers.
[14:16:07.689] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[14:16:37.194] INFO: Resuming triggers.
[14:16:48.244] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[14:17:17.995] INFO: Resuming triggers.
[14:17:29.050] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[14:17:59.151] INFO: Resuming triggers.
[14:18:10.201] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[14:18:40.394] INFO: Resuming triggers.
[14:18:51.443] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[14:19:20.580] INFO: Resuming triggers.
[14:19:31.628] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[14:20:01.414] INFO: Resuming triggers.
[14:20:12.464] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[14:20:42.927] INFO: Resuming triggers.
[14:20:53.977] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[14:21:24.396] INFO: Resuming triggers.
[14:21:25.300] INFO: data taking finished, elapsed time: 100 seconds.
[14:21:28.129] INFO: PixTest:: pg_setup set to default.
[14:21:28.132] INFO: PixTestXray::doPhRun() done
[14:21:28.287] INFO: enter test to run
[14:22:04.596] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:22:04.596] INFO: running: xray
[14:22:04.597] INFO: ----------------------------------------------------------------------
[14:22:04.597] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:22:04.597] INFO: ----------------------------------------------------------------------
[14:22:05.579] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:22:11.880] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[14:22:42.119] INFO: Resuming triggers.
[14:22:48.423] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[14:23:18.685] INFO: Resuming triggers.
[14:23:24.991] INFO: run duration 18 seconds, buffer almost full (81%), pausing triggers.
[14:23:55.144] INFO: Resuming triggers.
[14:24:01.447] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[14:24:31.669] INFO: Resuming triggers.
[14:24:37.975] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[14:25:08.166] INFO: Resuming triggers.
[14:25:14.473] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[14:25:44.699] INFO: Resuming triggers.
[14:25:50.005] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[14:26:21.242] INFO: Resuming triggers.
[14:26:27.544] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[14:26:57.802] INFO: Resuming triggers.
[14:27:04.104] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[14:27:34.313] INFO: Resuming triggers.
[14:27:40.612] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[14:28:10.854] INFO: Resuming triggers.
[14:28:17.155] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[14:28:47.374] INFO: Resuming triggers.
[14:28:53.676] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[14:29:23.808] INFO: Resuming triggers.
[14:29:30.107] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[14:30:00.828] INFO: Resuming triggers.
[14:30:07.127] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[14:30:38.081] INFO: Resuming triggers.
[14:30:44.379] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[14:31:15.780] INFO: Resuming triggers.
[14:31:21.585] INFO: data taking finished, elapsed time: 100 seconds.
[14:31:49.767] INFO: PixTest:: pg_setup set to default.
[14:31:49.770] INFO: PixTestXray::doPhRun() done
[14:31:49.923] INFO: enter test to run
[14:32:21.520] INFO: test: HighRate no parameter change
[14:32:21.520] INFO: running: highrate
[14:32:21.537] INFO: ----------------------------------------------------------------------
[14:32:21.538] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[14:32:21.538] INFO: ----------------------------------------------------------------------
[14:32:21.684] INFO: Expecting 768 events.
[14:32:22.818] INFO: 768 events read in total (419ms).
[14:32:22.818] INFO: Test took 1269ms.
[14:32:23.621] INFO: Expecting 41600 events.
[14:32:26.803] INFO: 41600 events read in total (2655ms).
[14:32:26.804] INFO: Test took 3980ms.
[14:32:26.844] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:32:27.550] INFO: Expecting 41600 events.
[14:32:30.823] INFO: 41600 events read in total (2746ms).
[14:32:30.824] INFO: Test took 3961ms.
[14:32:30.864] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:32:31.566] INFO: Expecting 41600 events.
[14:32:34.980] INFO: 41600 events read in total (2887ms).
[14:32:34.981] INFO: Test took 4098ms.
[14:32:35.020] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:32:35.724] INFO: Expecting 41600 events.
[14:32:39.041] INFO: 41600 events read in total (2791ms).
[14:32:39.042] INFO: Test took 4002ms.
[14:32:39.082] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:32:39.795] INFO: Expecting 41600 events.
[14:32:43.158] INFO: 41600 events read in total (2837ms).
[14:32:43.159] INFO: Test took 4058ms.
[14:32:43.199] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:32:43.912] INFO: Expecting 41600 events.
[14:32:47.314] INFO: 41600 events read in total (2875ms).
[14:32:47.315] INFO: Test took 4096ms.
[14:32:47.356] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:32:48.060] INFO: Expecting 41600 events.
[14:32:51.460] INFO: 41600 events read in total (2874ms).
[14:32:51.461] INFO: Test took 4085ms.
[14:32:51.500] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:32:52.213] INFO: Expecting 41600 events.
[14:32:55.578] INFO: 41600 events read in total (2838ms).
[14:32:55.579] INFO: Test took 4056ms.
[14:32:55.618] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:32:56.333] INFO: Expecting 41600 events.
[14:32:59.634] INFO: 41600 events read in total (2774ms).
[14:32:59.635] INFO: Test took 3997ms.
[14:32:59.675] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:00.388] INFO: Expecting 41600 events.
[14:33:03.714] INFO: 41600 events read in total (2799ms).
[14:33:03.715] INFO: Test took 4021ms.
[14:33:03.756] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:04.468] INFO: Expecting 41600 events.
[14:33:07.884] INFO: 41600 events read in total (2889ms).
[14:33:07.885] INFO: Test took 4109ms.
[14:33:07.924] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:08.636] INFO: Expecting 41600 events.
[14:33:11.923] INFO: 41600 events read in total (2760ms).
[14:33:11.924] INFO: Test took 3980ms.
[14:33:11.964] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:12.677] INFO: Expecting 41600 events.
[14:33:15.987] INFO: 41600 events read in total (2783ms).
[14:33:15.988] INFO: Test took 4004ms.
[14:33:16.027] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:16.744] INFO: Expecting 41600 events.
[14:33:20.100] INFO: 41600 events read in total (2830ms).
[14:33:20.101] INFO: Test took 4055ms.
[14:33:20.141] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:20.832] INFO: Expecting 41600 events.
[14:33:24.164] INFO: 41600 events read in total (2806ms).
[14:33:24.166] INFO: Test took 4006ms.
[14:33:24.205] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:24.920] INFO: Expecting 41600 events.
[14:33:28.375] INFO: 41600 events read in total (2928ms).
[14:33:28.376] INFO: Test took 4151ms.
[14:33:28.415] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:29.129] INFO: Expecting 41600 events.
[14:33:32.454] INFO: 41600 events read in total (2798ms).
[14:33:32.455] INFO: Test took 4021ms.
[14:33:32.494] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:33.208] INFO: Expecting 41600 events.
[14:33:36.547] INFO: 41600 events read in total (2812ms).
[14:33:36.548] INFO: Test took 4033ms.
[14:33:36.588] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:37.301] INFO: Expecting 41600 events.
[14:33:40.648] INFO: 41600 events read in total (2820ms).
[14:33:40.649] INFO: Test took 4040ms.
[14:33:40.688] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:41.401] INFO: Expecting 41600 events.
[14:33:44.571] INFO: 41600 events read in total (2644ms).
[14:33:44.571] INFO: Test took 3863ms.
[14:33:44.610] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:44.955] INFO: enter test to run
[14:34:02.895] INFO: test: HighRate no parameter change
[14:34:02.895] INFO: running: highrate
[14:34:02.896] INFO: ----------------------------------------------------------------------
[14:34:02.896] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:34:02.896] INFO: ----------------------------------------------------------------------
[14:34:03.516] INFO: Expecting 208000 events.
[14:34:15.807] INFO: 208000 events read in total (11764ms).
[14:34:15.810] INFO: Test took 12905ms.
[14:34:15.980] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:34:16.243] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 67 0 0 0 0 0 0 0 2 0
[14:34:16.243] INFO: number of red-efficiency pixels: 96 50 107 132 177 191 319 81 100 134 109 93 123 91 24 36
[14:34:16.243] INFO: number of X-ray hits detected: 73176 47093 75762 114444 120527 128506 157228 86291 84575 119425 119220 99286 104172 65724 22472 25621
[14:34:16.243] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:34:16.243] INFO: number of Vcal hits detected: 207877 207949 207889 207861 207820 207805 202937 207918 207899 207864 207891 207903 207875 207909 207877 207964
[14:34:16.243] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.9 99.9 99.9 99.1 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[14:34:16.243] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.9 99.9 99.9 97.6 100.0 100.0 99.9 99.9 100.0 99.9 100.0 99.9 100.0
[14:34:16.243] INFO: X-ray hit rate [MHz/cm2]: 21.4 13.8 22.2 33.5 35.3 37.7 46.1 25.3 24.8 35.0 34.9 29.1 30.5 19.3 6.6 7.5
[14:34:16.243] INFO: PixTestHighRate::doXPixelAlive() done
[14:34:16.288] INFO: PixTest:: pg_setup set to default.
[14:34:16.302] INFO: enter test to run
[14:34:57.879] INFO: test: HighRate no parameter change
[14:34:57.879] INFO: running: highrate
[14:34:57.880] INFO: ----------------------------------------------------------------------
[14:34:57.880] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:34:57.880] INFO: ----------------------------------------------------------------------
[14:34:58.497] INFO: Expecting 208000 events.
[14:35:12.588] INFO: 208000 events read in total (13564ms).
[14:35:12.594] INFO: Test took 14705ms.
[14:35:12.919] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:35:13.231] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 52 0 0 0 0 0 0 0 2 0
[14:35:13.232] INFO: number of red-efficiency pixels: 272 167 397 565 594 662 726 337 333 456 426 425 361 309 66 60
[14:35:13.232] INFO: number of X-ray hits detected: 148106 95670 153648 230668 244549 260368 287123 175510 170769 241528 242374 201639 212196 133122 46061 52242
[14:35:13.232] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:35:13.232] INFO: number of Vcal hits detected: 207669 207824 207543 207375 207340 207218 202061 207619 207641 207486 207530 207524 207625 207664 207832 207940
[14:35:13.232] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.7 98.3 99.8 99.8 99.8 99.8 99.8 99.8 99.8 100.0 100.0
[14:35:13.232] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.7 99.7 99.6 97.1 99.8 99.8 99.8 99.8 99.8 99.8 99.8 99.9 100.0
[14:35:13.232] INFO: X-ray hit rate [MHz/cm2]: 43.4 28.0 45.0 67.6 71.7 76.3 84.2 51.4 50.1 70.8 71.0 59.1 62.2 39.0 13.5 15.3
[14:35:13.232] INFO: PixTestHighRate::doXPixelAlive() done
[14:35:13.287] INFO: PixTest:: pg_setup set to default.
[14:35:13.302] INFO: enter test to run
[14:35:36.607] INFO: test: HighRate no parameter change
[14:35:36.607] INFO: running: highrate
[14:35:36.608] INFO: ----------------------------------------------------------------------
[14:35:36.608] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:35:36.608] INFO: ----------------------------------------------------------------------
[14:35:37.228] INFO: Expecting 208000 events.
[14:35:53.474] INFO: 208000 events read in total (15719ms).
[14:35:53.482] INFO: Test took 16864ms.
[14:35:53.980] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:35:54.346] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 53 0 0 0 0 0 0 0 2 0
[14:35:54.346] INFO: number of red-efficiency pixels: 612 318 816 1297 1343 1560 1396 692 756 1090 1012 990 824 691 105 96
[14:35:54.346] INFO: number of X-ray hits detected: 221826 143448 232094 347143 368342 391148 416565 264469 258604 361909 361625 302002 320309 200610 69632 79036
[14:35:54.346] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:35:54.346] INFO: number of Vcal hits detected: 207233 207641 206806 206266 206179 205754 200855 207159 207089 206655 206722 206710 207025 207078 207794 207903
[14:35:54.346] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.5 99.3 99.2 99.0 97.8 99.6 99.6 99.4 99.4 99.5 99.6 99.6 100.0 100.0
[14:35:54.346] INFO: Vcal hit overall efficiency (%): 99.6 99.8 99.4 99.2 99.1 98.9 96.6 99.6 99.6 99.4 99.4 99.4 99.5 99.6 99.9 100.0
[14:35:54.346] INFO: X-ray hit rate [MHz/cm2]: 65.0 42.0 68.0 101.8 108.0 114.6 122.1 77.5 75.8 106.1 106.0 88.5 93.9 58.8 20.4 23.2
[14:35:54.346] INFO: PixTestHighRate::doXPixelAlive() done
[14:35:54.394] INFO: PixTest:: pg_setup set to default.
[14:35:54.413] INFO: enter test to run
[14:36:10.758] INFO: test: exit no parameter change
[14:36:11.163] QUIET: Connection to board 33 closed.
[14:36:11.174] INFO: pXar: this is the end, my friend