[16:33:38.948]     INFO: *** Welcome to pxar ***
[16:33:38.948]     INFO: *** Today: 2016/10/27
[16:33:38.964]     INFO: *** Version: v1.9.0-818-g96727
[16:33:38.964]     INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//dacParameters35_C15.dat
[16:33:38.965]     INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:33:38.965]     INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//defaultMaskFile.dat
[16:33:38.965]     INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C15.dat
[16:33:39.035]     INFO:         clk: 4
[16:33:39.035]     INFO:         ctr: 4
[16:33:39.035]     INFO:         sda: 19
[16:33:39.035]     INFO:         tin: 9
[16:33:39.035]     INFO:         level: 15
[16:33:39.035]     INFO:         triggerdelay: 0
[16:33:39.035]    QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[16:33:39.035]     INFO: Log level: INFO
[16:33:39.051]    QUIET: Connection to board DTB_WREHUL opened.
[16:33:39.054]     INFO: DTB startup information
--- DTB info------------------------------------------
Board id:    30
HW version:  DTB1.2
FW version:  4.2
SW version:  4.5
USB id:      DTB_WREHUL
MAC address: 40D85511801E
Hostname:    pixelDTB030
Comment:     
------------------------------------------------------
[16:33:39.056]     INFO: RPC call hashes of host and DTB match: 398089610
[16:33:40.608]     INFO: DUT info: 
[16:33:40.608]     INFO: The DUT currently contains the following objects:
[16:33:40.608]     INFO:  2 TBM Cores tbm08c (2 ON)
[16:33:40.608]     INFO: 	TBM Core alpha (0): 7 registers set
[16:33:40.608]     INFO: 	TBM Core beta  (1): 7 registers set
[16:33:40.608]     INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[16:33:40.608]     INFO: 	ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.608]     INFO: 	ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.608]     INFO: 	ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.608]     INFO: 	ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.608]     INFO: 	ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.608]     INFO: 	ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.609]     INFO: 	ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.609]     INFO: 	ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.609]     INFO: 	ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.609]     INFO: 	ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.609]     INFO: 	ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.609]     INFO: 	ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.609]     INFO: 	ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.609]     INFO: 	ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.609]     INFO: 	ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:40.609]     INFO: 	ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[16:33:41.012]     INFO: enter 'restricted' command line mode
[16:33:41.012]     INFO: enter test to run
[16:33:50.415]     INFO:   test: PixelAlive no parameter change
[16:33:50.415]     INFO:   running: pixelalive
[16:33:50.424]     INFO:    ----------------------------------------------------------------------
[16:33:50.424]     INFO:    PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[16:33:50.424]     INFO:    ----------------------------------------------------------------------
[16:33:50.748]     INFO: Expecting 41600 events.
[16:33:55.095]     INFO: 41600 events read in total (3628ms).
[16:33:55.265]     INFO: Test took 4839ms.
[16:33:55.277]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:33:55.545]     INFO: PixTestAlive::aliveTest() done
[16:33:55.545]     INFO: number of dead pixels (per ROC):     0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0
[16:33:55.574]     INFO: enter test to run
[16:41:38.156]     INFO:   test: timing no parameter change
[16:41:38.156]     INFO:   running: timing
[16:41:38.175]     INFO: ######################################################################
[16:41:38.182]     INFO: PixTestTiming::doTest()
[16:41:38.182]     INFO: ######################################################################
[16:41:38.182]     INFO:    ----------------------------------------------------------------------
[16:41:38.182]     INFO:    PixTestTiming::TBMPhaseScan()
[16:41:38.182]     INFO:    ----------------------------------------------------------------------
[16:47:05.566]     INFO: TBM Phase Settings: 236
[16:47:05.566]     INFO: 400MHz Phase: 3
[16:47:05.566]     INFO: 160MHz Phase: 7
[16:47:05.566]     INFO: Functional Phase Area: 5
[16:47:05.576]     INFO: Test took 327394 ms.
[16:47:05.576]     INFO: PixTestTiming::TBMPhaseScan() done.
[16:47:05.576]     INFO:    ----------------------------------------------------------------------
[16:47:05.577]     INFO:    PixTestTiming::ROCDelayScan()
[16:47:05.577]     INFO:    ----------------------------------------------------------------------
[16:51:02.263]     INFO: ROC Delay Settings: 228
[16:51:02.263]     INFO: ROC Header-Trailer/Token Delay: 11
[16:51:02.263]     INFO: ROC Port 0 Delay: 4
[16:51:02.263]     INFO: ROC Port 1 Delay: 4
[16:51:02.263]     INFO: Functional ROC Area: 4
[16:51:02.266]     INFO: Test took 236690 ms.
[16:51:02.266]     INFO: PixTestTiming::ROCDelayScan() done.
[16:51:02.266]     INFO:    ----------------------------------------------------------------------
[16:51:02.266]     INFO:    PixTestTiming::TimingTest()
[16:51:02.266]     INFO:    ----------------------------------------------------------------------
[16:51:18.770]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:51:34.264]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:51:49.463]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:52:04.436]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:52:19.432]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:52:34.398]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:52:49.397]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:53:04.386]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:53:19.360]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:53:34.349]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:53:34.731]     INFO: Fetched DAQ statistics. Counters are being reset now.
[16:53:34.748]     INFO:    ----------------------------------------------------------------------
[16:53:34.748]     INFO:    The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:53:34.748]     INFO:    ----------------------------------------------------------------------
[16:53:34.748]     INFO:    ----------------------------------------------------------------------
[16:53:34.748]     INFO:    Read back bit status: 1
[16:53:34.748]     INFO:    ----------------------------------------------------------------------
[16:53:34.748]     INFO:    ----------------------------------------------------------------------
[16:53:34.748]     INFO:    Timings are good!
[16:53:34.748]     INFO:    ----------------------------------------------------------------------
[16:53:34.748]     INFO: Test took 152482 ms.
[16:53:34.749]     INFO: PixTestTiming::TimingTest() done.
[16:53:34.762]     INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:53:34.762]     INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:53:34.763]     INFO: PixTestTiming::doTest took 716591 ms.
[16:53:34.763]     INFO: PixTestTiming::doTest() done
[16:53:34.763]     INFO: Write out TBMPhaseScan_0_V0
[16:53:34.763]     INFO: Write out TBMPhaseScan_1_V0
[16:53:34.763]     INFO: Write out CombinedTBMPhaseScan_V0
[16:53:34.789]     INFO: Write out ROCDelayScan3_V0
[16:53:34.789]     INFO: enter test to run
[16:54:15.295]     INFO:   test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:54:15.295]     INFO:   running: highrate
[16:54:15.295]     INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:54:15.547]     INFO:    ----------------------------------------------------------------------
[16:54:15.547]     INFO:    PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:54:15.547]     INFO:    ----------------------------------------------------------------------
[16:54:15.547]     INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:54:15.547]     INFO: edge/corner pixel THR is adjusted
[16:54:15.547]     INFO: PixTestHighRate::trimHotPixels: step 0...
[16:54:16.505]     INFO: Collecting data for 5 seconds...
[16:54:21.523]     INFO: Done with hot pixel readout
[16:54:33.021]     INFO: PixTest::       pg_setup set to default.
[16:54:33.021]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:33.021]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:33.021]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:33.021]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:33.021]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:33.021]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:33.021]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:33.021]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:33.022]     INFO: 10 hot pixels found in step 0
[16:54:34.021]     INFO: Collecting data for 5 seconds...
[16:54:39.038]     INFO: Done with hot pixel readout
[16:54:50.182]     INFO: PixTest::       pg_setup set to default.
[16:54:50.182]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:50.182]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:50.182]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:50.182]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:50.182]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:50.182]  WARNING:   => trimBits already at highest possible threshold, 'real' hot pixel found
[16:54:50.183]     INFO: 6 hot pixels found in step 1
[16:54:50.219]     INFO: 6 hot pixels could not be trimmed and have been masked.
[16:54:50.223]     INFO: PixTest::trimHotPixels() done
[16:54:50.223]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C0.dat
[16:54:50.228]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C1.dat
[16:54:50.235]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C2.dat
[16:54:50.240]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C3.dat
[16:54:50.246]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C4.dat
[16:54:50.253]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C5.dat
[16:54:50.258]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C6.dat
[16:54:50.263]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C7.dat
[16:54:50.269]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C8.dat
[16:54:50.274]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C9.dat
[16:54:50.280]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C10.dat
[16:54:50.285]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C11.dat
[16:54:50.290]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C12.dat
[16:54:50.296]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C13.dat
[16:54:50.301]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C14.dat
[16:54:50.307]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C15.dat
[16:54:50.312]     INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//defaultMaskFile.dat
[16:54:50.322]     INFO: enter test to run
[16:55:39.382]     INFO:   test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:55:39.382]     INFO:   running: highrate
[16:55:39.386]     INFO:    ----------------------------------------------------------------------
[16:55:39.386]     INFO:    PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:55:39.386]     INFO:    ----------------------------------------------------------------------
[16:55:39.387]     INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:55:39.387]     INFO: edge/corner pixel THR is adjusted
[16:55:39.387]     INFO: PixTestHighRate::trimHotPixels: step 0...
[16:55:40.344]     INFO: Collecting data for 1 seconds...
[16:55:41.347]     INFO: Done with hot pixel readout
[16:55:45.331]     INFO: PixTest::       pg_setup set to default.
[16:55:45.331]     INFO: 0 hot pixels found in step 0
[16:55:45.337]     INFO: 0 hot pixels could not be trimmed and have been masked.
[16:55:45.424]     INFO: PixTest::trimHotPixels() done
[16:55:45.424]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C0.dat
[16:55:45.435]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C1.dat
[16:55:45.440]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C2.dat
[16:55:45.446]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C3.dat
[16:55:45.451]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C4.dat
[16:55:45.456]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C5.dat
[16:55:45.462]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C6.dat
[16:55:45.467]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C7.dat
[16:55:45.473]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C8.dat
[16:55:45.478]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C9.dat
[16:55:45.483]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C10.dat
[16:55:45.488]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C11.dat
[16:55:45.494]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C12.dat
[16:55:45.499]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C13.dat
[16:55:45.504]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C14.dat
[16:55:45.509]     INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//trimParameters35_C15.dat
[16:55:45.515]     INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-15_FPIXTest-17C-FNAL-161019-1034-150V_2016-10-19_10h34m_1476891274/000_FPIXTest_p17//defaultMaskFile.dat
[16:55:45.525]     INFO: enter test to run
[16:56:18.182]     INFO:   test: Xray setting parameters: ->source=DCLowRate<-
[16:56:18.182]     INFO:   running: xray
[16:56:18.183]     INFO:    ----------------------------------------------------------------------
[16:56:18.183]     INFO:    PixTestXray::doPhRun() fParRunSeconds = 100
[16:56:18.183]     INFO:    ----------------------------------------------------------------------
[16:56:19.146]     INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds,  fEventsMax = 10000000
[16:56:30.805]     INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[16:57:00.580]     INFO: Resuming triggers.
[16:57:12.238]     INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[16:57:41.759]     INFO: Resuming triggers.
[16:57:53.418]     INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[16:58:20.469]     INFO: Resuming triggers.
[16:58:32.129]     INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[16:59:01.767]     INFO: Resuming triggers.
[16:59:13.425]     INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[16:59:42.665]     INFO: Resuming triggers.
[16:59:54.323]     INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[17:00:24.313]     INFO: Resuming triggers.
[17:00:35.973]     INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[17:01:05.847]     INFO: Resuming triggers.
[17:01:17.509]     INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[17:01:47.326]     INFO: Resuming triggers.
[17:01:54.396]     INFO: data taking finished, elapsed time: 100 seconds.
[17:02:12.612]     INFO: PixTest::       pg_setup set to default.
[17:02:12.615]     INFO: PixTestXray::doPhRun() done
[17:02:12.899]     INFO: enter test to run
[17:03:05.979]     INFO:   test: Xray setting parameters: ->source=DCHighRate<-
[17:03:05.979]     INFO:   running: xray
[17:03:05.981]     INFO:    ----------------------------------------------------------------------
[17:03:05.981]     INFO:    PixTestXray::doPhRun() fParRunSeconds = 100
[17:03:05.981]     INFO:    ----------------------------------------------------------------------
[17:03:06.944]     INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds,  fEventsMax = 10000000
[17:03:13.837]     INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[17:03:45.040]     INFO: Resuming triggers.
[17:03:51.931]     INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[17:04:23.642]     INFO: Resuming triggers.
[17:04:30.533]     INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[17:05:02.567]     INFO: Resuming triggers.
[17:05:09.458]     INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[17:05:41.078]     INFO: Resuming triggers.
[17:05:47.966]     INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[17:06:19.194]     INFO: Resuming triggers.
[17:06:26.084]     INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[17:06:57.551]     INFO: Resuming triggers.
[17:07:04.440]     INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[17:07:35.490]     INFO: Resuming triggers.
[17:07:42.378]     INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[17:08:12.823]     INFO: Resuming triggers.
[17:08:19.711]     INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[17:08:50.031]     INFO: Resuming triggers.
[17:08:56.919]     INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[17:09:27.175]     INFO: Resuming triggers.
[17:09:34.065]     INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[17:10:04.552]     INFO: Resuming triggers.
[17:10:11.443]     INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[17:10:41.793]     INFO: Resuming triggers.
[17:10:48.685]     INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[17:11:19.310]     INFO: Resuming triggers.
[17:11:26.202]     INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[17:11:56.754]     INFO: Resuming triggers.
[17:12:00.644]     INFO: data taking finished, elapsed time: 100 seconds.
[17:12:17.959]     INFO: PixTest::       pg_setup set to default.
[17:12:17.963]     INFO: PixTestXray::doPhRun() done
[17:12:18.132]     INFO: enter test to run
[17:13:05.535]     INFO:   test: HighRate no parameter change
[17:13:05.535]     INFO:   running: highrate
[17:13:05.589]     INFO:    ----------------------------------------------------------------------
[17:13:05.589]     INFO:    PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[17:13:05.589]     INFO:    ----------------------------------------------------------------------
[17:13:05.769]     INFO: Expecting 768 events.
[17:13:06.903]     INFO: 768 events read in total (418ms).
[17:13:06.904]     INFO: Test took 1270ms.
[17:13:07.707]     INFO: Expecting 41600 events.
[17:13:10.820]     INFO: 41600 events read in total (2586ms).
[17:13:10.821]     INFO: Test took 3909ms.
[17:13:10.854]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:11.583]     INFO: Expecting 41600 events.
[17:13:14.781]     INFO: 41600 events read in total (2671ms).
[17:13:14.781]     INFO: Test took 3908ms.
[17:13:14.814]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:15.540]     INFO: Expecting 41600 events.
[17:13:18.754]     INFO: 41600 events read in total (2688ms).
[17:13:18.755]     INFO: Test took 3923ms.
[17:13:18.789]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:19.514]     INFO: Expecting 41600 events.
[17:13:22.740]     INFO: 41600 events read in total (2699ms).
[17:13:22.741]     INFO: Test took 3934ms.
[17:13:22.774]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:23.500]     INFO: Expecting 41600 events.
[17:13:26.723]     INFO: 41600 events read in total (2696ms).
[17:13:26.724]     INFO: Test took 3932ms.
[17:13:26.757]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:27.482]     INFO: Expecting 41600 events.
[17:13:30.709]     INFO: 41600 events read in total (2700ms).
[17:13:30.710]     INFO: Test took 3935ms.
[17:13:30.744]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:31.471]     INFO: Expecting 41600 events.
[17:13:34.704]     INFO: 41600 events read in total (2706ms).
[17:13:34.705]     INFO: Test took 3943ms.
[17:13:34.738]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:35.465]     INFO: Expecting 41600 events.
[17:13:38.649]     INFO: 41600 events read in total (2657ms).
[17:13:38.650]     INFO: Test took 3893ms.
[17:13:38.683]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:39.404]     INFO: Expecting 41600 events.
[17:13:42.651]     INFO: 41600 events read in total (2720ms).
[17:13:42.652]     INFO: Test took 3951ms.
[17:13:42.685]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:43.413]     INFO: Expecting 41600 events.
[17:13:46.656]     INFO: 41600 events read in total (2716ms).
[17:13:46.657]     INFO: Test took 3953ms.
[17:13:46.691]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:47.414]     INFO: Expecting 41600 events.
[17:13:50.664]     INFO: 41600 events read in total (2723ms).
[17:13:50.665]     INFO: Test took 3956ms.
[17:13:50.698]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:51.424]     INFO: Expecting 41600 events.
[17:13:54.706]     INFO: 41600 events read in total (2755ms).
[17:13:54.707]     INFO: Test took 3992ms.
[17:13:54.740]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:55.461]     INFO: Expecting 41600 events.
[17:13:58.771]     INFO: 41600 events read in total (2784ms).
[17:13:58.773]     INFO: Test took 4014ms.
[17:13:58.806]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:13:59.526]     INFO: Expecting 41600 events.
[17:14:02.819]     INFO: 41600 events read in total (2766ms).
[17:14:02.820]     INFO: Test took 3995ms.
[17:14:02.854]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:14:03.577]     INFO: Expecting 41600 events.
[17:14:06.821]     INFO: 41600 events read in total (2717ms).
[17:14:06.822]     INFO: Test took 3951ms.
[17:14:06.866]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:14:07.564]     INFO: Expecting 41600 events.
[17:14:10.929]     INFO: 41600 events read in total (2838ms).
[17:14:10.930]     INFO: Test took 4038ms.
[17:14:10.963]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:14:11.674]     INFO: Expecting 41600 events.
[17:14:14.993]     INFO: 41600 events read in total (2793ms).
[17:14:14.994]     INFO: Test took 4014ms.
[17:14:15.027]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:14:15.733]     INFO: Expecting 41600 events.
[17:14:18.922]     INFO: 41600 events read in total (2662ms).
[17:14:18.923]     INFO: Test took 3878ms.
[17:14:18.957]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:14:19.676]     INFO: Expecting 41600 events.
[17:14:22.924]     INFO: 41600 events read in total (2721ms).
[17:14:22.925]     INFO: Test took 3951ms.
[17:14:22.963]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:14:23.673]     INFO: Expecting 41600 events.
[17:14:26.734]     INFO: 41600 events read in total (2534ms).
[17:14:26.735]     INFO: Test took 3754ms.
[17:14:26.768]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:14:27.123]     INFO: enter test to run
[17:15:40.678]     INFO:   test: HighRate no parameter change
[17:15:40.678]     INFO:   running: highrate
[17:15:40.679]     INFO:    ----------------------------------------------------------------------
[17:15:40.679]     INFO:    PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:15:40.679]     INFO:    ----------------------------------------------------------------------
[17:15:41.294]     INFO: Expecting 208000 events.
[17:15:53.359]     INFO: 208000 events read in total (11538ms).
[17:15:53.362]     INFO: Test took 12675ms.
[17:15:53.504]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:15:53.756]     INFO: number of dead pixels (per ROC):     0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0
[17:15:53.756]     INFO: number of red-efficiency pixels:    82   46   82  106  138  114  111   91  100  126  172  140  103   74   21   26
[17:15:53.756]     INFO: number of X-ray hits detected:    64482 40700 60127 96542 100545 104814 104700 74097 74343 102583 101107 86655 87169 51154 20770 23174
[17:15:53.756]     INFO: number of triggers sent (total per ROC):  208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:15:53.756]     INFO: number of Vcal hits detected:  207914 207953 207916 207892 207860 207883 207884 207909 207897 207868 207822 207859 207896 207925 207979 207974
[17:15:53.756]     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 100.0 100.0 100.0 100.0
[17:15:53.756]     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 100.0 100.0 100.0 100.0
[17:15:53.756]     INFO: X-ray hit rate [MHz/cm2]:  18.9 11.9 17.6 28.3 29.5 30.7 30.7 21.7 21.8 30.1 29.6 25.4 25.5 15.0 6.1 6.8
[17:15:53.756]     INFO: PixTestHighRate::doXPixelAlive() done
[17:15:53.808]     INFO: PixTest::       pg_setup set to default.
[17:15:53.823]     INFO: enter test to run
[17:16:21.405]     INFO:   test: HighRate no parameter change
[17:16:21.406]     INFO:   running: highrate
[17:16:21.407]     INFO:    ----------------------------------------------------------------------
[17:16:21.407]     INFO:    PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:16:21.407]     INFO:    ----------------------------------------------------------------------
[17:16:22.022]     INFO: Expecting 208000 events.
[17:16:35.545]     INFO: 208000 events read in total (12996ms).
[17:16:35.550]     INFO: Test took 14135ms.
[17:16:35.834]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:16:36.137]     INFO: number of dead pixels (per ROC):     0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0
[17:16:36.137]     INFO: number of red-efficiency pixels:   263  109  230  380  338  362  367  276  295  367  484  355  361  189   66   66
[17:16:36.137]     INFO: number of X-ray hits detected:    131875 82907 121934 198647 206170 214715 214683 152380 151872 210661 207385 177955 178238 104537 43589 48181
[17:16:36.137]     INFO: number of triggers sent (total per ROC):  208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:16:36.137]     INFO: number of Vcal hits detected:  207709 207886 207753 207578 207651 207614 207606 207706 207685 207596 207471 207621 207609 207798 207934 207933
[17:16:36.137]     INFO: Vcal hit fiducial efficiency (%):  99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[17:16:36.137]     INFO: Vcal hit overall efficiency (%):  99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.8 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[17:16:36.137]     INFO: X-ray hit rate [MHz/cm2]:  38.7 24.3 35.7 58.2 60.4 62.9 62.9 44.7 44.5 61.7 60.8 52.2 52.2 30.6 12.8 14.1
[17:16:36.137]     INFO: PixTestHighRate::doXPixelAlive() done
[17:16:36.183]     INFO: PixTest::       pg_setup set to default.
[17:16:36.199]     INFO: enter test to run
[17:16:58.197]     INFO:   test: HighRate no parameter change
[17:16:58.197]     INFO:   running: highrate
[17:16:58.198]     INFO:    ----------------------------------------------------------------------
[17:16:58.198]     INFO:    PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:16:58.198]     INFO:    ----------------------------------------------------------------------
[17:16:58.820]     INFO: Expecting 208000 events.
[17:17:14.232]     INFO: 208000 events read in total (14885ms).
[17:17:14.239]     INFO: Test took 16032ms.
[17:17:14.676]     INFO: Fetched DAQ statistics. Counters are being reset now.
[17:17:15.021]     INFO: number of dead pixels (per ROC):     0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0
[17:17:15.021]     INFO: number of red-efficiency pixels:   570  234  561  852  758  896  850  713  619  863 1103  823  799  442   85   61
[17:17:15.021]     INFO: number of X-ray hits detected:    200221 125524 186284 301127 312707 327986 324784 230030 230764 319923 314247 270176 272480 160017 65146 73437
[17:17:15.021]     INFO: number of triggers sent (total per ROC):  208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:17:15.021]     INFO: number of Vcal hits detected:  207290 207749 207308 206978 207122 206950 206959 207139 207288 206949 206597 207007 207079 207457 207915 207937
[17:17:15.021]     INFO: Vcal hit fiducial efficiency (%):  99.7 99.9 99.7 99.6 99.6 99.5 99.5 99.6 99.7 99.5 99.4 99.6 99.6 99.8 100.0 100.0
[17:17:15.021]     INFO: Vcal hit overall efficiency (%):  99.7 99.9 99.7 99.5 99.6 99.5 99.5 99.6 99.7 99.5 99.3 99.5 99.6 99.7 100.0 100.0
[17:17:15.021]     INFO: X-ray hit rate [MHz/cm2]:  58.7 36.8 54.6 88.3 91.7 96.1 95.2 67.4 67.6 93.8 92.1 79.2 79.9 46.9 19.1 21.5
[17:17:15.021]     INFO: PixTestHighRate::doXPixelAlive() done
[17:17:15.069]     INFO: PixTest::       pg_setup set to default.
[17:17:15.087]     INFO: enter test to run
[17:17:33.461]     INFO:   test: exit no parameter change
[17:17:34.041]    QUIET: Connection to board 30 closed.
[17:17:34.067]     INFO: pXar: this is the end, my friend