[15:46:21.254] INFO: *** Welcome to pxar ***
[15:46:21.254] INFO: *** Today: 2016/10/20
[15:46:21.459] INFO: *** Version: v1.9.0-818-g96727
[15:46:21.459] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//dacParameters35_C15.dat
[15:46:21.499] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:46:21.499] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//defaultMaskFile.dat
[15:46:21.501] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C15.dat
[15:46:21.599] INFO: clk: 4
[15:46:21.599] INFO: ctr: 4
[15:46:21.599] INFO: sda: 19
[15:46:21.599] INFO: tin: 9
[15:46:21.599] INFO: level: 15
[15:46:21.599] INFO: triggerdelay: 0
[15:46:21.599] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:46:21.599] INFO: Log level: INFO
[15:46:21.617] QUIET: Connection to board DTB_WREKRL opened.
[15:46:21.621] 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:
------------------------------------------------------
[15:46:21.624] INFO: RPC call hashes of host and DTB match: 398089610
[15:46:23.164] INFO: DUT info:
[15:46:23.164] INFO: The DUT currently contains the following objects:
[15:46:23.164] INFO: 2 TBM Cores tbm08c (2 ON)
[15:46:23.164] INFO: TBM Core alpha (0): 7 registers set
[15:46:23.164] INFO: TBM Core beta (1): 7 registers set
[15:46:23.164] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:46:23.164] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.164] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.164] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.164] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.164] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.164] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.164] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.164] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.164] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.164] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.165] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.165] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.165] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.165] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.165] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.165] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:23.568] INFO: enter 'restricted' command line mode
[15:46:23.568] INFO: enter test to run
[15:46:30.408] INFO: test: PixelAlive no parameter change
[15:46:30.408] INFO: running: pixelalive
[15:46:30.417] INFO: ----------------------------------------------------------------------
[15:46:30.417] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[15:46:30.417] INFO: ----------------------------------------------------------------------
[15:46:30.739] INFO: Expecting 41600 events.
[15:46:35.069] INFO: 41600 events read in total (3612ms).
[15:46:35.240] INFO: Test took 4821ms.
[15:46:35.250] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:35.513] INFO: PixTestAlive::aliveTest() done
[15:46:35.514] INFO: number of dead pixels (per ROC): 2 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:46:35.550] INFO: enter test to run
[15:46:42.552] INFO: test: timing no parameter change
[15:46:42.552] INFO: running: timing
[15:46:42.555] INFO: ######################################################################
[15:46:42.555] INFO: PixTestTiming::doTest()
[15:46:42.555] INFO: ######################################################################
[15:46:42.555] INFO: ----------------------------------------------------------------------
[15:46:42.555] INFO: PixTestTiming::TBMPhaseScan()
[15:46:42.555] INFO: ----------------------------------------------------------------------
[15:51:25.234] INFO: TBM Phase Settings: 236
[15:51:25.234] INFO: 400MHz Phase: 3
[15:51:25.234] INFO: 160MHz Phase: 7
[15:51:25.234] INFO: Functional Phase Area: 4
[15:51:25.237] INFO: Test took 282682 ms.
[15:51:25.237] INFO: PixTestTiming::TBMPhaseScan() done.
[15:51:25.237] INFO: ----------------------------------------------------------------------
[15:51:25.237] INFO: PixTestTiming::ROCDelayScan()
[15:51:25.237] INFO: ----------------------------------------------------------------------
[15:54:21.133] INFO: ROC Delay Settings: 228
[15:54:21.133] INFO: ROC Header-Trailer/Token Delay: 11
[15:54:21.133] INFO: ROC Port 0 Delay: 4
[15:54:21.133] INFO: ROC Port 1 Delay: 4
[15:54:21.133] INFO: Functional ROC Area: 5
[15:54:21.136] INFO: Test took 175899 ms.
[15:54:21.136] INFO: PixTestTiming::ROCDelayScan() done.
[15:54:21.136] INFO: ----------------------------------------------------------------------
[15:54:21.136] INFO: PixTestTiming::TimingTest()
[15:54:21.136] INFO: ----------------------------------------------------------------------
[15:54:37.552] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:54:52.783] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:07.623] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:22.612] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:37.582] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:55:52.556] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:56:07.527] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:56:22.493] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:56:37.496] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:56:52.457] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:56:52.836] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:56:52.853] INFO: ----------------------------------------------------------------------
[15:56:52.853] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:56:52.853] INFO: ----------------------------------------------------------------------
[15:56:52.853] INFO: ----------------------------------------------------------------------
[15:56:52.853] INFO: Read back bit status: 1
[15:56:52.853] INFO: ----------------------------------------------------------------------
[15:56:52.853] INFO: ----------------------------------------------------------------------
[15:56:52.853] INFO: Timings are good!
[15:56:52.853] INFO: ----------------------------------------------------------------------
[15:56:52.853] INFO: Test took 151717 ms.
[15:56:52.853] INFO: PixTestTiming::TimingTest() done.
[15:56:52.853] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:56:52.853] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:56:52.853] INFO: PixTestTiming::doTest took 610301 ms.
[15:56:52.853] INFO: PixTestTiming::doTest() done
[15:56:52.853] INFO: Write out TBMPhaseScan_0_V0
[15:56:52.853] INFO: Write out TBMPhaseScan_1_V0
[15:56:52.854] INFO: Write out CombinedTBMPhaseScan_V0
[15:56:52.871] INFO: Write out ROCDelayScan3_V0
[15:56:52.872] INFO: enter test to run
[15:57:32.716] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:57:32.716] INFO: running: highrate
[15:57:32.724] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:57:33.014] INFO: ----------------------------------------------------------------------
[15:57:33.014] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:57:33.014] INFO: ----------------------------------------------------------------------
[15:57:33.014] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:57:33.015] INFO: edge/corner pixel THR is adjusted
[15:57:33.015] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:57:33.974] INFO: Collecting data for 5 seconds...
[15:57:38.993] INFO: Done with hot pixel readout
[15:57:50.849] INFO: PixTest:: pg_setup set to default.
[15:57:50.849] INFO: 4 hot pixels found in step 0
[15:57:51.843] INFO: Collecting data for 5 seconds...
[15:57:56.860] INFO: Done with hot pixel readout
[15:58:08.698] INFO: PixTest:: pg_setup set to default.
[15:58:08.699] INFO: 7 hot pixels found in step 1
[15:58:09.695] INFO: Collecting data for 5 seconds...
[15:58:14.711] INFO: Done with hot pixel readout
[15:58:26.579] INFO: PixTest:: pg_setup set to default.
[15:58:26.580] INFO: 5 hot pixels found in step 2
[15:58:27.574] INFO: Collecting data for 5 seconds...
[15:58:32.591] INFO: Done with hot pixel readout
[15:58:44.222] INFO: PixTest:: pg_setup set to default.
[15:58:44.222] INFO: 9 hot pixels found in step 3
[15:58:45.217] INFO: Collecting data for 5 seconds...
[15:58:50.233] INFO: Done with hot pixel readout
[15:59:02.011] INFO: PixTest:: pg_setup set to default.
[15:59:02.011] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:59:02.012] INFO: 7 hot pixels found in step 4
[15:59:02.005] INFO: Collecting data for 5 seconds...
[15:59:08.023] INFO: Done with hot pixel readout
[15:59:19.808] INFO: PixTest:: pg_setup set to default.
[15:59:19.808] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:59:19.809] INFO: 6 hot pixels found in step 5
[15:59:20.802] INFO: Collecting data for 5 seconds...
[15:59:25.819] INFO: Done with hot pixel readout
[15:59:37.644] INFO: PixTest:: pg_setup set to default.
[15:59:37.645] INFO: 9 hot pixels found in step 6
[15:59:38.639] INFO: Collecting data for 5 seconds...
[15:59:43.656] INFO: Done with hot pixel readout
[15:59:55.473] INFO: PixTest:: pg_setup set to default.
[15:59:55.474] INFO: 3 hot pixels found in step 7
[15:59:56.467] INFO: Collecting data for 5 seconds...
[16:00:01.484] INFO: Done with hot pixel readout
[16:00:13.329] INFO: PixTest:: pg_setup set to default.
[16:00:13.330] INFO: 9 hot pixels found in step 8
[16:00:14.324] INFO: Collecting data for 5 seconds...
[16:00:19.340] INFO: Done with hot pixel readout
[16:00:31.160] INFO: PixTest:: pg_setup set to default.
[16:00:31.161] INFO: 6 hot pixels found in step 9
[16:00:32.154] INFO: Collecting data for 5 seconds...
[16:00:37.171] INFO: Done with hot pixel readout
[16:00:49.055] INFO: PixTest:: pg_setup set to default.
[16:00:49.056] INFO: 4 hot pixels found in step 10
[16:00:50.049] INFO: Collecting data for 5 seconds...
[16:00:55.066] INFO: Done with hot pixel readout
[16:01:06.915] INFO: PixTest:: pg_setup set to default.
[16:01:06.916] INFO: 1 hot pixels found in step 11
[16:01:07.910] INFO: Collecting data for 5 seconds...
[16:01:12.927] INFO: Done with hot pixel readout
[16:01:24.779] INFO: PixTest:: pg_setup set to default.
[16:01:24.780] INFO: 7 hot pixels found in step 12
[16:01:25.774] INFO: Collecting data for 5 seconds...
[16:01:30.791] INFO: Done with hot pixel readout
[16:01:42.577] INFO: PixTest:: pg_setup set to default.
[16:01:42.578] INFO: 4 hot pixels found in step 13
[16:01:43.571] INFO: Collecting data for 5 seconds...
[16:01:48.589] INFO: Done with hot pixel readout
[16:02:00.454] INFO: PixTest:: pg_setup set to default.
[16:02:00.455] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[16:02:00.455] INFO: 3 hot pixels found in step 14
[16:02:00.492] INFO: 3 hot pixels could not be trimmed and have been masked.
[16:02:00.496] INFO: PixTest::trimHotPixels() done
[16:02:00.496] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C0.dat
[16:02:00.507] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C1.dat
[16:02:00.513] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C2.dat
[16:02:00.518] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C3.dat
[16:02:00.524] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C4.dat
[16:02:00.529] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C5.dat
[16:02:00.534] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C6.dat
[16:02:00.540] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C7.dat
[16:02:00.545] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C8.dat
[16:02:00.551] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C9.dat
[16:02:00.556] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C10.dat
[16:02:00.561] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C11.dat
[16:02:00.567] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C12.dat
[16:02:00.572] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C13.dat
[16:02:00.578] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C14.dat
[16:02:00.583] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C15.dat
[16:02:00.588] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//defaultMaskFile.dat
[16:02:00.605] INFO: enter test to run
[16:02:41.545] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:02:41.545] INFO: running: highrate
[16:02:41.550] INFO: ----------------------------------------------------------------------
[16:02:41.550] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:02:41.550] INFO: ----------------------------------------------------------------------
[16:02:41.550] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:02:41.550] INFO: edge/corner pixel THR is adjusted
[16:02:41.550] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:02:42.508] INFO: Collecting data for 1 seconds...
[16:02:43.512] INFO: Done with hot pixel readout
[16:02:47.536] INFO: PixTest:: pg_setup set to default.
[16:02:47.537] INFO: 0 hot pixels found in step 0
[16:02:47.542] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:02:47.633] INFO: PixTest::trimHotPixels() done
[16:02:47.633] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C0.dat
[16:02:47.639] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C1.dat
[16:02:47.644] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C2.dat
[16:02:47.650] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C3.dat
[16:02:47.657] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C4.dat
[16:02:47.663] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C5.dat
[16:02:47.669] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C6.dat
[16:02:47.675] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C7.dat
[16:02:47.681] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C8.dat
[16:02:47.686] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C9.dat
[16:02:47.692] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C10.dat
[16:02:47.697] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C11.dat
[16:02:47.703] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C12.dat
[16:02:47.709] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C13.dat
[16:02:47.715] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C14.dat
[16:02:47.720] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//trimParameters35_C15.dat
[16:02:47.726] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-K-1-26_FPIXTest-17C-FNAL-161019-1258-150V_2016-10-19_12h58m_1476899905/000_FPIXTest_p17//defaultMaskFile.dat
[16:02:47.739] INFO: enter test to run
[16:03:19.177] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:03:19.177] INFO: running: xray
[16:03:19.178] INFO: ----------------------------------------------------------------------
[16:03:19.178] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:03:19.178] INFO: ----------------------------------------------------------------------
[16:03:20.165] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:03:31.549] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[16:04:01.378] INFO: Resuming triggers.
[16:04:12.766] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[16:04:42.901] INFO: Resuming triggers.
[16:04:54.292] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[16:05:24.225] INFO: Resuming triggers.
[16:05:35.615] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[16:06:05.512] INFO: Resuming triggers.
[16:06:16.905] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[16:06:47.280] INFO: Resuming triggers.
[16:06:58.673] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[16:07:29.212] INFO: Resuming triggers.
[16:07:40.607] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[16:08:11.323] INFO: Resuming triggers.
[16:08:22.713] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[16:08:52.754] INFO: Resuming triggers.
[16:09:02.009] INFO: data taking finished, elapsed time: 100 seconds.
[16:09:25.997] INFO: PixTest:: pg_setup set to default.
[16:09:25.000] INFO: PixTestXray::doPhRun() done
[16:09:26.299] INFO: enter test to run
[16:10:11.238] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:10:11.239] INFO: running: xray
[16:10:11.240] INFO: ----------------------------------------------------------------------
[16:10:11.240] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:10:11.240] INFO: ----------------------------------------------------------------------
[16:10:12.225] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:10:18.851] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[16:10:49.012] INFO: Resuming triggers.
[16:10:55.640] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[16:11:25.822] INFO: Resuming triggers.
[16:11:32.454] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[16:12:02.498] INFO: Resuming triggers.
[16:12:09.123] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[16:12:39.128] INFO: Resuming triggers.
[16:12:45.754] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[16:13:15.758] INFO: Resuming triggers.
[16:13:22.380] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[16:13:52.416] INFO: Resuming triggers.
[16:13:59.039] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[16:14:29.164] INFO: Resuming triggers.
[16:14:35.789] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[16:15:05.842] INFO: Resuming triggers.
[16:15:12.463] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[16:15:42.534] INFO: Resuming triggers.
[16:15:49.161] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[16:16:19.495] INFO: Resuming triggers.
[16:16:26.121] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[16:16:57.052] INFO: Resuming triggers.
[16:17:03.678] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[16:17:34.567] INFO: Resuming triggers.
[16:17:41.191] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[16:18:12.091] INFO: Resuming triggers.
[16:18:18.718] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[16:18:49.169] INFO: Resuming triggers.
[16:18:55.795] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[16:19:26.542] INFO: Resuming triggers.
[16:19:27.506] INFO: data taking finished, elapsed time: 100 seconds.
[16:19:32.279] INFO: PixTest:: pg_setup set to default.
[16:19:32.283] INFO: PixTestXray::doPhRun() done
[16:19:32.435] INFO: enter test to run
[16:20:33.834] INFO: test: HighRate no parameter change
[16:20:33.834] INFO: running: highrate
[16:20:33.845] INFO: ----------------------------------------------------------------------
[16:20:33.845] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:20:33.845] INFO: ----------------------------------------------------------------------
[16:20:33.999] INFO: Expecting 768 events.
[16:20:35.138] INFO: 768 events read in total (423ms).
[16:20:35.139] INFO: Test took 1274ms.
[16:20:35.941] INFO: Expecting 41600 events.
[16:20:39.118] INFO: 41600 events read in total (2650ms).
[16:20:39.119] INFO: Test took 3975ms.
[16:20:39.155] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:20:39.877] INFO: Expecting 41600 events.
[16:20:43.115] INFO: 41600 events read in total (2711ms).
[16:20:43.116] INFO: Test took 3919ms.
[16:20:43.152] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:20:43.870] INFO: Expecting 41600 events.
[16:20:47.137] INFO: 41600 events read in total (2740ms).
[16:20:47.138] INFO: Test took 3968ms.
[16:20:47.174] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:20:47.890] INFO: Expecting 41600 events.
[16:20:51.204] INFO: 41600 events read in total (2787ms).
[16:20:51.205] INFO: Test took 4013ms.
[16:20:51.240] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:20:51.955] INFO: Expecting 41600 events.
[16:20:55.257] INFO: 41600 events read in total (2775ms).
[16:20:55.258] INFO: Test took 3998ms.
[16:20:55.303] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:20:55.002] INFO: Expecting 41600 events.
[16:20:59.237] INFO: 41600 events read in total (2709ms).
[16:20:59.238] INFO: Test took 3909ms.
[16:20:59.275] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:20:59.997] INFO: Expecting 41600 events.
[16:21:03.276] INFO: 41600 events read in total (2753ms).
[16:21:03.277] INFO: Test took 3984ms.
[16:21:03.313] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:04.029] INFO: Expecting 41600 events.
[16:21:07.346] INFO: 41600 events read in total (2790ms).
[16:21:07.347] INFO: Test took 4016ms.
[16:21:07.382] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:08.101] INFO: Expecting 41600 events.
[16:21:11.400] INFO: 41600 events read in total (2772ms).
[16:21:11.401] INFO: Test took 4001ms.
[16:21:11.436] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:12.154] INFO: Expecting 41600 events.
[16:21:15.489] INFO: 41600 events read in total (2808ms).
[16:21:15.490] INFO: Test took 4036ms.
[16:21:15.531] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:16.238] INFO: Expecting 41600 events.
[16:21:19.570] INFO: 41600 events read in total (2805ms).
[16:21:19.571] INFO: Test took 4022ms.
[16:21:19.607] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:20.322] INFO: Expecting 41600 events.
[16:21:23.643] INFO: 41600 events read in total (2794ms).
[16:21:23.644] INFO: Test took 4019ms.
[16:21:23.680] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:24.401] INFO: Expecting 41600 events.
[16:21:27.683] INFO: 41600 events read in total (2755ms).
[16:21:27.684] INFO: Test took 3986ms.
[16:21:27.721] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:28.438] INFO: Expecting 41600 events.
[16:21:31.733] INFO: 41600 events read in total (2768ms).
[16:21:31.734] INFO: Test took 3996ms.
[16:21:31.769] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:32.491] INFO: Expecting 41600 events.
[16:21:35.788] INFO: 41600 events read in total (2770ms).
[16:21:35.789] INFO: Test took 4003ms.
[16:21:35.824] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:36.544] INFO: Expecting 41600 events.
[16:21:39.812] INFO: 41600 events read in total (2741ms).
[16:21:39.813] INFO: Test took 3971ms.
[16:21:39.850] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:40.563] INFO: Expecting 41600 events.
[16:21:43.812] INFO: 41600 events read in total (2722ms).
[16:21:43.813] INFO: Test took 3938ms.
[16:21:43.849] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:44.568] INFO: Expecting 41600 events.
[16:21:47.877] INFO: 41600 events read in total (2783ms).
[16:21:47.878] INFO: Test took 4011ms.
[16:21:47.913] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:48.627] INFO: Expecting 41600 events.
[16:21:51.901] INFO: 41600 events read in total (2747ms).
[16:21:51.902] INFO: Test took 3970ms.
[16:21:51.938] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:52.656] INFO: Expecting 41600 events.
[16:21:55.856] INFO: 41600 events read in total (2674ms).
[16:21:55.857] INFO: Test took 3901ms.
[16:21:55.891] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:21:56.244] INFO: enter test to run
[16:22:58.729] INFO: test: HighRate no parameter change
[16:22:58.729] INFO: running: highrate
[16:22:58.730] INFO: ----------------------------------------------------------------------
[16:22:58.730] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:22:58.730] INFO: ----------------------------------------------------------------------
[16:22:59.351] INFO: Expecting 208000 events.
[16:23:11.568] INFO: 208000 events read in total (11690ms).
[16:23:11.572] INFO: Test took 12833ms.
[16:23:11.723] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:23:11.981] INFO: number of dead pixels (per ROC): 2 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:23:11.994] INFO: number of red-efficiency pixels: 92 58 101 182 139 181 184 109 94 140 122 97 102 68 25 26
[16:23:11.994] INFO: number of X-ray hits detected: 68663 44991 69980 111769 113764 120192 120565 80888 75166 102086 96568 85330 89517 52156 23072 24487
[16:23:11.994] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:23:11.994] INFO: number of Vcal hits detected: 207809 207942 207800 207807 207855 207813 207808 207889 207906 207853 207875 207902 207898 207932 207975 207974
[16:23:11.994] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[16:23:11.994] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[16:23:11.994] INFO: X-ray hit rate [MHz/cm2]: 20.1 13.2 20.5 32.8 33.3 35.2 35.3 23.7 22.0 29.9 28.3 25.0 26.2 15.3 6.8 7.2
[16:23:11.994] INFO: PixTestHighRate::doXPixelAlive() done
[16:23:12.044] INFO: PixTest:: pg_setup set to default.
[16:23:12.061] INFO: enter test to run
[16:23:45.489] INFO: test: HighRate no parameter change
[16:23:45.489] INFO: running: highrate
[16:23:45.490] INFO: ----------------------------------------------------------------------
[16:23:45.490] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:23:45.490] INFO: ----------------------------------------------------------------------
[16:23:46.103] INFO: Expecting 208000 events.
[16:23:59.793] INFO: 208000 events read in total (13163ms).
[16:23:59.798] INFO: Test took 14298ms.
[16:24:00.096] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:00.402] INFO: number of dead pixels (per ROC): 2 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:24:00.402] INFO: number of red-efficiency pixels: 257 160 324 569 557 668 646 350 227 398 395 291 323 221 71 60
[16:24:00.402] INFO: number of X-ray hits detected: 141135 92649 144399 230399 236444 247929 247489 166356 155904 210393 200536 175967 184608 108484 47216 50746
[16:24:00.402] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:24:00.402] INFO: number of Vcal hits detected: 207614 207833 207535 207363 207387 207261 207269 207614 207764 207569 207573 207688 207654 207763 207929 207939
[16:24:00.402] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.7 99.7 99.8 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[16:24:00.402] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.7 99.7 99.6 99.6 99.8 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[16:24:00.403] INFO: X-ray hit rate [MHz/cm2]: 41.4 27.2 42.3 67.5 69.3 72.7 72.5 48.8 45.7 61.7 58.8 51.6 54.1 31.8 13.8 14.9
[16:24:00.403] INFO: PixTestHighRate::doXPixelAlive() done
[16:24:00.453] INFO: PixTest:: pg_setup set to default.
[16:24:00.471] INFO: enter test to run
[16:24:20.985] INFO: test: HighRate no parameter change
[16:24:20.985] INFO: running: highrate
[16:24:20.986] INFO: ----------------------------------------------------------------------
[16:24:20.986] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:24:20.986] INFO: ----------------------------------------------------------------------
[16:24:21.604] INFO: Expecting 208000 events.
[16:24:37.189] INFO: 208000 events read in total (15058ms).
[16:24:37.196] INFO: Test took 16201ms.
[16:24:37.637] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:37.995] INFO: number of dead pixels (per ROC): 2 0 2 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:24:37.995] INFO: number of red-efficiency pixels: 557 298 713 1223 1292 1512 1365 736 543 875 882 619 792 435 114 126
[16:24:37.996] INFO: number of X-ray hits detected: 212640 139793 216541 346293 356722 373389 371972 251727 235215 316695 301604 266682 279052 163310 71984 77121
[16:24:37.996] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:24:37.996] INFO: number of Vcal hits detected: 207208 207671 206934 206401 206335 205870 206157 207067 207402 206957 206958 207284 207102 207482 207879 207872
[16:24:37.996] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.3 99.3 99.1 99.2 99.6 99.7 99.5 99.5 99.7 99.6 99.8 99.9 99.9
[16:24:37.996] INFO: Vcal hit overall efficiency (%): 99.6 99.8 99.5 99.2 99.2 99.0 99.1 99.6 99.7 99.5 99.5 99.7 99.6 99.8 99.9 99.9
[16:24:37.996] INFO: X-ray hit rate [MHz/cm2]: 62.3 41.0 63.5 101.5 104.6 109.4 109.0 73.8 68.9 92.8 88.4 78.2 81.8 47.9 21.1 22.6
[16:24:37.996] INFO: PixTestHighRate::doXPixelAlive() done
[16:24:38.050] INFO: PixTest:: pg_setup set to default.
[16:24:38.062] INFO: enter test to run
[16:25:02.848] INFO: test: exit no parameter change
[16:25:03.365] QUIET: Connection to board 33 closed.
[16:25:03.447] INFO: pXar: this is the end, my friend