[09:59:46.070] INFO: *** Welcome to pxar ***
[09:59:46.070] INFO: *** Today: 2016/09/30
[09:59:46.088] INFO: *** Version: v1.9.0-818-g96727
[09:59:46.088] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//dacParameters35_C15.dat
[09:59:46.108] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:59:46.108] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//defaultMaskFile.dat
[09:59:46.108] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C15.dat
[09:59:46.204] INFO: clk: 4
[09:59:46.204] INFO: ctr: 4
[09:59:46.204] INFO: sda: 19
[09:59:46.204] INFO: tin: 9
[09:59:46.204] INFO: level: 15
[09:59:46.204] INFO: triggerdelay: 0
[09:59:46.204] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[09:59:46.204] INFO: Log level: INFO
[09:59:46.221] QUIET: Connection to board DTB_WREKRL opened.
[09:59:46.224] 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:
------------------------------------------------------
[09:59:46.227] INFO: RPC call hashes of host and DTB match: 398089610
[09:59:47.758] INFO: DUT info:
[09:59:47.758] INFO: The DUT currently contains the following objects:
[09:59:47.758] INFO: 2 TBM Cores tbm08c (2 ON)
[09:59:47.758] INFO: TBM Core alpha (0): 7 registers set
[09:59:47.758] INFO: TBM Core beta (1): 7 registers set
[09:59:47.758] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[09:59:47.758] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.758] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.758] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.758] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.758] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.758] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.758] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.758] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.758] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.758] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.758] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.759] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.759] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.759] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.759] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:47.759] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[09:59:48.187] INFO: enter 'restricted' command line mode
[09:59:48.187] INFO: enter test to run
[09:59:53.529] INFO: test: PixelAlive no parameter change
[09:59:53.529] INFO: running: pixelalive
[09:59:53.538] INFO: ----------------------------------------------------------------------
[09:59:53.538] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[09:59:53.538] INFO: ----------------------------------------------------------------------
[09:59:53.956] INFO: Expecting 41600 events.
[09:59:58.346] INFO: 41600 events read in total (3671ms).
[09:59:58.486] INFO: Test took 4925ms.
[09:59:58.493] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:58.791] INFO: PixTestAlive::aliveTest() done
[09:59:58.791] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[09:59:58.823] INFO: enter test to run
[10:00:06.889] INFO: test: timing no parameter change
[10:00:06.889] INFO: running: timing
[10:00:06.892] INFO: ######################################################################
[10:00:06.892] INFO: PixTestTiming::doTest()
[10:00:06.892] INFO: ######################################################################
[10:00:06.893] INFO: ----------------------------------------------------------------------
[10:00:06.893] INFO: PixTestTiming::TBMPhaseScan()
[10:00:06.893] INFO: ----------------------------------------------------------------------
[10:05:57.221] INFO: TBM Phase Settings: 232
[10:05:57.221] INFO: 400MHz Phase: 2
[10:05:57.221] INFO: 160MHz Phase: 7
[10:05:57.221] INFO: Functional Phase Area: 3
[10:05:57.224] INFO: Test took 350332 ms.
[10:05:57.224] INFO: PixTestTiming::TBMPhaseScan() done.
[10:05:57.224] INFO: ----------------------------------------------------------------------
[10:05:57.224] INFO: PixTestTiming::ROCDelayScan()
[10:05:57.224] INFO: ----------------------------------------------------------------------
[10:08:02.495] INFO: ROC Delay Settings: 228
[10:08:02.495] INFO: ROC Header-Trailer/Token Delay: 11
[10:08:02.495] INFO: ROC Port 0 Delay: 4
[10:08:02.495] INFO: ROC Port 1 Delay: 4
[10:08:02.495] INFO: Functional ROC Area: 5
[10:08:02.498] INFO: Test took 125274 ms.
[10:08:02.498] INFO: PixTestTiming::ROCDelayScan() done.
[10:08:02.498] INFO: ----------------------------------------------------------------------
[10:08:02.498] INFO: PixTestTiming::TimingTest()
[10:08:02.498] INFO: ----------------------------------------------------------------------
[10:08:18.640] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:08:33.669] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:08:48.636] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:09:03.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:09:18.573] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:09:33.470] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:09:48.489] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:03.560] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:18.453] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:33.334] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:33.716] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:10:33.735] INFO: ----------------------------------------------------------------------
[10:10:33.735] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[10:10:33.735] INFO: ----------------------------------------------------------------------
[10:10:33.735] INFO: ----------------------------------------------------------------------
[10:10:33.735] INFO: Read back bit status: 1
[10:10:33.735] INFO: ----------------------------------------------------------------------
[10:10:33.735] INFO: ----------------------------------------------------------------------
[10:10:33.735] INFO: Timings are good!
[10:10:33.735] INFO: ----------------------------------------------------------------------
[10:10:33.735] INFO: Test took 151237 ms.
[10:10:33.735] INFO: PixTestTiming::TimingTest() done.
[10:10:33.751] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//tbmParameters_C0a.dat
[10:10:33.751] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:10:33.751] INFO: PixTestTiming::doTest took 626862 ms.
[10:10:33.751] INFO: PixTestTiming::doTest() done
[10:10:33.751] INFO: Write out TBMPhaseScan_0_V0
[10:10:33.751] INFO: Write out TBMPhaseScan_1_V0
[10:10:33.751] INFO: Write out CombinedTBMPhaseScan_V0
[10:10:33.777] INFO: Write out ROCDelayScan3_V0
[10:10:33.777] INFO: enter test to run
[10:11:32.484] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:11:32.484] INFO: running: highrate
[10:11:32.485] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:11:32.734] INFO: ----------------------------------------------------------------------
[10:11:32.734] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:11:32.734] INFO: ----------------------------------------------------------------------
[10:11:32.734] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:11:32.750] INFO: edge/corner pixel THR is adjusted
[10:11:32.750] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:11:33.708] INFO: Collecting data for 5 seconds...
[10:11:38.728] INFO: Done with hot pixel readout
[10:11:50.993] INFO: PixTest:: pg_setup set to default.
[10:11:50.994] INFO: 20 hot pixels found in step 0
[10:11:51.990] INFO: Collecting data for 5 seconds...
[10:11:57.008] INFO: Done with hot pixel readout
[10:12:09.435] INFO: PixTest:: pg_setup set to default.


[10:12:09.437] INFO: 34 hot pixels found in step 1
[10:12:10.432] INFO: Collecting data for 5 seconds...
[10:12:15.450] INFO: Done with hot pixel readout
[10:12:27.791] INFO: PixTest:: pg_setup set to default.

[10:12:27.792] INFO: 14 hot pixels found in step 2
[10:12:28.788] INFO: Collecting data for 5 seconds...
[10:12:33.807] INFO: Done with hot pixel readout
[10:12:46.022] INFO: PixTest:: pg_setup set to default.

[10:12:46.023] INFO: 21 hot pixels found in step 3
[10:12:47.020] INFO: Collecting data for 5 seconds...
[10:12:52.039] INFO: Done with hot pixel readout
[10:13:04.270] INFO: PixTest:: pg_setup set to default.


[10:13:04.271] INFO: 21 hot pixels found in step 4
[10:13:05.268] INFO: Collecting data for 5 seconds...
[10:13:10.287] INFO: Done with hot pixel readout
[10:13:22.203] INFO: PixTest:: pg_setup set to default.

[10:13:22.204] INFO: 27 hot pixels found in step 5
[10:13:23.200] INFO: Collecting data for 5 seconds...
[10:13:28.219] INFO: Done with hot pixel readout
[10:13:40.593] INFO: PixTest:: pg_setup set to default.
[10:13:40.594] INFO: 27 hot pixels found in step 6
[10:13:41.590] INFO: Collecting data for 5 seconds...
[10:13:46.606] INFO: Done with hot pixel readout
[10:13:58.519] INFO: PixTest:: pg_setup set to default.


[10:13:58.520] INFO: 24 hot pixels found in step 7
[10:13:59.515] INFO: Collecting data for 5 seconds...
[10:14:04.532] INFO: Done with hot pixel readout
[10:14:16.498] INFO: PixTest:: pg_setup set to default.



[10:14:16.499] INFO: 18 hot pixels found in step 8
[10:14:17.494] INFO: Collecting data for 5 seconds...
[10:14:22.511] INFO: Done with hot pixel readout
[10:14:34.471] INFO: PixTest:: pg_setup set to default.

[10:14:34.472] INFO: 22 hot pixels found in step 9
[10:14:35.467] INFO: Collecting data for 5 seconds...
[10:14:40.483] INFO: Done with hot pixel readout
[10:14:52.422] INFO: PixTest:: pg_setup set to default.



[10:14:52.423] INFO: 27 hot pixels found in step 10
[10:14:53.418] INFO: Collecting data for 5 seconds...
[10:14:58.434] INFO: Done with hot pixel readout
[10:15:10.396] INFO: PixTest:: pg_setup set to default.


[10:15:10.397] INFO: 20 hot pixels found in step 11
[10:15:11.392] INFO: Collecting data for 5 seconds...
[10:15:16.410] INFO: Done with hot pixel readout
[10:15:28.243] INFO: PixTest:: pg_setup set to default.

[10:15:28.244] INFO: 16 hot pixels found in step 12
[10:15:29.239] INFO: Collecting data for 5 seconds...
[10:15:34.255] INFO: Done with hot pixel readout
[10:15:46.291] INFO: PixTest:: pg_setup set to default.


[10:15:46.292] INFO: 21 hot pixels found in step 13
[10:15:47.288] INFO: Collecting data for 5 seconds...
[10:15:52.305] INFO: Done with hot pixel readout
[10:16:04.181] INFO: PixTest:: pg_setup set to default.


[10:16:04.182] INFO: 28 hot pixels found in step 14
[10:16:04.221] INFO: 28 hot pixels could not be trimmed and have been masked.
[10:16:04.224] INFO: PixTest::trimHotPixels() done
[10:16:04.224] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C0.dat
[10:16:04.231] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C1.dat
[10:16:04.237] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C2.dat
[10:16:04.242] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C3.dat
[10:16:04.248] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C4.dat
[10:16:04.253] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C5.dat
[10:16:04.258] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C6.dat
[10:16:04.264] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C7.dat
[10:16:04.269] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C8.dat
[10:16:04.274] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C9.dat
[10:16:04.280] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C10.dat
[10:16:04.285] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C11.dat
[10:16:04.290] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C12.dat
[10:16:04.295] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C13.dat
[10:16:04.301] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C14.dat
[10:16:04.306] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C15.dat
[10:16:04.311] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//defaultMaskFile.dat
[10:16:04.321] INFO: enter test to run
[10:16:28.442] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:16:28.442] INFO: running: highrate
[10:16:28.447] INFO: ----------------------------------------------------------------------
[10:16:28.447] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:16:28.447] INFO: ----------------------------------------------------------------------
[10:16:28.447] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:16:28.447] INFO: edge/corner pixel THR is adjusted
[10:16:28.447] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:16:29.405] INFO: Collecting data for 1 seconds...
[10:16:30.409] INFO: Done with hot pixel readout
[10:16:34.517] INFO: PixTest:: pg_setup set to default.
[10:16:34.518] INFO: 0 hot pixels found in step 0
[10:16:34.523] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:16:34.608] INFO: PixTest::trimHotPixels() done
[10:16:34.608] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C0.dat
[10:16:34.620] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C1.dat
[10:16:34.627] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C2.dat
[10:16:34.632] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C3.dat
[10:16:34.637] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C4.dat
[10:16:34.643] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C5.dat
[10:16:34.648] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C6.dat
[10:16:34.653] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C7.dat
[10:16:34.658] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C8.dat
[10:16:34.664] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C9.dat
[10:16:34.669] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C10.dat
[10:16:34.674] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C11.dat
[10:16:34.680] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C12.dat
[10:16:34.685] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C13.dat
[10:16:34.690] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C14.dat
[10:16:34.695] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//trimParameters35_C15.dat
[10:16:34.700] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-04_FPIXTest-17C-FNAL-160927-1211-150V_2016-09-27_12h11m_1474996287/000_FPIXTest_p17//defaultMaskFile.dat
[10:16:34.710] INFO: enter test to run
[10:16:53.562] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:16:53.562] INFO: running: xray
[10:16:53.563] INFO: ----------------------------------------------------------------------
[10:16:53.563] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:16:53.563] INFO: ----------------------------------------------------------------------
[10:16:54.541] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:17:05.771] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[10:17:35.255] INFO: Resuming triggers.
[10:17:46.485] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[10:18:15.846] INFO: Resuming triggers.
[10:18:27.077] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[10:18:56.597] INFO: Resuming triggers.
[10:19:07.824] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[10:19:37.219] INFO: Resuming triggers.
[10:19:48.444] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[10:20:17.911] INFO: Resuming triggers.
[10:20:29.139] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[10:20:58.469] INFO: Resuming triggers.
[10:21:09.695] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[10:21:39.532] INFO: Resuming triggers.
[10:21:50.761] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[10:22:20.435] INFO: Resuming triggers.
[10:22:30.942] INFO: data taking finished, elapsed time: 100 seconds.
[10:22:59.309] INFO: PixTest:: pg_setup set to default.
[10:22:59.312] INFO: PixTestXray::doPhRun() done
[10:22:59.532] INFO: enter test to run
[10:23:26.535] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[10:23:26.536] INFO: running: xray
[10:23:26.537] INFO: ----------------------------------------------------------------------
[10:23:26.537] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:23:26.537] INFO: ----------------------------------------------------------------------
[10:23:27.500] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:23:33.952] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[10:24:05.033] INFO: Resuming triggers.
[10:24:11.489] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[10:24:42.540] INFO: Resuming triggers.
[10:24:48.997] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[10:25:19.924] INFO: Resuming triggers.
[10:25:26.382] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[10:25:57.587] INFO: Resuming triggers.
[10:26:04.049] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[10:26:36.080] INFO: Resuming triggers.
[10:26:42.535] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[10:27:13.631] INFO: Resuming triggers.
[10:27:20.092] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[10:27:51.636] INFO: Resuming triggers.
[10:27:58.099] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[10:28:28.803] INFO: Resuming triggers.
[10:28:35.260] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[10:29:05.481] INFO: Resuming triggers.
[10:29:11.944] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[10:29:42.095] INFO: Resuming triggers.
[10:29:48.555] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[10:30:18.752] INFO: Resuming triggers.
[10:30:25.206] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[10:30:55.300] INFO: Resuming triggers.
[10:31:01.753] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[10:31:31.933] INFO: Resuming triggers.
[10:31:38.388] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[10:32:08.639] INFO: Resuming triggers.
[10:32:15.091] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[10:32:45.422] INFO: Resuming triggers.
[10:32:48.936] INFO: data taking finished, elapsed time: 100 seconds.
[10:33:05.572] INFO: PixTest:: pg_setup set to default.
[10:33:05.576] INFO: PixTestXray::doPhRun() done
[10:33:05.758] INFO: enter test to run
[10:33:26.963] INFO: test: HighRate no parameter change
[10:33:26.963] INFO: running: highrate
[10:33:26.974] INFO: ----------------------------------------------------------------------
[10:33:26.974] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[10:33:26.974] INFO: ----------------------------------------------------------------------
[10:33:27.128] INFO: Expecting 768 events.
[10:33:28.262] INFO: 768 events read in total (418ms).
[10:33:28.262] INFO: Test took 1267ms.
[10:33:29.065] INFO: Expecting 41600 events.
[10:33:32.221] INFO: 41600 events read in total (2629ms).
[10:33:32.221] INFO: Test took 3951ms.
[10:33:32.256] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:33:32.982] INFO: Expecting 41600 events.
[10:33:36.218] INFO: 41600 events read in total (2709ms).
[10:33:36.219] INFO: Test took 3945ms.
[10:33:36.254] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:33:36.977] INFO: Expecting 41600 events.
[10:33:40.216] INFO: 41600 events read in total (2712ms).
[10:33:40.217] INFO: Test took 3944ms.
[10:33:40.252] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:33:40.975] INFO: Expecting 41600 events.
[10:33:44.210] INFO: 41600 events read in total (2708ms).
[10:33:44.211] INFO: Test took 3940ms.
[10:33:44.245] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:33:44.969] INFO: Expecting 41600 events.
[10:33:48.208] INFO: 41600 events read in total (2713ms).
[10:33:48.209] INFO: Test took 3946ms.
[10:33:48.245] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:33:48.968] INFO: Expecting 41600 events.
[10:33:52.223] INFO: 41600 events read in total (2728ms).
[10:33:52.224] INFO: Test took 3959ms.
[10:33:52.259] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:33:52.980] INFO: Expecting 41600 events.
[10:33:56.221] INFO: 41600 events read in total (2714ms).
[10:33:56.222] INFO: Test took 3944ms.
[10:33:56.257] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:33:56.980] INFO: Expecting 41600 events.
[10:34:00.203] INFO: 41600 events read in total (2696ms).
[10:34:00.205] INFO: Test took 3930ms.
[10:34:00.240] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:00.959] INFO: Expecting 41600 events.
[10:34:04.187] INFO: 41600 events read in total (2701ms).
[10:34:04.188] INFO: Test took 3929ms.
[10:34:04.224] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:04.943] INFO: Expecting 41600 events.
[10:34:08.196] INFO: 41600 events read in total (2726ms).
[10:34:08.197] INFO: Test took 3955ms.
[10:34:08.231] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:08.951] INFO: Expecting 41600 events.
[10:34:12.192] INFO: 41600 events read in total (2714ms).
[10:34:12.193] INFO: Test took 3944ms.
[10:34:12.228] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:12.949] INFO: Expecting 41600 events.
[10:34:16.192] INFO: 41600 events read in total (2716ms).
[10:34:16.193] INFO: Test took 3946ms.
[10:34:16.228] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:16.953] INFO: Expecting 41600 events.
[10:34:20.207] INFO: 41600 events read in total (2727ms).
[10:34:20.208] INFO: Test took 3961ms.
[10:34:20.243] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:20.962] INFO: Expecting 41600 events.
[10:34:24.228] INFO: 41600 events read in total (2739ms).
[10:34:24.229] INFO: Test took 3966ms.
[10:34:24.264] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:24.983] INFO: Expecting 41600 events.
[10:34:28.225] INFO: 41600 events read in total (2715ms).
[10:34:28.226] INFO: Test took 3944ms.
[10:34:28.261] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:28.985] INFO: Expecting 41600 events.
[10:34:32.242] INFO: 41600 events read in total (2731ms).
[10:34:32.243] INFO: Test took 3963ms.
[10:34:32.277] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:32.995] INFO: Expecting 41600 events.
[10:34:36.241] INFO: 41600 events read in total (2719ms).
[10:34:36.242] INFO: Test took 3947ms.
[10:34:36.276] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:36.998] INFO: Expecting 41600 events.
[10:34:40.236] INFO: 41600 events read in total (2711ms).
[10:34:40.237] INFO: Test took 3941ms.
[10:34:40.272] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:40.993] INFO: Expecting 41600 events.
[10:34:44.183] INFO: 41600 events read in total (2663ms).
[10:34:44.184] INFO: Test took 3892ms.
[10:34:44.219] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:44.938] INFO: Expecting 41600 events.
[10:34:48.022] INFO: 41600 events read in total (2557ms).
[10:34:48.023] INFO: Test took 3782ms.
[10:34:48.056] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:48.422] INFO: enter test to run
[10:36:02.970] INFO: test: HighRate no parameter change
[10:36:02.970] INFO: running: highrate
[10:36:02.971] INFO: ----------------------------------------------------------------------
[10:36:02.971] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:36:02.971] INFO: ----------------------------------------------------------------------
[10:36:03.597] INFO: Expecting 208000 events.
[10:36:15.181] INFO: 208000 events read in total (11057ms).
[10:36:15.184] INFO: Test took 12204ms.
[10:36:15.341] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:36:15.599] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:36:15.599] INFO: number of red-efficiency pixels: 80 57 88 148 121 141 129 109 101 157 142 109 113 90 24 40
[10:36:15.599] INFO: number of X-ray hits detected: 64829 41142 66741 100662 105205 115276 110208 82103 85658 112632 110573 92387 97096 57308 21854 26451
[10:36:15.599] 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:36:15.599] INFO: number of Vcal hits detected: 207918 207914 207910 207846 207875 207856 207869 207889 207886 207841 207856 207888 207884 207909 207976 207960
[10:36:15.600] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[10:36:15.600] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[10:36:15.600] INFO: X-ray hit rate [MHz/cm2]: 19.0 12.1 19.6 29.5 30.8 33.8 32.3 24.1 25.1 33.0 32.4 27.1 28.5 16.8 6.4 7.8
[10:36:15.600] INFO: PixTestHighRate::doXPixelAlive() done
[10:36:15.645] INFO: PixTest:: pg_setup set to default.
[10:36:15.655] INFO: enter test to run
[10:36:30.938] INFO: test: HighRate no parameter change
[10:36:30.938] INFO: running: highrate
[10:36:30.939] INFO: ----------------------------------------------------------------------
[10:36:30.940] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:36:30.940] INFO: ----------------------------------------------------------------------
[10:36:31.561] INFO: Expecting 208000 events.
[10:36:45.561] INFO: 208000 events read in total (13473ms).
[10:36:45.567] INFO: Test took 14619ms.
[10:36:45.891] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:36:46.199] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:36:46.199] INFO: number of red-efficiency pixels: 265 138 335 506 422 586 504 351 301 632 616 340 442 272 42 68
[10:36:46.200] INFO: number of X-ray hits detected: 138923 88490 143525 215091 225463 247816 237129 175844 184081 240994 235816 197432 207781 121936 47074 56955
[10:36:46.200] 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:36:46.200] INFO: number of Vcal hits detected: 207713 207814 207627 207449 207540 207359 207454 207611 207646 207294 207306 207636 207525 207704 207956 207931
[10:36:46.200] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.7 99.8 99.8 99.8 99.7 99.7 99.8 99.8 99.9 100.0 100.0
[10:36:46.200] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.8 99.7 99.7 99.8 99.8 99.7 99.7 99.8 99.8 99.9 100.0 100.0
[10:36:46.200] INFO: X-ray hit rate [MHz/cm2]: 40.7 25.9 42.1 63.0 66.1 72.6 69.5 51.5 54.0 70.6 69.1 57.9 60.9 35.7 13.8 16.7
[10:36:46.200] INFO: PixTestHighRate::doXPixelAlive() done
[10:36:46.256] INFO: PixTest:: pg_setup set to default.
[10:36:46.268] INFO: enter test to run
[10:37:06.474] INFO: test: HighRate no parameter change
[10:37:06.474] INFO: running: highrate
[10:37:06.475] INFO: ----------------------------------------------------------------------
[10:37:06.475] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:37:06.475] INFO: ----------------------------------------------------------------------
[10:37:07.101] INFO: Expecting 208000 events.
[10:37:23.188] INFO: 208000 events read in total (15560ms).
[10:37:23.196] INFO: Test took 16711ms.
[10:37:23.708] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:37:24.073] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:37:24.073] INFO: number of red-efficiency pixels: 549 268 741 1140 1002 1149 1151 831 678 1442 1356 789 1036 629 85 109
[10:37:24.073] INFO: number of X-ray hits detected: 208374 131512 216039 323176 337526 372060 354418 264620 275699 361035 352247 296412 312891 182179 71213 85389
[10:37:24.073] 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:37:24.073] INFO: number of Vcal hits detected: 207362 207625 206951 206489 206776 206528 206533 206921 207158 206063 206222 207056 206704 207177 207912 207887
[10:37:24.073] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.6 99.4 99.5 99.4 99.4 99.5 99.6 99.1 99.2 99.6 99.4 99.6 100.0 99.9
[10:37:24.073] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.5 99.3 99.4 99.3 99.3 99.5 99.6 99.1 99.1 99.5 99.4 99.6 100.0 99.9
[10:37:24.073] INFO: X-ray hit rate [MHz/cm2]: 61.1 38.5 63.3 94.7 98.9 109.1 103.9 77.6 80.8 105.8 103.2 86.9 91.7 53.4 20.9 25.0
[10:37:24.073] INFO: PixTestHighRate::doXPixelAlive() done
[10:37:24.118] INFO: PixTest:: pg_setup set to default.
[10:37:24.137] INFO: enter test to run
[10:37:28.162] INFO: test: exit no parameter change
[10:37:28.765] QUIET: Connection to board 33 closed.
[10:37:28.777] INFO: pXar: this is the end, my friend