[11:29:36.593] INFO: *** Welcome to pxar ***
[11:29:36.593] INFO: *** Today: 2016/09/16
[11:29:39.997] INFO: *** Version: v1.9.0-818-g96727
[11:29:39.997] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//dacParameters35_C15.dat
[11:29:40.173] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:29:40.174] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//defaultMaskFile.dat
[11:29:40.184] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C15.dat
[11:29:40.428] INFO: clk: 4
[11:29:40.428] INFO: ctr: 4
[11:29:40.428] INFO: sda: 19
[11:29:40.428] INFO: tin: 9
[11:29:40.428] INFO: level: 15
[11:29:40.428] INFO: triggerdelay: 0
[11:29:40.428] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:29:40.428] INFO: Log level: INFO
[11:29:40.467] QUIET: Connection to board DTB_WREKRL opened.
[11:29:40.470] 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:29:40.473] INFO: RPC call hashes of host and DTB match: 398089610
[11:29:42.008] INFO: DUT info:
[11:29:42.008] INFO: The DUT currently contains the following objects:
[11:29:42.008] INFO: 2 TBM Cores tbm08c (2 ON)
[11:29:42.048] INFO: TBM Core alpha (0): 7 registers set
[11:29:42.048] INFO: TBM Core beta (1): 7 registers set
[11:29:42.048] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:29:42.048] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.048] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:29:42.497] INFO: enter 'restricted' command line mode
[11:29:42.497] INFO: enter test to run
[11:29:50.432] INFO: test: PixelAlive no parameter change
[11:29:50.432] INFO: running: pixelalive
[11:29:50.516] INFO: ----------------------------------------------------------------------
[11:29:50.516] 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:29:50.516] INFO: ----------------------------------------------------------------------
[11:29:50.839] INFO: Expecting 41600 events.
[11:29:55.189] INFO: 41600 events read in total (3632ms).
[11:29:55.355] INFO: Test took 4837ms.
[11:29:55.369] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:55.897] INFO: PixTestAlive::aliveTest() done
[11:29:55.897] INFO: number of dead pixels (per ROC): 0 0 0 0 10 0 0 1 0 0 0 0 0 0 0 0
[11:29:55.961] INFO: enter test to run
[11:29:59.488] INFO: test: timing no parameter change
[11:29:59.488] INFO: running: timing
[11:29:59.492] INFO: ######################################################################
[11:29:59.492] INFO: PixTestTiming::doTest()
[11:29:59.492] INFO: ######################################################################
[11:29:59.492] INFO: ----------------------------------------------------------------------
[11:29:59.492] INFO: PixTestTiming::TBMPhaseScan()
[11:29:59.492] INFO: ----------------------------------------------------------------------
[11:36:05.316] INFO: TBM Phase Settings: 200
[11:36:05.316] INFO: 400MHz Phase: 2
[11:36:05.316] INFO: 160MHz Phase: 6
[11:36:05.316] INFO: Functional Phase Area: 3
[11:36:05.333] INFO: Test took 365841 ms.
[11:36:05.333] INFO: PixTestTiming::TBMPhaseScan() done.
[11:36:05.334] INFO: ----------------------------------------------------------------------
[11:36:05.334] INFO: PixTestTiming::ROCDelayScan()
[11:36:05.334] INFO: ----------------------------------------------------------------------
[11:38:04.453] INFO: ROC Delay Settings: 218
[11:38:04.453] INFO: ROC Header-Trailer/Token Delay: 11
[11:38:04.453] INFO: ROC Port 0 Delay: 2
[11:38:04.453] INFO: ROC Port 1 Delay: 3
[11:38:04.453] INFO: Functional ROC Area: 4
[11:38:04.456] INFO: Test took 119123 ms.
[11:38:04.456] INFO: PixTestTiming::ROCDelayScan() done.
[11:38:04.456] INFO: ----------------------------------------------------------------------
[11:38:04.456] INFO: PixTestTiming::TimingTest()
[11:38:04.456] INFO: ----------------------------------------------------------------------
[11:38:20.686] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:35.548] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:50.536] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:05.576] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:20.611] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:35.620] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:50.743] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:05.672] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:20.788] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:35.812] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:36.192] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:36.210] INFO: ----------------------------------------------------------------------
[11:40:36.210] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:40:36.210] INFO: ----------------------------------------------------------------------
[11:40:36.210] INFO: ----------------------------------------------------------------------
[11:40:36.210] INFO: Read back bit status: 1
[11:40:36.210] INFO: ----------------------------------------------------------------------
[11:40:36.210] INFO: ----------------------------------------------------------------------
[11:40:36.210] INFO: Timings are good!
[11:40:36.210] INFO: ----------------------------------------------------------------------
[11:40:36.210] INFO: Test took 151754 ms.
[11:40:36.210] INFO: PixTestTiming::TimingTest() done.
[11:40:36.221] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:40:36.226] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:40:36.226] INFO: PixTestTiming::doTest took 636738 ms.
[11:40:36.226] INFO: PixTestTiming::doTest() done
[11:40:36.226] INFO: Write out TBMPhaseScan_0_V0
[11:40:36.227] INFO: Write out TBMPhaseScan_1_V0
[11:40:36.227] INFO: Write out CombinedTBMPhaseScan_V0
[11:40:36.266] INFO: Write out ROCDelayScan3_V0
[11:40:36.266] INFO: enter test to run
[11:41:19.820] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:41:19.820] INFO: running: highrate
[11:41:19.856] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:41:20.405] INFO: ----------------------------------------------------------------------
[11:41:20.405] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:41:20.405] INFO: ----------------------------------------------------------------------
[11:41:20.405] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:41:20.405] INFO: edge/corner pixel THR is adjusted
[11:41:20.405] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:41:21.384] INFO: Collecting data for 5 seconds...
[11:41:26.403] INFO: Done with hot pixel readout
[11:41:38.241] INFO: PixTest:: pg_setup set to default.
[11:41:38.242] INFO: 6 hot pixels found in step 0
[11:41:39.235] INFO: Collecting data for 5 seconds...
[11:41:44.253] INFO: Done with hot pixel readout
[11:41:56.126] INFO: PixTest:: pg_setup set to default.
[11:41:56.127] INFO: 4 hot pixels found in step 1
[11:41:57.120] INFO: Collecting data for 5 seconds...
[11:42:02.139] INFO: Done with hot pixel readout
[11:42:14.352] INFO: PixTest:: pg_setup set to default.
[11:42:14.352] INFO: 2 hot pixels found in step 2
[11:42:15.341] INFO: Collecting data for 5 seconds...
[11:42:20.359] INFO: Done with hot pixel readout
[11:42:32.275] INFO: PixTest:: pg_setup set to default.
[11:42:32.276] INFO: 3 hot pixels found in step 3
[11:42:33.268] INFO: Collecting data for 5 seconds...
[11:42:38.287] INFO: Done with hot pixel readout
[11:42:50.151] INFO: PixTest:: pg_setup set to default.
[11:42:50.152] INFO: 4 hot pixels found in step 4
[11:42:51.143] INFO: Collecting data for 5 seconds...
[11:42:56.162] INFO: Done with hot pixel readout
[11:43:08.167] INFO: PixTest:: pg_setup set to default.
[11:43:08.168] INFO: 2 hot pixels found in step 5
[11:43:09.160] INFO: Collecting data for 5 seconds...
[11:43:14.180] INFO: Done with hot pixel readout
[11:43:26.314] INFO: PixTest:: pg_setup set to default.
[11:43:26.315] INFO: 1 hot pixels found in step 6
[11:43:27.307] INFO: Collecting data for 5 seconds...
[11:43:32.326] INFO: Done with hot pixel readout
[11:43:44.399] INFO: PixTest:: pg_setup set to default.
[11:43:44.400] INFO: 1 hot pixels found in step 7
[11:43:45.396] INFO: Collecting data for 5 seconds...
[11:43:50.416] INFO: Done with hot pixel readout
[11:44:02.336] INFO: PixTest:: pg_setup set to default.
[11:44:02.336] INFO: 2 hot pixels found in step 8
[11:44:03.330] INFO: Collecting data for 5 seconds...
[11:44:08.348] INFO: Done with hot pixel readout
[11:44:20.058] INFO: PixTest:: pg_setup set to default.
[11:44:20.059] INFO: 5 hot pixels found in step 9
[11:44:21.052] INFO: Collecting data for 5 seconds...
[11:44:26.068] INFO: Done with hot pixel readout
[11:44:37.770] INFO: PixTest:: pg_setup set to default.
[11:44:37.771] INFO: 1 hot pixels found in step 10
[11:44:38.765] INFO: Collecting data for 5 seconds...
[11:44:43.782] INFO: Done with hot pixel readout
[11:44:55.424] INFO: PixTest:: pg_setup set to default.
[11:44:55.425] INFO: 1 hot pixels found in step 11
[11:44:56.417] INFO: Collecting data for 5 seconds...
[11:45:01.433] INFO: Done with hot pixel readout
[11:45:13.096] INFO: PixTest:: pg_setup set to default.
[11:45:13.097] INFO: 1 hot pixels found in step 12
[11:45:14.090] INFO: Collecting data for 5 seconds...
[11:45:19.106] INFO: Done with hot pixel readout
[11:45:30.810] INFO: PixTest:: pg_setup set to default.
[11:45:30.810] INFO: 1 hot pixels found in step 13
[11:45:31.802] INFO: Collecting data for 5 seconds...
[11:45:36.820] INFO: Done with hot pixel readout
[11:45:48.450] INFO: PixTest:: pg_setup set to default.
[11:45:48.451] INFO: 3 hot pixels found in step 14
[11:45:48.488] INFO: 3 hot pixels could not be trimmed and have been masked.
[11:45:48.491] INFO: PixTest::trimHotPixels() done
[11:45:48.510] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C0.dat
[11:45:48.520] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C1.dat
[11:45:48.525] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C2.dat
[11:45:48.531] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C3.dat
[11:45:48.536] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C4.dat
[11:45:48.542] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C5.dat
[11:45:48.547] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C6.dat
[11:45:48.553] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C7.dat
[11:45:48.558] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C8.dat
[11:45:48.564] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C9.dat
[11:45:48.569] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C10.dat
[11:45:48.575] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C11.dat
[11:45:48.580] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C12.dat
[11:45:48.585] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C13.dat
[11:45:48.591] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C14.dat
[11:45:48.596] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C15.dat
[11:45:48.602] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//defaultMaskFile.dat
[11:45:48.616] INFO: enter test to run
[11:46:20.474] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:46:20.474] INFO: running: highrate
[11:46:20.479] INFO: ----------------------------------------------------------------------
[11:46:20.479] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:46:20.479] INFO: ----------------------------------------------------------------------
[11:46:20.479] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:46:20.479] INFO: edge/corner pixel THR is adjusted
[11:46:20.479] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:46:21.436] INFO: Collecting data for 1 seconds...
[11:46:22.440] INFO: Done with hot pixel readout
[11:46:26.435] INFO: PixTest:: pg_setup set to default.
[11:46:26.436] INFO: 0 hot pixels found in step 0
[11:46:26.441] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:46:26.533] INFO: PixTest::trimHotPixels() done
[11:46:26.534] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C0.dat
[11:46:26.545] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C1.dat
[11:46:26.551] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C2.dat
[11:46:26.557] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C3.dat
[11:46:26.562] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C4.dat
[11:46:26.568] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C5.dat
[11:46:26.573] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C6.dat
[11:46:26.578] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C7.dat
[11:46:26.583] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C8.dat
[11:46:26.589] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C9.dat
[11:46:26.594] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C10.dat
[11:46:26.599] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C11.dat
[11:46:26.605] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C12.dat
[11:46:26.610] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C13.dat
[11:46:26.615] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C14.dat
[11:46:26.620] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//trimParameters35_C15.dat
[11:46:26.626] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-6-50_FPIXTest-17C-FNAL-160913-1217-150V_2016-09-13_12h17m_1473787067/000_FPIXTest_p17//defaultMaskFile.dat
[11:46:26.636] INFO: enter test to run
[11:46:58.162] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:46:58.162] INFO: running: xray
[11:46:58.163] INFO: ----------------------------------------------------------------------
[11:46:58.163] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:46:58.163] INFO: ----------------------------------------------------------------------
[11:46:59.145] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:47:10.731] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:47:40.248] INFO: Resuming triggers.
[11:47:51.833] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[11:48:21.229] INFO: Resuming triggers.
[11:48:32.818] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:49:02.247] INFO: Resuming triggers.
[11:49:13.836] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:49:43.163] INFO: Resuming triggers.
[11:49:54.749] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[11:50:22.865] INFO: Resuming triggers.
[11:50:34.451] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[11:51:03.561] INFO: Resuming triggers.
[11:51:15.146] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:51:40.879] INFO: Resuming triggers.
[11:51:52.464] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[11:52:17.298] INFO: Resuming triggers.
[11:52:24.931] INFO: data taking finished, elapsed time: 100 seconds.
[11:52:41.679] INFO: PixTest:: pg_setup set to default.
[11:52:41.682] INFO: PixTestXray::doPhRun() done
[11:52:42.188] INFO: enter test to run
[11:54:49.964] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:54:49.964] INFO: running: xray
[11:54:49.965] INFO: ----------------------------------------------------------------------
[11:54:49.965] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:54:49.965] INFO: ----------------------------------------------------------------------
[11:54:50.930] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:54:57.735] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:55:28.501] INFO: Resuming triggers.
[11:55:35.305] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[11:56:06.153] INFO: Resuming triggers.
[11:56:12.956] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[11:56:43.392] INFO: Resuming triggers.
[11:56:50.199] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[11:57:20.838] INFO: Resuming triggers.
[11:57:27.643] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[11:57:58.649] INFO: Resuming triggers.
[11:58:05.453] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[11:58:37.035] INFO: Resuming triggers.
[11:58:43.839] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[11:59:15.262] INFO: Resuming triggers.
[11:59:22.067] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[11:59:53.092] INFO: Resuming triggers.
[11:59:59.901] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[12:00:30.986] INFO: Resuming triggers.
[12:00:37.798] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[12:01:09.161] INFO: Resuming triggers.
[12:01:15.969] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[12:01:46.308] INFO: Resuming triggers.
[12:01:53.118] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[12:02:23.286] INFO: Resuming triggers.
[12:02:30.095] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[12:03:00.421] INFO: Resuming triggers.
[12:03:07.235] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[12:03:37.674] INFO: Resuming triggers.
[12:03:42.724] INFO: data taking finished, elapsed time: 100 seconds.
[12:04:03.923] INFO: PixTest:: pg_setup set to default.
[12:04:03.926] INFO: PixTestXray::doPhRun() done
[12:04:04.112] INFO: enter test to run
[12:05:29.282] INFO: test: HighRate no parameter change
[12:05:29.282] INFO: running: highrate
[12:05:29.322] INFO: ----------------------------------------------------------------------
[12:05:29.322] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:05:29.322] INFO: ----------------------------------------------------------------------
[12:05:29.480] INFO: Expecting 768 events.
[12:05:30.623] INFO: 768 events read in total (419ms).
[12:05:30.623] INFO: Test took 1277ms.
[12:05:31.426] INFO: Expecting 41600 events.
[12:05:34.460] INFO: 41600 events read in total (2507ms).
[12:05:34.461] INFO: Test took 3761ms.
[12:05:34.493] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:35.220] INFO: Expecting 41600 events.
[12:05:38.119] INFO: 41600 events read in total (2372ms).
[12:05:38.120] INFO: Test took 3548ms.
[12:05:38.155] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:38.880] INFO: Expecting 41600 events.
[12:05:42.055] INFO: 41600 events read in total (2648ms).
[12:05:42.055] INFO: Test took 3882ms.
[12:05:42.089] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:42.815] INFO: Expecting 41600 events.
[12:05:45.818] INFO: 41600 events read in total (2476ms).
[12:05:45.819] INFO: Test took 3713ms.
[12:05:45.854] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:46.578] INFO: Expecting 41600 events.
[12:05:49.787] INFO: 41600 events read in total (2682ms).
[12:05:49.789] INFO: Test took 3917ms.
[12:05:49.829] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:50.545] INFO: Expecting 41600 events.
[12:05:53.750] INFO: 41600 events read in total (2679ms).
[12:05:53.751] INFO: Test took 3904ms.
[12:05:53.785] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:54.512] INFO: Expecting 41600 events.
[12:05:57.682] INFO: 41600 events read in total (2643ms).
[12:05:57.683] INFO: Test took 3880ms.
[12:05:57.716] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:58.441] INFO: Expecting 41600 events.
[12:06:01.664] INFO: 41600 events read in total (2697ms).
[12:06:01.665] INFO: Test took 3930ms.
[12:06:01.699] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:02.423] INFO: Expecting 41600 events.
[12:06:05.603] INFO: 41600 events read in total (2653ms).
[12:06:05.604] INFO: Test took 3887ms.
[12:06:05.637] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:06.363] INFO: Expecting 41600 events.
[12:06:09.566] INFO: 41600 events read in total (2677ms).
[12:06:09.567] INFO: Test took 3911ms.
[12:06:09.600] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:10.328] INFO: Expecting 41600 events.
[12:06:13.535] INFO: 41600 events read in total (2680ms).
[12:06:13.536] INFO: Test took 3918ms.
[12:06:13.569] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:14.293] INFO: Expecting 41600 events.
[12:06:17.518] INFO: 41600 events read in total (2698ms).
[12:06:17.519] INFO: Test took 3931ms.
[12:06:17.552] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:18.275] INFO: Expecting 41600 events.
[12:06:21.491] INFO: 41600 events read in total (2689ms).
[12:06:21.492] INFO: Test took 3923ms.
[12:06:21.525] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:22.250] INFO: Expecting 41600 events.
[12:06:25.462] INFO: 41600 events read in total (2685ms).
[12:06:25.463] INFO: Test took 3921ms.
[12:06:25.496] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:26.220] INFO: Expecting 41600 events.
[12:06:29.434] INFO: 41600 events read in total (2687ms).
[12:06:29.435] INFO: Test took 3921ms.
[12:06:29.469] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:30.193] INFO: Expecting 41600 events.
[12:06:33.420] INFO: 41600 events read in total (2701ms).
[12:06:33.421] INFO: Test took 3934ms.
[12:06:33.455] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:34.181] INFO: Expecting 41600 events.
[12:06:37.401] INFO: 41600 events read in total (2693ms).
[12:06:37.402] INFO: Test took 3929ms.
[12:06:37.435] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:38.158] INFO: Expecting 41600 events.
[12:06:41.397] INFO: 41600 events read in total (2712ms).
[12:06:41.398] INFO: Test took 3944ms.
[12:06:41.431] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:42.155] INFO: Expecting 41600 events.
[12:06:45.372] INFO: 41600 events read in total (2690ms).
[12:06:45.373] INFO: Test took 3925ms.
[12:06:45.406] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:46.131] INFO: Expecting 41600 events.
[12:06:49.211] INFO: 41600 events read in total (2553ms).
[12:06:49.212] INFO: Test took 3788ms.
[12:06:49.245] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:06:49.616] INFO: enter test to run
[12:07:05.681] INFO: test: HighRate no parameter change
[12:07:05.681] INFO: running: highrate
[12:07:05.682] INFO: ----------------------------------------------------------------------
[12:07:05.682] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:07:05.682] INFO: ----------------------------------------------------------------------
[12:07:06.318] INFO: Expecting 208000 events.
[12:07:18.074] INFO: 208000 events read in total (11229ms).
[12:07:18.077] INFO: Test took 12371ms.
[12:07:18.218] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:07:18.468] INFO: number of dead pixels (per ROC): 0 0 0 0 6 0 0 1 0 0 0 0 0 0 0 0
[12:07:18.487] INFO: number of red-efficiency pixels: 71 48 83 145 151 136 148 121 82 134 140 73 84 68 34 23
[12:07:18.487] INFO: number of X-ray hits detected: 65068 41551 63734 98539 104367 107941 106054 80874 79206 98783 97269 79691 83033 51510 21217 28824
[12:07:18.487] 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:07:18.487] INFO: number of Vcal hits detected: 207929 207950 207915 207853 207549 207860 207848 207828 207916 207865 207856 207925 207913 207931 207966 207977
[12:07:18.487] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[12:07:18.487] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.8 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[12:07:18.487] INFO: X-ray hit rate [MHz/cm2]: 19.1 12.2 18.7 28.9 30.6 31.6 31.1 23.7 23.2 29.0 28.5 23.4 24.3 15.1 6.2 8.4
[12:07:18.487] INFO: PixTestHighRate::doXPixelAlive() done
[12:07:18.536] INFO: PixTest:: pg_setup set to default.
[12:07:18.553] INFO: enter test to run
[12:07:47.609] INFO: test: HighRate no parameter change
[12:07:47.609] INFO: running: highrate
[12:07:47.610] INFO: ----------------------------------------------------------------------
[12:07:47.610] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:07:47.610] INFO: ----------------------------------------------------------------------
[12:07:48.250] INFO: Expecting 208000 events.
[12:08:01.736] INFO: 208000 events read in total (12959ms).
[12:08:01.741] INFO: Test took 14120ms.
[12:08:02.033] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:08:02.336] INFO: number of dead pixels (per ROC): 0 0 0 0 5 0 0 1 0 0 0 0 0 0 0 0
[12:08:02.336] INFO: number of red-efficiency pixels: 224 150 310 329 464 496 491 341 272 473 402 283 257 223 57 62
[12:08:02.336] INFO: number of X-ray hits detected: 136358 87260 134290 204638 217999 225037 221743 168414 164919 206914 202653 167111 173478 107653 44066 59528
[12:08:02.336] 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:08:02.336] INFO: number of Vcal hits detected: 207762 207849 207658 207658 207200 207448 207463 207573 207715 207492 207569 207704 207734 207764 207943 207936
[12:08:02.336] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[12:08:02.336] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.6 99.7 99.7 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[12:08:02.336] INFO: X-ray hit rate [MHz/cm2]: 40.0 25.6 39.4 60.0 63.9 66.0 65.0 49.4 48.3 60.6 59.4 49.0 50.8 31.6 12.9 17.4
[12:08:02.336] INFO: PixTestHighRate::doXPixelAlive() done
[12:08:02.381] INFO: PixTest:: pg_setup set to default.
[12:08:02.395] INFO: enter test to run
[12:08:24.641] INFO: test: HighRate no parameter change
[12:08:24.641] INFO: running: highrate
[12:08:24.642] INFO: ----------------------------------------------------------------------
[12:08:24.642] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:08:24.642] INFO: ----------------------------------------------------------------------
[12:08:25.262] INFO: Expecting 208000 events.
[12:08:40.626] INFO: 208000 events read in total (14837ms).
[12:08:40.633] INFO: Test took 15982ms.
[12:08:41.091] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:08:41.440] INFO: number of dead pixels (per ROC): 0 0 0 0 6 0 0 1 0 0 0 0 0 0 0 0
[12:08:41.440] INFO: number of red-efficiency pixels: 472 304 636 783 1193 1246 1187 788 610 1101 999 524 538 484 94 113
[12:08:41.440] INFO: number of X-ray hits detected: 207395 131679 203269 309803 328223 340200 336382 255532 250523 312356 306321 252324 263213 163573 67759 90647
[12:08:41.440] 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:08:41.440] INFO: number of Vcal hits detected: 207459 207660 207158 207088 206186 206382 206474 206954 207308 206615 206798 207418 207406 207429 207906 207883
[12:08:41.440] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.6 99.3 99.3 99.3 99.6 99.7 99.4 99.5 99.7 99.7 99.7 100.0 99.9
[12:08:41.440] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.6 99.6 99.1 99.2 99.3 99.5 99.7 99.3 99.4 99.7 99.7 99.7 100.0 99.9
[12:08:41.440] INFO: X-ray hit rate [MHz/cm2]: 60.8 38.6 59.6 90.8 96.2 99.7 98.6 74.9 73.4 91.6 89.8 74.0 77.1 47.9 19.9 26.6
[12:08:41.440] INFO: PixTestHighRate::doXPixelAlive() done
[12:08:41.487] INFO: PixTest:: pg_setup set to default.
[12:08:41.507] INFO: enter test to run
[12:09:18.856] INFO: test: exit no parameter change
[12:09:20.010] QUIET: Connection to board 33 closed.
[12:09:20.312] INFO: pXar: this is the end, my friend