[15:09:20.847] INFO: *** Welcome to pxar ***
[15:09:20.847] INFO: *** Today: 2016/09/15
[15:09:23.380] INFO: *** Version: v1.9.0-818-g96727
[15:09:23.380] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//dacParameters35_C15.dat
[15:09:23.654] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:09:23.654] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//defaultMaskFile.dat
[15:09:23.657] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C15.dat
[15:09:24.010] INFO: clk: 4
[15:09:24.010] INFO: ctr: 4
[15:09:24.010] INFO: sda: 19
[15:09:24.010] INFO: tin: 9
[15:09:24.010] INFO: level: 15
[15:09:24.010] INFO: triggerdelay: 0
[15:09:24.010] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:09:24.010] INFO: Log level: INFO
[15:09:24.052] QUIET: Connection to board DTB_WREKRL opened.
[15:09:24.056] 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:09:24.059] INFO: RPC call hashes of host and DTB match: 398089610
[15:09:25.612] INFO: DUT info:
[15:09:25.612] INFO: The DUT currently contains the following objects:
[15:09:25.612] INFO: 2 TBM Cores tbm08c (2 ON)
[15:09:25.617] INFO: TBM Core alpha (0): 7 registers set
[15:09:25.617] INFO: TBM Core beta (1): 7 registers set
[15:09:25.617] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:09:25.617] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.617] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.617] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.617] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.617] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.617] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.617] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.618] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.618] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.618] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.618] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.618] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.618] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.618] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.618] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:25.618] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:26.086] INFO: enter 'restricted' command line mode
[15:09:26.086] INFO: enter test to run
[15:09:58.292] INFO: test: PixelAlive no parameter change
[15:09:58.292] INFO: running: pixelalive
[15:09:58.364] INFO: ----------------------------------------------------------------------
[15:09:58.364] 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:09:58.364] INFO: ----------------------------------------------------------------------
[15:09:58.684] INFO: Expecting 41600 events.
[15:10:02.923] INFO: 41600 events read in total (3520ms).
[15:10:03.091] INFO: Test took 4725ms.
[15:10:03.102] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:10:03.778] INFO: PixTestAlive::aliveTest() done
[15:10:03.778] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:10:03.971] INFO: enter test to run
[15:10:41.244] INFO: test: timing no parameter change
[15:10:41.244] INFO: running: timing
[15:10:41.247] INFO: ######################################################################
[15:10:41.247] INFO: PixTestTiming::doTest()
[15:10:41.247] INFO: ######################################################################
[15:10:41.247] INFO: ----------------------------------------------------------------------
[15:10:41.247] INFO: PixTestTiming::TBMPhaseScan()
[15:10:41.247] INFO: ----------------------------------------------------------------------
[15:15:31.950] INFO: TBM Phase Settings: 192
[15:15:31.950] INFO: 400MHz Phase: 0
[15:15:31.950] INFO: 160MHz Phase: 6
[15:15:31.950] INFO: Functional Phase Area: 4
[15:15:31.961] INFO: Test took 290714 ms.
[15:15:31.961] INFO: PixTestTiming::TBMPhaseScan() done.
[15:15:31.962] INFO: ----------------------------------------------------------------------
[15:15:31.962] INFO: PixTestTiming::ROCDelayScan()
[15:15:31.962] INFO: ----------------------------------------------------------------------
[15:18:27.050] INFO: ROC Delay Settings: 219
[15:18:27.050] INFO: ROC Header-Trailer/Token Delay: 11
[15:18:27.050] INFO: ROC Port 0 Delay: 3
[15:18:27.050] INFO: ROC Port 1 Delay: 3
[15:18:27.050] INFO: Functional ROC Area: 4
[15:18:27.053] INFO: Test took 175091 ms.
[15:18:27.053] INFO: PixTestTiming::ROCDelayScan() done.
[15:18:27.053] INFO: ----------------------------------------------------------------------
[15:18:27.053] INFO: PixTestTiming::TimingTest()
[15:18:27.053] INFO: ----------------------------------------------------------------------
[15:18:43.224] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:18:58.232] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:13.241] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:28.169] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:43.147] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:58.138] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:13.122] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:28.133] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:43.164] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:58.012] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:58.390] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:58.407] INFO: ----------------------------------------------------------------------
[15:20:58.407] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:20:58.407] INFO: ----------------------------------------------------------------------
[15:20:58.407] INFO: ----------------------------------------------------------------------
[15:20:58.407] INFO: Read back bit status: 1
[15:20:58.407] INFO: ----------------------------------------------------------------------
[15:20:58.407] INFO: ----------------------------------------------------------------------
[15:20:58.407] INFO: Timings are good!
[15:20:58.407] INFO: ----------------------------------------------------------------------
[15:20:58.407] INFO: Test took 151354 ms.
[15:20:58.407] INFO: PixTestTiming::TimingTest() done.
[15:20:58.424] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:20:58.424] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:20:58.424] INFO: PixTestTiming::doTest took 617180 ms.
[15:20:58.424] INFO: PixTestTiming::doTest() done
[15:20:58.424] INFO: Write out TBMPhaseScan_0_V0
[15:20:58.424] INFO: Write out TBMPhaseScan_1_V0
[15:20:58.424] INFO: Write out CombinedTBMPhaseScan_V0
[15:20:58.502] INFO: Write out ROCDelayScan3_V0
[15:20:58.502] INFO: enter test to run
[15:21:50.471] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:21:50.471] INFO: running: highrate
[15:21:50.500] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:21:50.940] INFO: ----------------------------------------------------------------------
[15:21:50.941] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:21:50.941] INFO: ----------------------------------------------------------------------
[15:21:50.941] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:21:50.941] INFO: edge/corner pixel THR is adjusted
[15:21:50.941] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:21:51.920] INFO: Collecting data for 5 seconds...
[15:21:56.938] INFO: Done with hot pixel readout
[15:22:08.646] INFO: PixTest:: pg_setup set to default.
[15:22:08.647] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:22:08.647] INFO: 13 hot pixels found in step 0
[15:22:09.641] INFO: Collecting data for 5 seconds...
[15:22:14.659] INFO: Done with hot pixel readout
[15:22:26.428] INFO: PixTest:: pg_setup set to default.
[15:22:26.429] INFO: 11 hot pixels found in step 1
[15:22:27.423] INFO: Collecting data for 5 seconds...
[15:22:32.440] INFO: Done with hot pixel readout
[15:22:43.952] INFO: PixTest:: pg_setup set to default.
[15:22:43.952] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:22:43.953] INFO: 14 hot pixels found in step 2
[15:22:44.947] INFO: Collecting data for 5 seconds...
[15:22:49.966] INFO: Done with hot pixel readout
[15:23:01.536] INFO: PixTest:: pg_setup set to default.
[15:23:01.536] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:23:01.537] INFO: 16 hot pixels found in step 3
[15:23:02.532] INFO: Collecting data for 5 seconds...
[15:23:07.551] INFO: Done with hot pixel readout
[15:23:19.075] INFO: PixTest:: pg_setup set to default.
[15:23:19.076] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:23:19.076] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:23:19.076] INFO: 11 hot pixels found in step 4
[15:23:20.070] INFO: Collecting data for 5 seconds...
[15:23:25.088] INFO: Done with hot pixel readout
[15:23:36.648] INFO: PixTest:: pg_setup set to default.
[15:23:36.648] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:23:36.649] INFO: 14 hot pixels found in step 5
[15:23:37.644] INFO: Collecting data for 5 seconds...
[15:23:42.661] INFO: Done with hot pixel readout
[15:23:54.414] INFO: PixTest:: pg_setup set to default.
[15:23:54.414] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:23:54.415] INFO: 9 hot pixels found in step 6
[15:23:55.409] INFO: Collecting data for 5 seconds...
[15:24:00.426] INFO: Done with hot pixel readout
[15:24:12.349] INFO: PixTest:: pg_setup set to default.
[15:24:12.350] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:24:12.350] INFO: 10 hot pixels found in step 7
[15:24:13.344] INFO: Collecting data for 5 seconds...
[15:24:18.364] INFO: Done with hot pixel readout
[15:24:30.481] INFO: PixTest:: pg_setup set to default.
[15:24:30.482] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:24:30.482] INFO: 7 hot pixels found in step 8
[15:24:31.476] INFO: Collecting data for 5 seconds...
[15:24:36.494] INFO: Done with hot pixel readout
[15:24:48.721] INFO: PixTest:: pg_setup set to default.
[15:24:48.722] INFO: 13 hot pixels found in step 9
[15:24:49.715] INFO: Collecting data for 5 seconds...
[15:24:54.734] INFO: Done with hot pixel readout
[15:25:07.098] INFO: PixTest:: pg_setup set to default.
[15:25:07.098] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:25:07.099] INFO: 6 hot pixels found in step 10
[15:25:08.093] INFO: Collecting data for 5 seconds...
[15:25:13.113] INFO: Done with hot pixel readout
[15:25:25.288] INFO: PixTest:: pg_setup set to default.
[15:25:25.288] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:25:25.289] INFO: 11 hot pixels found in step 11
[15:25:26.282] INFO: Collecting data for 5 seconds...
[15:25:31.298] INFO: Done with hot pixel readout
[15:25:43.043] INFO: PixTest:: pg_setup set to default.
[15:25:43.043] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:25:43.043] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:25:43.044] INFO: 14 hot pixels found in step 12
[15:25:44.036] INFO: Collecting data for 5 seconds...
[15:25:49.056] INFO: Done with hot pixel readout
[15:26:01.233] INFO: PixTest:: pg_setup set to default.
[15:26:01.233] INFO: 2 hot pixels found in step 13
[15:26:02.226] INFO: Collecting data for 5 seconds...
[15:26:07.244] INFO: Done with hot pixel readout
[15:26:19.333] INFO: PixTest:: pg_setup set to default.
[15:26:19.333] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:26:19.334] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:26:19.334] INFO: 11 hot pixels found in step 14
[15:26:19.372] INFO: 11 hot pixels could not be trimmed and have been masked.
[15:26:19.375] INFO: PixTest::trimHotPixels() done
[15:26:19.387] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C0.dat
[15:26:19.396] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C1.dat
[15:26:19.402] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C2.dat
[15:26:19.407] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C3.dat
[15:26:19.412] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C4.dat
[15:26:19.418] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C5.dat
[15:26:19.423] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C6.dat
[15:26:19.428] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C7.dat
[15:26:19.434] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C8.dat
[15:26:19.439] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C9.dat
[15:26:19.445] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C10.dat
[15:26:19.450] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C11.dat
[15:26:19.456] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C12.dat
[15:26:19.461] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C13.dat
[15:26:19.466] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C14.dat
[15:26:19.472] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C15.dat
[15:26:19.477] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//defaultMaskFile.dat
[15:26:19.488] INFO: enter test to run
[15:26:45.413] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:26:45.413] INFO: running: highrate
[15:26:45.418] INFO: ----------------------------------------------------------------------
[15:26:45.418] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:26:45.418] INFO: ----------------------------------------------------------------------
[15:26:45.418] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:26:45.418] INFO: edge/corner pixel THR is adjusted
[15:26:45.418] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:26:46.376] INFO: Collecting data for 1 seconds...
[15:26:47.380] INFO: Done with hot pixel readout
[15:26:51.447] INFO: PixTest:: pg_setup set to default.
[15:26:51.448] INFO: 0 hot pixels found in step 0
[15:26:51.453] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:26:51.540] INFO: PixTest::trimHotPixels() done
[15:26:51.540] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C0.dat
[15:26:51.557] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C1.dat
[15:26:51.568] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C2.dat
[15:26:51.574] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C3.dat
[15:26:51.580] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C4.dat
[15:26:51.585] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C5.dat
[15:26:51.591] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C6.dat
[15:26:51.596] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C7.dat
[15:26:51.612] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C8.dat
[15:26:51.617] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C9.dat
[15:26:51.623] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C10.dat
[15:26:51.628] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C11.dat
[15:26:51.633] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C12.dat
[15:26:51.639] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C13.dat
[15:26:51.644] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C14.dat
[15:26:51.649] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C15.dat
[15:26:51.655] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-22_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//defaultMaskFile.dat
[15:26:51.664] INFO: enter test to run
[15:27:25.845] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:27:25.845] INFO: running: xray
[15:27:25.846] INFO: ----------------------------------------------------------------------
[15:27:25.846] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:27:25.846] INFO: ----------------------------------------------------------------------
[15:27:26.831] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:27:38.238] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:28:07.834] INFO: Resuming triggers.
[15:28:19.344] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:28:48.987] INFO: Resuming triggers.
[15:29:00.399] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[15:29:29.384] INFO: Resuming triggers.
[15:29:40.795] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:30:10.136] INFO: Resuming triggers.
[15:30:21.552] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[15:30:50.175] INFO: Resuming triggers.
[15:31:01.594] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[15:31:30.979] INFO: Resuming triggers.
[15:31:42.391] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[15:32:10.446] INFO: Resuming triggers.
[15:32:21.858] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[15:32:50.578] INFO: Resuming triggers.
[15:32:59.571] INFO: data taking finished, elapsed time: 100 seconds.
[15:33:22.961] INFO: PixTest:: pg_setup set to default.
[15:33:22.965] INFO: PixTestXray::doPhRun() done
[15:33:23.157] INFO: enter test to run
[15:35:03.642] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:35:03.642] INFO: running: xray
[15:35:03.644] INFO: ----------------------------------------------------------------------
[15:35:03.644] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:35:03.644] INFO: ----------------------------------------------------------------------
[15:35:04.606] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:35:11.268] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:35:42.055] INFO: Resuming triggers.
[15:35:48.715] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[15:36:20.322] INFO: Resuming triggers.
[15:36:26.983] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[15:36:58.095] INFO: Resuming triggers.
[15:37:04.756] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[15:37:35.937] INFO: Resuming triggers.
[15:37:42.598] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[15:38:14.105] INFO: Resuming triggers.
[15:38:20.765] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[15:38:52.440] INFO: Resuming triggers.
[15:38:59.102] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[15:39:30.290] INFO: Resuming triggers.
[15:39:36.949] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[15:40:08.864] INFO: Resuming triggers.
[15:40:15.526] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[15:40:46.388] INFO: Resuming triggers.
[15:40:53.050] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[15:41:23.433] INFO: Resuming triggers.
[15:41:30.102] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[15:42:00.385] INFO: Resuming triggers.
[15:42:07.053] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[15:42:37.349] INFO: Resuming triggers.
[15:42:44.013] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[15:43:14.330] INFO: Resuming triggers.
[15:43:20.996] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[15:43:51.309] INFO: Resuming triggers.
[15:43:57.977] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[15:44:28.404] INFO: Resuming triggers.
[15:44:28.807] INFO: data taking finished, elapsed time: 100 seconds.
[15:44:30.959] INFO: PixTest:: pg_setup set to default.
[15:44:30.963] INFO: PixTestXray::doPhRun() done
[15:44:31.111] INFO: enter test to run
[15:45:44.206] INFO: test: HighRate no parameter change
[15:45:44.206] INFO: running: highrate
[15:45:44.229] INFO: ----------------------------------------------------------------------
[15:45:44.229] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:45:44.229] INFO: ----------------------------------------------------------------------
[15:45:44.387] INFO: Expecting 768 events.
[15:45:45.522] INFO: 768 events read in total (419ms).
[15:45:45.522] INFO: Test took 1269ms.
[15:45:46.326] INFO: Expecting 41600 events.
[15:45:49.389] INFO: 41600 events read in total (2537ms).
[15:45:49.390] INFO: Test took 3813ms.
[15:45:49.424] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:50.153] INFO: Expecting 41600 events.
[15:45:53.376] INFO: 41600 events read in total (2696ms).
[15:45:53.377] INFO: Test took 3935ms.
[15:45:53.411] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:54.135] INFO: Expecting 41600 events.
[15:45:57.385] INFO: 41600 events read in total (2723ms).
[15:45:57.386] INFO: Test took 3956ms.
[15:45:57.421] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:58.144] INFO: Expecting 41600 events.
[15:46:01.370] INFO: 41600 events read in total (2699ms).
[15:46:01.371] INFO: Test took 3931ms.
[15:46:01.407] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:02.129] INFO: Expecting 41600 events.
[15:46:05.376] INFO: 41600 events read in total (2720ms).
[15:46:05.377] INFO: Test took 3952ms.
[15:46:05.412] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:06.134] INFO: Expecting 41600 events.
[15:46:09.386] INFO: 41600 events read in total (2725ms).
[15:46:09.387] INFO: Test took 3958ms.
[15:46:09.422] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:10.147] INFO: Expecting 41600 events.
[15:46:13.419] INFO: 41600 events read in total (2745ms).
[15:46:13.420] INFO: Test took 3979ms.
[15:46:13.455] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:14.179] INFO: Expecting 41600 events.
[15:46:17.428] INFO: 41600 events read in total (2722ms).
[15:46:17.429] INFO: Test took 3954ms.
[15:46:17.463] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:18.188] INFO: Expecting 41600 events.
[15:46:21.443] INFO: 41600 events read in total (2728ms).
[15:46:21.444] INFO: Test took 3962ms.
[15:46:21.479] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:22.199] INFO: Expecting 41600 events.
[15:46:25.452] INFO: 41600 events read in total (2726ms).
[15:46:25.453] INFO: Test took 3955ms.
[15:46:25.487] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:26.211] INFO: Expecting 41600 events.
[15:46:29.473] INFO: 41600 events read in total (2735ms).
[15:46:29.474] INFO: Test took 3969ms.
[15:46:29.509] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:30.231] INFO: Expecting 41600 events.
[15:46:33.482] INFO: 41600 events read in total (2724ms).
[15:46:33.483] INFO: Test took 3955ms.
[15:46:33.518] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:34.242] INFO: Expecting 41600 events.
[15:46:37.503] INFO: 41600 events read in total (2734ms).
[15:46:37.504] INFO: Test took 3967ms.
[15:46:37.539] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:38.264] INFO: Expecting 41600 events.
[15:46:41.522] INFO: 41600 events read in total (2732ms).
[15:46:41.523] INFO: Test took 3966ms.
[15:46:41.558] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:42.282] INFO: Expecting 41600 events.
[15:46:45.531] INFO: 41600 events read in total (2722ms).
[15:46:45.532] INFO: Test took 3954ms.
[15:46:45.566] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:46.292] INFO: Expecting 41600 events.
[15:46:49.549] INFO: 41600 events read in total (2730ms).
[15:46:49.550] INFO: Test took 3967ms.
[15:46:49.584] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:50.308] INFO: Expecting 41600 events.
[15:46:53.579] INFO: 41600 events read in total (2744ms).
[15:46:53.580] INFO: Test took 3977ms.
[15:46:53.615] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:54.334] INFO: Expecting 41600 events.
[15:46:57.600] INFO: 41600 events read in total (2739ms).
[15:46:57.601] INFO: Test took 3968ms.
[15:46:57.636] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:58.358] INFO: Expecting 41600 events.
[15:47:01.597] INFO: 41600 events read in total (2712ms).
[15:47:01.598] INFO: Test took 3944ms.
[15:47:01.633] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:02.356] INFO: Expecting 41600 events.
[15:47:05.529] INFO: 41600 events read in total (2646ms).
[15:47:05.530] INFO: Test took 3878ms.
[15:47:05.565] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:05.927] INFO: enter test to run
[15:47:17.373] INFO: test: HighRate no parameter change
[15:47:17.373] INFO: running: highrate
[15:47:17.374] INFO: ----------------------------------------------------------------------
[15:47:17.374] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:47:17.374] INFO: ----------------------------------------------------------------------
[15:47:17.992] INFO: Expecting 208000 events.
[15:47:29.876] INFO: 208000 events read in total (11357ms).
[15:47:29.879] INFO: Test took 12496ms.
[15:47:30.029] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:30.281] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:47:30.281] INFO: number of red-efficiency pixels: 81 66 87 144 123 150 166 86 95 144 111 103 110 50 23 30
[15:47:30.281] INFO: number of X-ray hits detected: 70544 46904 72222 109364 111513 115647 119404 79208 70734 98395 100186 88571 88289 54914 22533 25211
[15:47:30.281] 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:47:30.281] INFO: number of Vcal hits detected: 207917 207931 207910 207854 207875 207845 207830 207913 207902 207856 207882 207891 207889 207949 207977 207970
[15:47:30.281] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[15:47:30.281] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[15:47:30.281] INFO: X-ray hit rate [MHz/cm2]: 20.7 13.7 21.2 32.1 32.7 33.9 35.0 23.2 20.7 28.8 29.4 26.0 25.9 16.1 6.6 7.4
[15:47:30.281] INFO: PixTestHighRate::doXPixelAlive() done
[15:47:30.328] INFO: PixTest:: pg_setup set to default.
[15:47:30.341] INFO: enter test to run
[15:47:52.813] INFO: test: HighRate no parameter change
[15:47:52.813] INFO: running: highrate
[15:47:52.814] INFO: ----------------------------------------------------------------------
[15:47:52.814] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:47:52.814] INFO: ----------------------------------------------------------------------
[15:47:53.444] INFO: Expecting 208000 events.
[15:48:07.286] INFO: 208000 events read in total (13315ms).
[15:48:07.292] INFO: Test took 14469ms.
[15:48:07.589] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:07.895] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:48:07.895] INFO: number of red-efficiency pixels: 262 165 333 395 444 541 585 297 245 389 329 313 320 224 54 57
[15:48:07.895] INFO: number of X-ray hits detected: 144213 96160 146667 224272 225453 234252 243754 161857 145237 200564 204011 180421 178991 113126 46184 51316
[15:48:07.895] 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:48:07.895] INFO: number of Vcal hits detected: 207710 207831 207625 207570 207524 207389 207363 207682 207738 207574 207626 207656 207665 207764 207945 207942
[15:48:07.895] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.7 99.7 99.9 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[15:48:07.895] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.7 99.7 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[15:48:07.895] INFO: X-ray hit rate [MHz/cm2]: 42.3 28.2 43.0 65.7 66.1 68.7 71.4 47.4 42.6 58.8 59.8 52.9 52.5 33.2 13.5 15.0
[15:48:07.895] INFO: PixTestHighRate::doXPixelAlive() done
[15:48:07.943] INFO: PixTest:: pg_setup set to default.
[15:48:07.960] INFO: enter test to run
[15:48:33.100] INFO: test: HighRate no parameter change
[15:48:33.100] INFO: running: highrate
[15:48:33.102] INFO: ----------------------------------------------------------------------
[15:48:33.102] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:48:33.102] INFO: ----------------------------------------------------------------------
[15:48:33.718] INFO: Expecting 208000 events.
[15:48:49.571] INFO: 208000 events read in total (15326ms).
[15:48:49.579] INFO: Test took 16468ms.
[15:48:50.026] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:50.380] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:48:50.381] INFO: number of red-efficiency pixels: 583 339 735 968 915 1328 1405 612 494 1006 737 600 784 515 97 91
[15:48:50.381] INFO: number of X-ray hits detected: 218797 146097 222448 338554 341753 354450 367770 247002 219916 305033 309398 274042 272465 171851 70177 77880
[15:48:50.381] 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:48:50.381] INFO: number of Vcal hits detected: 207291 207613 206932 206819 206869 206242 206104 207216 207423 206771 207108 207295 207067 207363 207898 207906
[15:48:50.381] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.6 99.5 99.5 99.2 99.2 99.7 99.7 99.5 99.6 99.7 99.6 99.7 100.0 100.0
[15:48:50.381] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.5 99.4 99.5 99.2 99.1 99.6 99.7 99.4 99.6 99.7 99.6 99.7 100.0 100.0
[15:48:50.381] INFO: X-ray hit rate [MHz/cm2]: 64.1 42.8 65.2 99.2 100.2 103.9 107.8 72.4 64.5 89.4 90.7 80.3 79.9 50.4 20.6 22.8
[15:48:50.381] INFO: PixTestHighRate::doXPixelAlive() done
[15:48:50.428] INFO: PixTest:: pg_setup set to default.
[15:48:50.447] INFO: enter test to run
[15:49:27.996] INFO: test: exit no parameter change
[15:49:29.451] QUIET: Connection to board 33 closed.
[15:49:29.865] INFO: pXar: this is the end, my friend