[15:59:43.488] INFO: *** Welcome to pxar ***
[15:59:43.488] INFO: *** Today: 2016/10/06
[15:59:44.367] INFO: *** Version: v1.9.0-818-g96727
[15:59:44.367] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//dacParameters35_C15.dat
[15:59:44.380] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:59:44.380] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//defaultMaskFile.dat
[15:59:44.387] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C15.dat
[15:59:44.534] INFO: clk: 4
[15:59:44.534] INFO: ctr: 4
[15:59:44.534] INFO: sda: 19
[15:59:44.534] INFO: tin: 9
[15:59:44.534] INFO: level: 15
[15:59:44.534] INFO: triggerdelay: 0
[15:59:44.534] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:59:44.534] INFO: Log level: INFO
[15:59:44.573] QUIET: Connection to board DTB_WREKRL opened.
[15:59:44.576] 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:59:44.578] INFO: RPC call hashes of host and DTB match: 398089610
[15:59:46.117] INFO: DUT info:
[15:59:46.117] INFO: The DUT currently contains the following objects:
[15:59:46.117] INFO: 2 TBM Cores tbm08c (2 ON)
[15:59:46.137] INFO: TBM Core alpha (0): 7 registers set
[15:59:46.137] INFO: TBM Core beta (1): 7 registers set
[15:59:46.137] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:59:46.137] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.137] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.137] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.137] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.137] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.137] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.138] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.138] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.138] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.138] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.138] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.138] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.138] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.138] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.138] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.138] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:46.565] INFO: enter 'restricted' command line mode
[15:59:46.565] INFO: enter test to run
[15:59:54.214] INFO: test: PixelAlive no parameter change
[15:59:54.214] INFO: running: pixelalive
[15:59:54.237] INFO: ----------------------------------------------------------------------
[15:59:54.237] 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:59:54.237] INFO: ----------------------------------------------------------------------
[15:59:54.558] INFO: Expecting 41600 events.
[15:59:58.888] INFO: 41600 events read in total (3612ms).
[15:59:59.056] INFO: Test took 4817ms.
[15:59:59.068] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:59.344] INFO: PixTestAlive::aliveTest() done
[15:59:59.344] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 0 0 0 0 0 3 0 0
[15:59:59.375] INFO: enter test to run
[16:00:02.910] INFO: test: timing no parameter change
[16:00:02.910] INFO: running: timing
[16:00:02.914] INFO: ######################################################################
[16:00:02.914] INFO: PixTestTiming::doTest()
[16:00:02.914] INFO: ######################################################################
[16:00:02.914] INFO: ----------------------------------------------------------------------
[16:00:02.914] INFO: PixTestTiming::TBMPhaseScan()
[16:00:02.914] INFO: ----------------------------------------------------------------------
[16:07:52.420] INFO: TBM Phase Settings: 240
[16:07:52.420] INFO: 400MHz Phase: 4
[16:07:52.420] INFO: 160MHz Phase: 7
[16:07:52.420] INFO: Functional Phase Area: 5
[16:07:52.423] INFO: Test took 469509 ms.
[16:07:52.423] INFO: PixTestTiming::TBMPhaseScan() done.
[16:07:52.424] INFO: ----------------------------------------------------------------------
[16:07:52.424] INFO: PixTestTiming::ROCDelayScan()
[16:07:52.424] INFO: ----------------------------------------------------------------------
[16:09:52.638] INFO: ROC Delay Settings: 228
[16:09:52.638] INFO: ROC Header-Trailer/Token Delay: 11
[16:09:52.638] INFO: ROC Port 0 Delay: 4
[16:09:52.638] INFO: ROC Port 1 Delay: 4
[16:09:52.638] INFO: Functional ROC Area: 5
[16:09:52.641] INFO: Test took 120217 ms.
[16:09:52.641] INFO: PixTestTiming::ROCDelayScan() done.
[16:09:52.642] INFO: ----------------------------------------------------------------------
[16:09:52.642] INFO: PixTestTiming::TimingTest()
[16:09:52.642] INFO: ----------------------------------------------------------------------
[16:10:08.883] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:10:24.167] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:10:39.114] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:10:54.055] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:11:09.018] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:11:23.923] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:11:38.877] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:11:53.836] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:08.782] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:23.767] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:24.145] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:24.162] INFO: ----------------------------------------------------------------------
[16:12:24.162] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:12:24.162] INFO: ----------------------------------------------------------------------
[16:12:24.162] INFO: ----------------------------------------------------------------------
[16:12:24.162] INFO: Read back bit status: 1
[16:12:24.162] INFO: ----------------------------------------------------------------------
[16:12:24.162] INFO: ----------------------------------------------------------------------
[16:12:24.162] INFO: Timings are good!
[16:12:24.162] INFO: ----------------------------------------------------------------------
[16:12:24.162] INFO: Test took 151520 ms.
[16:12:24.162] INFO: PixTestTiming::TimingTest() done.
[16:12:24.162] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:12:24.163] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:12:24.163] INFO: PixTestTiming::doTest took 741253 ms.
[16:12:24.163] INFO: PixTestTiming::doTest() done
[16:12:24.163] INFO: Write out TBMPhaseScan_0_V0
[16:12:24.163] INFO: Write out TBMPhaseScan_1_V0
[16:12:24.163] INFO: Write out CombinedTBMPhaseScan_V0
[16:12:24.184] INFO: Write out ROCDelayScan3_V0
[16:12:24.185] INFO: enter test to run
[16:13:18.097] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:13:18.097] INFO: running: highrate
[16:13:18.110] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:13:18.362] INFO: ----------------------------------------------------------------------
[16:13:18.362] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:13:18.362] INFO: ----------------------------------------------------------------------
[16:13:18.362] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:13:18.362] INFO: edge/corner pixel THR is adjusted
[16:13:18.362] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:13:19.339] INFO: Collecting data for 5 seconds...
[16:13:24.357] INFO: Done with hot pixel readout
[16:13:35.954] INFO: PixTest:: pg_setup set to default.
[16:13:35.955] INFO: 6 hot pixels found in step 0
[16:13:36.946] INFO: Collecting data for 5 seconds...
[16:13:41.963] INFO: Done with hot pixel readout
[16:13:53.571] INFO: PixTest:: pg_setup set to default.
[16:13:53.572] INFO: 6 hot pixels found in step 1
[16:13:54.564] INFO: Collecting data for 5 seconds...
[16:13:59.580] INFO: Done with hot pixel readout
[16:14:11.187] INFO: PixTest:: pg_setup set to default.
[16:14:11.188] INFO: 4 hot pixels found in step 2
[16:14:12.180] INFO: Collecting data for 5 seconds...
[16:14:17.195] INFO: Done with hot pixel readout
[16:14:28.584] INFO: PixTest:: pg_setup set to default.
[16:14:28.585] INFO: 4 hot pixels found in step 3
[16:14:29.577] INFO: Collecting data for 5 seconds...
[16:14:34.593] INFO: Done with hot pixel readout
[16:14:46.094] INFO: PixTest:: pg_setup set to default.
[16:14:46.095] INFO: 5 hot pixels found in step 4
[16:14:47.087] INFO: Collecting data for 5 seconds...
[16:14:52.104] INFO: Done with hot pixel readout
[16:15:03.686] INFO: PixTest:: pg_setup set to default.
[16:15:03.687] INFO: 3 hot pixels found in step 5
[16:15:04.679] INFO: Collecting data for 5 seconds...
[16:15:09.696] INFO: Done with hot pixel readout
[16:15:21.312] INFO: PixTest:: pg_setup set to default.
[16:15:21.313] INFO: 8 hot pixels found in step 6
[16:15:22.304] INFO: Collecting data for 5 seconds...
[16:15:27.322] INFO: Done with hot pixel readout
[16:15:38.807] INFO: PixTest:: pg_setup set to default.
[16:15:38.808] INFO: 3 hot pixels found in step 7
[16:15:39.800] INFO: Collecting data for 5 seconds...
[16:15:44.818] INFO: Done with hot pixel readout
[16:15:56.446] INFO: PixTest:: pg_setup set to default.
[16:15:56.446] INFO: 2 hot pixels found in step 8
[16:15:57.439] INFO: Collecting data for 5 seconds...
[16:16:02.456] INFO: Done with hot pixel readout
[16:16:14.093] INFO: PixTest:: pg_setup set to default.
[16:16:14.094] INFO: 3 hot pixels found in step 9
[16:16:15.086] INFO: Collecting data for 5 seconds...
[16:16:20.105] INFO: Done with hot pixel readout
[16:16:31.636] INFO: PixTest:: pg_setup set to default.
[16:16:31.637] INFO: 5 hot pixels found in step 10
[16:16:32.630] INFO: Collecting data for 5 seconds...
[16:16:37.649] INFO: Done with hot pixel readout
[16:16:49.043] INFO: PixTest:: pg_setup set to default.

[16:16:49.044] INFO: 1 hot pixels found in step 11
[16:16:49.081] INFO: 1 hot pixels could not be trimmed and have been masked.
[16:16:49.084] INFO: PixTest::trimHotPixels() done
[16:16:49.084] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C0.dat
[16:16:49.090] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C1.dat
[16:16:49.096] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C2.dat
[16:16:49.101] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C3.dat
[16:16:49.106] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C4.dat
[16:16:49.112] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C5.dat
[16:16:49.117] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C6.dat
[16:16:49.123] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C7.dat
[16:16:49.128] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C8.dat
[16:16:49.148] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C9.dat
[16:16:49.155] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C10.dat
[16:16:49.160] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C11.dat
[16:16:49.167] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C12.dat
[16:16:49.172] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C13.dat
[16:16:49.178] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C14.dat
[16:16:49.184] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C15.dat
[16:16:49.189] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//defaultMaskFile.dat
[16:16:49.208] INFO: enter test to run
[16:17:18.631] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:17:18.631] INFO: running: highrate
[16:17:18.636] INFO: ----------------------------------------------------------------------
[16:17:18.636] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:17:18.636] INFO: ----------------------------------------------------------------------
[16:17:18.636] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:17:18.636] INFO: edge/corner pixel THR is adjusted
[16:17:18.636] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:17:19.593] INFO: Collecting data for 1 seconds...
[16:17:20.597] INFO: Done with hot pixel readout
[16:17:24.544] INFO: PixTest:: pg_setup set to default.
[16:17:24.545] INFO: 0 hot pixels found in step 0
[16:17:24.550] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:17:24.641] INFO: PixTest::trimHotPixels() done
[16:17:24.641] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C0.dat
[16:17:24.653] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C1.dat
[16:17:24.663] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C2.dat
[16:17:24.669] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C3.dat
[16:17:24.674] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C4.dat
[16:17:24.680] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C5.dat
[16:17:24.685] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C6.dat
[16:17:24.691] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C7.dat
[16:17:24.697] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C8.dat
[16:17:24.702] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C9.dat
[16:17:24.708] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C10.dat
[16:17:24.713] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C11.dat
[16:17:24.719] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C12.dat
[16:17:24.724] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C13.dat
[16:17:24.729] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C14.dat
[16:17:24.735] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C15.dat
[16:17:24.740] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-P-2-32_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//defaultMaskFile.dat
[16:17:24.756] INFO: enter test to run
[16:17:58.023] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:17:58.023] INFO: running: xray
[16:17:58.024] INFO: ----------------------------------------------------------------------
[16:17:58.024] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:17:58.024] INFO: ----------------------------------------------------------------------
[16:17:58.988] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:18:10.675] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[16:18:38.505] INFO: Resuming triggers.
[16:18:50.285] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[16:19:19.532] INFO: Resuming triggers.
[16:19:31.220] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[16:20:01.653] INFO: Resuming triggers.
[16:20:13.346] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[16:20:43.153] INFO: Resuming triggers.
[16:20:54.840] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[16:21:25.073] INFO: Resuming triggers.
[16:21:36.758] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[16:22:06.668] INFO: Resuming triggers.
[16:22:18.356] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[16:22:47.663] INFO: Resuming triggers.
[16:22:59.346] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[16:23:28.793] INFO: Resuming triggers.
[16:23:35.665] INFO: data taking finished, elapsed time: 100 seconds.
[16:23:53.082] INFO: PixTest:: pg_setup set to default.
[16:23:53.086] INFO: PixTestXray::doPhRun() done
[16:23:53.259] INFO: enter test to run
[16:24:33.052] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:24:33.052] INFO: running: xray
[16:24:33.054] INFO: ----------------------------------------------------------------------
[16:24:33.054] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:24:33.054] INFO: ----------------------------------------------------------------------
[16:24:34.017] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:24:40.949] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[16:25:11.140] INFO: Resuming triggers.
[16:25:18.071] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[16:25:48.156] INFO: Resuming triggers.
[16:25:55.084] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[16:26:25.303] INFO: Resuming triggers.
[16:26:32.234] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[16:27:02.390] INFO: Resuming triggers.
[16:27:09.323] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[16:27:39.353] INFO: Resuming triggers.
[16:27:46.290] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[16:28:16.341] INFO: Resuming triggers.
[16:28:23.274] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[16:28:53.508] INFO: Resuming triggers.
[16:29:00.442] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[16:29:31.219] INFO: Resuming triggers.
[16:29:38.154] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[16:30:08.644] INFO: Resuming triggers.
[16:30:15.578] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[16:30:46.546] INFO: Resuming triggers.
[16:30:53.487] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[16:31:23.541] INFO: Resuming triggers.
[16:31:30.482] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[16:32:01.372] INFO: Resuming triggers.
[16:32:08.308] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[16:32:40.363] INFO: Resuming triggers.
[16:32:47.302] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[16:33:18.766] INFO: Resuming triggers.
[16:33:22.040] INFO: data taking finished, elapsed time: 100 seconds.
[16:33:37.233] INFO: PixTest:: pg_setup set to default.
[16:33:37.236] INFO: PixTestXray::doPhRun() done
[16:33:37.388] INFO: enter test to run
[16:34:16.209] INFO: test: HighRate no parameter change
[16:34:16.209] INFO: running: highrate
[16:34:16.225] INFO: ----------------------------------------------------------------------
[16:34:16.225] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:34:16.225] INFO: ----------------------------------------------------------------------
[16:34:16.380] INFO: Expecting 768 events.
[16:34:17.513] INFO: 768 events read in total (419ms).
[16:34:17.514] INFO: Test took 1268ms.
[16:34:18.316] INFO: Expecting 41600 events.
[16:34:21.476] INFO: 41600 events read in total (2633ms).
[16:34:21.477] INFO: Test took 3956ms.
[16:34:21.510] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:34:22.236] INFO: Expecting 41600 events.
[16:34:25.415] INFO: 41600 events read in total (2652ms).
[16:34:25.416] INFO: Test took 3889ms.
[16:34:25.449] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:34:26.175] INFO: Expecting 41600 events.
[16:34:29.385] INFO: 41600 events read in total (2683ms).
[16:34:29.386] INFO: Test took 3920ms.
[16:34:29.419] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:34:30.141] INFO: Expecting 41600 events.
[16:34:33.350] INFO: 41600 events read in total (2682ms).
[16:34:33.351] INFO: Test took 3916ms.
[16:34:33.384] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:34:34.112] INFO: Expecting 41600 events.
[16:34:37.343] INFO: 41600 events read in total (2704ms).
[16:34:37.344] INFO: Test took 3941ms.
[16:34:37.377] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:34:38.100] INFO: Expecting 41600 events.
[16:34:41.314] INFO: 41600 events read in total (2687ms).
[16:34:41.315] INFO: Test took 3919ms.
[16:34:41.348] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:34:42.073] INFO: Expecting 41600 events.
[16:34:45.229] INFO: 41600 events read in total (2629ms).
[16:34:45.230] INFO: Test took 3864ms.
[16:34:45.264] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:34:45.990] INFO: Expecting 41600 events.
[16:34:49.224] INFO: 41600 events read in total (2707ms).
[16:34:49.225] INFO: Test took 3942ms.
[16:34:49.258] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:34:49.985] INFO: Expecting 41600 events.
[16:34:53.220] INFO: 41600 events read in total (2708ms).
[16:34:53.221] INFO: Test took 3945ms.
[16:34:53.254] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:34:53.981] INFO: Expecting 41600 events.
[16:34:57.214] INFO: 41600 events read in total (2706ms).
[16:34:57.215] INFO: Test took 3944ms.
[16:34:57.248] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:34:57.970] INFO: Expecting 41600 events.
[16:35:01.201] INFO: 41600 events read in total (2704ms).
[16:35:01.202] INFO: Test took 3936ms.
[16:35:01.234] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:01.962] INFO: Expecting 41600 events.
[16:35:05.196] INFO: 41600 events read in total (2707ms).
[16:35:05.197] INFO: Test took 3945ms.
[16:35:05.231] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:05.956] INFO: Expecting 41600 events.
[16:35:09.169] INFO: 41600 events read in total (2686ms).
[16:35:09.170] INFO: Test took 3920ms.
[16:35:09.204] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:09.930] INFO: Expecting 41600 events.
[16:35:13.154] INFO: 41600 events read in total (2697ms).
[16:35:13.155] INFO: Test took 3933ms.
[16:35:13.188] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:13.916] INFO: Expecting 41600 events.
[16:35:17.157] INFO: 41600 events read in total (2714ms).
[16:35:17.158] INFO: Test took 3952ms.
[16:35:17.191] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:17.913] INFO: Expecting 41600 events.
[16:35:21.166] INFO: 41600 events read in total (2726ms).
[16:35:21.167] INFO: Test took 3957ms.
[16:35:21.199] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:21.924] INFO: Expecting 41600 events.
[16:35:25.114] INFO: 41600 events read in total (2663ms).
[16:35:25.115] INFO: Test took 3898ms.
[16:35:25.148] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:25.873] INFO: Expecting 41600 events.
[16:35:29.103] INFO: 41600 events read in total (2703ms).
[16:35:29.104] INFO: Test took 3938ms.
[16:35:29.137] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:29.865] INFO: Expecting 41600 events.
[16:35:32.002] INFO: 41600 events read in total (2610ms).
[16:35:32.003] INFO: Test took 3846ms.
[16:35:33.036] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:33.764] INFO: Expecting 41600 events.
[16:35:36.773] INFO: 41600 events read in total (2482ms).
[16:35:36.774] INFO: Test took 3720ms.
[16:35:36.806] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:35:37.175] INFO: enter test to run
[16:35:53.720] INFO: test: HighRate no parameter change
[16:35:53.720] INFO: running: highrate
[16:35:53.721] INFO: ----------------------------------------------------------------------
[16:35:53.721] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:35:53.721] INFO: ----------------------------------------------------------------------
[16:35:54.340] INFO: Expecting 208000 events.
[16:36:06.147] INFO: 208000 events read in total (11280ms).
[16:36:06.151] INFO: Test took 12422ms.
[16:36:06.287] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:06.538] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 0 0 0 0 0 3 0 0
[16:36:06.538] INFO: number of red-efficiency pixels: 105 44 82 128 128 140 115 87 78 99 110 91 96 75 26 29
[16:36:06.538] INFO: number of X-ray hits detected: 62556 41506 65544 101411 110897 111544 107317 74034 70664 91927 91607 78405 84729 50960 22832 27548
[16:36:06.538] 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:36:06.538] INFO: number of Vcal hits detected: 207890 207956 207917 207870 207821 207856 207883 207913 207920 207900 207888 207907 207903 207777 207973 207971
[16:36:06.538] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[16:36:06.538] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 99.9 100.0 100.0 99.9 100.0 100.0
[16:36:06.538] INFO: X-ray hit rate [MHz/cm2]: 18.3 12.2 19.2 29.7 32.5 32.7 31.5 21.7 20.7 26.9 26.9 23.0 24.8 14.9 6.7 8.1
[16:36:06.538] INFO: PixTestHighRate::doXPixelAlive() done
[16:36:06.591] INFO: PixTest:: pg_setup set to default.
[16:36:06.605] INFO: enter test to run
[16:36:28.047] INFO: test: HighRate no parameter change
[16:36:28.048] INFO: running: highrate
[16:36:28.049] INFO: ----------------------------------------------------------------------
[16:36:28.049] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:36:28.049] INFO: ----------------------------------------------------------------------
[16:36:28.665] INFO: Expecting 208000 events.
[16:36:42.115] INFO: 208000 events read in total (12924ms).
[16:36:42.120] INFO: Test took 14062ms.
[16:36:42.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:36:42.691] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 0 0 0 0 0 3 0 0
[16:36:42.691] INFO: number of red-efficiency pixels: 235 134 322 467 402 446 419 312 186 381 322 285 235 137 61 60
[16:36:42.691] INFO: number of X-ray hits detected: 127510 85195 133833 209961 226254 229779 220276 153596 144423 187714 188598 161589 173994 105345 46743 57180
[16:36:42.691] 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:36:42.691] INFO: number of Vcal hits detected: 207749 207859 207653 207494 207517 207522 207546 207661 207806 207601 207658 207700 207753 207707 207938 207939
[16:36:42.691] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.8 99.8 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[16:36:42.691] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.8 99.8 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[16:36:42.691] INFO: X-ray hit rate [MHz/cm2]: 37.4 25.0 39.2 61.5 66.3 67.3 64.6 45.0 42.3 55.0 55.3 47.4 51.0 30.9 13.7 16.8
[16:36:42.691] INFO: PixTestHighRate::doXPixelAlive() done
[16:36:42.740] INFO: PixTest:: pg_setup set to default.
[16:36:42.752] INFO: enter test to run
[16:37:03.775] INFO: test: HighRate no parameter change
[16:37:03.775] INFO: running: highrate
[16:37:03.777] INFO: ----------------------------------------------------------------------
[16:37:03.777] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:37:03.777] INFO: ----------------------------------------------------------------------
[16:37:04.398] INFO: Expecting 208000 events.
[16:37:19.563] INFO: 208000 events read in total (14638ms).
[16:37:19.570] INFO: Test took 15783ms.
[16:37:19.974] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:37:20.316] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 0 0 0 0 0 3 0 0
[16:37:20.316] INFO: number of red-efficiency pixels: 490 245 689 1017 904 942 905 657 417 848 818 655 559 377 100 100
[16:37:20.316] INFO: number of X-ray hits detected: 192113 128446 201993 315991 344737 345540 331999 231250 219297 283112 283999 243672 262434 158840 70980 86474
[16:37:20.316] 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:37:20.316] INFO: number of Vcal hits detected: 207413 207732 207072 206764 206887 206856 206876 207184 207533 207024 207046 207250 207384 207429 207898 207898
[16:37:20.316] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.5 99.5 99.5 99.5 99.6 99.8 99.6 99.6 99.7 99.7 99.8 100.0 100.0
[16:37:20.316] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.6 99.4 99.5 99.5 99.5 99.6 99.8 99.5 99.5 99.6 99.7 99.7 100.0 100.0
[16:37:20.316] INFO: X-ray hit rate [MHz/cm2]: 56.3 37.6 59.2 92.6 101.0 101.3 97.3 67.8 64.3 83.0 83.2 71.4 76.9 46.6 20.8 25.3
[16:37:20.316] INFO: PixTestHighRate::doXPixelAlive() done
[16:37:20.364] INFO: PixTest:: pg_setup set to default.
[16:37:20.381] INFO: enter test to run
[16:37:49.519] INFO: test: exit no parameter change
[16:37:50.026] QUIET: Connection to board 33 closed.
[16:37:50.037] INFO: pXar: this is the end, my friend