[15:06:16.707] INFO: *** Welcome to pxar ***
[15:06:16.707] INFO: *** Today: 2016/06/22
[15:06:17.528] INFO: *** Version: v1.9.0-814-g7497
[15:06:17.528] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//dacParameters35_C15.dat
[15:06:17.606] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:06:17.606] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//defaultMaskFile.dat
[15:06:17.618] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C15.dat
[15:06:17.758] INFO: clk: 4
[15:06:17.758] INFO: ctr: 4
[15:06:17.758] INFO: sda: 19
[15:06:17.758] INFO: tin: 9
[15:06:17.758] INFO: level: 15
[15:06:17.758] INFO: triggerdelay: 0
[15:06:17.758] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:06:17.758] INFO: Log level: INFO
[15:06:17.805] QUIET: Connection to board DTB_WREKRL opened.
[15:06:17.808] 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:
------------------------------------------------------
[15:06:17.811] INFO: RPC call hashes of host and DTB match: 398089610
[15:06:19.347] INFO: DUT info:
[15:06:19.347] INFO: The DUT currently contains the following objects:
[15:06:19.347] INFO: 2 TBM Cores tbm08c (2 ON)
[15:06:19.347] INFO: TBM Core alpha (0): 7 registers set
[15:06:19.347] INFO: TBM Core beta (1): 7 registers set
[15:06:19.347] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:06:19.347] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.347] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.347] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.347] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.347] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.347] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.347] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.347] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.347] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.347] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.347] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.347] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.348] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.348] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.348] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.348] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:06:19.763] INFO: enter 'restricted' command line mode
[15:06:19.763] INFO: enter test to run
[15:06:21.038] INFO: test: timing no parameter change
[15:06:21.038] INFO: running: timing
[15:06:21.061] INFO: ######################################################################
[15:06:21.063] INFO: PixTestTiming::doTest()
[15:06:21.063] INFO: ######################################################################
[15:06:21.064] INFO: ----------------------------------------------------------------------
[15:06:21.064] INFO: PixTestTiming::TBMPhaseScan()
[15:06:21.064] INFO: ----------------------------------------------------------------------
[15:12:14.322] INFO: TBM Phase Settings: 224
[15:12:14.346] INFO: 400MHz Phase: 0
[15:12:14.346] INFO: 160MHz Phase: 7
[15:12:14.346] INFO: Functional Phase Area: 4
[15:12:14.375] INFO: Test took 353312 ms.
[15:12:14.375] INFO: PixTestTiming::TBMPhaseScan() done.
[15:12:14.375] INFO: ----------------------------------------------------------------------
[15:12:14.375] INFO: PixTestTiming::ROCDelayScan()
[15:12:14.375] INFO: ----------------------------------------------------------------------
[15:15:10.082] INFO: ROC Delay Settings: 228
[15:15:10.082] INFO: ROC Header-Trailer/Token Delay: 11
[15:15:10.082] INFO: ROC Port 0 Delay: 4
[15:15:10.082] INFO: ROC Port 1 Delay: 4
[15:15:10.082] INFO: Functional ROC Area: 5
[15:15:10.085] INFO: Test took 175710 ms.
[15:15:10.085] INFO: PixTestTiming::ROCDelayScan() done.
[15:15:10.085] INFO: ----------------------------------------------------------------------
[15:15:10.085] INFO: PixTestTiming::TimingTest()
[15:15:10.085] INFO: ----------------------------------------------------------------------
[15:15:26.199] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:15:40.964] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:15:55.847] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:10.629] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:25.420] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:40.196] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:54.980] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:09.984] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:25.053] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:40.098] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:40.475] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:40.492] INFO: ----------------------------------------------------------------------
[15:17:40.492] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:17:40.492] INFO: ----------------------------------------------------------------------
[15:17:40.492] INFO: ----------------------------------------------------------------------
[15:17:40.492] INFO: Read back bit status: 1
[15:17:40.492] INFO: ----------------------------------------------------------------------
[15:17:40.492] INFO: ----------------------------------------------------------------------
[15:17:40.492] INFO: Timings are good!
[15:17:40.492] INFO: ----------------------------------------------------------------------
[15:17:40.492] INFO: Test took 150407 ms.
[15:17:40.492] INFO: PixTestTiming::TimingTest() done.
[15:17:40.511] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:17:40.531] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:17:40.531] INFO: PixTestTiming::doTest took 679475 ms.
[15:17:40.531] INFO: PixTestTiming::doTest() done
[15:17:40.531] INFO: Write out TBMPhaseScan_0_V0
[15:17:41.283] INFO: Write out TBMPhaseScan_1_V0
[15:17:41.285] INFO: Write out CombinedTBMPhaseScan_V0
[15:17:41.415] INFO: Write out ROCDelayScan3_V0
[15:17:41.438] INFO: enter test to run
[15:19:19.940] INFO: test: PixelAlive no parameter change
[15:19:19.940] INFO: running: pixelalive
[15:19:19.994] INFO: ----------------------------------------------------------------------
[15:19:19.994] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[15:19:19.994] INFO: ----------------------------------------------------------------------
[15:19:20.340] INFO: Expecting 41600 events.
[15:19:24.712] INFO: 41600 events read in total (3657ms).
[15:19:24.713] INFO: Test took 4701ms.
[15:19:24.748] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:25.101] INFO: PixTestAlive::aliveTest() done
[15:19:25.101] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1
[15:19:25.104] INFO: enter test to run
[15:21:32.640] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:21:32.640] INFO: running: highrate
[15:21:32.725] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:21:33.642] INFO: ----------------------------------------------------------------------
[15:21:33.642] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:21:33.642] INFO: ----------------------------------------------------------------------
[15:21:33.642] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:21:33.642] INFO: edge/corner pixel THR is adjusted
[15:21:33.642] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:21:34.663] INFO: Collecting data for 5 seconds...
[15:21:39.682] INFO: Done with hot pixel readout
[15:21:51.655] INFO: PixTest:: pg_setup set to default.


[15:21:51.655] INFO: 5 hot pixels found in step 0
[15:21:52.651] INFO: Collecting data for 5 seconds...
[15:21:57.669] INFO: Done with hot pixel readout
[15:22:09.815] INFO: PixTest:: pg_setup set to default.


[15:22:09.816] INFO: 7 hot pixels found in step 1
[15:22:10.813] INFO: Collecting data for 5 seconds...
[15:22:15.832] INFO: Done with hot pixel readout
[15:22:27.976] INFO: PixTest:: pg_setup set to default.
[15:22:27.977] INFO: 7 hot pixels found in step 2
[15:22:28.972] INFO: Collecting data for 5 seconds...
[15:22:33.990] INFO: Done with hot pixel readout
[15:22:45.950] INFO: PixTest:: pg_setup set to default.

[15:22:45.951] INFO: 8 hot pixels found in step 3
[15:22:46.946] INFO: Collecting data for 5 seconds...
[15:22:51.962] INFO: Done with hot pixel readout
[15:23:03.558] INFO: PixTest:: pg_setup set to default.
[15:23:03.558] INFO: 7 hot pixels found in step 4
[15:23:04.555] INFO: Collecting data for 5 seconds...
[15:23:09.572] INFO: Done with hot pixel readout
[15:23:19.610] INFO: PixTest:: pg_setup set to default.

[15:23:19.611] INFO: 4 hot pixels found in step 5
[15:23:20.605] INFO: Collecting data for 5 seconds...
[15:23:25.612] INFO: Done with hot pixel readout
[15:23:34.902] INFO: PixTest:: pg_setup set to default.

[15:23:34.903] INFO: 7 hot pixels found in step 6
[15:23:35.897] INFO: Collecting data for 5 seconds...
[15:23:40.906] INFO: Done with hot pixel readout
[15:23:52.755] INFO: PixTest:: pg_setup set to default.

[15:23:52.756] INFO: 9 hot pixels found in step 7
[15:23:53.752] INFO: Collecting data for 5 seconds...
[15:23:58.768] INFO: Done with hot pixel readout
[15:24:10.637] INFO: PixTest:: pg_setup set to default.

[15:24:10.638] INFO: 10 hot pixels found in step 8
[15:24:11.635] INFO: Collecting data for 5 seconds...
[15:24:16.651] INFO: Done with hot pixel readout
[15:24:28.510] INFO: PixTest:: pg_setup set to default.

[15:24:28.512] INFO: 5 hot pixels found in step 9
[15:24:29.506] INFO: Collecting data for 5 seconds...
[15:24:34.522] INFO: Done with hot pixel readout
[15:24:46.360] INFO: PixTest:: pg_setup set to default.


[15:24:46.361] INFO: 7 hot pixels found in step 10
[15:24:47.356] INFO: Collecting data for 5 seconds...
[15:24:52.372] INFO: Done with hot pixel readout
[15:25:04.274] INFO: PixTest:: pg_setup set to default.

[15:25:04.275] INFO: 5 hot pixels found in step 11
[15:25:05.271] INFO: Collecting data for 5 seconds...
[15:25:10.286] INFO: Done with hot pixel readout
[15:25:22.131] INFO: PixTest:: pg_setup set to default.

[15:25:22.132] INFO: 3 hot pixels found in step 12
[15:25:23.128] INFO: Collecting data for 5 seconds...
[15:25:28.145] INFO: Done with hot pixel readout
[15:25:40.031] INFO: PixTest:: pg_setup set to default.
[15:25:40.032] INFO: 4 hot pixels found in step 13
[15:25:41.027] INFO: Collecting data for 5 seconds...
[15:25:46.043] INFO: Done with hot pixel readout
[15:25:57.874] INFO: PixTest:: pg_setup set to default.

[15:25:57.875] INFO: 3 hot pixels found in step 14
[15:25:57.914] INFO: 3 hot pixels could not be trimmed and have been masked.
[15:25:57.918] INFO: PixTest::trimHotPixels() done
[15:25:57.918] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C0.dat
[15:25:57.923] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C1.dat
[15:25:57.929] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C2.dat
[15:25:57.935] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C3.dat
[15:25:57.941] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C4.dat
[15:25:57.946] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C5.dat
[15:25:57.951] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C6.dat
[15:25:57.956] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C7.dat
[15:25:57.961] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C8.dat
[15:25:57.976] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C9.dat
[15:25:57.999] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C10.dat
[15:25:58.004] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C11.dat
[15:25:58.010] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C12.dat
[15:25:58.015] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C13.dat
[15:25:58.020] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C14.dat
[15:25:58.025] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C15.dat
[15:25:58.051] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//defaultMaskFile.dat
[15:25:58.092] INFO: enter test to run
[15:26:47.774] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:26:47.774] INFO: running: highrate
[15:26:47.779] INFO: ----------------------------------------------------------------------
[15:26:47.779] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:26:47.779] INFO: ----------------------------------------------------------------------
[15:26:47.779] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:26:47.779] INFO: edge/corner pixel THR is adjusted
[15:26:47.779] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:26:48.736] INFO: Collecting data for 1 seconds...
[15:26:49.740] INFO: Done with hot pixel readout
[15:26:53.739] INFO: PixTest:: pg_setup set to default.
[15:26:53.740] INFO: 0 hot pixels found in step 0
[15:26:53.745] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:26:53.836] INFO: PixTest::trimHotPixels() done
[15:26:53.837] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C0.dat
[15:26:53.847] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C1.dat
[15:26:53.852] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C2.dat
[15:26:53.857] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C3.dat
[15:26:53.863] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C4.dat
[15:26:53.868] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C5.dat
[15:26:53.873] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C6.dat
[15:26:53.878] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C7.dat
[15:26:53.884] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C8.dat
[15:26:53.889] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C9.dat
[15:26:53.894] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C10.dat
[15:26:53.899] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C11.dat
[15:26:53.905] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C12.dat
[15:26:53.910] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C13.dat
[15:26:53.915] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C14.dat
[15:26:53.920] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//trimParameters35_C15.dat
[15:26:53.925] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-K-3-15_FPIXTest-17C-FNAL-160616-0922_2016-06-16_09h22m_1466086927/000_FPIXTest_p17//defaultMaskFile.dat
[15:26:53.935] INFO: enter test to run
[15:27:28.966] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:27:28.966] INFO: running: xray
[15:27:28.988] INFO: ----------------------------------------------------------------------
[15:27:28.988] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:27:28.988] INFO: ----------------------------------------------------------------------
[15:27:29.974] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:27:41.305] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:28:10.787] INFO: Resuming triggers.
[15:28:22.121] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:28:51.562] INFO: Resuming triggers.
[15:29:02.899] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[15:29:31.558] INFO: Resuming triggers.
[15:29:42.893] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:30:08.684] INFO: Resuming triggers.
[15:30:20.022] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[15:30:42.889] INFO: Resuming triggers.
[15:30:54.229] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[15:31:17.764] INFO: Resuming triggers.
[15:31:29.102] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[15:31:58.682] INFO: Resuming triggers.
[15:32:10.019] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[15:32:39.532] INFO: Resuming triggers.
[15:32:49.161] INFO: data taking finished, elapsed time: 100 seconds.
[15:33:14.469] INFO: PixTest:: pg_setup set to default.
[15:33:14.472] INFO: PixTestXray::doPhRun() done
[15:33:14.945] INFO: enter test to run
[15:35:35.962] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:35:35.963] INFO: running: xray
[15:35:35.964] INFO: ----------------------------------------------------------------------
[15:35:35.964] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:35:35.964] INFO: ----------------------------------------------------------------------
[15:35:36.927] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:35:43.620] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:36:14.459] INFO: Resuming triggers.
[15:36:21.152] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[15:36:51.385] INFO: Resuming triggers.
[15:36:58.086] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[15:37:28.039] INFO: Resuming triggers.
[15:37:34.736] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[15:38:04.910] INFO: Resuming triggers.
[15:38:11.611] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[15:38:41.723] INFO: Resuming triggers.
[15:38:48.420] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[15:39:18.553] INFO: Resuming triggers.
[15:39:25.253] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[15:39:55.395] INFO: Resuming triggers.
[15:40:02.099] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[15:40:32.224] INFO: Resuming triggers.
[15:40:38.925] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[15:41:06.871] INFO: Resuming triggers.
[15:41:13.571] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[15:41:43.767] INFO: Resuming triggers.
[15:41:50.469] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[15:42:20.683] INFO: Resuming triggers.
[15:42:27.380] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[15:42:54.686] INFO: Resuming triggers.
[15:43:01.387] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[15:43:30.376] INFO: Resuming triggers.
[15:43:37.073] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[15:44:08.381] INFO: Resuming triggers.
[15:44:14.920] INFO: data taking finished, elapsed time: 100 seconds.
[15:44:45.019] INFO: PixTest:: pg_setup set to default.
[15:44:45.022] INFO: PixTestXray::doPhRun() done
[15:44:45.174] INFO: enter test to run
[15:45:33.590] INFO: test: HighRate no parameter change
[15:45:33.590] INFO: running: highrate
[15:45:33.613] INFO: ----------------------------------------------------------------------
[15:45:33.613] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:45:33.613] INFO: ----------------------------------------------------------------------
[15:45:33.773] INFO: Expecting 768 events.
[15:45:34.912] INFO: 768 events read in total (424ms).
[15:45:34.912] INFO: Test took 1275ms.
[15:45:35.715] INFO: Expecting 41600 events.
[15:45:38.808] INFO: 41600 events read in total (2567ms).
[15:45:38.809] INFO: Test took 3855ms.
[15:45:38.843] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:39.562] INFO: Expecting 41600 events.
[15:45:42.925] INFO: 41600 events read in total (2836ms).
[15:45:42.926] INFO: Test took 4066ms.
[15:45:42.962] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:43.683] INFO: Expecting 41600 events.
[15:45:47.002] INFO: 41600 events read in total (2792ms).
[15:45:47.003] INFO: Test took 4024ms.
[15:45:47.038] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:47.755] INFO: Expecting 41600 events.
[15:45:51.093] INFO: 41600 events read in total (2811ms).
[15:45:51.094] INFO: Test took 4039ms.
[15:45:51.130] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:51.846] INFO: Expecting 41600 events.
[15:45:55.172] INFO: 41600 events read in total (2799ms).
[15:45:55.173] INFO: Test took 4026ms.
[15:45:55.208] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:55.926] INFO: Expecting 41600 events.
[15:45:59.195] INFO: 41600 events read in total (2742ms).
[15:45:59.196] INFO: Test took 3970ms.
[15:45:59.231] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:59.951] INFO: Expecting 41600 events.
[15:46:03.191] INFO: 41600 events read in total (2713ms).
[15:46:03.192] INFO: Test took 3943ms.
[15:46:03.226] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:03.948] INFO: Expecting 41600 events.
[15:46:07.317] INFO: 41600 events read in total (2842ms).
[15:46:07.318] INFO: Test took 4073ms.
[15:46:07.353] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:08.070] INFO: Expecting 41600 events.
[15:46:11.427] INFO: 41600 events read in total (2830ms).
[15:46:11.428] INFO: Test took 4058ms.
[15:46:11.464] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:12.180] INFO: Expecting 41600 events.
[15:46:15.483] INFO: 41600 events read in total (2776ms).
[15:46:15.484] INFO: Test took 4002ms.
[15:46:15.520] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:16.243] INFO: Expecting 41600 events.
[15:46:19.574] INFO: 41600 events read in total (2804ms).
[15:46:19.575] INFO: Test took 4037ms.
[15:46:19.610] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:20.332] INFO: Expecting 41600 events.
[15:46:23.697] INFO: 41600 events read in total (2838ms).
[15:46:23.698] INFO: Test took 4070ms.
[15:46:23.736] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:24.450] INFO: Expecting 41600 events.
[15:46:27.783] INFO: 41600 events read in total (2807ms).
[15:46:27.784] INFO: Test took 4030ms.
[15:46:27.820] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:28.542] INFO: Expecting 41600 events.
[15:46:31.980] INFO: 41600 events read in total (2911ms).
[15:46:31.981] INFO: Test took 4142ms.
[15:46:32.016] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:32.728] INFO: Expecting 41600 events.
[15:46:36.002] INFO: 41600 events read in total (2747ms).
[15:46:36.003] INFO: Test took 3970ms.
[15:46:36.039] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:36.760] INFO: Expecting 41600 events.
[15:46:40.067] INFO: 41600 events read in total (2780ms).
[15:46:40.068] INFO: Test took 4011ms.
[15:46:40.104] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:40.821] INFO: Expecting 41600 events.
[15:46:44.150] INFO: 41600 events read in total (2802ms).
[15:46:44.151] INFO: Test took 4029ms.
[15:46:44.187] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:44.908] INFO: Expecting 41600 events.
[15:46:48.252] INFO: 41600 events read in total (2817ms).
[15:46:48.253] INFO: Test took 4048ms.
[15:46:48.288] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:49.007] INFO: Expecting 41600 events.
[15:46:52.377] INFO: 41600 events read in total (2843ms).
[15:46:52.379] INFO: Test took 4073ms.
[15:46:52.423] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:53.115] INFO: Expecting 41600 events.
[15:46:56.268] INFO: 41600 events read in total (2626ms).
[15:46:56.269] INFO: Test took 3819ms.
[15:46:56.304] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:56.665] INFO: enter test to run
[15:47:24.677] INFO: test: HighRate no parameter change
[15:47:24.678] INFO: running: highrate
[15:47:24.679] INFO: ----------------------------------------------------------------------
[15:47:24.679] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:47:24.679] INFO: ----------------------------------------------------------------------
[15:47:25.298] INFO: Expecting 208000 events.
[15:47:37.135] INFO: 208000 events read in total (11310ms).
[15:47:37.138] INFO: Test took 12450ms.
[15:47:37.283] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:37.537] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1
[15:47:37.537] INFO: number of red-efficiency pixels: 73 51 90 142 123 136 164 125 85 109 110 76 93 54 24 29
[15:47:37.537] INFO: number of X-ray hits detected: 66431 45467 68243 110488 111769 118766 121482 90235 83679 92122 92494 79781 84288 50417 21353 23926
[15:47:37.537] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:47:37.537] INFO: number of Vcal hits detected: 207927 207948 207907 207858 207871 207861 207833 207874 207914 207890 207890 207923 207905 207945 207976 207922
[15:47:37.537] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[15:47:37.537] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[15:47:37.537] INFO: X-ray hit rate [MHz/cm2]: 19.5 13.3 20.0 32.4 32.8 34.8 35.6 26.4 24.5 27.0 27.1 23.4 24.7 14.8 6.3 7.0
[15:47:37.537] INFO: PixTestHighRate::doXPixelAlive() done
[15:47:37.588] INFO: PixTest:: pg_setup set to default.
[15:47:37.601] INFO: enter test to run
[15:48:20.989] INFO: test: HighRate no parameter change
[15:48:20.989] INFO: running: highrate
[15:48:20.990] INFO: ----------------------------------------------------------------------
[15:48:20.990] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:48:20.990] INFO: ----------------------------------------------------------------------
[15:48:21.607] INFO: Expecting 208000 events.
[15:48:35.113] INFO: 208000 events read in total (12979ms).
[15:48:35.118] INFO: Test took 14118ms.
[15:48:35.411] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:35.709] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1
[15:48:35.709] INFO: number of red-efficiency pixels: 167 137 303 512 409 398 560 358 232 351 366 217 238 166 50 64
[15:48:35.709] INFO: number of X-ray hits detected: 135865 91830 139789 225743 226783 243369 245625 184830 171019 188433 188011 162168 171271 103332 43830 49033
[15:48:35.709] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:48:35.709] INFO: number of Vcal hits detected: 207825 207856 207664 207447 207550 207558 207386 207616 207761 207631 207611 207775 207750 207825 207948 207887
[15:48:35.709] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.7 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[15:48:35.709] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.8 99.8 99.7 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 99.9
[15:48:35.709] INFO: X-ray hit rate [MHz/cm2]: 39.8 26.9 41.0 66.2 66.5 71.3 72.0 54.2 50.1 55.2 55.1 47.5 50.2 30.3 12.8 14.4
[15:48:35.709] INFO: PixTestHighRate::doXPixelAlive() done
[15:48:35.761] INFO: PixTest:: pg_setup set to default.
[15:48:35.777] INFO: enter test to run
[15:48:54.244] INFO: test: HighRate no parameter change
[15:48:54.245] INFO: running: highrate
[15:48:54.245] INFO: ----------------------------------------------------------------------
[15:48:54.245] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:48:54.245] INFO: ----------------------------------------------------------------------
[15:48:54.856] INFO: Expecting 208000 events.
[15:49:08.959] INFO: 208000 events read in total (13576ms).
[15:49:08.966] INFO: Test took 14713ms.
[15:49:09.411] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:09.757] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1
[15:49:09.758] INFO: number of red-efficiency pixels: 411 286 640 1177 917 991 1312 761 496 812 793 472 523 405 86 90
[15:49:09.758] INFO: number of X-ray hits detected: 205259 140242 210489 339623 342020 366152 371730 278010 257880 283985 284016 244720 259143 155864 66115 73783
[15:49:09.758] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:49:09.758] INFO: number of Vcal hits detected: 207518 207682 207158 206513 206887 206775 206217 207073 207446 207031 207064 207482 207403 207521 207911 207860
[15:49:09.758] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.4 99.5 99.5 99.2 99.6 99.8 99.6 99.6 99.8 99.7 99.8 100.0 100.0
[15:49:09.758] INFO: Vcal hit overall efficiency (%): 99.8 99.8 99.6 99.3 99.5 99.4 99.1 99.6 99.7 99.5 99.6 99.8 99.7 99.8 100.0 99.9
[15:49:09.758] INFO: X-ray hit rate [MHz/cm2]: 60.2 41.1 61.7 99.5 100.2 107.3 109.0 81.5 75.6 83.2 83.2 71.7 76.0 45.7 19.4 21.6
[15:49:09.758] INFO: PixTestHighRate::doXPixelAlive() done
[15:49:09.812] INFO: PixTest:: pg_setup set to default.
[15:49:09.831] INFO: enter test to run
[15:49:21.933] INFO: test: exit no parameter change
[15:49:22.361] QUIET: Connection to board 33 closed.
[15:49:22.384] INFO: pXar: this is the end, my friend