[15:03:13.676] INFO: *** Welcome to pxar ***
[15:03:13.676] INFO: *** Today: 2016/10/07
[15:03:13.691] INFO: *** Version: v1.9.0-818-g96727
[15:03:13.691] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//dacParameters35_C15.dat
[15:03:13.692] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:03:13.692] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//defaultMaskFile.dat
[15:03:13.692] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C15.dat
[15:03:13.764] INFO: clk: 4
[15:03:13.764] INFO: ctr: 4
[15:03:13.764] INFO: sda: 19
[15:03:13.764] INFO: tin: 9
[15:03:13.764] INFO: level: 15
[15:03:13.764] INFO: triggerdelay: 0
[15:03:13.764] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:03:13.764] INFO: Log level: INFO
[15:03:13.779] QUIET: Connection to board DTB_WREKRL opened.
[15:03:13.783] 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:03:13.785] INFO: RPC call hashes of host and DTB match: 398089610
[15:03:15.330] INFO: DUT info:
[15:03:15.330] INFO: The DUT currently contains the following objects:
[15:03:15.330] INFO: 2 TBM Cores tbm08c (2 ON)
[15:03:15.330] INFO: TBM Core alpha (0): 7 registers set
[15:03:15.330] INFO: TBM Core beta (1): 7 registers set
[15:03:15.330] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:03:15.330] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.330] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.330] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.330] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.330] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.330] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.331] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.331] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.331] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.331] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.331] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.331] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.331] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.331] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.331] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.331] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:15.734] INFO: enter 'restricted' command line mode
[15:03:15.734] INFO: enter test to run
[15:03:21.985] INFO: test: PixelAlive no parameter change
[15:03:21.985] INFO: running: pixelalive
[15:03:21.994] INFO: ----------------------------------------------------------------------
[15:03:21.994] 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:03:21.994] INFO: ----------------------------------------------------------------------
[15:03:22.318] INFO: Expecting 41600 events.
[15:03:26.660] INFO: 41600 events read in total (3624ms).
[15:03:26.829] INFO: Test took 4833ms.
[15:03:26.838] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:27.103] INFO: PixTestAlive::aliveTest() done
[15:03:27.103] INFO: number of dead pixels (per ROC): 0 0 52 0 0 0 3 0 0 0 0 0 0 0 0 0
[15:03:27.132] INFO: enter test to run
[15:03:34.257] INFO: test: timing no parameter change
[15:03:34.257] INFO: running: timing
[15:03:34.260] INFO: ######################################################################
[15:03:34.260] INFO: PixTestTiming::doTest()
[15:03:34.260] INFO: ######################################################################
[15:03:34.260] INFO: ----------------------------------------------------------------------
[15:03:34.260] INFO: PixTestTiming::TBMPhaseScan()
[15:03:34.260] INFO: ----------------------------------------------------------------------
[15:08:03.456] INFO: TBM Phase Settings: 236
[15:08:03.456] INFO: 400MHz Phase: 3
[15:08:03.456] INFO: 160MHz Phase: 7
[15:08:03.456] INFO: Functional Phase Area: 5
[15:08:03.459] INFO: Test took 269199 ms.
[15:08:03.459] INFO: PixTestTiming::TBMPhaseScan() done.
[15:08:03.460] INFO: ----------------------------------------------------------------------
[15:08:03.460] INFO: PixTestTiming::ROCDelayScan()
[15:08:03.460] INFO: ----------------------------------------------------------------------
[15:10:04.609] INFO: ROC Delay Settings: 227
[15:10:04.609] INFO: ROC Header-Trailer/Token Delay: 11
[15:10:04.609] INFO: ROC Port 0 Delay: 3
[15:10:04.609] INFO: ROC Port 1 Delay: 4
[15:10:04.609] INFO: Functional ROC Area: 4
[15:10:04.612] INFO: Test took 121153 ms.
[15:10:04.612] INFO: PixTestTiming::ROCDelayScan() done.
[15:10:04.612] INFO: ----------------------------------------------------------------------
[15:10:04.612] INFO: PixTestTiming::TimingTest()
[15:10:04.612] INFO: ----------------------------------------------------------------------
[15:10:20.771] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:10:35.717] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:10:50.674] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:11:05.670] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:11:20.638] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:11:35.599] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:11:50.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:12:05.551] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:12:20.523] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:12:35.527] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:12:35.905] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:12:35.923] INFO: ----------------------------------------------------------------------
[15:12:35.923] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:12:35.923] INFO: ----------------------------------------------------------------------
[15:12:35.923] INFO: ----------------------------------------------------------------------
[15:12:35.923] INFO: Read back bit status: 1
[15:12:35.923] INFO: ----------------------------------------------------------------------
[15:12:35.923] INFO: ----------------------------------------------------------------------
[15:12:35.923] INFO: Timings are good!
[15:12:35.923] INFO: ----------------------------------------------------------------------
[15:12:35.923] INFO: Test took 151311 ms.
[15:12:35.923] INFO: PixTestTiming::TimingTest() done.
[15:12:35.924] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:12:35.924] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:12:35.924] INFO: PixTestTiming::doTest took 541667 ms.
[15:12:35.924] INFO: PixTestTiming::doTest() done
[15:12:35.924] INFO: Write out TBMPhaseScan_0_V0
[15:12:35.924] INFO: Write out TBMPhaseScan_1_V0
[15:12:35.924] INFO: Write out CombinedTBMPhaseScan_V0
[15:12:35.925] INFO: Write out ROCDelayScan3_V0
[15:12:35.925] INFO: enter test to run
[15:13:59.700] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:13:59.701] INFO: running: highrate
[15:13:59.711] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:13:59.966] INFO: ----------------------------------------------------------------------
[15:13:59.966] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:13:59.966] INFO: ----------------------------------------------------------------------
[15:13:59.966] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:13:59.967] INFO: edge/corner pixel THR is adjusted
[15:13:59.967] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:14:00.926] INFO: Collecting data for 5 seconds...
[15:14:05.942] INFO: Done with hot pixel readout
[15:14:17.627] INFO: PixTest:: pg_setup set to default.
[15:14:17.628] INFO: 10 hot pixels found in step 0
[15:14:18.619] INFO: Collecting data for 5 seconds...
[15:14:23.637] INFO: Done with hot pixel readout
[15:14:35.182] INFO: PixTest:: pg_setup set to default.
[15:14:35.183] INFO: 8 hot pixels found in step 1
[15:14:36.173] INFO: Collecting data for 5 seconds...
[15:14:41.191] INFO: Done with hot pixel readout
[15:14:52.727] INFO: PixTest:: pg_setup set to default.
[15:14:52.728] INFO: 12 hot pixels found in step 2
[15:14:53.719] INFO: Collecting data for 5 seconds...
[15:14:58.738] INFO: Done with hot pixel readout
[15:15:10.075] INFO: PixTest:: pg_setup set to default.
[15:15:10.076] INFO: 9 hot pixels found in step 3
[15:15:11.067] INFO: Collecting data for 5 seconds...
[15:15:16.084] INFO: Done with hot pixel readout
[15:15:27.427] INFO: PixTest:: pg_setup set to default.
[15:15:27.428] INFO: 8 hot pixels found in step 4
[15:15:28.419] INFO: Collecting data for 5 seconds...
[15:15:33.439] INFO: Done with hot pixel readout
[15:15:45.014] INFO: PixTest:: pg_setup set to default.
[15:15:45.014] INFO: 7 hot pixels found in step 5
[15:15:45.006] INFO: Collecting data for 5 seconds...
[15:15:51.026] INFO: Done with hot pixel readout
[15:16:02.539] INFO: PixTest:: pg_setup set to default.
[15:16:02.539] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:16:02.540] INFO: 3 hot pixels found in step 6
[15:16:03.530] INFO: Collecting data for 5 seconds...
[15:16:08.549] INFO: Done with hot pixel readout
[15:16:20.053] INFO: PixTest:: pg_setup set to default.
[15:16:20.054] INFO: 5 hot pixels found in step 7
[15:16:21.045] INFO: Collecting data for 5 seconds...
[15:16:26.063] INFO: Done with hot pixel readout
[15:16:37.452] INFO: PixTest:: pg_setup set to default.
[15:16:37.453] INFO: 5 hot pixels found in step 8
[15:16:38.444] INFO: Collecting data for 5 seconds...
[15:16:43.462] INFO: Done with hot pixel readout
[15:16:55.066] INFO: PixTest:: pg_setup set to default.
[15:16:55.066] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:16:55.067] INFO: 5 hot pixels found in step 9
[15:16:56.057] INFO: Collecting data for 5 seconds...
[15:17:01.076] INFO: Done with hot pixel readout
[15:17:12.334] INFO: PixTest:: pg_setup set to default.
[15:17:12.334] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:17:12.335] INFO: 4 hot pixels found in step 10
[15:17:13.325] INFO: Collecting data for 5 seconds...
[15:17:18.345] INFO: Done with hot pixel readout
[15:17:30.206] INFO: PixTest:: pg_setup set to default.
[15:17:30.207] INFO: 4 hot pixels found in step 11
[15:17:31.198] INFO: Collecting data for 5 seconds...
[15:17:36.218] INFO: Done with hot pixel readout
[15:17:48.200] INFO: PixTest:: pg_setup set to default.
[15:17:48.200] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:17:48.201] INFO: 2 hot pixels found in step 12
[15:17:49.191] INFO: Collecting data for 5 seconds...
[15:17:54.210] INFO: Done with hot pixel readout
[15:18:06.186] INFO: PixTest:: pg_setup set to default.
[15:18:06.187] INFO: 4 hot pixels found in step 13
[15:18:07.178] INFO: Collecting data for 5 seconds...
[15:18:12.196] INFO: Done with hot pixel readout
[15:18:24.178] INFO: PixTest:: pg_setup set to default.
[15:18:24.179] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:18:24.179] INFO: 4 hot pixels found in step 14
[15:18:24.214] INFO: 4 hot pixels could not be trimmed and have been masked.
[15:18:24.217] INFO: PixTest::trimHotPixels() done
[15:18:24.217] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C0.dat
[15:18:24.225] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C1.dat
[15:18:24.231] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C2.dat
[15:18:24.236] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C3.dat
[15:18:24.242] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C4.dat
[15:18:24.248] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C5.dat
[15:18:24.254] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C6.dat
[15:18:24.259] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C7.dat
[15:18:24.265] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C8.dat
[15:18:24.271] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C9.dat
[15:18:24.276] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C10.dat
[15:18:24.282] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C11.dat
[15:18:24.288] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C12.dat
[15:18:24.293] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C13.dat
[15:18:24.299] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C14.dat
[15:18:24.305] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C15.dat
[15:18:24.310] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//defaultMaskFile.dat
[15:18:24.320] INFO: enter test to run
[15:18:49.355] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:18:49.355] INFO: running: highrate
[15:18:49.360] INFO: ----------------------------------------------------------------------
[15:18:49.360] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:18:49.360] INFO: ----------------------------------------------------------------------
[15:18:49.360] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:18:49.360] INFO: edge/corner pixel THR is adjusted
[15:18:49.360] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:18:50.317] INFO: Collecting data for 1 seconds...
[15:18:51.322] INFO: Done with hot pixel readout
[15:18:55.220] INFO: PixTest:: pg_setup set to default.
[15:18:55.221] INFO: 0 hot pixels found in step 0
[15:18:55.227] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:18:55.318] INFO: PixTest::trimHotPixels() done
[15:18:55.319] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C0.dat
[15:18:55.331] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C1.dat
[15:18:55.346] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C2.dat
[15:18:55.352] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C3.dat
[15:18:55.358] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C4.dat
[15:18:55.363] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C5.dat
[15:18:55.369] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C6.dat
[15:18:55.375] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C7.dat
[15:18:55.380] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C8.dat
[15:18:55.386] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C9.dat
[15:18:55.392] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C10.dat
[15:18:55.398] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C11.dat
[15:18:55.403] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C12.dat
[15:18:55.409] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C13.dat
[15:18:55.415] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C14.dat
[15:18:55.421] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//trimParameters35_C15.dat
[15:18:55.426] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-03_FPIXTest-17C-FNAL-161005-1237-150V_2016-10-05_12h37m_1475689043/000_FPIXTest_p17//defaultMaskFile.dat
[15:18:55.436] INFO: enter test to run
[15:19:15.626] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:19:15.627] INFO: running: xray
[15:19:15.628] INFO: ----------------------------------------------------------------------
[15:19:15.628] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:19:15.628] INFO: ----------------------------------------------------------------------
[15:19:16.608] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:19:28.492] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:19:58.391] INFO: Resuming triggers.
[15:20:10.276] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[15:20:40.056] INFO: Resuming triggers.
[15:20:51.940] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[15:21:21.649] INFO: Resuming triggers.
[15:21:33.535] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[15:22:03.377] INFO: Resuming triggers.
[15:22:15.260] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[15:22:44.966] INFO: Resuming triggers.
[15:22:56.849] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[15:23:26.547] INFO: Resuming triggers.
[15:23:38.440] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[15:24:08.327] INFO: Resuming triggers.
[15:24:20.215] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[15:24:50.094] INFO: Resuming triggers.
[15:24:55.344] INFO: data taking finished, elapsed time: 100 seconds.
[15:25:08.808] INFO: PixTest:: pg_setup set to default.
[15:25:08.811] INFO: PixTestXray::doPhRun() done
[15:25:08.001] INFO: enter test to run
[15:25:52.200] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:25:52.200] INFO: running: xray
[15:25:52.201] INFO: ----------------------------------------------------------------------
[15:25:52.201] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:25:52.201] INFO: ----------------------------------------------------------------------
[15:25:53.165] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:26:00.317] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[15:26:31.168] INFO: Resuming triggers.
[15:26:38.318] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[15:27:09.123] INFO: Resuming triggers.
[15:27:16.278] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[15:27:48.106] INFO: Resuming triggers.
[15:27:55.254] INFO: run duration 28 seconds, buffer almost full (81%), pausing triggers.
[15:28:26.045] INFO: Resuming triggers.
[15:28:33.191] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[15:29:04.613] INFO: Resuming triggers.
[15:29:11.767] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[15:29:43.079] INFO: Resuming triggers.
[15:29:50.229] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[15:30:22.485] INFO: Resuming triggers.
[15:30:29.637] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[15:31:01.478] INFO: Resuming triggers.
[15:31:08.625] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[15:31:40.300] INFO: Resuming triggers.
[15:31:47.449] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[15:32:18.373] INFO: Resuming triggers.
[15:32:25.524] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[15:32:56.351] INFO: Resuming triggers.
[15:33:03.504] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[15:33:34.043] INFO: Resuming triggers.
[15:33:41.199] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[15:34:12.060] INFO: Resuming triggers.
[15:34:19.217] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[15:34:50.132] INFO: Resuming triggers.
[15:34:50.368] INFO: data taking finished, elapsed time: 100 seconds.
[15:34:51.772] INFO: PixTest:: pg_setup set to default.
[15:34:51.775] INFO: PixTestXray::doPhRun() done
[15:34:51.920] INFO: enter test to run
[15:35:32.891] INFO: test: HighRate no parameter change
[15:35:32.891] INFO: running: highrate
[15:35:32.908] INFO: ----------------------------------------------------------------------
[15:35:32.908] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:35:32.908] INFO: ----------------------------------------------------------------------
[15:35:33.055] INFO: Expecting 768 events.
[15:35:34.189] INFO: 768 events read in total (419ms).
[15:35:34.189] INFO: Test took 1269ms.
[15:35:34.992] INFO: Expecting 41600 events.
[15:35:38.095] INFO: 41600 events read in total (2576ms).
[15:35:38.096] INFO: Test took 3898ms.
[15:35:38.126] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:35:38.858] INFO: Expecting 41600 events.
[15:35:42.054] INFO: 41600 events read in total (2669ms).
[15:35:42.055] INFO: Test took 3914ms.
[15:35:42.085] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:35:42.814] INFO: Expecting 41600 events.
[15:35:46.018] INFO: 41600 events read in total (2678ms).
[15:35:46.019] INFO: Test took 3917ms.
[15:35:46.049] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:35:46.781] INFO: Expecting 41600 events.
[15:35:50.014] INFO: 41600 events read in total (2706ms).
[15:35:50.015] INFO: Test took 3949ms.
[15:35:50.046] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:35:50.775] INFO: Expecting 41600 events.
[15:35:53.005] INFO: 41600 events read in total (2703ms).
[15:35:53.006] INFO: Test took 3945ms.
[15:35:54.037] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:35:54.760] INFO: Expecting 41600 events.
[15:35:57.984] INFO: 41600 events read in total (2697ms).
[15:35:57.985] INFO: Test took 3932ms.
[15:35:58.017] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:35:58.748] INFO: Expecting 41600 events.
[15:36:01.976] INFO: 41600 events read in total (2701ms).
[15:36:01.977] INFO: Test took 3942ms.
[15:36:02.017] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:02.735] INFO: Expecting 41600 events.
[15:36:05.902] INFO: 41600 events read in total (2640ms).
[15:36:05.903] INFO: Test took 3869ms.
[15:36:05.933] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:06.665] INFO: Expecting 41600 events.
[15:36:09.961] INFO: 41600 events read in total (2713ms).
[15:36:09.962] INFO: Test took 4012ms.
[15:36:09.992] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:10.724] INFO: Expecting 41600 events.
[15:36:13.954] INFO: 41600 events read in total (2703ms).
[15:36:13.955] INFO: Test took 3946ms.
[15:36:13.985] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:14.715] INFO: Expecting 41600 events.
[15:36:17.948] INFO: 41600 events read in total (2706ms).
[15:36:17.949] INFO: Test took 3946ms.
[15:36:17.980] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:18.709] INFO: Expecting 41600 events.
[15:36:21.932] INFO: 41600 events read in total (2696ms).
[15:36:21.933] INFO: Test took 3937ms.
[15:36:21.963] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:22.693] INFO: Expecting 41600 events.
[15:36:25.915] INFO: 41600 events read in total (2696ms).
[15:36:25.916] INFO: Test took 3935ms.
[15:36:25.946] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:26.674] INFO: Expecting 41600 events.
[15:36:29.899] INFO: 41600 events read in total (2698ms).
[15:36:29.900] INFO: Test took 3936ms.
[15:36:29.930] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:30.657] INFO: Expecting 41600 events.
[15:36:33.883] INFO: 41600 events read in total (2699ms).
[15:36:33.884] INFO: Test took 3938ms.
[15:36:33.914] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:34.642] INFO: Expecting 41600 events.
[15:36:37.871] INFO: 41600 events read in total (2702ms).
[15:36:37.872] INFO: Test took 3941ms.
[15:36:37.902] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:38.635] INFO: Expecting 41600 events.
[15:36:41.880] INFO: 41600 events read in total (2718ms).
[15:36:41.880] INFO: Test took 3961ms.
[15:36:41.911] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:42.644] INFO: Expecting 41600 events.
[15:36:45.801] INFO: 41600 events read in total (2631ms).
[15:36:45.802] INFO: Test took 3875ms.
[15:36:45.832] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:46.563] INFO: Expecting 41600 events.
[15:36:49.785] INFO: 41600 events read in total (2695ms).
[15:36:49.786] INFO: Test took 3937ms.
[15:36:49.817] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:50.548] INFO: Expecting 41600 events.
[15:36:53.611] INFO: 41600 events read in total (2536ms).
[15:36:53.612] INFO: Test took 3778ms.
[15:36:53.641] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:54.015] INFO: enter test to run
[15:38:22.243] INFO: test: HighRate no parameter change
[15:38:22.243] INFO: running: highrate
[15:38:22.244] INFO: ----------------------------------------------------------------------
[15:38:22.244] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:38:22.244] INFO: ----------------------------------------------------------------------
[15:38:22.865] INFO: Expecting 208000 events.
[15:38:34.605] INFO: 208000 events read in total (11213ms).
[15:38:34.608] INFO: Test took 12356ms.
[15:38:34.734] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:34.980] INFO: number of dead pixels (per ROC): 0 0 52 0 0 0 3 0 0 0 0 0 0 0 0 0
[15:38:34.980] INFO: number of red-efficiency pixels: 54 48 140 98 117 146 53 90 268 106 110 81 94 66 26 36
[15:38:34.980] INFO: number of X-ray hits detected: 62067 40896 65243 92377 98730 106231 50092 74160 66078 93012 90401 74922 81721 46181 19480 25213
[15:38:34.980] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:38:34.980] INFO: number of Vcal hits detected: 207946 207952 205310 207900 207881 207853 207798 207909 207727 207891 207889 207919 207905 207930 207974 207964
[15:38:34.980] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[15:38:34.980] INFO: Vcal hit overall efficiency (%): 100.0 100.0 98.7 100.0 99.9 99.9 99.9 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[15:38:34.980] INFO: X-ray hit rate [MHz/cm2]: 18.2 12.0 19.1 27.1 28.9 31.1 14.7 21.7 19.4 27.3 26.5 22.0 24.0 13.5 5.7 7.4
[15:38:34.980] INFO: PixTestHighRate::doXPixelAlive() done
[15:38:35.032] INFO: PixTest:: pg_setup set to default.
[15:38:35.049] INFO: enter test to run
[15:39:39.706] INFO: test: HighRate no parameter change
[15:39:39.706] INFO: running: highrate
[15:39:39.708] INFO: ----------------------------------------------------------------------
[15:39:39.708] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:39:39.708] INFO: ----------------------------------------------------------------------
[15:39:40.326] INFO: Expecting 208000 events.
[15:39:53.611] INFO: 208000 events read in total (12758ms).
[15:39:53.616] INFO: Test took 13899ms.
[15:39:53.874] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:39:54.164] INFO: number of dead pixels (per ROC): 0 0 52 0 0 0 3 0 0 0 0 0 0 0 0 0
[15:39:54.164] INFO: number of red-efficiency pixels: 206 106 289 291 350 427 239 279 384 355 299 236 308 160 57 55
[15:39:54.164] INFO: number of X-ray hits detected: 130873 85857 137981 194983 208776 222984 105977 156908 139433 195989 190520 158516 171992 97977 41069 53955
[15:39:54.164] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:39:54.164] INFO: number of Vcal hits detected: 207779 207889 205137 207687 207634 207540 207590 207700 207444 207633 207685 207752 207670 207834 207943 207945
[15:39:54.164] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.9 99.8 99.8 99.9 99.9 99.7 99.8 99.9 99.9 99.9 99.9 100.0 100.0
[15:39:54.164] INFO: Vcal hit overall efficiency (%): 99.9 99.9 98.6 99.8 99.8 99.8 99.8 99.9 99.7 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[15:39:54.164] INFO: X-ray hit rate [MHz/cm2]: 38.4 25.2 40.4 57.2 61.2 65.4 31.1 46.0 40.9 57.4 55.8 46.5 50.4 28.7 12.0 15.8
[15:39:54.164] INFO: PixTestHighRate::doXPixelAlive() done
[15:39:54.212] INFO: PixTest:: pg_setup set to default.
[15:39:54.224] INFO: enter test to run
[15:40:12.642] INFO: test: HighRate no parameter change
[15:40:12.642] INFO: running: highrate
[15:40:12.643] INFO: ----------------------------------------------------------------------
[15:40:12.643] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:40:12.643] INFO: ----------------------------------------------------------------------
[15:40:13.264] INFO: Expecting 208000 events.
[15:40:28.516] INFO: 208000 events read in total (14725ms).
[15:40:28.523] INFO: Test took 15871ms.
[15:40:28.920] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:29.258] INFO: number of dead pixels (per ROC): 0 0 52 0 0 0 3 0 0 0 0 0 0 0 0 0
[15:40:29.258] INFO: number of red-efficiency pixels: 426 241 597 704 763 1036 514 602 644 681 708 570 729 377 84 91
[15:40:29.258] INFO: number of X-ray hits detected: 198802 130320 209233 295096 315163 339789 161066 239128 212681 296661 289517 240819 262687 149300 62788 82072
[15:40:29.258] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:40:29.258] INFO: number of Vcal hits detected: 207491 207734 204714 207187 207087 206690 207179 207284 204771 207219 207157 207352 207163 207566 207913 207907
[15:40:29.258] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.6 99.6 99.4 99.7 99.7 98.4 99.7 99.6 99.7 99.6 99.8 100.0 100.0
[15:40:29.258] INFO: Vcal hit overall efficiency (%): 99.8 99.9 98.4 99.6 99.6 99.4 99.6 99.7 98.4 99.6 99.6 99.7 99.6 99.8 100.0 100.0
[15:40:29.258] INFO: X-ray hit rate [MHz/cm2]: 58.3 38.2 61.3 86.5 92.4 99.6 47.2 70.1 62.3 87.0 84.9 70.6 77.0 43.8 18.4 24.1
[15:40:29.258] INFO: PixTestHighRate::doXPixelAlive() done
[15:40:29.304] INFO: PixTest:: pg_setup set to default.
[15:40:29.318] INFO: enter test to run
[15:40:48.105] INFO: test: exit no parameter change
[15:40:49.455] QUIET: Connection to board 33 closed.
[15:40:49.468] INFO: pXar: this is the end, my friend