[07:55:14.015] INFO: *** Welcome to pxar ***
[07:55:14.015] INFO: *** Today: 2016/10/13
[07:55:14.580] INFO: *** Version: v1.9.0-818-g96727
[07:55:14.580] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//dacParameters35_C15.dat
[07:55:14.611] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//tbmParameters_C0b.dat
[07:55:14.626] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//defaultMaskFile.dat
[07:55:14.645] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C15.dat
[07:55:14.747] INFO: clk: 4
[07:55:14.747] INFO: ctr: 4
[07:55:14.747] INFO: sda: 19
[07:55:14.747] INFO: tin: 9
[07:55:14.747] INFO: level: 15
[07:55:14.747] INFO: triggerdelay: 0
[07:55:14.763] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[07:55:14.763] INFO: Log level: INFO
[07:55:14.788] QUIET: Connection to board DTB_WREKRL opened.
[07:55:14.791] 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:
------------------------------------------------------
[07:55:14.794] INFO: RPC call hashes of host and DTB match: 398089610
[07:55:16.328] INFO: DUT info:
[07:55:16.329] INFO: The DUT currently contains the following objects:
[07:55:16.329] INFO: 2 TBM Cores tbm08c (2 ON)
[07:55:16.329] INFO: TBM Core alpha (0): 7 registers set
[07:55:16.329] INFO: TBM Core beta (1): 7 registers set
[07:55:16.329] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[07:55:16.329] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.329] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[07:55:16.795] INFO: enter 'restricted' command line mode
[07:55:16.795] INFO: enter test to run
[07:55:23.132] INFO: test: PixelAlive no parameter change
[07:55:23.132] INFO: running: pixelalive
[07:55:23.159] INFO: ----------------------------------------------------------------------
[07:55:23.159] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[07:55:23.159] INFO: ----------------------------------------------------------------------
[07:55:23.475] INFO: Expecting 41600 events.
[07:55:27.808] INFO: 41600 events read in total (3614ms).
[07:55:27.976] INFO: Test took 4813ms.
[07:55:27.988] INFO: Fetched DAQ statistics. Counters are being reset now.
[07:55:28.555] INFO: PixTestAlive::aliveTest() done
[07:55:28.555] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[07:55:28.668] INFO: enter test to run
[07:55:30.683] INFO: test: timing no parameter change
[07:55:30.683] INFO: running: timing
[07:55:30.687] INFO: ######################################################################
[07:55:30.687] INFO: PixTestTiming::doTest()
[07:55:30.687] INFO: ######################################################################
[07:55:30.687] INFO: ----------------------------------------------------------------------
[07:55:30.687] INFO: PixTestTiming::TBMPhaseScan()
[07:55:30.687] INFO: ----------------------------------------------------------------------
[08:03:15.666] INFO: TBM Phase Settings: 232
[08:03:15.666] INFO: 400MHz Phase: 2
[08:03:15.666] INFO: 160MHz Phase: 7
[08:03:15.666] INFO: Functional Phase Area: 3
[08:03:15.677] INFO: Test took 464990 ms.
[08:03:15.677] INFO: PixTestTiming::TBMPhaseScan() done.
[08:03:15.677] INFO: ----------------------------------------------------------------------
[08:03:15.677] INFO: PixTestTiming::ROCDelayScan()
[08:03:15.677] INFO: ----------------------------------------------------------------------
[08:05:04.006] INFO: ROC Delay Settings: 227
[08:05:04.006] INFO: ROC Header-Trailer/Token Delay: 11
[08:05:04.006] INFO: ROC Port 0 Delay: 3
[08:05:04.007] INFO: ROC Port 1 Delay: 4
[08:05:04.007] INFO: Functional ROC Area: 3
[08:05:04.010] INFO: Test took 108333 ms.
[08:05:04.010] INFO: PixTestTiming::ROCDelayScan() done.
[08:05:04.010] INFO: ----------------------------------------------------------------------
[08:05:04.010] INFO: PixTestTiming::TimingTest()
[08:05:04.010] INFO: ----------------------------------------------------------------------
[08:05:20.380] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:05:35.452] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:05:50.515] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:06:05.623] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:06:20.671] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:06:35.768] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:06:50.884] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:07:06.007] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:07:21.139] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:07:36.244] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:07:36.621] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:07:36.639] INFO: ----------------------------------------------------------------------
[08:07:36.639] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[08:07:36.639] INFO: ----------------------------------------------------------------------
[08:07:36.639] INFO: ----------------------------------------------------------------------
[08:07:36.639] INFO: Read back bit status: 1
[08:07:36.639] INFO: ----------------------------------------------------------------------
[08:07:36.639] INFO: ----------------------------------------------------------------------
[08:07:36.639] INFO: Timings are good!
[08:07:36.639] INFO: ----------------------------------------------------------------------
[08:07:36.639] INFO: Test took 152629 ms.
[08:07:36.639] INFO: PixTestTiming::TimingTest() done.
[08:07:36.746] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//tbmParameters_C0a.dat
[08:07:36.746] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//tbmParameters_C0b.dat
[08:07:36.746] INFO: PixTestTiming::doTest took 726062 ms.
[08:07:36.746] INFO: PixTestTiming::doTest() done
[08:07:36.746] INFO: Write out TBMPhaseScan_0_V0
[08:07:36.746] INFO: Write out TBMPhaseScan_1_V0
[08:07:36.746] INFO: Write out CombinedTBMPhaseScan_V0
[08:07:36.918] INFO: Write out ROCDelayScan3_V0
[08:07:36.918] INFO: enter test to run
[08:08:10.670] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[08:08:10.670] INFO: running: highrate
[08:08:10.700] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[08:08:10.974] INFO: ----------------------------------------------------------------------
[08:08:10.974] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[08:08:10.974] INFO: ----------------------------------------------------------------------
[08:08:10.974] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[08:08:10.974] INFO: edge/corner pixel THR is adjusted
[08:08:10.974] INFO: PixTestHighRate::trimHotPixels: step 0...
[08:08:11.946] INFO: Collecting data for 5 seconds...
[08:08:16.964] INFO: Done with hot pixel readout
[08:08:28.682] INFO: PixTest:: pg_setup set to default.
[08:08:28.683] INFO: 8 hot pixels found in step 0
[08:08:29.676] INFO: Collecting data for 5 seconds...
[08:08:34.692] INFO: Done with hot pixel readout
[08:08:46.407] INFO: PixTest:: pg_setup set to default.
[08:08:46.408] INFO: 9 hot pixels found in step 1
[08:08:47.400] INFO: Collecting data for 5 seconds...
[08:08:52.417] INFO: Done with hot pixel readout
[08:09:04.098] INFO: PixTest:: pg_setup set to default.
[08:09:04.099] INFO: 5 hot pixels found in step 2
[08:09:05.092] INFO: Collecting data for 5 seconds...
[08:09:10.109] INFO: Done with hot pixel readout
[08:09:21.831] INFO: PixTest:: pg_setup set to default.


[08:09:21.832] INFO: 13 hot pixels found in step 3
[08:09:22.825] INFO: Collecting data for 5 seconds...
[08:09:27.841] INFO: Done with hot pixel readout
[08:09:39.556] INFO: PixTest:: pg_setup set to default.


[08:09:39.557] INFO: 13 hot pixels found in step 4
[08:09:40.549] INFO: Collecting data for 5 seconds...
[08:09:45.566] INFO: Done with hot pixel readout
[08:09:57.303] INFO: PixTest:: pg_setup set to default.
[08:09:57.304] INFO: 10 hot pixels found in step 5
[08:09:58.296] INFO: Collecting data for 5 seconds...
[08:10:03.313] INFO: Done with hot pixel readout
[08:10:14.969] INFO: PixTest:: pg_setup set to default.
[08:10:14.970] INFO: 6 hot pixels found in step 6
[08:10:15.963] INFO: Collecting data for 5 seconds...
[08:10:20.979] INFO: Done with hot pixel readout
[08:10:32.726] INFO: PixTest:: pg_setup set to default.
[08:10:32.727] INFO: 3 hot pixels found in step 7
[08:10:33.719] INFO: Collecting data for 5 seconds...
[08:10:38.736] INFO: Done with hot pixel readout
[08:10:50.473] INFO: PixTest:: pg_setup set to default.
[08:10:50.474] INFO: 7 hot pixels found in step 8
[08:10:51.466] INFO: Collecting data for 5 seconds...
[08:10:56.483] INFO: Done with hot pixel readout
[08:11:08.260] INFO: PixTest:: pg_setup set to default.
[08:11:08.261] INFO: 10 hot pixels found in step 9
[08:11:09.253] INFO: Collecting data for 5 seconds...
[08:11:14.270] INFO: Done with hot pixel readout
[08:11:26.021] INFO: PixTest:: pg_setup set to default.

[08:11:26.022] INFO: 12 hot pixels found in step 10
[08:11:27.015] INFO: Collecting data for 5 seconds...
[08:11:32.032] INFO: Done with hot pixel readout
[08:11:43.794] INFO: PixTest:: pg_setup set to default.
[08:11:43.795] INFO: 3 hot pixels found in step 11
[08:11:44.788] INFO: Collecting data for 5 seconds...
[08:11:49.805] INFO: Done with hot pixel readout
[08:12:01.533] INFO: PixTest:: pg_setup set to default.
[08:12:01.534] INFO: 7 hot pixels found in step 12
[08:12:02.527] INFO: Collecting data for 5 seconds...
[08:12:07.543] INFO: Done with hot pixel readout
[08:12:19.256] INFO: PixTest:: pg_setup set to default.
[08:12:19.257] INFO: 4 hot pixels found in step 13
[08:12:20.251] INFO: Collecting data for 5 seconds...
[08:12:25.267] INFO: Done with hot pixel readout
[08:12:36.951] INFO: PixTest:: pg_setup set to default.
[08:12:36.952] INFO: 5 hot pixels found in step 14
[08:12:36.988] INFO: 5 hot pixels could not be trimmed and have been masked.
[08:12:36.992] INFO: PixTest::trimHotPixels() done
[08:12:36.992] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C0.dat
[08:12:36.997] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C1.dat
[08:12:36.003] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C2.dat
[08:12:37.010] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C3.dat
[08:12:37.016] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C4.dat
[08:12:37.021] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C5.dat
[08:12:37.048] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C6.dat
[08:12:37.053] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C7.dat
[08:12:37.058] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C8.dat
[08:12:37.064] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C9.dat
[08:12:37.069] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C10.dat
[08:12:37.074] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C11.dat
[08:12:37.079] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C12.dat
[08:12:37.085] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C13.dat
[08:12:37.090] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C14.dat
[08:12:37.095] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C15.dat
[08:12:37.100] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//defaultMaskFile.dat
[08:12:37.114] INFO: enter test to run
[08:13:50.822] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[08:13:50.822] INFO: running: highrate
[08:13:50.827] INFO: ----------------------------------------------------------------------
[08:13:50.827] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[08:13:50.827] INFO: ----------------------------------------------------------------------
[08:13:50.827] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[08:13:50.827] INFO: edge/corner pixel THR is adjusted
[08:13:50.827] INFO: PixTestHighRate::trimHotPixels: step 0...
[08:13:51.784] INFO: Collecting data for 1 seconds...
[08:13:52.788] INFO: Done with hot pixel readout
[08:13:56.628] INFO: PixTest:: pg_setup set to default.
[08:13:56.628] INFO: 0 hot pixels found in step 0
[08:13:56.634] INFO: 0 hot pixels could not be trimmed and have been masked.
[08:13:56.732] INFO: PixTest::trimHotPixels() done
[08:13:56.732] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C0.dat
[08:13:56.747] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C1.dat
[08:13:56.759] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C2.dat
[08:13:56.766] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C3.dat
[08:13:56.772] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C4.dat
[08:13:56.777] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C5.dat
[08:13:56.782] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C6.dat
[08:13:56.788] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C7.dat
[08:13:56.793] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C8.dat
[08:13:56.799] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C9.dat
[08:13:56.804] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C10.dat
[08:13:56.810] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C11.dat
[08:13:56.815] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C12.dat
[08:13:56.820] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C13.dat
[08:13:56.826] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C14.dat
[08:13:56.831] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//trimParameters35_C15.dat
[08:13:56.837] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-06_FPIXTest-17C-FNAL-161011-0938-150V_2016-10-11_09h38m_1476196700/000_FPIXTest_p17//defaultMaskFile.dat
[08:13:56.853] INFO: enter test to run
[08:14:16.604] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[08:14:16.604] INFO: running: xray
[08:14:16.605] INFO: ----------------------------------------------------------------------
[08:14:16.605] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[08:14:16.605] INFO: ----------------------------------------------------------------------
[08:14:17.589] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[08:14:29.415] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[08:14:57.875] INFO: Resuming triggers.
[08:15:09.797] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[08:15:38.009] INFO: Resuming triggers.
[08:15:49.842] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[08:16:19.262] INFO: Resuming triggers.
[08:16:31.092] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[08:17:00.391] INFO: Resuming triggers.
[08:17:12.224] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[08:17:41.979] INFO: Resuming triggers.
[08:17:53.809] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[08:18:22.458] INFO: Resuming triggers.
[08:18:34.291] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[08:19:03.868] INFO: Resuming triggers.
[08:19:15.702] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[08:19:44.828] INFO: Resuming triggers.
[08:19:50.539] INFO: data taking finished, elapsed time: 100 seconds.
[08:20:05.355] INFO: PixTest:: pg_setup set to default.
[08:20:05.358] INFO: PixTestXray::doPhRun() done
[08:20:06.108] INFO: enter test to run
[08:22:57.429] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[08:22:57.429] INFO: running: xray
[08:22:57.451] INFO: ----------------------------------------------------------------------
[08:22:57.452] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[08:22:57.452] INFO: ----------------------------------------------------------------------
[08:22:58.433] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[08:23:05.394] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[08:23:35.795] INFO: Resuming triggers.
[08:23:42.754] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[08:24:13.097] INFO: Resuming triggers.
[08:24:20.058] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[08:24:50.318] INFO: Resuming triggers.
[08:24:57.279] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[08:25:27.538] INFO: Resuming triggers.
[08:25:34.499] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[08:26:04.735] INFO: Resuming triggers.
[08:26:11.698] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[08:26:41.970] INFO: Resuming triggers.
[08:26:48.933] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[08:27:19.227] INFO: Resuming triggers.
[08:27:26.191] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[08:27:56.395] INFO: Resuming triggers.
[08:28:03.361] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[08:28:33.727] INFO: Resuming triggers.
[08:28:40.691] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[08:29:11.425] INFO: Resuming triggers.
[08:29:18.390] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[08:29:49.273] INFO: Resuming triggers.
[08:29:56.236] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[08:30:26.001] INFO: Resuming triggers.
[08:30:33.969] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[08:31:04.711] INFO: Resuming triggers.
[08:31:11.673] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[08:31:42.437] INFO: Resuming triggers.
[08:31:45.295] INFO: data taking finished, elapsed time: 100 seconds.
[08:31:58.173] INFO: PixTest:: pg_setup set to default.
[08:31:58.176] INFO: PixTestXray::doPhRun() done
[08:31:58.348] INFO: enter test to run
[08:32:18.645] INFO: test: HighRate no parameter change
[08:32:18.645] INFO: running: highrate
[08:32:18.695] INFO: ----------------------------------------------------------------------
[08:32:18.695] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[08:32:18.695] INFO: ----------------------------------------------------------------------
[08:32:18.855] INFO: Expecting 768 events.
[08:32:19.994] INFO: 768 events read in total (423ms).
[08:32:19.995] INFO: Test took 1273ms.
[08:32:20.797] INFO: Expecting 41600 events.
[08:32:23.819] INFO: 41600 events read in total (2495ms).
[08:32:23.820] INFO: Test took 3735ms.
[08:32:23.850] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:24.584] INFO: Expecting 41600 events.
[08:32:27.784] INFO: 41600 events read in total (2673ms).
[08:32:27.785] INFO: Test took 3878ms.
[08:32:27.817] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:28.542] INFO: Expecting 41600 events.
[08:32:31.701] INFO: 41600 events read in total (2632ms).
[08:32:31.702] INFO: Test took 3860ms.
[08:32:31.733] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:32.462] INFO: Expecting 41600 events.
[08:32:35.641] INFO: 41600 events read in total (2652ms).
[08:32:35.642] INFO: Test took 3892ms.
[08:32:35.675] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:36.402] INFO: Expecting 41600 events.
[08:32:39.623] INFO: 41600 events read in total (2694ms).
[08:32:39.623] INFO: Test took 3932ms.
[08:32:39.655] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:40.385] INFO: Expecting 41600 events.
[08:32:43.557] INFO: 41600 events read in total (2645ms).
[08:32:43.558] INFO: Test took 3887ms.
[08:32:43.588] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:44.318] INFO: Expecting 41600 events.
[08:32:47.508] INFO: 41600 events read in total (2663ms).
[08:32:47.509] INFO: Test took 3905ms.
[08:32:47.541] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:48.269] INFO: Expecting 41600 events.
[08:32:51.480] INFO: 41600 events read in total (2684ms).
[08:32:51.481] INFO: Test took 3921ms.
[08:32:51.512] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:52.242] INFO: Expecting 41600 events.
[08:32:55.501] INFO: 41600 events read in total (2732ms).
[08:32:55.502] INFO: Test took 3973ms.
[08:32:55.533] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:32:56.262] INFO: Expecting 41600 events.
[08:32:59.468] INFO: 41600 events read in total (2680ms).
[08:32:59.469] INFO: Test took 3918ms.
[08:32:59.499] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:00.226] INFO: Expecting 41600 events.
[08:33:03.465] INFO: 41600 events read in total (2712ms).
[08:33:03.466] INFO: Test took 3949ms.
[08:33:03.500] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:04.225] INFO: Expecting 41600 events.
[08:33:07.387] INFO: 41600 events read in total (2635ms).
[08:33:07.388] INFO: Test took 3871ms.
[08:33:07.420] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:08.153] INFO: Expecting 41600 events.
[08:33:11.489] INFO: 41600 events read in total (2809ms).
[08:33:11.490] INFO: Test took 4053ms.
[08:33:11.521] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:12.242] INFO: Expecting 41600 events.
[08:33:15.511] INFO: 41600 events read in total (2742ms).
[08:33:15.512] INFO: Test took 3975ms.
[08:33:15.544] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:16.268] INFO: Expecting 41600 events.
[08:33:19.407] INFO: 41600 events read in total (2612ms).
[08:33:19.408] INFO: Test took 3847ms.
[08:33:19.442] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:20.164] INFO: Expecting 41600 events.
[08:33:23.377] INFO: 41600 events read in total (2687ms).
[08:33:23.378] INFO: Test took 3919ms.
[08:33:23.409] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:24.137] INFO: Expecting 41600 events.
[08:33:27.366] INFO: 41600 events read in total (2702ms).
[08:33:27.367] INFO: Test took 3941ms.
[08:33:27.399] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:28.123] INFO: Expecting 41600 events.
[08:33:31.338] INFO: 41600 events read in total (2688ms).
[08:33:31.339] INFO: Test took 3923ms.
[08:33:31.370] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:32.095] INFO: Expecting 41600 events.
[08:33:35.204] INFO: 41600 events read in total (2582ms).
[08:33:35.205] INFO: Test took 3818ms.
[08:33:35.236] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:35.959] INFO: Expecting 41600 events.
[08:33:38.970] INFO: 41600 events read in total (2484ms).
[08:33:38.970] INFO: Test took 3717ms.
[08:33:38.002] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:39.359] INFO: enter test to run
[08:33:44.684] INFO: test: HighRate no parameter change
[08:33:44.684] INFO: running: highrate
[08:33:44.686] INFO: ----------------------------------------------------------------------
[08:33:44.686] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[08:33:44.686] INFO: ----------------------------------------------------------------------
[08:33:45.310] INFO: Expecting 208000 events.
[08:33:57.133] INFO: 208000 events read in total (11296ms).
[08:33:57.136] INFO: Test took 12430ms.
[08:33:57.265] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:33:57.512] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[08:33:57.522] INFO: number of red-efficiency pixels: 68 45 71 107 115 125 130 86 85 106 104 81 71 57 17 191
[08:33:57.522] INFO: number of X-ray hits detected: 56782 36978 58070 93045 99203 103509 102020 75789 66848 82739 79960 65748 69409 43281 17934 23473
[08:33:57.522] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[08:33:57.522] INFO: number of Vcal hits detected: 207931 207955 207927 207890 207883 207873 207865 207912 207914 207890 207844 207906 207927 207943 207983 207808
[08:33:57.522] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 99.9
[08:33:57.522] 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 100.0 100.0 100.0 100.0 99.9
[08:33:57.522] INFO: X-ray hit rate [MHz/cm2]: 16.6 10.8 17.0 27.3 29.1 30.3 29.9 22.2 19.6 24.3 23.4 19.3 20.3 12.7 5.3 6.9
[08:33:57.522] INFO: PixTestHighRate::doXPixelAlive() done
[08:33:57.567] INFO: PixTest:: pg_setup set to default.
[08:33:57.577] INFO: enter test to run
[08:34:25.084] INFO: test: HighRate no parameter change
[08:34:25.084] INFO: running: highrate
[08:34:25.085] INFO: ----------------------------------------------------------------------
[08:34:25.085] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[08:34:25.085] INFO: ----------------------------------------------------------------------
[08:34:25.706] INFO: Expecting 208000 events.
[08:34:39.577] INFO: 208000 events read in total (13344ms).
[08:34:39.582] INFO: Test took 14488ms.
[08:34:39.862] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:34:40.156] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[08:34:40.156] INFO: number of red-efficiency pixels: 235 113 218 462 569 400 536 328 255 395 307 240 267 232 53 227
[08:34:40.202] INFO: number of X-ray hits detected: 128405 84296 130616 207263 222872 234232 228514 171020 152044 186743 180451 147478 156882 96535 40746 53274
[08:34:40.202] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[08:34:40.202] INFO: number of Vcal hits detected: 207749 207882 207768 207507 207376 207563 207400 207646 207733 207565 207625 207731 207725 207457 207946 207771
[08:34:40.203] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.7 99.8 99.9 99.8 99.9 99.9 99.9 99.7 100.0 99.9
[08:34:40.203] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.7 99.8 99.9 99.8 99.8 99.9 99.9 99.7 100.0 99.9
[08:34:40.203] INFO: X-ray hit rate [MHz/cm2]: 37.6 24.7 38.3 60.8 65.3 68.7 67.0 50.1 44.6 54.7 52.9 43.2 46.0 28.3 11.9 15.6
[08:34:40.203] INFO: PixTestHighRate::doXPixelAlive() done
[08:34:40.247] INFO: PixTest:: pg_setup set to default.
[08:34:40.263] INFO: enter test to run
[08:34:58.739] INFO: test: HighRate no parameter change
[08:34:58.740] INFO: running: highrate
[08:34:58.741] INFO: ----------------------------------------------------------------------
[08:34:58.741] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[08:34:58.741] INFO: ----------------------------------------------------------------------
[08:34:59.362] INFO: Expecting 208000 events.
[08:35:14.587] INFO: 208000 events read in total (14698ms).
[08:35:14.594] INFO: Test took 15842ms.
[08:35:14.002] INFO: Fetched DAQ statistics. Counters are being reset now.
[08:35:15.340] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[08:35:15.340] INFO: number of red-efficiency pixels: 450 182 458 960 1205 947 1142 708 501 870 775 391 537 437 87 271
[08:35:15.340] INFO: number of X-ray hits detected: 188955 123908 192618 305725 328864 344496 337843 251780 223842 275583 264639 218179 230911 143132 60370 79507
[08:35:15.340] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[08:35:15.341] INFO: number of Vcal hits detected: 207482 207808 207448 206810 206437 206813 206507 207122 207432 206962 207062 207545 207403 205721 207913 207722
[08:35:15.341] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.5 99.3 99.5 99.4 99.6 99.8 99.5 99.6 99.8 99.7 98.9 100.0 99.9
[08:35:15.341] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.4 99.2 99.4 99.3 99.6 99.7 99.5 99.5 99.8 99.7 98.9 100.0 99.9
[08:35:15.341] INFO: X-ray hit rate [MHz/cm2]: 55.4 36.3 56.5 89.6 96.4 101.0 99.0 73.8 65.6 80.8 77.6 63.9 67.7 42.0 17.7 23.3
[08:35:15.341] INFO: PixTestHighRate::doXPixelAlive() done
[08:35:15.396] INFO: PixTest:: pg_setup set to default.
[08:35:15.413] INFO: enter test to run
[08:35:27.323] INFO: test: exit no parameter change
[08:35:28.621] QUIET: Connection to board 33 closed.
[08:35:29.049] INFO: pXar: this is the end, my friend