[20:32:48.808] INFO: *** Welcome to pxar ***
[20:32:48.808] INFO: *** Today: 2016/09/07
[20:32:48.826] INFO: *** Version: v1.9.0-818-g96727
[20:32:48.826] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//dacParameters35_C15.dat
[20:32:48.827] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//tbmParameters_C0b.dat
[20:32:48.827] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//defaultMaskFile.dat
[20:32:48.827] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C15.dat
[20:32:48.901] INFO: clk: 4
[20:32:48.901] INFO: ctr: 4
[20:32:48.901] INFO: sda: 19
[20:32:48.901] INFO: tin: 9
[20:32:48.901] INFO: level: 15
[20:32:48.901] INFO: triggerdelay: 0
[20:32:48.901] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[20:32:48.901] INFO: Log level: INFO
[20:32:48.920] QUIET: Connection to board DTB_WREKRL opened.
[20:32:48.923] 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:
------------------------------------------------------
[20:32:48.925] INFO: RPC call hashes of host and DTB match: 398089610
[20:32:50.452] INFO: DUT info:
[20:32:50.452] INFO: The DUT currently contains the following objects:
[20:32:50.452] INFO: 2 TBM Cores tbm08c (2 ON)
[20:32:50.452] INFO: TBM Core alpha (0): 7 registers set
[20:32:50.452] INFO: TBM Core beta (1): 7 registers set
[20:32:50.452] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[20:32:50.452] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.452] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.453] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[20:32:50.856] INFO: enter 'restricted' command line mode
[20:32:50.856] INFO: enter test to run
[20:32:55.348] INFO: test: PixelAlive no parameter change
[20:32:55.348] INFO: running: pixelalive
[20:32:55.357] INFO: ----------------------------------------------------------------------
[20:32:55.357] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[20:32:55.357] INFO: ----------------------------------------------------------------------
[20:32:55.675] INFO: Expecting 41600 events.
[20:32:59.002] INFO: 41600 events read in total (3609ms).
[20:33:00.168] INFO: Test took 4809ms.
[20:33:00.182] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:33:00.464] INFO: PixTestAlive::aliveTest() done
[20:33:00.464] INFO: number of dead pixels (per ROC): 0 0 2 0 0 2 0 0 0 0 0 0 0 0 0 0
[20:33:00.492] INFO: enter test to run
[20:37:52.074] INFO: test: timing no parameter change
[20:37:52.074] INFO: running: timing
[20:37:52.100] INFO: ######################################################################
[20:37:52.107] INFO: PixTestTiming::doTest()
[20:37:52.107] INFO: ######################################################################
[20:37:52.107] INFO: ----------------------------------------------------------------------
[20:37:52.107] INFO: PixTestTiming::TBMPhaseScan()
[20:37:52.107] INFO: ----------------------------------------------------------------------
[20:42:15.208] INFO: TBM Phase Settings: 236
[20:42:15.208] INFO: 400MHz Phase: 3
[20:42:15.208] INFO: 160MHz Phase: 7
[20:42:15.208] INFO: Functional Phase Area: 4
[20:42:15.219] INFO: Test took 263112 ms.
[20:42:15.219] INFO: PixTestTiming::TBMPhaseScan() done.
[20:42:15.219] INFO: ----------------------------------------------------------------------
[20:42:15.219] INFO: PixTestTiming::ROCDelayScan()
[20:42:15.219] INFO: ----------------------------------------------------------------------
[20:44:23.132] INFO: ROC Delay Settings: 228
[20:44:23.132] INFO: ROC Header-Trailer/Token Delay: 11
[20:44:23.133] INFO: ROC Port 0 Delay: 4
[20:44:23.133] INFO: ROC Port 1 Delay: 4
[20:44:23.133] INFO: Functional ROC Area: 5
[20:44:23.136] INFO: Test took 127917 ms.
[20:44:23.136] INFO: PixTestTiming::ROCDelayScan() done.
[20:44:23.136] INFO: ----------------------------------------------------------------------
[20:44:23.136] INFO: PixTestTiming::TimingTest()
[20:44:23.136] INFO: ----------------------------------------------------------------------
[20:44:39.252] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:44:54.215] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:45:09.197] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:45:24.142] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:45:39.104] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:45:54.055] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:46:09.021] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:46:23.971] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:46:38.958] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:46:53.914] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:46:54.295] INFO: Fetched DAQ statistics. Counters are being reset now.
[20:46:54.314] INFO: ----------------------------------------------------------------------
[20:46:54.314] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[20:46:54.315] INFO: ----------------------------------------------------------------------
[20:46:54.315] INFO: ----------------------------------------------------------------------
[20:46:54.315] INFO: Read back bit status: 1
[20:46:54.315] INFO: ----------------------------------------------------------------------
[20:46:54.315] INFO: ----------------------------------------------------------------------
[20:46:54.315] INFO: Timings are good!
[20:46:54.315] INFO: ----------------------------------------------------------------------
[20:46:54.315] INFO: Test took 151179 ms.
[20:46:54.315] INFO: PixTestTiming::TimingTest() done.
[20:46:54.332] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//tbmParameters_C0a.dat
[20:46:54.332] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//tbmParameters_C0b.dat
[20:46:54.332] INFO: PixTestTiming::doTest took 542235 ms.
[20:46:54.332] INFO: PixTestTiming::doTest() done
[20:46:54.332] INFO: Write out TBMPhaseScan_0_V0
[20:46:54.333] INFO: Write out TBMPhaseScan_1_V0
[20:46:54.333] INFO: Write out CombinedTBMPhaseScan_V0
[20:46:54.369] INFO: Write out ROCDelayScan3_V0
[20:46:54.370] INFO: enter test to run
[20:47:24.430] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[20:47:24.430] INFO: running: highrate
[20:47:24.431] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[20:47:24.582] INFO: ----------------------------------------------------------------------
[20:47:24.582] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[20:47:24.582] INFO: ----------------------------------------------------------------------
[20:47:24.582] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[20:47:24.582] INFO: edge/corner pixel THR is adjusted
[20:47:24.582] INFO: PixTestHighRate::trimHotPixels: step 0...
[20:47:25.541] INFO: Collecting data for 5 seconds...
[20:47:30.557] INFO: Done with hot pixel readout
[20:47:42.206] INFO: PixTest:: pg_setup set to default.
[20:47:42.206] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:47:42.206] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:47:42.206] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:47:42.206] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:47:42.206] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:47:42.207] INFO: 6 hot pixels found in step 0
[20:47:43.199] INFO: Collecting data for 5 seconds...
[20:47:48.217] INFO: Done with hot pixel readout
[20:47:59.730] INFO: PixTest:: pg_setup set to default.
[20:47:59.730] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:47:59.730] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:47:59.730] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:47:59.731] INFO: 4 hot pixels found in step 1
[20:48:00.723] INFO: Collecting data for 5 seconds...
[20:48:05.741] INFO: Done with hot pixel readout
[20:48:17.372] INFO: PixTest:: pg_setup set to default.
[20:48:17.372] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:48:17.372] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:48:17.372] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:48:17.372] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:48:17.372] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:48:17.373] INFO: 6 hot pixels found in step 2
[20:48:18.366] INFO: Collecting data for 5 seconds...
[20:48:23.383] INFO: Done with hot pixel readout
[20:48:35.095] INFO: PixTest:: pg_setup set to default.
[20:48:35.095] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:48:35.095] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:48:35.096] INFO: 3 hot pixels found in step 3
[20:48:36.088] INFO: Collecting data for 5 seconds...
[20:48:41.107] INFO: Done with hot pixel readout
[20:48:52.656] INFO: PixTest:: pg_setup set to default.
[20:48:52.656] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:48:52.656] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:48:52.656] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:48:52.656] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[20:48:52.657] INFO: 4 hot pixels found in step 4
[20:48:52.694] INFO: 4 hot pixels could not be trimmed and have been masked.
[20:48:52.697] INFO: PixTest::trimHotPixels() done
[20:48:52.697] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C0.dat
[20:48:52.704] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C1.dat
[20:48:52.709] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C2.dat
[20:48:52.714] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C3.dat
[20:48:52.720] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C4.dat
[20:48:52.725] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C5.dat
[20:48:52.730] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C6.dat
[20:48:52.736] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C7.dat
[20:48:52.741] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C8.dat
[20:48:52.746] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C9.dat
[20:48:52.752] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C10.dat
[20:48:52.757] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C11.dat
[20:48:52.762] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C12.dat
[20:48:52.767] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C13.dat
[20:48:52.773] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C14.dat
[20:48:52.778] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C15.dat
[20:48:52.783] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//defaultMaskFile.dat
[20:48:52.793] INFO: enter test to run
[20:52:28.420] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[20:52:28.420] INFO: running: highrate
[20:52:28.424] INFO: ----------------------------------------------------------------------
[20:52:28.425] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[20:52:28.425] INFO: ----------------------------------------------------------------------
[20:52:28.425] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[20:52:28.425] INFO: edge/corner pixel THR is adjusted
[20:52:28.425] INFO: PixTestHighRate::trimHotPixels: step 0...
[20:52:29.381] INFO: Collecting data for 1 seconds...
[20:52:30.386] INFO: Done with hot pixel readout
[20:52:34.517] INFO: PixTest:: pg_setup set to default.
[20:52:34.518] INFO: 0 hot pixels found in step 0
[20:52:34.523] INFO: 0 hot pixels could not be trimmed and have been masked.
[20:52:34.578] INFO: PixTest::trimHotPixels() done
[20:52:34.578] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C0.dat
[20:52:34.587] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C1.dat
[20:52:34.597] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C2.dat
[20:52:34.603] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C3.dat
[20:52:34.609] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C4.dat
[20:52:34.615] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C5.dat
[20:52:34.620] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C6.dat
[20:52:34.626] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C7.dat
[20:52:34.632] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C8.dat
[20:52:34.637] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C9.dat
[20:52:34.643] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C10.dat
[20:52:34.648] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C11.dat
[20:52:34.654] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C12.dat
[20:52:34.659] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C13.dat
[20:52:34.665] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C14.dat
[20:52:34.670] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//trimParameters35_C15.dat
[20:52:34.676] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-3-23_FPIXTest-17C-FNAL-160906-1408-150V_2016-09-06_14h08m_1473188910/000_FPIXTest_p17//defaultMaskFile.dat
[20:52:34.685] INFO: enter test to run
[20:52:57.084] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[20:52:57.084] INFO: running: xray
[20:52:57.085] INFO: ----------------------------------------------------------------------
[20:52:57.085] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[20:52:57.085] INFO: ----------------------------------------------------------------------
[20:52:58.048] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[20:53:09.379] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[20:53:38.847] INFO: Resuming triggers.
[20:53:50.180] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[20:54:19.601] INFO: Resuming triggers.
[20:54:30.940] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[20:55:00.443] INFO: Resuming triggers.
[20:55:11.780] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[20:55:41.199] INFO: Resuming triggers.
[20:55:52.534] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[20:56:21.983] INFO: Resuming triggers.
[20:56:33.314] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[20:57:02.782] INFO: Resuming triggers.
[20:57:14.113] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[20:57:43.501] INFO: Resuming triggers.
[20:57:54.837] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[20:58:24.243] INFO: Resuming triggers.
[20:58:33.912] INFO: data taking finished, elapsed time: 100 seconds.
[20:58:59.130] INFO: PixTest:: pg_setup set to default.
[20:58:59.133] INFO: PixTestXray::doPhRun() done
[20:58:59.345] INFO: enter test to run
[20:59:25.937] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[20:59:25.937] INFO: running: xray
[20:59:25.938] INFO: ----------------------------------------------------------------------
[20:59:25.938] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[20:59:25.938] INFO: ----------------------------------------------------------------------
[20:59:26.920] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[20:59:33.456] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[21:00:03.729] INFO: Resuming triggers.
[21:00:10.266] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[21:00:40.430] INFO: Resuming triggers.
[21:00:46.970] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[21:01:18.027] INFO: Resuming triggers.
[21:01:24.567] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[21:01:55.209] INFO: Resuming triggers.
[21:02:01.749] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[21:02:32.781] INFO: Resuming triggers.
[21:02:39.323] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[21:03:10.484] INFO: Resuming triggers.
[21:03:17.023] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[21:03:48.601] INFO: Resuming triggers.
[21:03:55.141] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[21:04:26.402] INFO: Resuming triggers.
[21:04:32.944] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[21:05:04.303] INFO: Resuming triggers.
[21:05:10.841] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[21:05:41.651] INFO: Resuming triggers.
[21:05:48.190] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[21:06:18.473] INFO: Resuming triggers.
[21:06:25.011] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[21:06:55.121] INFO: Resuming triggers.
[21:07:01.654] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[21:07:31.865] INFO: Resuming triggers.
[21:07:38.400] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[21:08:08.519] INFO: Resuming triggers.
[21:08:15.054] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[21:08:45.460] INFO: Resuming triggers.
[21:08:47.742] INFO: data taking finished, elapsed time: 100 seconds.
[21:08:58.590] INFO: PixTest:: pg_setup set to default.
[21:08:58.594] INFO: PixTestXray::doPhRun() done
[21:08:58.743] INFO: enter test to run
[21:10:20.365] INFO: test: HighRate no parameter change
[21:10:20.365] INFO: running: highrate
[21:10:20.371] INFO: ----------------------------------------------------------------------
[21:10:20.371] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[21:10:20.371] INFO: ----------------------------------------------------------------------
[21:10:20.526] INFO: Expecting 768 events.
[21:10:21.660] INFO: 768 events read in total (418ms).
[21:10:21.660] INFO: Test took 1269ms.
[21:10:22.464] INFO: Expecting 41600 events.
[21:10:25.568] INFO: 41600 events read in total (2578ms).
[21:10:25.569] INFO: Test took 3901ms.
[21:10:25.604] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:10:26.328] INFO: Expecting 41600 events.
[21:10:29.546] INFO: 41600 events read in total (2691ms).
[21:10:29.547] INFO: Test took 3926ms.
[21:10:29.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:10:30.306] INFO: Expecting 41600 events.
[21:10:33.542] INFO: 41600 events read in total (2709ms).
[21:10:33.543] INFO: Test took 3943ms.
[21:10:33.577] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:10:34.300] INFO: Expecting 41600 events.
[21:10:37.525] INFO: 41600 events read in total (2698ms).
[21:10:37.526] INFO: Test took 3931ms.
[21:10:37.560] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:10:38.283] INFO: Expecting 41600 events.
[21:10:41.508] INFO: 41600 events read in total (2698ms).
[21:10:41.509] INFO: Test took 3930ms.
[21:10:41.544] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:10:42.265] INFO: Expecting 41600 events.
[21:10:45.514] INFO: 41600 events read in total (2722ms).
[21:10:45.515] INFO: Test took 3952ms.
[21:10:45.550] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:10:46.270] INFO: Expecting 41600 events.
[21:10:49.523] INFO: 41600 events read in total (2726ms).
[21:10:49.524] INFO: Test took 3955ms.
[21:10:49.559] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:10:50.279] INFO: Expecting 41600 events.
[21:10:53.509] INFO: 41600 events read in total (2703ms).
[21:10:53.510] INFO: Test took 3934ms.
[21:10:53.545] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:10:54.268] INFO: Expecting 41600 events.
[21:10:57.529] INFO: 41600 events read in total (2734ms).
[21:10:57.549] INFO: Test took 3985ms.
[21:10:57.594] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:10:58.287] INFO: Expecting 41600 events.
[21:11:01.549] INFO: 41600 events read in total (2735ms).
[21:11:01.550] INFO: Test took 3937ms.
[21:11:01.585] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:02.309] INFO: Expecting 41600 events.
[21:11:05.555] INFO: 41600 events read in total (2719ms).
[21:11:05.556] INFO: Test took 3952ms.
[21:11:05.591] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:06.310] INFO: Expecting 41600 events.
[21:11:09.554] INFO: 41600 events read in total (2717ms).
[21:11:09.555] INFO: Test took 3945ms.
[21:11:09.590] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:10.313] INFO: Expecting 41600 events.
[21:11:13.564] INFO: 41600 events read in total (2724ms).
[21:11:13.565] INFO: Test took 3956ms.
[21:11:13.600] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:14.325] INFO: Expecting 41600 events.
[21:11:17.580] INFO: 41600 events read in total (2728ms).
[21:11:17.581] INFO: Test took 3964ms.
[21:11:17.616] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:18.336] INFO: Expecting 41600 events.
[21:11:21.578] INFO: 41600 events read in total (2716ms).
[21:11:21.579] INFO: Test took 3946ms.
[21:11:21.613] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:22.337] INFO: Expecting 41600 events.
[21:11:25.595] INFO: 41600 events read in total (2731ms).
[21:11:25.596] INFO: Test took 3964ms.
[21:11:25.631] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:26.350] INFO: Expecting 41600 events.
[21:11:29.608] INFO: 41600 events read in total (2731ms).
[21:11:29.609] INFO: Test took 3960ms.
[21:11:29.644] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:30.368] INFO: Expecting 41600 events.
[21:11:33.556] INFO: 41600 events read in total (2661ms).
[21:11:33.557] INFO: Test took 3893ms.
[21:11:33.591] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:34.316] INFO: Expecting 41600 events.
[21:11:37.537] INFO: 41600 events read in total (2695ms).
[21:11:37.538] INFO: Test took 3927ms.
[21:11:37.572] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:38.295] INFO: Expecting 41600 events.
[21:11:41.397] INFO: 41600 events read in total (2575ms).
[21:11:41.398] INFO: Test took 3806ms.
[21:11:41.433] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:11:41.794] INFO: enter test to run
[21:11:49.588] INFO: test: HighRate no parameter change
[21:11:49.588] INFO: running: highrate
[21:11:49.589] INFO: ----------------------------------------------------------------------
[21:11:49.589] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[21:11:49.589] INFO: ----------------------------------------------------------------------
[21:11:50.203] INFO: Expecting 208000 events.
[21:12:02.124] INFO: 208000 events read in total (11394ms).
[21:12:02.127] INFO: Test took 12530ms.
[21:12:02.277] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:12:02.532] INFO: number of dead pixels (per ROC): 0 0 1 0 0 2 0 0 0 0 0 0 0 0 0 0
[21:12:02.532] INFO: number of red-efficiency pixels: 99 39 96 148 130 141 120 96 101 147 155 145 136 68 27 41
[21:12:02.532] INFO: number of X-ray hits detected: 72115 44631 67825 101867 106213 109330 104632 77987 84549 111356 110347 93472 100800 60989 22797 25931
[21:12:02.532] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[21:12:02.532] INFO: number of Vcal hits detected: 207900 207961 207806 207850 207867 207758 207879 207904 207897 207848 207841 207853 207862 207929 207973 207959
[21:12:02.532] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[21:12:02.532] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[21:12:02.532] INFO: X-ray hit rate [MHz/cm2]: 21.1 13.1 19.9 29.9 31.1 32.0 30.7 22.9 24.8 32.6 32.3 27.4 29.5 17.9 6.7 7.6
[21:12:02.532] INFO: PixTestHighRate::doXPixelAlive() done
[21:12:02.583] INFO: PixTest:: pg_setup set to default.
[21:12:02.597] INFO: enter test to run
[21:12:53.996] INFO: test: HighRate no parameter change
[21:12:53.996] INFO: running: highrate
[21:12:53.997] INFO: ----------------------------------------------------------------------
[21:12:53.997] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[21:12:53.997] INFO: ----------------------------------------------------------------------
[21:12:54.616] INFO: Expecting 208000 events.
[21:13:08.285] INFO: 208000 events read in total (13142ms).
[21:13:08.290] INFO: Test took 14283ms.
[21:13:08.586] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:13:08.887] INFO: number of dead pixels (per ROC): 0 0 2 0 0 2 0 0 0 0 0 0 0 0 0 0
[21:13:08.887] INFO: number of red-efficiency pixels: 310 124 330 460 472 518 469 253 320 452 522 417 477 217 63 61
[21:13:08.887] INFO: number of X-ray hits detected: 148726 91793 139580 208230 216650 223192 213465 160347 174091 229405 226328 192128 206791 125678 47618 52781
[21:13:08.887] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[21:13:08.887] INFO: number of Vcal hits detected: 207653 207869 207533 207493 207479 207341 207488 207736 207657 207517 207421 207554 207487 207764 207937 207937
[21:13:08.887] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[21:13:08.887] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.8 99.7 99.7 99.8 99.9 99.8 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[21:13:08.887] INFO: X-ray hit rate [MHz/cm2]: 43.6 26.9 40.9 61.0 63.5 65.4 62.6 47.0 51.0 67.2 66.3 56.3 60.6 36.8 14.0 15.5
[21:13:08.887] INFO: PixTestHighRate::doXPixelAlive() done
[21:13:08.932] INFO: PixTest:: pg_setup set to default.
[21:13:08.946] INFO: enter test to run
[21:13:28.580] INFO: test: HighRate no parameter change
[21:13:28.580] INFO: running: highrate
[21:13:28.581] INFO: ----------------------------------------------------------------------
[21:13:28.581] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[21:13:28.581] INFO: ----------------------------------------------------------------------
[21:13:29.205] INFO: Expecting 208000 events.
[21:13:45.040] INFO: 208000 events read in total (15308ms).
[21:13:45.048] INFO: Test took 16458ms.
[21:13:45.515] INFO: Fetched DAQ statistics. Counters are being reset now.
[21:13:45.874] INFO: number of dead pixels (per ROC): 0 0 2 0 0 1 0 0 0 0 0 0 0 0 0 0
[21:13:45.874] INFO: number of red-efficiency pixels: 650 254 700 1054 1118 1180 1006 550 746 1053 1162 928 1039 448 100 92
[21:13:45.874] INFO: number of X-ray hits detected: 222159 136361 208453 311177 323633 333317 318630 239640 261152 342394 337261 287321 307419 187801 70778 79028
[21:13:45.874] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[21:13:45.874] INFO: number of Vcal hits detected: 207134 207723 206980 206681 206615 206403 206770 207361 207093 206654 206522 206848 206698 207455 207899 207907
[21:13:45.874] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.4 99.4 99.3 99.5 99.7 99.6 99.4 99.3 99.5 99.4 99.8 100.0 100.0
[21:13:45.874] INFO: Vcal hit overall efficiency (%): 99.6 99.9 99.5 99.4 99.3 99.2 99.4 99.7 99.6 99.4 99.3 99.4 99.4 99.7 100.0 100.0
[21:13:45.874] INFO: X-ray hit rate [MHz/cm2]: 65.1 40.0 61.1 91.2 94.9 97.7 93.4 70.2 76.5 100.4 98.9 84.2 90.1 55.0 20.7 23.2
[21:13:45.874] INFO: PixTestHighRate::doXPixelAlive() done
[21:13:45.922] INFO: PixTest:: pg_setup set to default.
[21:13:45.945] INFO: enter test to run
[21:13:53.387] INFO: test: exit no parameter change
[21:13:53.954] QUIET: Connection to board 33 closed.
[21:13:53.966] INFO: pXar: this is the end, my friend