[10:13:09.505] INFO: *** Welcome to pxar ***
[10:13:09.505] INFO: *** Today: 2016/11/11
[10:13:10.700] INFO: *** Version: v1.9.0-818-g96727
[10:13:10.700] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//dacParameters35_C15.dat
[10:13:10.766] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:13:10.766] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//defaultMaskFile.dat
[10:13:10.770] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C15.dat
[10:13:10.901] INFO: clk: 4
[10:13:10.901] INFO: ctr: 4
[10:13:10.901] INFO: sda: 19
[10:13:10.901] INFO: tin: 9
[10:13:10.901] INFO: level: 15
[10:13:10.901] INFO: triggerdelay: 0
[10:13:10.901] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[10:13:10.901] INFO: Log level: INFO
[10:13:10.919] QUIET: Connection to board DTB_WREHUL opened.
[10:13:10.922] 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:
------------------------------------------------------
[10:13:10.925] INFO: RPC call hashes of host and DTB match: 398089610
[10:13:12.456] INFO: DUT info:
[10:13:12.456] INFO: The DUT currently contains the following objects:
[10:13:12.456] INFO: 2 TBM Cores tbm08c (2 ON)
[10:13:12.456] INFO: TBM Core alpha (0): 7 registers set
[10:13:12.456] INFO: TBM Core beta (1): 7 registers set
[10:13:12.456] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[10:13:12.456] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.456] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[10:13:12.888] INFO: enter 'restricted' command line mode
[10:13:12.888] INFO: enter test to run
[10:13:18.208] INFO: test: PixelAlive no parameter change
[10:13:18.208] INFO: running: pixelalive
[10:13:18.274] INFO: ----------------------------------------------------------------------
[10:13:18.274] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[10:13:18.274] INFO: ----------------------------------------------------------------------
[10:13:18.594] INFO: Expecting 41600 events.
[10:13:22.934] INFO: 41600 events read in total (3621ms).
[10:13:23.101] INFO: Test took 4823ms.
[10:13:23.115] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:13:23.938] INFO: PixTestAlive::aliveTest() done
[10:13:23.938] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 1 0 0 0 1 0 0 0 9 0
[10:13:24.114] INFO: enter test to run
[10:13:31.408] INFO: test: timing no parameter change
[10:13:31.408] INFO: running: timing
[10:13:31.412] INFO: ######################################################################
[10:13:31.412] INFO: PixTestTiming::doTest()
[10:13:31.412] INFO: ######################################################################
[10:13:31.412] INFO: ----------------------------------------------------------------------
[10:13:31.412] INFO: PixTestTiming::TBMPhaseScan()
[10:13:31.412] INFO: ----------------------------------------------------------------------
[10:20:31.279] INFO: TBM Phase Settings: 220
[10:20:31.279] INFO: 400MHz Phase: 7
[10:20:31.279] INFO: 160MHz Phase: 6
[10:20:31.279] INFO: Functional Phase Area: 1
[10:20:31.295] INFO: Test took 419883 ms.
[10:20:31.295] INFO: PixTestTiming::TBMPhaseScan() done.
[10:20:31.295] INFO: ----------------------------------------------------------------------
[10:20:31.295] INFO: PixTestTiming::ROCDelayScan()
[10:20:31.295] INFO: ----------------------------------------------------------------------
[10:23:04.083] INFO: ROC Delay Settings: 219
[10:23:04.083] INFO: ROC Header-Trailer/Token Delay: 11
[10:23:04.083] INFO: ROC Port 0 Delay: 3
[10:23:04.083] INFO: ROC Port 1 Delay: 3
[10:23:04.083] INFO: Functional ROC Area: 2
[10:23:04.086] INFO: Test took 152791 ms.
[10:23:04.086] INFO: PixTestTiming::ROCDelayScan() done.
[10:23:04.087] INFO: ----------------------------------------------------------------------
[10:23:04.087] INFO: PixTestTiming::TimingTest()
[10:23:04.087] INFO: ----------------------------------------------------------------------
[10:23:20.301] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:23:35.607] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:23:50.865] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:06.208] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:21.388] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:36.451] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:51.593] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:06.695] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:21.833] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:37.184] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:37.562] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:37.581] INFO: ----------------------------------------------------------------------
[10:25:37.581] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[10:25:37.581] INFO: ----------------------------------------------------------------------
[10:25:37.581] INFO: ----------------------------------------------------------------------
[10:25:37.581] INFO: Read back bit status: 1
[10:25:37.581] INFO: ----------------------------------------------------------------------
[10:25:37.581] INFO: ----------------------------------------------------------------------
[10:25:37.581] INFO: Timings are good!
[10:25:37.581] INFO: ----------------------------------------------------------------------
[10:25:37.581] INFO: Test took 153495 ms.
[10:25:37.581] INFO: PixTestTiming::TimingTest() done.
[10:25:37.599] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0a.dat
[10:25:37.599] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:25:37.599] INFO: PixTestTiming::doTest took 726191 ms.
[10:25:37.599] INFO: PixTestTiming::doTest() done
[10:25:37.600] INFO: Write out TBMPhaseScan_0_V0
[10:25:37.600] INFO: Write out TBMPhaseScan_1_V0
[10:25:37.600] INFO: Write out CombinedTBMPhaseScan_V0
[10:25:37.625] INFO: Write out ROCDelayScan3_V0
[10:25:37.626] INFO: enter test to run
[10:26:25.171] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:26:25.171] INFO: running: highrate
[10:26:25.242] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:26:25.558] INFO: ----------------------------------------------------------------------
[10:26:25.558] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:26:25.558] INFO: ----------------------------------------------------------------------
[10:26:25.558] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:26:25.558] INFO: edge/corner pixel THR is adjusted
[10:26:25.558] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:26:26.516] INFO: Collecting data for 5 seconds...
[10:26:31.535] INFO: Done with hot pixel readout
[10:26:43.548] INFO: PixTest:: pg_setup set to default.
[10:26:43.548] INFO: 7 hot pixels found in step 0
[10:26:44.543] INFO: Collecting data for 5 seconds...
[10:26:49.561] INFO: Done with hot pixel readout
[10:27:01.568] INFO: PixTest:: pg_setup set to default.
[10:27:01.569] INFO: 7 hot pixels found in step 1
[10:27:02.565] INFO: Collecting data for 5 seconds...
[10:27:07.582] INFO: Done with hot pixel readout
[10:27:19.547] INFO: PixTest:: pg_setup set to default.
[10:27:19.548] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[10:27:19.548] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[10:27:19.548] INFO: 6 hot pixels found in step 2
[10:27:20.545] INFO: Collecting data for 5 seconds...
[10:27:25.562] INFO: Done with hot pixel readout
[10:27:37.530] INFO: PixTest:: pg_setup set to default.
[10:27:37.531] INFO: 8 hot pixels found in step 3
[10:27:38.530] INFO: Collecting data for 5 seconds...
[10:27:43.547] INFO: Done with hot pixel readout
[10:27:55.536] INFO: PixTest:: pg_setup set to default.
[10:27:55.536] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[10:27:55.537] INFO: 4 hot pixels found in step 4
[10:27:56.532] INFO: Collecting data for 5 seconds...
[10:28:01.550] INFO: Done with hot pixel readout
[10:28:13.557] INFO: PixTest:: pg_setup set to default.
[10:28:13.558] INFO: 17 hot pixels found in step 5
[10:28:14.554] INFO: Collecting data for 5 seconds...
[10:28:19.571] INFO: Done with hot pixel readout
[10:28:31.617] INFO: PixTest:: pg_setup set to default.
[10:28:31.618] INFO: 8 hot pixels found in step 6
[10:28:32.614] INFO: Collecting data for 5 seconds...
[10:28:37.631] INFO: Done with hot pixel readout
[10:28:49.645] INFO: PixTest:: pg_setup set to default.
[10:28:49.646] INFO: 7 hot pixels found in step 7
[10:28:50.643] INFO: Collecting data for 5 seconds...
[10:28:55.660] INFO: Done with hot pixel readout
[10:29:07.672] INFO: PixTest:: pg_setup set to default.
[10:29:07.673] INFO: 13 hot pixels found in step 8
[10:29:08.668] INFO: Collecting data for 5 seconds...
[10:29:13.686] INFO: Done with hot pixel readout
[10:29:25.665] INFO: PixTest:: pg_setup set to default.
[10:29:25.666] INFO: 11 hot pixels found in step 9
[10:29:26.664] INFO: Collecting data for 5 seconds...
[10:29:31.681] INFO: Done with hot pixel readout
[10:29:43.692] INFO: PixTest:: pg_setup set to default.
[10:29:43.693] INFO: 10 hot pixels found in step 10
[10:29:44.690] INFO: Collecting data for 5 seconds...
[10:29:49.707] INFO: Done with hot pixel readout
[10:30:01.617] INFO: PixTest:: pg_setup set to default.
[10:30:01.618] INFO: 5 hot pixels found in step 11
[10:30:02.614] INFO: Collecting data for 5 seconds...
[10:30:07.631] INFO: Done with hot pixel readout
[10:30:19.631] INFO: PixTest:: pg_setup set to default.
[10:30:19.632] INFO: 6 hot pixels found in step 12
[10:30:20.629] INFO: Collecting data for 5 seconds...
[10:30:25.646] INFO: Done with hot pixel readout
[10:30:37.639] INFO: PixTest:: pg_setup set to default.
[10:30:37.640] INFO: 7 hot pixels found in step 13
[10:30:38.635] INFO: Collecting data for 5 seconds...
[10:30:43.653] INFO: Done with hot pixel readout
[10:30:55.666] INFO: PixTest:: pg_setup set to default.
[10:30:55.667] INFO: 8 hot pixels found in step 14
[10:30:55.707] INFO: 8 hot pixels could not be trimmed and have been masked.
[10:30:55.710] INFO: PixTest::trimHotPixels() done
[10:30:55.711] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C0.dat
[10:30:55.716] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C1.dat
[10:30:55.722] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C2.dat
[10:30:55.729] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C3.dat
[10:30:55.734] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C4.dat
[10:30:55.740] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C5.dat
[10:30:55.745] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C6.dat
[10:30:55.751] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C7.dat
[10:30:55.756] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C8.dat
[10:30:55.762] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C9.dat
[10:30:55.767] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C10.dat
[10:30:55.772] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C11.dat
[10:30:55.778] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C12.dat
[10:30:55.783] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C13.dat
[10:30:55.789] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C14.dat
[10:30:55.794] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C15.dat
[10:30:55.829] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//defaultMaskFile.dat
[10:30:55.845] INFO: enter test to run
[10:31:34.505] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:31:34.505] INFO: running: highrate
[10:31:34.509] INFO: ----------------------------------------------------------------------
[10:31:34.510] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:31:34.510] INFO: ----------------------------------------------------------------------
[10:31:34.510] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:31:34.510] INFO: edge/corner pixel THR is adjusted
[10:31:34.510] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:31:35.468] INFO: Collecting data for 1 seconds...
[10:31:36.472] INFO: Done with hot pixel readout
[10:31:40.665] INFO: PixTest:: pg_setup set to default.
[10:31:40.666] INFO: 0 hot pixels found in step 0
[10:31:40.671] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:31:40.758] INFO: PixTest::trimHotPixels() done
[10:31:40.758] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C0.dat
[10:31:40.787] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C1.dat
[10:31:40.793] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C2.dat
[10:31:40.798] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C3.dat
[10:31:40.804] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C4.dat
[10:31:40.810] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C5.dat
[10:31:40.815] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C6.dat
[10:31:40.821] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C7.dat
[10:31:40.826] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C8.dat
[10:31:40.832] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C9.dat
[10:31:40.837] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C10.dat
[10:31:40.843] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C11.dat
[10:31:40.848] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C12.dat
[10:31:40.854] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C13.dat
[10:31:40.859] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C14.dat
[10:31:40.865] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//trimParameters35_C15.dat
[10:31:40.871] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-05_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629555/000_FPIXTest_p17//defaultMaskFile.dat
[10:31:40.887] INFO: enter test to run
[10:32:17.449] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:32:17.449] INFO: running: xray
[10:32:17.450] INFO: ----------------------------------------------------------------------
[10:32:17.450] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:32:17.450] INFO: ----------------------------------------------------------------------
[10:32:18.431] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:32:29.644] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[10:32:59.041] INFO: Resuming triggers.
[10:33:10.256] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[10:33:40.336] INFO: Resuming triggers.
[10:33:51.559] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[10:34:21.586] INFO: Resuming triggers.
[10:34:32.805] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[10:35:02.903] INFO: Resuming triggers.
[10:35:14.120] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[10:35:44.029] INFO: Resuming triggers.
[10:35:55.251] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[10:36:25.090] INFO: Resuming triggers.
[10:36:36.305] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[10:37:06.609] INFO: Resuming triggers.
[10:37:17.827] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[10:37:48.133] INFO: Resuming triggers.
[10:37:58.769] INFO: data taking finished, elapsed time: 100 seconds.
[10:38:27.777] INFO: PixTest:: pg_setup set to default.
[10:38:27.780] INFO: PixTestXray::doPhRun() done
[10:38:28.197] INFO: enter test to run
[10:40:18.645] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[10:40:18.645] INFO: running: xray
[10:40:18.646] INFO: ----------------------------------------------------------------------
[10:40:18.646] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:40:18.646] INFO: ----------------------------------------------------------------------
[10:40:19.611] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:40:25.980] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[10:40:55.944] INFO: Resuming triggers.
[10:41:02.314] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[10:41:32.359] INFO: Resuming triggers.
[10:41:38.732] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[10:42:08.672] INFO: Resuming triggers.
[10:42:15.042] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[10:42:45.145] INFO: Resuming triggers.
[10:42:51.517] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[10:43:21.489] INFO: Resuming triggers.
[10:43:27.861] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[10:43:57.815] INFO: Resuming triggers.
[10:44:04.190] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[10:44:34.332] INFO: Resuming triggers.
[10:44:40.704] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[10:45:10.520] INFO: Resuming triggers.
[10:45:16.897] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[10:45:46.972] INFO: Resuming triggers.
[10:45:53.347] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[10:46:23.323] INFO: Resuming triggers.
[10:46:29.701] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[10:47:00.282] INFO: Resuming triggers.
[10:47:06.655] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[10:47:37.271] INFO: Resuming triggers.
[10:47:43.643] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[10:48:14.807] INFO: Resuming triggers.
[10:48:21.178] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[10:48:52.029] INFO: Resuming triggers.
[10:48:58.402] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[10:49:29.395] INFO: Resuming triggers.
[10:49:34.172] INFO: data taking finished, elapsed time: 100 seconds.
[10:49:57.284] INFO: PixTest:: pg_setup set to default.
[10:49:57.287] INFO: PixTestXray::doPhRun() done
[10:49:57.437] INFO: enter test to run
[10:51:09.881] INFO: test: HighRate no parameter change
[10:51:09.881] INFO: running: highrate
[10:51:09.896] INFO: ----------------------------------------------------------------------
[10:51:09.896] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[10:51:09.896] INFO: ----------------------------------------------------------------------
[10:51:10.061] INFO: Expecting 768 events.
[10:51:11.224] INFO: 768 events read in total (447ms).
[10:51:11.224] INFO: Test took 1297ms.
[10:51:12.027] INFO: Expecting 41600 events.
[10:51:15.168] INFO: 41600 events read in total (2614ms).
[10:51:15.169] INFO: Test took 3859ms.
[10:51:15.205] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:15.928] INFO: Expecting 41600 events.
[10:51:19.144] INFO: 41600 events read in total (2689ms).
[10:51:19.145] INFO: Test took 3907ms.
[10:51:19.182] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:19.904] INFO: Expecting 41600 events.
[10:51:23.198] INFO: 41600 events read in total (2768ms).
[10:51:23.199] INFO: Test took 3999ms.
[10:51:23.238] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:23.947] INFO: Expecting 41600 events.
[10:51:27.185] INFO: 41600 events read in total (2712ms).
[10:51:27.186] INFO: Test took 3929ms.
[10:51:27.223] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:27.944] INFO: Expecting 41600 events.
[10:51:31.251] INFO: 41600 events read in total (2780ms).
[10:51:31.252] INFO: Test took 4009ms.
[10:51:31.289] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:31.006] INFO: Expecting 41600 events.
[10:51:35.333] INFO: 41600 events read in total (2800ms).
[10:51:35.334] INFO: Test took 4026ms.
[10:51:35.371] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:36.091] INFO: Expecting 41600 events.
[10:51:39.405] INFO: 41600 events read in total (2787ms).
[10:51:39.406] INFO: Test took 4016ms.
[10:51:39.445] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:40.157] INFO: Expecting 41600 events.
[10:51:43.480] INFO: 41600 events read in total (2796ms).
[10:51:43.481] INFO: Test took 4013ms.
[10:51:43.519] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:44.234] INFO: Expecting 41600 events.
[10:51:47.569] INFO: 41600 events read in total (2808ms).
[10:51:47.570] INFO: Test took 4032ms.
[10:51:47.607] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:48.323] INFO: Expecting 41600 events.
[10:51:51.542] INFO: 41600 events read in total (2693ms).
[10:51:51.543] INFO: Test took 3917ms.
[10:51:51.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:52.298] INFO: Expecting 41600 events.
[10:51:55.600] INFO: 41600 events read in total (2776ms).
[10:51:55.601] INFO: Test took 4001ms.
[10:51:55.639] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:56.357] INFO: Expecting 41600 events.
[10:51:59.583] INFO: 41600 events read in total (2699ms).
[10:51:59.584] INFO: Test took 3927ms.
[10:51:59.621] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:00.341] INFO: Expecting 41600 events.
[10:52:03.677] INFO: 41600 events read in total (2809ms).
[10:52:03.678] INFO: Test took 4038ms.
[10:52:03.715] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:04.435] INFO: Expecting 41600 events.
[10:52:07.713] INFO: 41600 events read in total (2751ms).
[10:52:07.714] INFO: Test took 3979ms.
[10:52:07.755] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:08.462] INFO: Expecting 41600 events.
[10:52:11.688] INFO: 41600 events read in total (2699ms).
[10:52:11.689] INFO: Test took 3915ms.
[10:52:11.726] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:12.443] INFO: Expecting 41600 events.
[10:52:15.646] INFO: 41600 events read in total (2676ms).
[10:52:15.647] INFO: Test took 3902ms.
[10:52:15.685] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:16.405] INFO: Expecting 41600 events.
[10:52:19.582] INFO: 41600 events read in total (2650ms).
[10:52:19.583] INFO: Test took 3879ms.
[10:52:19.621] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:20.343] INFO: Expecting 41600 events.
[10:52:23.560] INFO: 41600 events read in total (2690ms).
[10:52:23.561] INFO: Test took 3919ms.
[10:52:23.598] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:24.318] INFO: Expecting 41600 events.
[10:52:27.551] INFO: 41600 events read in total (2706ms).
[10:52:27.552] INFO: Test took 3931ms.
[10:52:27.588] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:28.309] INFO: Expecting 41600 events.
[10:52:31.478] INFO: 41600 events read in total (2642ms).
[10:52:31.479] INFO: Test took 3872ms.
[10:52:31.516] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:34.567] INFO: enter test to run
[10:52:46.205] INFO: test: HighRate no parameter change
[10:52:46.205] INFO: running: highrate
[10:52:46.516] INFO: ----------------------------------------------------------------------
[10:52:46.517] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:52:46.517] INFO: ----------------------------------------------------------------------
[10:52:47.413] INFO: Expecting 208000 events.
[10:52:59.646] INFO: 208000 events read in total (11706ms).
[10:52:59.649] INFO: Test took 12844ms.
[10:52:59.802] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:53:00.087] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 1 0 0 0 1 0 0 0 9 0
[10:53:00.446] INFO: number of red-efficiency pixels: 71 48 76 126 128 160 156 100 103 149 146 125 128 63 37 18
[10:53:00.446] INFO: number of X-ray hits detected: 65996 42909 65645 109202 114324 125431 125417 82969 85408 118499 116039 93649 100196 57774 22102 25089
[10:53:00.446] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:53:00.446] INFO: number of Vcal hits detected: 207831 207951 207921 207873 207868 207833 207788 207896 207897 207850 207804 207873 207872 207936 207522 207982
[10:53:00.446] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[10:53:00.446] INFO: Vcal hit overall efficiency (%): 99.9 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 99.8 100.0
[10:53:00.446] INFO: X-ray hit rate [MHz/cm2]: 19.3 12.6 19.2 32.0 33.5 36.8 36.8 24.3 25.0 34.7 34.0 27.4 29.4 16.9 6.5 7.4
[10:53:00.446] INFO: PixTestHighRate::doXPixelAlive() done
[10:53:00.499] INFO: PixTest:: pg_setup set to default.
[10:53:00.511] INFO: enter test to run
[10:53:47.784] INFO: test: HighRate no parameter change
[10:53:47.784] INFO: running: highrate
[10:53:47.785] INFO: ----------------------------------------------------------------------
[10:53:47.785] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:53:47.785] INFO: ----------------------------------------------------------------------
[10:53:48.408] INFO: Expecting 208000 events.
[10:54:02.852] INFO: 208000 events read in total (13917ms).
[10:54:02.858] INFO: Test took 15063ms.
[10:54:03.184] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:54:03.496] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 1 0 0 0 1 0 0 0 8 0
[10:54:03.496] INFO: number of red-efficiency pixels: 172 127 258 361 404 583 489 337 271 477 414 401 444 199 62 64
[10:54:03.496] INFO: number of X-ray hits detected: 135241 88384 136473 224019 235077 259320 258714 171428 176311 245465 239204 192464 205773 119436 45946 51583
[10:54:03.496] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:54:03.496] INFO: number of Vcal hits detected: 207719 207865 207705 207613 207565 207351 207398 207626 207715 207484 207496 207567 207528 207785 207497 207935
[10:54:03.496] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.7 99.8 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[10:54:03.496] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.7 99.7 99.8 99.9 99.8 99.8 99.8 99.8 99.9 99.8 100.0
[10:54:03.496] INFO: X-ray hit rate [MHz/cm2]: 39.6 25.9 40.0 65.7 68.9 76.0 75.8 50.2 51.7 71.9 70.1 56.4 60.3 35.0 13.5 15.1
[10:54:03.496] INFO: PixTestHighRate::doXPixelAlive() done
[10:54:03.544] INFO: PixTest:: pg_setup set to default.
[10:54:03.568] INFO: enter test to run
[10:54:27.703] INFO: test: HighRate no parameter change
[10:54:27.703] INFO: running: highrate
[10:54:27.705] INFO: ----------------------------------------------------------------------
[10:54:27.705] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:54:27.705] INFO: ----------------------------------------------------------------------
[10:54:28.329] INFO: Expecting 208000 events.
[10:54:44.786] INFO: 208000 events read in total (15930ms).
[10:54:44.794] INFO: Test took 17078ms.
[10:54:45.290] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:54:45.654] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 1 0 0 0 1 0 0 0 9 0
[10:54:45.654] INFO: number of red-efficiency pixels: 392 257 588 848 944 1397 1113 801 677 1020 958 903 946 389 84 113
[10:54:45.654] INFO: number of X-ray hits detected: 204470 133925 205971 338642 354546 390269 391911 258607 265144 369384 360389 291893 311095 180852 69510 78391
[10:54:45.654] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:54:45.654] INFO: number of Vcal hits detected: 207463 207722 207253 207007 206836 206066 206506 206915 207166 206757 206783 206879 206869 207559 207472 207886
[10:54:45.654] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.6 99.5 99.2 99.4 99.5 99.7 99.5 99.5 99.5 99.5 99.8 100.0 99.9
[10:54:45.654] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.6 99.5 99.4 99.1 99.3 99.5 99.6 99.4 99.4 99.5 99.5 99.8 99.7 99.9
[10:54:45.654] INFO: X-ray hit rate [MHz/cm2]: 59.9 39.3 60.4 99.3 103.9 114.4 114.9 75.8 77.7 108.3 105.6 85.6 91.2 53.0 20.4 23.0
[10:54:45.654] INFO: PixTestHighRate::doXPixelAlive() done
[10:54:45.699] INFO: PixTest:: pg_setup set to default.
[10:54:45.715] INFO: enter test to run
[10:55:19.863] INFO: test: exit no parameter change
[10:55:20.624] QUIET: Connection to board 30 closed.
[10:55:20.731] INFO: pXar: this is the end, my friend