[11:45:43.617] INFO: *** Welcome to pxar ***
[11:45:43.617] INFO: *** Today: 2016/10/12
[11:45:44.869] INFO: *** Version: v1.9.0-818-g96727
[11:45:44.870] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//dacParameters35_C15.dat
[11:45:44.931] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:45:44.932] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//defaultMaskFile.dat
[11:45:44.939] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C15.dat
[11:45:45.071] INFO: clk: 4
[11:45:45.071] INFO: ctr: 4
[11:45:45.071] INFO: sda: 19
[11:45:45.071] INFO: tin: 9
[11:45:45.071] INFO: level: 15
[11:45:45.071] INFO: triggerdelay: 0
[11:45:45.072] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:45:45.072] INFO: Log level: INFO
[11:45:45.089] QUIET: Connection to board DTB_WREKRL opened.
[11:45:45.093] 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:
------------------------------------------------------
[11:45:45.096] INFO: RPC call hashes of host and DTB match: 398089610
[11:45:46.645] INFO: DUT info:
[11:45:46.645] INFO: The DUT currently contains the following objects:
[11:45:46.646] INFO: 2 TBM Cores tbm08c (2 ON)
[11:45:46.646] INFO: TBM Core alpha (0): 7 registers set
[11:45:46.646] INFO: TBM Core beta (1): 7 registers set
[11:45:46.646] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:45:46.646] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:46.646] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:45:47.071] INFO: enter 'restricted' command line mode
[11:45:47.071] INFO: enter test to run
[11:45:52.067] INFO: test: PixelAlive no parameter change
[11:45:52.067] INFO: running: pixelalive
[11:45:52.124] INFO: ----------------------------------------------------------------------
[11:45:52.124] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:45:52.124] INFO: ----------------------------------------------------------------------
[11:45:52.449] INFO: Expecting 41600 events.
[11:45:56.834] INFO: 41600 events read in total (3667ms).
[11:45:56.001] INFO: Test took 4874ms.
[11:45:57.017] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:45:57.579] INFO: PixTestAlive::aliveTest() done
[11:45:57.580] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[11:45:57.730] INFO: enter test to run
[11:46:05.731] INFO: test: timing no parameter change
[11:46:05.731] INFO: running: timing
[11:46:05.734] INFO: ######################################################################
[11:46:05.734] INFO: PixTestTiming::doTest()
[11:46:05.734] INFO: ######################################################################
[11:46:05.734] INFO: ----------------------------------------------------------------------
[11:46:05.734] INFO: PixTestTiming::TBMPhaseScan()
[11:46:05.734] INFO: ----------------------------------------------------------------------
[11:50:26.352] INFO: TBM Phase Settings: 240
[11:50:26.352] INFO: 400MHz Phase: 4
[11:50:26.352] INFO: 160MHz Phase: 7
[11:50:26.352] INFO: Functional Phase Area: 4
[11:50:26.372] INFO: Test took 260638 ms.
[11:50:26.372] INFO: PixTestTiming::TBMPhaseScan() done.
[11:50:26.372] INFO: ----------------------------------------------------------------------
[11:50:26.372] INFO: PixTestTiming::ROCDelayScan()
[11:50:26.372] INFO: ----------------------------------------------------------------------
[11:52:26.383] INFO: ROC Delay Settings: 227
[11:52:26.383] INFO: ROC Header-Trailer/Token Delay: 11
[11:52:26.383] INFO: ROC Port 0 Delay: 3
[11:52:26.383] INFO: ROC Port 1 Delay: 4
[11:52:26.383] INFO: Functional ROC Area: 4
[11:52:26.387] INFO: Test took 120015 ms.
[11:52:26.387] INFO: PixTestTiming::ROCDelayScan() done.
[11:52:26.387] INFO: ----------------------------------------------------------------------
[11:52:26.387] INFO: PixTestTiming::TimingTest()
[11:52:26.387] INFO: ----------------------------------------------------------------------
[11:52:42.532] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:52:57.477] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:53:12.462] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:53:27.427] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:53:42.356] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:53:57.334] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:54:12.258] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:54:27.210] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:54:42.200] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:54:57.150] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:54:57.529] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:54:57.546] INFO: ----------------------------------------------------------------------
[11:54:57.546] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:54:57.546] INFO: ----------------------------------------------------------------------
[11:54:57.546] INFO: ----------------------------------------------------------------------
[11:54:57.546] INFO: Read back bit status: 1
[11:54:57.546] INFO: ----------------------------------------------------------------------
[11:54:57.546] INFO: ----------------------------------------------------------------------
[11:54:57.546] INFO: Timings are good!
[11:54:57.546] INFO: ----------------------------------------------------------------------
[11:54:57.546] INFO: Test took 151159 ms.
[11:54:57.546] INFO: PixTestTiming::TimingTest() done.
[11:54:57.546] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:54:57.546] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:54:57.546] INFO: PixTestTiming::doTest took 531815 ms.
[11:54:57.546] INFO: PixTestTiming::doTest() done
[11:54:57.546] INFO: Write out TBMPhaseScan_0_V0
[11:54:57.547] INFO: Write out TBMPhaseScan_1_V0
[11:54:57.547] INFO: Write out CombinedTBMPhaseScan_V0
[11:54:57.548] INFO: Write out ROCDelayScan3_V0
[11:54:57.548] INFO: enter test to run
[11:56:46.143] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:56:46.143] INFO: running: highrate
[11:56:46.160] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:56:46.427] INFO: ----------------------------------------------------------------------
[11:56:46.427] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:56:46.427] INFO: ----------------------------------------------------------------------
[11:56:46.427] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:56:46.427] INFO: edge/corner pixel THR is adjusted
[11:56:46.427] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:56:47.384] INFO: Collecting data for 5 seconds...
[11:56:52.404] INFO: Done with hot pixel readout
[11:57:04.369] INFO: PixTest:: pg_setup set to default.
[11:57:04.370] INFO: 1 hot pixels found in step 0
[11:57:05.363] INFO: Collecting data for 5 seconds...
[11:57:10.381] INFO: Done with hot pixel readout
[11:57:22.211] INFO: PixTest:: pg_setup set to default.
[11:57:22.212] INFO: 1 hot pixels found in step 1
[11:57:23.207] INFO: Collecting data for 5 seconds...
[11:57:28.226] INFO: Done with hot pixel readout
[11:57:39.719] INFO: PixTest:: pg_setup set to default.
[11:57:39.720] INFO: 3 hot pixels found in step 2
[11:57:40.714] INFO: Collecting data for 5 seconds...
[11:57:45.732] INFO: Done with hot pixel readout
[11:57:57.572] INFO: PixTest:: pg_setup set to default.
[11:57:57.573] INFO: 1 hot pixels found in step 3
[11:57:58.567] INFO: Collecting data for 5 seconds...
[11:58:03.587] INFO: Done with hot pixel readout
[11:58:14.976] INFO: PixTest:: pg_setup set to default.
[11:58:14.977] INFO: 2 hot pixels found in step 4
[11:58:15.972] INFO: Collecting data for 5 seconds...
[11:58:20.991] INFO: Done with hot pixel readout
[11:58:32.936] INFO: PixTest:: pg_setup set to default.
[11:58:32.936] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:58:32.937] INFO: 3 hot pixels found in step 5
[11:58:33.931] INFO: Collecting data for 5 seconds...
[11:58:38.951] INFO: Done with hot pixel readout
[11:58:51.214] INFO: PixTest:: pg_setup set to default.
[11:58:51.214] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:58:51.215] INFO: 4 hot pixels found in step 6
[11:58:52.208] INFO: Collecting data for 5 seconds...
[11:58:57.227] INFO: Done with hot pixel readout
[11:59:09.435] INFO: PixTest:: pg_setup set to default.
[11:59:09.436] INFO: 3 hot pixels found in step 7
[11:59:10.430] INFO: Collecting data for 5 seconds...
[11:59:15.450] INFO: Done with hot pixel readout
[11:59:27.616] INFO: PixTest:: pg_setup set to default.
[11:59:27.617] INFO: 1 hot pixels found in step 8
[11:59:28.610] INFO: Collecting data for 5 seconds...
[11:59:33.630] INFO: Done with hot pixel readout
[11:59:45.545] INFO: PixTest:: pg_setup set to default.
[11:59:45.546] INFO: 0 hot pixels found in step 9
[11:59:45.585] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:59:45.588] INFO: PixTest::trimHotPixels() done
[11:59:45.588] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C0.dat
[11:59:45.595] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C1.dat
[11:59:45.601] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C2.dat
[11:59:45.606] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C3.dat
[11:59:45.611] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C4.dat
[11:59:45.617] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C5.dat
[11:59:45.622] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C6.dat
[11:59:45.628] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C7.dat
[11:59:45.633] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C8.dat
[11:59:45.639] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C9.dat
[11:59:45.644] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C10.dat
[11:59:45.650] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C11.dat
[11:59:45.655] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C12.dat
[11:59:45.661] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C13.dat
[11:59:45.666] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C14.dat
[11:59:45.672] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C15.dat
[11:59:45.677] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//defaultMaskFile.dat
[11:59:45.687] INFO: enter test to run
[12:00:19.629] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:00:19.629] INFO: running: highrate
[12:00:19.634] INFO: ----------------------------------------------------------------------
[12:00:19.634] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:00:19.634] INFO: ----------------------------------------------------------------------
[12:00:19.634] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:00:19.634] INFO: edge/corner pixel THR is adjusted
[12:00:19.634] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:00:20.591] INFO: Collecting data for 1 seconds...
[12:00:21.596] INFO: Done with hot pixel readout
[12:00:25.696] INFO: PixTest:: pg_setup set to default.
[12:00:25.697] INFO: 0 hot pixels found in step 0
[12:00:25.702] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:00:25.786] INFO: PixTest::trimHotPixels() done
[12:00:25.786] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C0.dat
[12:00:25.795] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C1.dat
[12:00:25.802] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C2.dat
[12:00:25.809] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C3.dat
[12:00:25.815] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C4.dat
[12:00:25.822] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C5.dat
[12:00:25.829] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C6.dat
[12:00:25.836] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C7.dat
[12:00:25.841] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C8.dat
[12:00:25.846] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C9.dat
[12:00:25.854] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C10.dat
[12:00:25.860] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C11.dat
[12:00:25.867] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C12.dat
[12:00:25.872] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C13.dat
[12:00:25.878] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C14.dat
[12:00:25.883] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C15.dat
[12:00:25.888] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-34_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//defaultMaskFile.dat
[12:00:25.898] INFO: enter test to run
[12:00:59.085] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:00:59.085] INFO: running: xray
[12:00:59.086] INFO: ----------------------------------------------------------------------
[12:00:59.086] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:00:59.086] INFO: ----------------------------------------------------------------------
[12:01:00.067] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:01:11.433] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:01:40.751] INFO: Resuming triggers.
[12:01:52.118] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[12:02:21.425] INFO: Resuming triggers.
[12:02:32.787] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[12:03:02.336] INFO: Resuming triggers.
[12:03:13.700] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[12:03:43.049] INFO: Resuming triggers.
[12:03:54.411] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[12:04:23.814] INFO: Resuming triggers.
[12:04:35.182] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[12:05:04.546] INFO: Resuming triggers.
[12:05:15.916] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[12:05:45.249] INFO: Resuming triggers.
[12:05:56.612] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[12:06:26.074] INFO: Resuming triggers.
[12:06:35.488] INFO: data taking finished, elapsed time: 100 seconds.
[12:07:00.175] INFO: PixTest:: pg_setup set to default.
[12:07:00.179] INFO: PixTestXray::doPhRun() done
[12:07:00.383] INFO: enter test to run
[12:07:43.018] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:07:43.018] INFO: running: xray
[12:07:43.019] INFO: ----------------------------------------------------------------------
[12:07:43.019] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:07:43.020] INFO: ----------------------------------------------------------------------
[12:07:43.983] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:07:50.568] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:08:20.714] INFO: Resuming triggers.
[12:08:27.295] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[12:08:58.330] INFO: Resuming triggers.
[12:09:04.909] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[12:09:35.762] INFO: Resuming triggers.
[12:09:42.346] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[12:10:13.385] INFO: Resuming triggers.
[12:10:19.965] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[12:10:51.154] INFO: Resuming triggers.
[12:10:57.736] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[12:11:28.792] INFO: Resuming triggers.
[12:11:35.372] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[12:12:06.342] INFO: Resuming triggers.
[12:12:12.924] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[12:12:43.831] INFO: Resuming triggers.
[12:12:50.407] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[12:13:20.518] INFO: Resuming triggers.
[12:13:27.092] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[12:13:58.966] INFO: Resuming triggers.
[12:14:05.537] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[12:14:36.412] INFO: Resuming triggers.
[12:14:42.991] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[12:15:14.249] INFO: Resuming triggers.
[12:15:20.823] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[12:15:52.037] INFO: Resuming triggers.
[12:15:58.613] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[12:16:29.838] INFO: Resuming triggers.
[12:16:36.417] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[12:17:06.654] INFO: Resuming triggers.
[12:17:08.337] INFO: data taking finished, elapsed time: 100 seconds.
[12:17:16.414] INFO: PixTest:: pg_setup set to default.
[12:17:16.417] INFO: PixTestXray::doPhRun() done
[12:17:16.569] INFO: enter test to run
[12:17:50.878] INFO: test: HighRate no parameter change
[12:17:50.879] INFO: running: highrate
[12:17:50.900] INFO: ----------------------------------------------------------------------
[12:17:50.900] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:17:50.900] INFO: ----------------------------------------------------------------------
[12:17:51.054] INFO: Expecting 768 events.
[12:17:52.189] INFO: 768 events read in total (419ms).
[12:17:52.189] INFO: Test took 1269ms.
[12:17:52.992] INFO: Expecting 41600 events.
[12:17:56.170] INFO: 41600 events read in total (2651ms).
[12:17:56.171] INFO: Test took 3977ms.
[12:17:56.206] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:56.927] INFO: Expecting 41600 events.
[12:18:00.151] INFO: 41600 events read in total (2697ms).
[12:18:00.152] INFO: Test took 3927ms.
[12:18:00.187] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:00.908] INFO: Expecting 41600 events.
[12:18:04.139] INFO: 41600 events read in total (2705ms).
[12:18:04.140] INFO: Test took 3934ms.
[12:18:04.175] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:04.895] INFO: Expecting 41600 events.
[12:18:08.081] INFO: 41600 events read in total (2659ms).
[12:18:08.082] INFO: Test took 3889ms.
[12:18:08.117] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:08.839] INFO: Expecting 41600 events.
[12:18:12.026] INFO: 41600 events read in total (2660ms).
[12:18:12.027] INFO: Test took 3891ms.
[12:18:12.063] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:12.785] INFO: Expecting 41600 events.
[12:18:15.986] INFO: 41600 events read in total (2674ms).
[12:18:15.987] INFO: Test took 3905ms.
[12:18:16.030] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:16.742] INFO: Expecting 41600 events.
[12:18:19.002] INFO: 41600 events read in total (2733ms).
[12:18:19.003] INFO: Test took 3954ms.
[12:18:20.039] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:20.756] INFO: Expecting 41600 events.
[12:18:23.984] INFO: 41600 events read in total (2701ms).
[12:18:23.985] INFO: Test took 3926ms.
[12:18:24.022] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:24.737] INFO: Expecting 41600 events.
[12:18:27.637] INFO: 41600 events read in total (2373ms).
[12:18:27.638] INFO: Test took 3597ms.
[12:18:27.675] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:28.397] INFO: Expecting 41600 events.
[12:18:31.528] INFO: 41600 events read in total (2604ms).
[12:18:31.529] INFO: Test took 3835ms.
[12:18:31.564] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:32.287] INFO: Expecting 41600 events.
[12:18:35.437] INFO: 41600 events read in total (2623ms).
[12:18:35.438] INFO: Test took 3855ms.
[12:18:35.473] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:36.194] INFO: Expecting 41600 events.
[12:18:39.347] INFO: 41600 events read in total (2626ms).
[12:18:39.348] INFO: Test took 3857ms.
[12:18:39.384] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:40.100] INFO: Expecting 41600 events.
[12:18:43.297] INFO: 41600 events read in total (2671ms).
[12:18:43.298] INFO: Test took 3895ms.
[12:18:43.333] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:44.054] INFO: Expecting 41600 events.
[12:18:47.145] INFO: 41600 events read in total (2564ms).
[12:18:47.146] INFO: Test took 3794ms.
[12:18:47.182] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:47.906] INFO: Expecting 41600 events.
[12:18:50.944] INFO: 41600 events read in total (2511ms).
[12:18:50.945] INFO: Test took 3744ms.
[12:18:50.982] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:51.702] INFO: Expecting 41600 events.
[12:18:54.925] INFO: 41600 events read in total (2696ms).
[12:18:54.926] INFO: Test took 3925ms.
[12:18:54.961] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:55.681] INFO: Expecting 41600 events.
[12:18:58.910] INFO: 41600 events read in total (2702ms).
[12:18:58.910] INFO: Test took 3930ms.
[12:18:58.946] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:59.668] INFO: Expecting 41600 events.
[12:19:02.797] INFO: 41600 events read in total (2602ms).
[12:19:02.798] INFO: Test took 3835ms.
[12:19:02.833] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:19:03.556] INFO: Expecting 41600 events.
[12:19:06.755] INFO: 41600 events read in total (2673ms).
[12:19:06.756] INFO: Test took 3903ms.
[12:19:06.791] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:19:07.511] INFO: Expecting 41600 events.
[12:19:10.548] INFO: 41600 events read in total (2510ms).
[12:19:10.549] INFO: Test took 3739ms.
[12:19:10.584] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:19:10.946] INFO: enter test to run
[12:19:37.517] INFO: test: HighRate no parameter change
[12:19:37.517] INFO: running: highrate
[12:19:37.518] INFO: ----------------------------------------------------------------------
[12:19:37.518] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:19:37.518] INFO: ----------------------------------------------------------------------
[12:19:38.128] INFO: Expecting 208000 events.
[12:19:49.957] INFO: 208000 events read in total (11302ms).
[12:19:49.960] INFO: Test took 12434ms.
[12:19:50.111] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:19:50.365] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[12:19:50.383] INFO: number of red-efficiency pixels: 72 49 98 105 126 167 156 94 95 143 120 131 127 73 26 24
[12:19:50.384] INFO: number of X-ray hits detected: 65292 41877 68708 104540 108103 115220 117921 79459 80899 110912 107253 92093 93981 57500 22262 25002
[12:19:50.384] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:19:50.384] INFO: number of Vcal hits detected: 207927 207950 207899 207893 207871 207829 207843 207903 207902 207855 207877 207867 207869 207925 207925 207976
[12:19:50.384] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[12:19:50.384] 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
[12:19:50.384] INFO: X-ray hit rate [MHz/cm2]: 19.1 12.3 20.1 30.6 31.7 33.8 34.6 23.3 23.7 32.5 31.4 27.0 27.5 16.9 6.5 7.3
[12:19:50.384] INFO: PixTestHighRate::doXPixelAlive() done
[12:19:50.436] INFO: PixTest:: pg_setup set to default.
[12:19:50.451] INFO: enter test to run
[12:20:13.493] INFO: test: HighRate no parameter change
[12:20:13.493] INFO: running: highrate
[12:20:13.495] INFO: ----------------------------------------------------------------------
[12:20:13.495] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:20:13.495] INFO: ----------------------------------------------------------------------
[12:20:14.110] INFO: Expecting 208000 events.
[12:20:27.702] INFO: 208000 events read in total (13065ms).
[12:20:27.707] INFO: Test took 14203ms.
[12:20:27.004] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:20:28.309] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[12:20:28.309] INFO: number of red-efficiency pixels: 200 131 292 348 382 544 639 284 253 457 338 395 349 189 71 48
[12:20:28.309] INFO: number of X-ray hits detected: 134278 86299 141238 215684 223497 235771 241670 165250 167347 229279 219494 188443 193716 118098 46256 51513
[12:20:28.309] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:20:28.310] INFO: number of Vcal hits detected: 207788 207862 207688 207628 207595 207409 207261 207693 207741 207505 207640 207570 207624 207799 207880 207952
[12:20:28.310] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 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
[12:20:28.310] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.7 99.6 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 100.0
[12:20:28.310] INFO: X-ray hit rate [MHz/cm2]: 39.4 25.3 41.4 63.2 65.5 69.1 70.8 48.4 49.1 67.2 64.3 55.2 56.8 34.6 13.6 15.1
[12:20:28.310] INFO: PixTestHighRate::doXPixelAlive() done
[12:20:28.357] INFO: PixTest:: pg_setup set to default.
[12:20:28.373] INFO: enter test to run
[12:20:46.749] INFO: test: HighRate no parameter change
[12:20:46.749] INFO: running: highrate
[12:20:46.750] INFO: ----------------------------------------------------------------------
[12:20:46.750] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:20:46.750] INFO: ----------------------------------------------------------------------
[12:20:47.371] INFO: Expecting 208000 events.
[12:21:02.923] INFO: 208000 events read in total (15025ms).
[12:21:02.930] INFO: Test took 16171ms.
[12:21:03.369] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:21:03.722] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[12:21:03.722] INFO: number of red-efficiency pixels: 381 284 727 892 824 1307 1436 595 522 1095 823 951 764 397 109 108
[12:21:03.722] INFO: number of X-ray hits detected: 200909 129920 212461 322358 334974 353916 363701 248837 250797 345719 330719 284556 291757 179007 69271 78493
[12:21:03.722] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:21:03.722] INFO: number of Vcal hits detected: 207566 207687 207012 206947 207027 206217 206027 207279 207397 206654 207020 206783 207105 207520 207834 207891
[12:21:03.722] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.5 99.6 99.2 99.1 99.7 99.7 99.4 99.6 99.5 99.6 99.8 99.9 99.9
[12:21:03.722] INFO: Vcal hit overall efficiency (%): 99.8 99.8 99.5 99.5 99.5 99.1 99.1 99.7 99.7 99.4 99.5 99.4 99.6 99.8 99.9 99.9
[12:21:03.722] INFO: X-ray hit rate [MHz/cm2]: 58.9 38.1 62.3 94.5 98.2 103.7 106.6 72.9 73.5 101.3 96.9 83.4 85.5 52.5 20.3 23.0
[12:21:03.722] INFO: PixTestHighRate::doXPixelAlive() done
[12:21:03.767] INFO: PixTest:: pg_setup set to default.
[12:21:03.785] INFO: enter test to run
[12:21:26.285] INFO: test: exit no parameter change
[12:21:26.744] QUIET: Connection to board 33 closed.
[12:21:26.779] INFO: pXar: this is the end, my friend