[17:25:26.012] INFO: *** Welcome to pxar ***
[17:25:26.012] INFO: *** Today: 2016/09/28
[17:25:26.069] INFO: *** Version: v1.9.0-818-g96727
[17:25:26.069] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//dacParameters35_C15.dat
[17:25:26.109] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//tbmParameters_C0b.dat
[17:25:26.109] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//defaultMaskFile.dat
[17:25:26.126] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C15.dat
[17:25:26.221] INFO: clk: 4
[17:25:26.221] INFO: ctr: 4
[17:25:26.222] INFO: sda: 19
[17:25:26.222] INFO: tin: 9
[17:25:26.222] INFO: level: 15
[17:25:26.222] INFO: triggerdelay: 0
[17:25:26.222] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[17:25:26.222] INFO: Log level: INFO
[17:25:26.239] QUIET: Connection to board DTB_WREHUL opened.
[17:25:26.243] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 30
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREHUL
MAC address: 40D85511801E
Hostname: pixelDTB030
Comment:
------------------------------------------------------
[17:25:26.245] INFO: RPC call hashes of host and DTB match: 398089610
[17:25:27.777] INFO: DUT info:
[17:25:27.777] INFO: The DUT currently contains the following objects:
[17:25:27.777] INFO: 2 TBM Cores tbm08c (2 ON)
[17:25:27.777] INFO: TBM Core alpha (0): 7 registers set
[17:25:27.777] INFO: TBM Core beta (1): 7 registers set
[17:25:27.777] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[17:25:27.777] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.777] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.777] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.777] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.777] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.777] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.777] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.778] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.778] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.778] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.778] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.778] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.778] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.778] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.778] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:27.778] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[17:25:28.186] INFO: enter 'restricted' command line mode
[17:25:28.186] INFO: enter test to run
[17:25:54.518] INFO: test: PixelAlive no parameter change
[17:25:54.791] INFO: running: pixelalive
[17:25:54.800] INFO: ----------------------------------------------------------------------
[17:25:54.800] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[17:25:54.800] INFO: ----------------------------------------------------------------------
[17:25:55.122] INFO: Expecting 41600 events.
[17:25:59.442] INFO: 41600 events read in total (3602ms).
[17:25:59.611] INFO: Test took 4807ms.
[17:25:59.620] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:25:59.907] INFO: PixTestAlive::aliveTest() done
[17:25:59.907] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 1 0 1 0 0 0 0
[17:25:59.938] INFO: enter test to run
[17:26:09.334] INFO: test: timing no parameter change
[17:26:09.334] INFO: running: timing
[17:26:09.337] INFO: ######################################################################
[17:26:09.337] INFO: PixTestTiming::doTest()
[17:26:09.337] INFO: ######################################################################
[17:26:09.337] INFO: ----------------------------------------------------------------------
[17:26:09.337] INFO: PixTestTiming::TBMPhaseScan()
[17:26:09.337] INFO: ----------------------------------------------------------------------
[17:31:39.217] INFO: TBM Phase Settings: 236
[17:31:39.217] INFO: 400MHz Phase: 3
[17:31:39.217] INFO: 160MHz Phase: 7
[17:31:39.217] INFO: Functional Phase Area: 3
[17:31:39.220] INFO: Test took 329883 ms.
[17:31:39.220] INFO: PixTestTiming::TBMPhaseScan() done.
[17:31:39.221] INFO: ----------------------------------------------------------------------
[17:31:39.221] INFO: PixTestTiming::ROCDelayScan()
[17:31:39.221] INFO: ----------------------------------------------------------------------
[17:33:34.739] INFO: ROC Delay Settings: 227
[17:33:34.739] INFO: ROC Header-Trailer/Token Delay: 11
[17:33:34.739] INFO: ROC Port 0 Delay: 3
[17:33:34.739] INFO: ROC Port 1 Delay: 4
[17:33:34.739] INFO: Functional ROC Area: 4
[17:33:34.743] INFO: Test took 115523 ms.
[17:33:34.743] INFO: PixTestTiming::ROCDelayScan() done.
[17:33:34.743] INFO: ----------------------------------------------------------------------
[17:33:34.743] INFO: PixTestTiming::TimingTest()
[17:33:34.743] INFO: ----------------------------------------------------------------------
[17:33:51.051] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:34:06.048] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:34:21.243] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:34:36.391] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:34:51.543] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:35:06.754] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:35:21.916] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:35:37.156] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:35:52.316] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:36:07.613] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:36:07.993] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:36:08.011] INFO: ----------------------------------------------------------------------
[17:36:08.011] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[17:36:08.011] INFO: ----------------------------------------------------------------------
[17:36:08.011] INFO: ----------------------------------------------------------------------
[17:36:08.011] INFO: Read back bit status: 1
[17:36:08.011] INFO: ----------------------------------------------------------------------
[17:36:08.011] INFO: ----------------------------------------------------------------------
[17:36:08.011] INFO: Timings are good!
[17:36:08.011] INFO: ----------------------------------------------------------------------
[17:36:08.011] INFO: Test took 153268 ms.
[17:36:08.011] INFO: PixTestTiming::TimingTest() done.
[17:36:08.026] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//tbmParameters_C0a.dat
[17:36:08.026] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//tbmParameters_C0b.dat
[17:36:08.026] INFO: PixTestTiming::doTest took 598692 ms.
[17:36:08.026] INFO: PixTestTiming::doTest() done
[17:36:08.026] INFO: Write out TBMPhaseScan_0_V0
[17:36:08.027] INFO: Write out TBMPhaseScan_1_V0
[17:36:08.027] INFO: Write out CombinedTBMPhaseScan_V0
[17:36:08.042] INFO: Write out ROCDelayScan3_V0
[17:36:08.042] INFO: enter test to run
[17:36:47.857] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[17:36:47.857] INFO: running: highrate
[17:36:47.886] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[17:36:48.177] INFO: ----------------------------------------------------------------------
[17:36:48.177] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[17:36:48.177] INFO: ----------------------------------------------------------------------
[17:36:48.177] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[17:36:48.177] INFO: edge/corner pixel THR is adjusted
[17:36:48.177] INFO: PixTestHighRate::trimHotPixels: step 0...
[17:36:49.156] INFO: Collecting data for 5 seconds...
[17:36:54.175] INFO: Done with hot pixel readout
[17:37:06.053] INFO: PixTest:: pg_setup set to default.
[17:37:06.054] INFO: 23 hot pixels found in step 0
[17:37:07.049] INFO: Collecting data for 5 seconds...
[17:37:12.067] INFO: Done with hot pixel readout
[17:37:24.008] INFO: PixTest:: pg_setup set to default.
[17:37:24.009] INFO: 23 hot pixels found in step 1
[17:37:24.004] INFO: Collecting data for 5 seconds...
[17:37:30.022] INFO: Done with hot pixel readout
[17:37:41.955] INFO: PixTest:: pg_setup set to default.
[17:37:41.956] INFO: 22 hot pixels found in step 2
[17:37:42.951] INFO: Collecting data for 5 seconds...
[17:37:47.968] INFO: Done with hot pixel readout
[17:37:59.871] INFO: PixTest:: pg_setup set to default.
[17:37:59.872] INFO: 16 hot pixels found in step 3
[17:38:00.866] INFO: Collecting data for 5 seconds...
[17:38:05.884] INFO: Done with hot pixel readout
[17:38:17.803] INFO: PixTest:: pg_setup set to default.
[17:38:17.804] INFO: 14 hot pixels found in step 4
[17:38:18.798] INFO: Collecting data for 5 seconds...
[17:38:23.816] INFO: Done with hot pixel readout
[17:38:35.728] INFO: PixTest:: pg_setup set to default.

[17:38:35.728] INFO: 14 hot pixels found in step 5
[17:38:36.724] INFO: Collecting data for 5 seconds...
[17:38:41.742] INFO: Done with hot pixel readout
[17:38:53.731] INFO: PixTest:: pg_setup set to default.

[17:38:53.732] INFO: 15 hot pixels found in step 6
[17:38:54.728] INFO: Collecting data for 5 seconds...
[17:38:59.746] INFO: Done with hot pixel readout
[17:39:11.669] INFO: PixTest:: pg_setup set to default.

[17:39:11.670] INFO: 12 hot pixels found in step 7
[17:39:12.665] INFO: Collecting data for 5 seconds...
[17:39:17.683] INFO: Done with hot pixel readout
[17:39:29.465] INFO: PixTest:: pg_setup set to default.

[17:39:29.466] INFO: 14 hot pixels found in step 8
[17:39:30.461] INFO: Collecting data for 5 seconds...
[17:39:35.477] INFO: Done with hot pixel readout
[17:39:45.831] INFO: PixTest:: pg_setup set to default.

[17:39:45.832] INFO: 9 hot pixels found in step 9
[17:39:46.826] INFO: Collecting data for 5 seconds...
[17:39:51.843] INFO: Done with hot pixel readout
[17:40:02.687] INFO: PixTest:: pg_setup set to default.

[17:40:02.688] INFO: 9 hot pixels found in step 10
[17:40:03.690] INFO: Collecting data for 5 seconds...
[17:40:08.708] INFO: Done with hot pixel readout
[17:40:20.382] INFO: PixTest:: pg_setup set to default.

[17:40:20.383] INFO: 5 hot pixels found in step 11
[17:40:21.377] INFO: Collecting data for 5 seconds...
[17:40:26.395] INFO: Done with hot pixel readout
[17:40:38.029] INFO: PixTest:: pg_setup set to default.

[17:40:38.030] INFO: 8 hot pixels found in step 12
[17:40:39.023] INFO: Collecting data for 5 seconds...
[17:40:44.041] INFO: Done with hot pixel readout
[17:40:55.697] INFO: PixTest:: pg_setup set to default.

[17:40:55.698] INFO: 8 hot pixels found in step 13
[17:40:56.693] INFO: Collecting data for 5 seconds...
[17:41:01.711] INFO: Done with hot pixel readout
[17:41:13.436] INFO: PixTest:: pg_setup set to default.

[17:41:13.437] INFO: 5 hot pixels found in step 14
[17:41:13.484] INFO: 5 hot pixels could not be trimmed and have been masked.
[17:41:13.487] INFO: PixTest::trimHotPixels() done
[17:41:13.499] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C0.dat
[17:41:13.505] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C1.dat
[17:41:13.511] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C2.dat
[17:41:13.517] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C3.dat
[17:41:13.523] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C4.dat
[17:41:13.528] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C5.dat
[17:41:13.534] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C6.dat
[17:41:13.539] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C7.dat
[17:41:13.555] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C8.dat
[17:41:13.563] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C9.dat
[17:41:13.568] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C10.dat
[17:41:13.573] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C11.dat
[17:41:13.579] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C12.dat
[17:41:13.584] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C13.dat
[17:41:13.589] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C14.dat
[17:41:13.595] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C15.dat
[17:41:13.600] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//defaultMaskFile.dat
[17:41:13.618] INFO: enter test to run
[17:41:43.631] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[17:41:43.631] INFO: running: highrate
[17:41:43.636] INFO: ----------------------------------------------------------------------
[17:41:43.636] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[17:41:43.636] INFO: ----------------------------------------------------------------------
[17:41:43.636] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[17:41:43.636] INFO: edge/corner pixel THR is adjusted
[17:41:43.636] INFO: PixTestHighRate::trimHotPixels: step 0...
[17:41:44.594] INFO: Collecting data for 1 seconds...
[17:41:45.598] INFO: Done with hot pixel readout
[17:41:49.618] INFO: PixTest:: pg_setup set to default.
[17:41:49.619] INFO: 0 hot pixels found in step 0
[17:41:49.624] INFO: 0 hot pixels could not be trimmed and have been masked.
[17:41:49.710] INFO: PixTest::trimHotPixels() done
[17:41:49.710] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C0.dat
[17:41:49.720] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C1.dat
[17:41:49.725] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C2.dat
[17:41:49.731] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C3.dat
[17:41:49.736] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C4.dat
[17:41:49.741] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C5.dat
[17:41:49.747] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C6.dat
[17:41:49.752] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C7.dat
[17:41:49.757] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C8.dat
[17:41:49.762] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C9.dat
[17:41:49.768] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C10.dat
[17:41:49.773] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C11.dat
[17:41:49.778] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C12.dat
[17:41:49.784] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C13.dat
[17:41:49.789] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C14.dat
[17:41:49.794] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//trimParameters35_C15.dat
[17:41:49.800] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-3-47_FPIXTest-17C-FNAL-160915-0919-150V_2016-09-15_09h19m_1473949154/000_FPIXTest_p17//defaultMaskFile.dat
[17:41:49.810] INFO: enter test to run
[17:42:10.799] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[17:42:10.799] INFO: running: xray
[17:42:10.800] INFO: ----------------------------------------------------------------------
[17:42:10.800] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[17:42:10.800] INFO: ----------------------------------------------------------------------
[17:42:11.783] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[17:42:22.634] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[17:42:52.241] INFO: Resuming triggers.
[17:43:03.090] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[17:43:32.674] INFO: Resuming triggers.
[17:43:43.524] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[17:44:12.978] INFO: Resuming triggers.
[17:44:23.834] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[17:44:53.968] INFO: Resuming triggers.
[17:45:04.821] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[17:45:35.062] INFO: Resuming triggers.
[17:45:45.918] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[17:46:16.155] INFO: Resuming triggers.
[17:46:27.011] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[17:46:56.580] INFO: Resuming triggers.
[17:47:07.436] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[17:47:37.487] INFO: Resuming triggers.
[17:47:48.343] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[17:48:18.770] INFO: Resuming triggers.
[17:48:21.469] INFO: data taking finished, elapsed time: 100 seconds.
[17:48:29.310] INFO: PixTest:: pg_setup set to default.
[17:48:29.313] INFO: PixTestXray::doPhRun() done
[17:48:29.472] INFO: enter test to run
[17:49:01.180] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[17:49:01.180] INFO: running: xray
[17:49:01.182] INFO: ----------------------------------------------------------------------
[17:49:01.182] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[17:49:01.182] INFO: ----------------------------------------------------------------------
[17:49:02.145] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[17:49:08.727] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[17:49:39.224] INFO: Resuming triggers.
[17:49:45.809] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[17:50:15.940] INFO: Resuming triggers.
[17:50:22.524] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[17:50:52.703] INFO: Resuming triggers.
[17:50:59.288] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[17:51:29.303] INFO: Resuming triggers.
[17:51:35.884] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[17:52:06.061] INFO: Resuming triggers.
[17:52:12.642] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[17:52:42.716] INFO: Resuming triggers.
[17:52:49.296] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[17:53:19.490] INFO: Resuming triggers.
[17:53:26.070] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[17:53:56.241] INFO: Resuming triggers.
[17:54:02.822] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[17:54:32.883] INFO: Resuming triggers.
[17:54:39.463] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[17:55:09.454] INFO: Resuming triggers.
[17:55:16.034] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[17:55:46.052] INFO: Resuming triggers.
[17:55:52.631] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[17:56:22.909] INFO: Resuming triggers.
[17:56:29.491] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[17:56:59.023] INFO: Resuming triggers.
[17:57:05.606] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[17:57:36.175] INFO: Resuming triggers.
[17:57:42.759] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[17:58:13.430] INFO: Resuming triggers.
[17:58:15.065] INFO: data taking finished, elapsed time: 100 seconds.
[17:58:23.145] INFO: PixTest:: pg_setup set to default.
[17:58:23.148] INFO: PixTestXray::doPhRun() done
[17:58:23.367] INFO: enter test to run
[17:58:40.401] INFO: test: HighRate no parameter change
[17:58:40.401] INFO: running: highrate
[17:58:40.416] INFO: ----------------------------------------------------------------------
[17:58:40.416] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[17:58:40.416] INFO: ----------------------------------------------------------------------
[17:58:40.575] INFO: Expecting 768 events.
[17:58:41.721] INFO: 768 events read in total (431ms).
[17:58:41.722] INFO: Test took 1285ms.
[17:58:42.525] INFO: Expecting 41600 events.
[17:58:45.721] INFO: 41600 events read in total (2669ms).
[17:58:45.722] INFO: Test took 3957ms.
[17:58:45.759] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:46.478] INFO: Expecting 41600 events.
[17:58:49.745] INFO: 41600 events read in total (2740ms).
[17:58:49.746] INFO: Test took 3969ms.
[17:58:49.784] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:50.502] INFO: Expecting 41600 events.
[17:58:53.751] INFO: 41600 events read in total (2722ms).
[17:58:53.752] INFO: Test took 3948ms.
[17:58:53.790] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:54.506] INFO: Expecting 41600 events.
[17:58:57.589] INFO: 41600 events read in total (2556ms).
[17:58:57.590] INFO: Test took 3782ms.
[17:58:57.631] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:58.333] INFO: Expecting 41600 events.
[17:59:01.575] INFO: 41600 events read in total (2716ms).
[17:59:01.576] INFO: Test took 3926ms.
[17:59:01.620] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:02.317] INFO: Expecting 41600 events.
[17:59:05.546] INFO: 41600 events read in total (2702ms).
[17:59:05.547] INFO: Test took 3908ms.
[17:59:05.585] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:06.299] INFO: Expecting 41600 events.
[17:59:09.546] INFO: 41600 events read in total (2720ms).
[17:59:09.547] INFO: Test took 3941ms.
[17:59:09.584] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:10.297] INFO: Expecting 41600 events.
[17:59:13.613] INFO: 41600 events read in total (2789ms).
[17:59:13.614] INFO: Test took 4012ms.
[17:59:13.652] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:14.372] INFO: Expecting 41600 events.
[17:59:17.605] INFO: 41600 events read in total (2706ms).
[17:59:17.606] INFO: Test took 3935ms.
[17:59:17.643] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:18.357] INFO: Expecting 41600 events.
[17:59:21.639] INFO: 41600 events read in total (2755ms).
[17:59:21.640] INFO: Test took 3978ms.
[17:59:21.678] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:22.392] INFO: Expecting 41600 events.
[17:59:25.662] INFO: 41600 events read in total (2743ms).
[17:59:25.663] INFO: Test took 3967ms.
[17:59:25.701] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:26.418] INFO: Expecting 41600 events.
[17:59:29.773] INFO: 41600 events read in total (2829ms).
[17:59:29.774] INFO: Test took 4053ms.
[17:59:29.814] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:30.524] INFO: Expecting 41600 events.
[17:59:33.871] INFO: 41600 events read in total (2820ms).
[17:59:33.872] INFO: Test took 4039ms.
[17:59:33.910] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:34.628] INFO: Expecting 41600 events.
[17:59:37.829] INFO: 41600 events read in total (2674ms).
[17:59:37.830] INFO: Test took 3902ms.
[17:59:37.868] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:38.585] INFO: Expecting 41600 events.
[17:59:41.876] INFO: 41600 events read in total (2765ms).
[17:59:41.877] INFO: Test took 3990ms.
[17:59:41.917] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:42.617] INFO: Expecting 41600 events.
[17:59:45.927] INFO: 41600 events read in total (2783ms).
[17:59:45.928] INFO: Test took 3992ms.
[17:59:45.966] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:46.679] INFO: Expecting 41600 events.
[17:59:49.006] INFO: 41600 events read in total (2800ms).
[17:59:50.007] INFO: Test took 4022ms.
[17:59:50.045] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:50.758] INFO: Expecting 41600 events.
[17:59:54.040] INFO: 41600 events read in total (2755ms).
[17:59:54.041] INFO: Test took 3977ms.
[17:59:54.080] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:54.796] INFO: Expecting 41600 events.
[17:59:58.035] INFO: 41600 events read in total (2712ms).
[17:59:58.036] INFO: Test took 3937ms.
[17:59:58.073] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:58.790] INFO: Expecting 41600 events.
[18:00:01.785] INFO: 41600 events read in total (2469ms).
[18:00:01.786] INFO: Test took 3694ms.
[18:00:01.824] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:00:02.171] INFO: enter test to run
[18:00:12.408] INFO: test: HighRate no parameter change
[18:00:12.408] INFO: running: highrate
[18:00:12.409] INFO: ----------------------------------------------------------------------
[18:00:12.409] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:00:12.409] INFO: ----------------------------------------------------------------------
[18:00:13.030] INFO: Expecting 208000 events.
[18:00:25.013] INFO: 208000 events read in total (11456ms).
[18:00:25.016] INFO: Test took 12600ms.
[18:00:25.178] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:00:25.437] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 1 0 1 0 0 0 0
[18:00:25.438] INFO: number of red-efficiency pixels: 101 65 109 170 156 172 137 108 125 131 133 112 126 91 25 34
[18:00:25.438] INFO: number of X-ray hits detected: 79995 49883 74294 114498 116965 120911 117528 82677 82976 115486 115178 96918 97996 63958 26380 27823
[18:00:25.438] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:00:25.438] INFO: number of Vcal hits detected: 207897 207935 207884 207824 207840 207827 207862 207888 207875 207815 207864 207837 207874 207909 207974 207932
[18:00:25.438] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[18:00:25.438] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 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
[18:00:25.438] INFO: X-ray hit rate [MHz/cm2]: 23.4 14.6 21.8 33.6 34.3 35.4 34.4 24.2 24.3 33.8 33.8 28.4 28.7 18.7 7.7 8.2
[18:00:25.438] INFO: PixTestHighRate::doXPixelAlive() done
[18:00:25.483] INFO: PixTest:: pg_setup set to default.
[18:00:25.495] INFO: enter test to run
[18:00:39.776] INFO: test: HighRate no parameter change
[18:00:39.776] INFO: running: highrate
[18:00:39.777] INFO: ----------------------------------------------------------------------
[18:00:39.777] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:00:39.777] INFO: ----------------------------------------------------------------------
[18:00:40.401] INFO: Expecting 208000 events.
[18:00:54.187] INFO: 208000 events read in total (13259ms).
[18:00:54.193] INFO: Test took 14407ms.
[18:00:54.507] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:00:54.820] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0
[18:00:54.820] INFO: number of red-efficiency pixels: 352 157 362 585 518 552 452 390 333 406 440 330 309 271 70 65
[18:00:54.821] INFO: number of X-ray hits detected: 162820 101216 151990 233337 237614 246190 240184 168185 168404 235226 234093 198628 198342 130396 53244 57646
[18:00:54.821] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:00:54.821] INFO: number of Vcal hits detected: 207596 207837 207592 207353 207432 207382 207519 207573 207646 207509 207518 207601 207678 207704 207928 207914
[18:00:54.821] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.7 99.8 99.7 99.8 99.8 99.8 99.8 99.8 99.8 99.9 99.9 100.0 100.0
[18:00:54.821] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.7 99.7 99.7 99.8 99.8 99.8 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[18:00:54.821] INFO: X-ray hit rate [MHz/cm2]: 47.7 29.7 44.5 68.4 69.6 72.2 70.4 49.3 49.4 68.9 68.6 58.2 58.1 38.2 15.6 16.9
[18:00:54.821] INFO: PixTestHighRate::doXPixelAlive() done
[18:00:54.869] INFO: PixTest:: pg_setup set to default.
[18:00:54.883] INFO: enter test to run
[18:01:08.087] INFO: test: HighRate no parameter change
[18:01:08.088] INFO: running: highrate
[18:01:08.089] INFO: ----------------------------------------------------------------------
[18:01:08.089] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:01:08.089] INFO: ----------------------------------------------------------------------
[18:01:08.710] INFO: Expecting 208000 events.
[18:01:24.861] INFO: 208000 events read in total (15624ms).
[18:01:24.869] INFO: Test took 16770ms.
[18:01:25.354] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:01:25.715] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 1 0 1 0 0 0 0
[18:01:25.715] INFO: number of red-efficiency pixels: 723 227 760 1230 1104 1197 946 808 744 939 954 685 683 591 113 115
[18:01:25.715] INFO: number of X-ray hits detected: 236867 148586 220915 338573 346808 357497 347651 244864 246598 341592 339437 289054 289850 190446 77749 83248
[18:01:25.715] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:01:25.715] INFO: number of Vcal hits detected: 207019 207755 206924 206366 206639 206489 206824 206931 207081 206812 206838 207158 207222 207257 207883 207858
[18:01:25.715] INFO: Vcal hit fiducial efficiency (%): 99.6 99.9 99.5 99.3 99.4 99.3 99.5 99.5 99.6 99.5 99.5 99.7 99.7 99.7 99.9 99.9
[18:01:25.715] INFO: Vcal hit overall efficiency (%): 99.5 99.9 99.5 99.2 99.3 99.3 99.4 99.5 99.6 99.4 99.4 99.6 99.6 99.6 99.9 99.9
[18:01:25.715] INFO: X-ray hit rate [MHz/cm2]: 69.4 43.6 64.8 99.2 101.7 104.8 101.9 71.8 72.3 100.1 99.5 84.7 85.0 55.8 22.8 24.4
[18:01:25.715] INFO: PixTestHighRate::doXPixelAlive() done
[18:01:25.763] INFO: PixTest:: pg_setup set to default.
[18:01:25.781] INFO: enter test to run
[18:01:33.767] INFO: test: exit no parameter change
[18:01:34.593] QUIET: Connection to board 30 closed.
[18:01:34.729] INFO: pXar: this is the end, my friend