[11:11:55.443] INFO: *** Welcome to pxar ***
[11:11:55.443] INFO: *** Today: 2016/10/07
[11:11:56.655] INFO: *** Version: v1.9.0-818-g96727
[11:11:56.655] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//dacParameters35_C15.dat
[11:11:56.709] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:11:56.710] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//defaultMaskFile.dat
[11:11:56.714] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C15.dat
[11:11:56.826] INFO: clk: 4
[11:11:56.826] INFO: ctr: 4
[11:11:56.826] INFO: sda: 19
[11:11:56.826] INFO: tin: 9
[11:11:56.826] INFO: level: 15
[11:11:56.826] INFO: triggerdelay: 0
[11:11:56.827] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:11:56.827] INFO: Log level: INFO
[11:11:56.845] QUIET: Connection to board DTB_WREKRL opened.
[11:11:56.849] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[11:11:56.851] INFO: RPC call hashes of host and DTB match: 398089610
[11:11:58.382] INFO: DUT info:
[11:11:58.382] INFO: The DUT currently contains the following objects:
[11:11:58.382] INFO: 2 TBM Cores tbm08c (2 ON)
[11:11:58.382] INFO: TBM Core alpha (0): 7 registers set
[11:11:58.382] INFO: TBM Core beta (1): 7 registers set
[11:11:58.382] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:11:58.382] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.382] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.382] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.382] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.382] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.382] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.382] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.382] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.383] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.383] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.383] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.383] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.383] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.383] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.383] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.383] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:11:58.819] INFO: enter 'restricted' command line mode
[11:11:58.819] INFO: enter test to run
[11:12:05.158] INFO: test: PixelAlive no parameter change
[11:12:05.158] INFO: running: pixelalive
[11:12:05.214] INFO: ----------------------------------------------------------------------
[11:12:05.214] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:12:05.214] INFO: ----------------------------------------------------------------------
[11:12:05.536] INFO: Expecting 41600 events.
[11:12:09.880] INFO: 41600 events read in total (3626ms).
[11:12:10.049] INFO: Test took 4833ms.
[11:12:10.060] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:12:10.601] INFO: PixTestAlive::aliveTest() done
[11:12:10.601] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 1 8 0 0 1 0 1 0 0 0
[11:12:10.779] INFO: enter test to run
[11:12:15.254] INFO: test: timing no parameter change
[11:12:15.254] INFO: running: timing
[11:12:15.257] INFO: ######################################################################
[11:12:15.257] INFO: PixTestTiming::doTest()
[11:12:15.257] INFO: ######################################################################
[11:12:15.257] INFO: ----------------------------------------------------------------------
[11:12:15.258] INFO: PixTestTiming::TBMPhaseScan()
[11:12:15.258] INFO: ----------------------------------------------------------------------
[11:17:17.038] INFO: TBM Phase Settings: 224
[11:17:17.039] INFO: 400MHz Phase: 0
[11:17:17.039] INFO: 160MHz Phase: 7
[11:17:17.039] INFO: Functional Phase Area: 3
[11:17:17.061] INFO: Test took 301804 ms.
[11:17:17.061] INFO: PixTestTiming::TBMPhaseScan() done.
[11:17:17.062] INFO: ----------------------------------------------------------------------
[11:17:17.062] INFO: PixTestTiming::ROCDelayScan()
[11:17:17.062] INFO: ----------------------------------------------------------------------
[11:19:54.829] INFO: ROC Delay Settings: 227
[11:19:54.829] INFO: ROC Header-Trailer/Token Delay: 11
[11:19:54.829] INFO: ROC Port 0 Delay: 3
[11:19:54.829] INFO: ROC Port 1 Delay: 4
[11:19:54.829] INFO: Functional ROC Area: 4
[11:19:54.833] INFO: Test took 157771 ms.
[11:19:54.833] INFO: PixTestTiming::ROCDelayScan() done.
[11:19:54.833] INFO: ----------------------------------------------------------------------
[11:19:54.833] INFO: PixTestTiming::TimingTest()
[11:19:54.833] INFO: ----------------------------------------------------------------------
[11:20:11.136] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:20:26.203] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:20:41.278] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:20:56.405] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:21:11.563] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:21:26.611] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:21:41.739] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:21:56.901] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:22:11.898] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:22:27.094] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:22:27.476] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:22:27.494] INFO: ----------------------------------------------------------------------
[11:22:27.494] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:22:27.494] INFO: ----------------------------------------------------------------------
[11:22:27.494] INFO: ----------------------------------------------------------------------
[11:22:27.494] INFO: Read back bit status: 1
[11:22:27.494] INFO: ----------------------------------------------------------------------
[11:22:27.494] INFO: ----------------------------------------------------------------------
[11:22:27.494] INFO: Timings are good!
[11:22:27.494] INFO: ----------------------------------------------------------------------
[11:22:27.494] INFO: Test took 152661 ms.
[11:22:27.494] INFO: PixTestTiming::TimingTest() done.
[11:22:27.494] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:22:27.512] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:22:27.512] INFO: PixTestTiming::doTest took 612258 ms.
[11:22:27.512] INFO: PixTestTiming::doTest() done
[11:22:27.512] INFO: Write out TBMPhaseScan_0_V0
[11:22:27.513] INFO: Write out TBMPhaseScan_1_V0
[11:22:27.513] INFO: Write out CombinedTBMPhaseScan_V0
[11:22:27.514] INFO: Write out ROCDelayScan3_V0
[11:22:27.515] INFO: enter test to run
[11:23:25.026] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:23:25.026] INFO: running: highrate
[11:23:25.042] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:23:25.292] INFO: ----------------------------------------------------------------------
[11:23:25.292] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:23:25.292] INFO: ----------------------------------------------------------------------
[11:23:25.292] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:23:25.292] INFO: edge/corner pixel THR is adjusted
[11:23:25.292] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:23:26.249] INFO: Collecting data for 5 seconds...
[11:23:31.269] INFO: Done with hot pixel readout
[11:23:43.419] INFO: PixTest:: pg_setup set to default.

[11:23:43.420] INFO: 16 hot pixels found in step 0
[11:23:44.414] INFO: Collecting data for 5 seconds...
[11:23:49.434] INFO: Done with hot pixel readout
[11:24:01.538] INFO: PixTest:: pg_setup set to default.
[11:24:01.539] INFO: 18 hot pixels found in step 1
[11:24:02.532] INFO: Collecting data for 5 seconds...
[11:24:07.555] INFO: Done with hot pixel readout
[11:24:19.431] INFO: PixTest:: pg_setup set to default.
[11:24:19.431] INFO: 12 hot pixels found in step 2
[11:24:20.426] INFO: Collecting data for 5 seconds...
[11:24:25.446] INFO: Done with hot pixel readout
[11:24:37.224] INFO: PixTest:: pg_setup set to default.


[11:24:37.225] INFO: 11 hot pixels found in step 3
[11:24:38.217] INFO: Collecting data for 5 seconds...
[11:24:43.235] INFO: Done with hot pixel readout
[11:24:54.964] INFO: PixTest:: pg_setup set to default.

[11:24:54.965] INFO: 11 hot pixels found in step 4
[11:24:55.957] INFO: Collecting data for 5 seconds...
[11:25:00.974] INFO: Done with hot pixel readout
[11:25:12.801] INFO: PixTest:: pg_setup set to default.


[11:25:12.802] INFO: 11 hot pixels found in step 5
[11:25:13.795] INFO: Collecting data for 5 seconds...
[11:25:18.812] INFO: Done with hot pixel readout
[11:25:30.516] INFO: PixTest:: pg_setup set to default.



[11:25:30.517] INFO: 11 hot pixels found in step 6
[11:25:31.510] INFO: Collecting data for 5 seconds...
[11:25:36.527] INFO: Done with hot pixel readout
[11:25:48.298] INFO: PixTest:: pg_setup set to default.





[11:25:48.299] INFO: 14 hot pixels found in step 7
[11:25:49.293] INFO: Collecting data for 5 seconds...
[11:25:54.311] INFO: Done with hot pixel readout
[11:26:06.059] INFO: PixTest:: pg_setup set to default.




[11:26:06.060] INFO: 8 hot pixels found in step 8
[11:26:07.053] INFO: Collecting data for 5 seconds...
[11:26:12.071] INFO: Done with hot pixel readout
[11:26:23.838] INFO: PixTest:: pg_setup set to default.





[11:26:23.839] INFO: 9 hot pixels found in step 9
[11:26:24.833] INFO: Collecting data for 5 seconds...
[11:26:29.850] INFO: Done with hot pixel readout
[11:26:41.555] INFO: PixTest:: pg_setup set to default.






[11:26:41.556] INFO: 9 hot pixels found in step 10
[11:26:42.549] INFO: Collecting data for 5 seconds...
[11:26:47.566] INFO: Done with hot pixel readout
[11:26:59.289] INFO: PixTest:: pg_setup set to default.







[11:26:59.290] INFO: 11 hot pixels found in step 11
[11:27:00.284] INFO: Collecting data for 5 seconds...
[11:27:05.301] INFO: Done with hot pixel readout
[11:27:17.085] INFO: PixTest:: pg_setup set to default.




[11:27:17.086] INFO: 6 hot pixels found in step 12
[11:27:18.078] INFO: Collecting data for 5 seconds...
[11:27:23.097] INFO: Done with hot pixel readout
[11:27:34.801] INFO: PixTest:: pg_setup set to default.







[11:27:34.802] INFO: 12 hot pixels found in step 13
[11:27:35.796] INFO: Collecting data for 5 seconds...
[11:27:40.814] INFO: Done with hot pixel readout
[11:27:52.682] INFO: PixTest:: pg_setup set to default.





[11:27:52.683] INFO: 10 hot pixels found in step 14
[11:27:52.720] INFO: 10 hot pixels could not be trimmed and have been masked.
[11:27:52.724] INFO: PixTest::trimHotPixels() done
[11:27:52.724] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C0.dat
[11:27:52.729] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C1.dat
[11:27:52.736] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C2.dat
[11:27:52.743] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C3.dat
[11:27:52.748] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C4.dat
[11:27:52.753] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C5.dat
[11:27:52.759] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C6.dat
[11:27:52.764] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C7.dat
[11:27:52.769] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C8.dat
[11:27:52.775] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C9.dat
[11:27:52.780] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C10.dat
[11:27:52.785] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C11.dat
[11:27:52.791] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C12.dat
[11:27:52.796] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C13.dat
[11:27:52.801] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C14.dat
[11:27:52.807] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C15.dat
[11:27:52.812] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//defaultMaskFile.dat
[11:27:52.822] INFO: enter test to run
[11:28:23.303] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:28:23.303] INFO: running: highrate
[11:28:23.308] INFO: ----------------------------------------------------------------------
[11:28:23.308] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:28:23.308] INFO: ----------------------------------------------------------------------
[11:28:23.308] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:28:23.308] INFO: edge/corner pixel THR is adjusted
[11:28:23.308] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:28:24.266] INFO: Collecting data for 1 seconds...
[11:28:25.270] INFO: Done with hot pixel readout
[11:28:29.304] INFO: PixTest:: pg_setup set to default.
[11:28:29.305] INFO: 0 hot pixels found in step 0
[11:28:29.310] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:28:29.403] INFO: PixTest::trimHotPixels() done
[11:28:29.403] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C0.dat
[11:28:29.411] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C1.dat
[11:28:29.418] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C2.dat
[11:28:29.424] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C3.dat
[11:28:29.429] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C4.dat
[11:28:29.434] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C5.dat
[11:28:29.440] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C6.dat
[11:28:29.445] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C7.dat
[11:28:29.450] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C8.dat
[11:28:29.456] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C9.dat
[11:28:29.461] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C10.dat
[11:28:29.466] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C11.dat
[11:28:29.472] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C12.dat
[11:28:29.477] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C13.dat
[11:28:29.483] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C14.dat
[11:28:29.488] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C15.dat
[11:28:29.494] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-11_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//defaultMaskFile.dat
[11:28:29.504] INFO: enter test to run
[11:29:09.495] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:29:09.495] INFO: running: xray
[11:29:09.497] INFO: ----------------------------------------------------------------------
[11:29:09.497] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:29:09.497] INFO: ----------------------------------------------------------------------
[11:29:10.473] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:29:21.911] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:29:51.637] INFO: Resuming triggers.
[11:30:03.072] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[11:30:32.890] INFO: Resuming triggers.
[11:30:44.326] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:31:14.103] INFO: Resuming triggers.
[11:31:25.541] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[11:31:55.326] INFO: Resuming triggers.
[11:32:06.763] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[11:32:36.488] INFO: Resuming triggers.
[11:32:47.928] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[11:33:17.775] INFO: Resuming triggers.
[11:33:29.221] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[11:33:58.796] INFO: Resuming triggers.
[11:34:10.242] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[11:34:39.944] INFO: Resuming triggers.
[11:34:48.788] INFO: data taking finished, elapsed time: 100 seconds.
[11:35:12.341] INFO: PixTest:: pg_setup set to default.
[11:35:12.344] INFO: PixTestXray::doPhRun() done
[11:35:12.547] INFO: enter test to run
[11:35:57.844] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:35:57.844] INFO: running: xray
[11:35:57.845] INFO: ----------------------------------------------------------------------
[11:35:57.845] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:35:57.846] INFO: ----------------------------------------------------------------------
[11:35:58.809] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:36:05.544] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:36:37.074] INFO: Resuming triggers.
[11:36:43.815] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[11:37:15.379] INFO: Resuming triggers.
[11:37:22.112] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[11:37:52.665] INFO: Resuming triggers.
[11:37:59.400] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[11:38:29.886] INFO: Resuming triggers.
[11:38:36.619] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[11:39:07.075] INFO: Resuming triggers.
[11:39:13.813] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[11:39:44.418] INFO: Resuming triggers.
[11:39:51.153] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:40:21.712] INFO: Resuming triggers.
[11:40:28.442] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[11:40:59.022] INFO: Resuming triggers.
[11:41:05.758] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[11:41:36.368] INFO: Resuming triggers.
[11:41:43.101] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[11:42:13.675] INFO: Resuming triggers.
[11:42:20.408] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[11:42:51.068] INFO: Resuming triggers.
[11:42:57.803] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:43:28.615] INFO: Resuming triggers.
[11:43:35.348] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[11:44:06.172] INFO: Resuming triggers.
[11:44:12.908] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[11:44:43.530] INFO: Resuming triggers.
[11:44:49.591] INFO: data taking finished, elapsed time: 100 seconds.
[11:45:18.184] INFO: PixTest:: pg_setup set to default.
[11:45:18.187] INFO: PixTestXray::doPhRun() done
[11:45:18.360] INFO: enter test to run
[11:46:33.848] INFO: test: HighRate no parameter change
[11:46:33.848] INFO: running: highrate
[11:46:33.871] INFO: ----------------------------------------------------------------------
[11:46:33.871] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:46:33.871] INFO: ----------------------------------------------------------------------
[11:46:34.016] INFO: Expecting 768 events.
[11:46:35.192] INFO: 768 events read in total (454ms).
[11:46:35.193] INFO: Test took 1310ms.
[11:46:35.995] INFO: Expecting 41600 events.
[11:46:39.154] INFO: 41600 events read in total (2632ms).
[11:46:39.155] INFO: Test took 3956ms.
[11:46:39.189] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:46:39.915] INFO: Expecting 41600 events.
[11:46:43.092] INFO: 41600 events read in total (2650ms).
[11:46:43.093] INFO: Test took 3887ms.
[11:46:43.128] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:46:43.852] INFO: Expecting 41600 events.
[11:46:47.123] INFO: 41600 events read in total (2744ms).
[11:46:47.123] INFO: Test took 3978ms.
[11:46:47.158] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:46:47.879] INFO: Expecting 41600 events.
[11:46:51.129] INFO: 41600 events read in total (2724ms).
[11:46:51.130] INFO: Test took 3954ms.
[11:46:51.171] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:46:51.873] INFO: Expecting 41600 events.
[11:46:55.082] INFO: 41600 events read in total (2682ms).
[11:46:55.083] INFO: Test took 3894ms.
[11:46:55.117] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:46:55.837] INFO: Expecting 41600 events.
[11:46:59.081] INFO: 41600 events read in total (2717ms).
[11:46:59.082] INFO: Test took 3946ms.
[11:46:59.117] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:46:59.834] INFO: Expecting 41600 events.
[11:47:03.099] INFO: 41600 events read in total (2738ms).
[11:47:03.100] INFO: Test took 3966ms.
[11:47:03.135] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:03.857] INFO: Expecting 41600 events.
[11:47:07.069] INFO: 41600 events read in total (2685ms).
[11:47:07.071] INFO: Test took 3918ms.
[11:47:07.105] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:07.826] INFO: Expecting 41600 events.
[11:47:11.111] INFO: 41600 events read in total (2759ms).
[11:47:11.112] INFO: Test took 3989ms.
[11:47:11.146] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:11.867] INFO: Expecting 41600 events.
[11:47:15.143] INFO: 41600 events read in total (2750ms).
[11:47:15.144] INFO: Test took 3981ms.
[11:47:15.178] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:15.898] INFO: Expecting 41600 events.
[11:47:19.154] INFO: 41600 events read in total (2730ms).
[11:47:19.155] INFO: Test took 3959ms.
[11:47:19.190] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:19.914] INFO: Expecting 41600 events.
[11:47:23.179] INFO: 41600 events read in total (2738ms).
[11:47:23.180] INFO: Test took 3972ms.
[11:47:23.214] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:23.930] INFO: Expecting 41600 events.
[11:47:27.224] INFO: 41600 events read in total (2767ms).
[11:47:27.225] INFO: Test took 3993ms.
[11:47:27.260] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:27.979] INFO: Expecting 41600 events.
[11:47:31.192] INFO: 41600 events read in total (2686ms).
[11:47:31.193] INFO: Test took 3915ms.
[11:47:31.227] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:31.944] INFO: Expecting 41600 events.
[11:47:35.296] INFO: 41600 events read in total (2825ms).
[11:47:35.297] INFO: Test took 4052ms.
[11:47:35.331] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:36.056] INFO: Expecting 41600 events.
[11:47:39.244] INFO: 41600 events read in total (2661ms).
[11:47:39.245] INFO: Test took 3896ms.
[11:47:39.279] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:39.989] INFO: Expecting 41600 events.
[11:47:43.222] INFO: 41600 events read in total (2707ms).
[11:47:43.223] INFO: Test took 3926ms.
[11:47:43.258] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:43.976] INFO: Expecting 41600 events.
[11:47:47.221] INFO: 41600 events read in total (2718ms).
[11:47:47.222] INFO: Test took 3945ms.
[11:47:47.256] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:47.978] INFO: Expecting 41600 events.
[11:47:51.252] INFO: 41600 events read in total (2747ms).
[11:47:51.253] INFO: Test took 3979ms.
[11:47:51.288] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:52.007] INFO: Expecting 41600 events.
[11:47:55.164] INFO: 41600 events read in total (2630ms).
[11:47:55.165] INFO: Test took 3858ms.
[11:47:55.199] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:47:55.575] INFO: enter test to run
[11:48:25.815] INFO: test: HighRate no parameter change
[11:48:25.815] INFO: running: highrate
[11:48:25.817] INFO: ----------------------------------------------------------------------
[11:48:25.817] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:48:25.817] INFO: ----------------------------------------------------------------------
[11:48:26.437] INFO: Expecting 208000 events.
[11:48:38.805] INFO: 208000 events read in total (11841ms).
[11:48:38.808] INFO: Test took 12981ms.
[11:48:38.956] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:48:39.210] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 1 8 0 0 1 0 0 0 0 0
[11:48:39.210] INFO: number of red-efficiency pixels: 59 45 76 115 128 114 157 89 82 171 140 112 115 74 15 18
[11:48:39.210] INFO: number of X-ray hits detected: 66404 40811 58674 92686 99111 103919 105186 60817 83824 113432 112938 93811 100618 56913 22544 25404
[11:48:39.210] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:48:39.210] INFO: number of Vcal hits detected: 207938 207954 207924 207884 207868 207883 207790 207517 207918 207823 207800 207887 207882 207925 207985 207982
[11:48:39.210] 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 100.0 99.9 100.0 100.0 100.0
[11:48:39.210] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.8 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[11:48:39.210] INFO: X-ray hit rate [MHz/cm2]: 19.5 12.0 17.2 27.2 29.1 30.5 30.8 17.8 24.6 33.2 33.1 27.5 29.5 16.7 6.6 7.4
[11:48:39.210] INFO: PixTestHighRate::doXPixelAlive() done
[11:48:39.263] INFO: PixTest:: pg_setup set to default.
[11:48:39.279] INFO: enter test to run
[11:49:04.799] INFO: test: HighRate no parameter change
[11:49:04.799] INFO: running: highrate
[11:49:04.800] INFO: ----------------------------------------------------------------------
[11:49:04.800] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:49:04.800] INFO: ----------------------------------------------------------------------
[11:49:05.423] INFO: Expecting 208000 events.
[11:49:19.313] INFO: 208000 events read in total (13364ms).
[11:49:19.318] INFO: Test took 14509ms.
[11:49:19.612] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:19.920] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 1 8 0 0 1 0 0 0 0 0
[11:49:19.920] INFO: number of red-efficiency pixels: 206 145 236 358 433 365 483 211 353 538 444 399 360 253 65 63
[11:49:19.920] INFO: number of X-ray hits detected: 137560 83988 120863 191546 203020 214993 217556 126770 174724 233665 233520 193809 209159 117839 46585 53034
[11:49:19.920] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:49:19.920] INFO: number of Vcal hits detected: 207779 207848 207741 207631 207526 207605 207426 207392 207628 207401 207460 207547 207608 207726 207933 207935
[11:49:19.920] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.8 99.7 99.8 99.8 99.8 99.9 100.0 100.0
[11:49:19.920] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.7 99.7 99.8 99.7 99.7 99.8 99.8 99.9 100.0 100.0
[11:49:19.920] INFO: X-ray hit rate [MHz/cm2]: 40.3 24.6 35.4 56.1 59.5 63.0 63.8 37.2 51.2 68.5 68.4 56.8 61.3 34.5 13.7 15.5
[11:49:19.920] INFO: PixTestHighRate::doXPixelAlive() done
[11:49:19.967] INFO: PixTest:: pg_setup set to default.
[11:49:19.986] INFO: enter test to run
[11:49:41.471] INFO: test: HighRate no parameter change
[11:49:41.471] INFO: running: highrate
[11:49:41.472] INFO: ----------------------------------------------------------------------
[11:49:41.472] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:49:41.472] INFO: ----------------------------------------------------------------------
[11:49:42.094] INFO: Expecting 208000 events.
[11:49:58.202] INFO: 208000 events read in total (15581ms).
[11:49:58.209] INFO: Test took 16727ms.
[11:49:58.662] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:59.014] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 1 8 0 0 1 0 0 0 0 0
[11:49:59.015] INFO: number of red-efficiency pixels: 437 279 541 883 1039 846 1250 469 742 1346 1012 966 830 557 85 106
[11:49:59.015] INFO: number of X-ray hits detected: 208793 127507 183812 290271 307630 325349 329893 191928 263981 353141 352158 292358 316144 178430 71118 80071
[11:49:59.015] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:49:59.015] INFO: number of Vcal hits detected: 207496 207691 207341 206949 206761 206985 206368 207098 207077 206212 206680 206787 207004 207292 207911 207891
[11:49:59.015] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.5 99.5 99.6 99.3 99.8 99.6 99.2 99.4 99.5 99.6 99.7 100.0 99.9
[11:49:59.015] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.5 99.4 99.5 99.2 99.6 99.6 99.1 99.4 99.4 99.5 99.7 100.0 99.9
[11:49:59.015] INFO: X-ray hit rate [MHz/cm2]: 61.2 37.4 53.9 85.1 90.2 95.4 96.7 56.3 77.4 103.5 103.2 85.7 92.7 52.3 20.8 23.5
[11:49:59.015] INFO: PixTestHighRate::doXPixelAlive() done
[11:49:59.062] INFO: PixTest:: pg_setup set to default.
[11:49:59.081] INFO: enter test to run
[11:50:29.222] INFO: test: exit no parameter change
[11:50:29.650] QUIET: Connection to board 33 closed.
[11:50:29.666] INFO: pXar: this is the end, my friend