[15:09:49.380] INFO: *** Welcome to pxar ***
[15:09:49.380] INFO: *** Today: 2016/09/22
[15:09:52.071] INFO: *** Version: v1.9.0-818-g96727
[15:09:52.071] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//dacParameters35_C15.dat
[15:09:52.315] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:09:52.315] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//defaultMaskFile.dat
[15:09:52.320] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C15.dat
[15:09:52.781] INFO: clk: 4
[15:09:52.781] INFO: ctr: 4
[15:09:52.781] INFO: sda: 19
[15:09:52.781] INFO: tin: 9
[15:09:52.781] INFO: level: 15
[15:09:52.781] INFO: triggerdelay: 0
[15:09:52.781] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:09:52.781] INFO: Log level: INFO
[15:09:52.820] QUIET: Connection to board DTB_WREKRL opened.
[15:09:52.824] 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:09:52.826] INFO: RPC call hashes of host and DTB match: 398089610
[15:09:54.387] INFO: DUT info:
[15:09:54.387] INFO: The DUT currently contains the following objects:
[15:09:54.387] INFO: 2 TBM Cores tbm08c (2 ON)
[15:09:54.387] INFO: TBM Core alpha (0): 7 registers set
[15:09:54.387] INFO: TBM Core beta (1): 7 registers set
[15:09:54.387] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:09:54.387] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.387] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.388] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.388] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:54.969] INFO: enter 'restricted' command line mode
[15:09:54.969] INFO: enter test to run
[15:09:58.278] INFO: test: PixelAlive no parameter change
[15:09:58.278] INFO: running: pixelalive
[15:09:58.347] INFO: ----------------------------------------------------------------------
[15:09:58.347] 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:09:58.348] INFO: ----------------------------------------------------------------------
[15:09:58.695] INFO: Expecting 41600 events.
[15:10:03.055] INFO: 41600 events read in total (3641ms).
[15:10:03.224] INFO: Test took 4874ms.
[15:10:03.234] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:10:04.032] INFO: PixTestAlive::aliveTest() done
[15:10:04.032] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0
[15:10:04.296] INFO: enter test to run
[15:10:20.758] INFO: test: timing no parameter change
[15:10:20.758] INFO: running: timing
[15:10:20.761] INFO: ######################################################################
[15:10:20.761] INFO: PixTestTiming::doTest()
[15:10:20.761] INFO: ######################################################################
[15:10:20.761] INFO: ----------------------------------------------------------------------
[15:10:20.761] INFO: PixTestTiming::TBMPhaseScan()
[15:10:20.761] INFO: ----------------------------------------------------------------------
[15:16:52.050] INFO: TBM Phase Settings: 248
[15:16:52.050] INFO: 400MHz Phase: 6
[15:16:52.050] INFO: 160MHz Phase: 7
[15:16:52.051] INFO: Functional Phase Area: 3
[15:16:52.077] INFO: Test took 391316 ms.
[15:16:52.077] INFO: PixTestTiming::TBMPhaseScan() done.
[15:16:52.077] INFO: ----------------------------------------------------------------------
[15:16:52.077] INFO: PixTestTiming::ROCDelayScan()
[15:16:52.077] INFO: ----------------------------------------------------------------------
[15:18:56.502] INFO: ROC Delay Settings: 227
[15:18:56.502] INFO: ROC Header-Trailer/Token Delay: 11
[15:18:56.502] INFO: ROC Port 0 Delay: 3
[15:18:56.502] INFO: ROC Port 1 Delay: 4
[15:18:56.502] INFO: Functional ROC Area: 4
[15:18:56.505] INFO: Test took 124428 ms.
[15:18:56.505] INFO: PixTestTiming::ROCDelayScan() done.
[15:18:56.505] INFO: ----------------------------------------------------------------------
[15:18:56.505] INFO: PixTestTiming::TimingTest()
[15:18:56.505] INFO: ----------------------------------------------------------------------
[15:19:12.646] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:27.598] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:42.571] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:57.524] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:12.498] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:27.475] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:42.451] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:57.461] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:12.425] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:27.404] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:27.786] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:27.803] INFO: ----------------------------------------------------------------------
[15:21:27.803] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:21:27.803] INFO: ----------------------------------------------------------------------
[15:21:27.803] INFO: ----------------------------------------------------------------------
[15:21:27.803] INFO: Read back bit status: 1
[15:21:27.803] INFO: ----------------------------------------------------------------------
[15:21:27.803] INFO: ----------------------------------------------------------------------
[15:21:27.803] INFO: Timings are good!
[15:21:27.803] INFO: ----------------------------------------------------------------------
[15:21:27.803] INFO: Test took 151298 ms.
[15:21:27.803] INFO: PixTestTiming::TimingTest() done.
[15:21:27.803] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:21:27.803] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:21:27.803] INFO: PixTestTiming::doTest took 667045 ms.
[15:21:27.803] INFO: PixTestTiming::doTest() done
[15:21:27.803] INFO: Write out TBMPhaseScan_0_V0
[15:21:27.804] INFO: Write out TBMPhaseScan_1_V0
[15:21:27.804] INFO: Write out CombinedTBMPhaseScan_V0
[15:21:27.805] INFO: Write out ROCDelayScan3_V0
[15:21:27.805] INFO: enter test to run
[15:22:10.777] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:22:10.777] INFO: running: highrate
[15:22:10.791] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:22:11.043] INFO: ----------------------------------------------------------------------
[15:22:11.043] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:22:11.043] INFO: ----------------------------------------------------------------------
[15:22:11.043] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:22:11.043] INFO: edge/corner pixel THR is adjusted
[15:22:11.043] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:22:11.001] INFO: Collecting data for 5 seconds...
[15:22:17.018] INFO: Done with hot pixel readout
[15:22:28.771] INFO: PixTest:: pg_setup set to default.
[15:22:28.772] INFO: 10 hot pixels found in step 0
[15:22:29.765] INFO: Collecting data for 5 seconds...
[15:22:34.782] INFO: Done with hot pixel readout
[15:22:46.565] INFO: PixTest:: pg_setup set to default.
[15:22:46.566] INFO: 6 hot pixels found in step 1
[15:22:47.557] INFO: Collecting data for 5 seconds...
[15:22:52.575] INFO: Done with hot pixel readout
[15:23:04.208] INFO: PixTest:: pg_setup set to default.
[15:23:04.209] INFO: 10 hot pixels found in step 2
[15:23:05.202] INFO: Collecting data for 5 seconds...
[15:23:10.219] INFO: Done with hot pixel readout
[15:23:21.927] INFO: PixTest:: pg_setup set to default.
[15:23:21.928] INFO: 4 hot pixels found in step 3
[15:23:22.921] INFO: Collecting data for 5 seconds...
[15:23:27.938] INFO: Done with hot pixel readout
[15:23:39.630] INFO: PixTest:: pg_setup set to default.
[15:23:39.631] INFO: 3 hot pixels found in step 4
[15:23:40.623] INFO: Collecting data for 5 seconds...
[15:23:45.640] INFO: Done with hot pixel readout
[15:23:54.964] INFO: PixTest:: pg_setup set to default.
[15:23:54.965] INFO: 2 hot pixels found in step 5
[15:23:55.957] INFO: Collecting data for 5 seconds...
[15:24:00.972] INFO: Done with hot pixel readout
[15:24:12.570] INFO: PixTest:: pg_setup set to default.
[15:24:12.571] INFO: 3 hot pixels found in step 6
[15:24:13.563] INFO: Collecting data for 5 seconds...
[15:24:18.581] INFO: Done with hot pixel readout
[15:24:30.228] INFO: PixTest:: pg_setup set to default.
[15:24:30.229] INFO: 6 hot pixels found in step 7
[15:24:31.221] INFO: Collecting data for 5 seconds...
[15:24:36.240] INFO: Done with hot pixel readout
[15:24:45.875] INFO: PixTest:: pg_setup set to default.
[15:24:45.876] INFO: 5 hot pixels found in step 8
[15:24:46.868] INFO: Collecting data for 5 seconds...
[15:24:51.887] INFO: Done with hot pixel readout
[15:25:01.580] INFO: PixTest:: pg_setup set to default.

[15:25:01.581] INFO: 3 hot pixels found in step 9
[15:25:02.572] INFO: Collecting data for 5 seconds...
[15:25:07.586] INFO: Done with hot pixel readout
[15:25:19.195] INFO: PixTest:: pg_setup set to default.
[15:25:19.196] INFO: 4 hot pixels found in step 10
[15:25:20.188] INFO: Collecting data for 5 seconds...
[15:25:25.207] INFO: Done with hot pixel readout
[15:25:37.035] INFO: PixTest:: pg_setup set to default.
[15:25:37.036] INFO: 5 hot pixels found in step 11
[15:25:38.028] INFO: Collecting data for 5 seconds...
[15:25:43.046] INFO: Done with hot pixel readout
[15:25:54.767] INFO: PixTest:: pg_setup set to default.
[15:25:54.767] INFO: 2 hot pixels found in step 12
[15:25:55.760] INFO: Collecting data for 5 seconds...
[15:26:00.779] INFO: Done with hot pixel readout
[15:26:12.426] INFO: PixTest:: pg_setup set to default.
[15:26:12.427] INFO: 4 hot pixels found in step 13
[15:26:13.419] INFO: Collecting data for 5 seconds...
[15:26:18.438] INFO: Done with hot pixel readout
[15:26:30.040] INFO: PixTest:: pg_setup set to default.
[15:26:30.040] INFO: 2 hot pixels found in step 14
[15:26:30.077] INFO: 2 hot pixels could not be trimmed and have been masked.
[15:26:30.081] INFO: PixTest::trimHotPixels() done
[15:26:30.081] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C0.dat
[15:26:30.106] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C1.dat
[15:26:30.115] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C2.dat
[15:26:30.131] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C3.dat
[15:26:30.141] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C4.dat
[15:26:30.150] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C5.dat
[15:26:30.157] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C6.dat
[15:26:30.163] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C7.dat
[15:26:30.169] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C8.dat
[15:26:30.174] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C9.dat
[15:26:30.179] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C10.dat
[15:26:30.185] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C11.dat
[15:26:30.190] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C12.dat
[15:26:30.195] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C13.dat
[15:26:30.201] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C14.dat
[15:26:30.206] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C15.dat
[15:26:30.212] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//defaultMaskFile.dat
[15:26:30.222] INFO: enter test to run
[15:27:23.767] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:27:23.767] INFO: running: highrate
[15:27:23.772] INFO: ----------------------------------------------------------------------
[15:27:23.772] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:27:23.772] INFO: ----------------------------------------------------------------------
[15:27:23.772] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:27:23.772] INFO: edge/corner pixel THR is adjusted
[15:27:23.772] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:27:24.730] INFO: Collecting data for 1 seconds...
[15:27:25.734] INFO: Done with hot pixel readout
[15:27:29.725] INFO: PixTest:: pg_setup set to default.
[15:27:29.726] INFO: 0 hot pixels found in step 0
[15:27:29.731] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:27:29.821] INFO: PixTest::trimHotPixels() done
[15:27:29.821] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C0.dat
[15:27:29.832] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C1.dat
[15:27:29.838] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C2.dat
[15:27:29.844] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C3.dat
[15:27:29.849] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C4.dat
[15:27:29.855] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C5.dat
[15:27:29.860] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C6.dat
[15:27:29.865] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C7.dat
[15:27:29.870] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C8.dat
[15:27:29.875] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C9.dat
[15:27:29.881] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C10.dat
[15:27:29.886] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C11.dat
[15:27:29.891] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C12.dat
[15:27:29.897] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C13.dat
[15:27:29.902] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C14.dat
[15:27:29.907] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C15.dat
[15:27:29.912] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-48_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//defaultMaskFile.dat
[15:27:29.922] INFO: enter test to run
[15:27:57.439] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:27:57.439] INFO: running: xray
[15:27:57.441] INFO: ----------------------------------------------------------------------
[15:27:57.441] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:27:57.441] INFO: ----------------------------------------------------------------------
[15:27:58.445] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:28:09.959] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:28:40.438] INFO: Resuming triggers.
[15:28:51.955] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:29:21.685] INFO: Resuming triggers.
[15:29:33.204] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[15:30:02.745] INFO: Resuming triggers.
[15:30:14.267] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:30:43.921] INFO: Resuming triggers.
[15:30:55.442] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[15:31:25.047] INFO: Resuming triggers.
[15:31:36.568] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[15:32:06.119] INFO: Resuming triggers.
[15:32:17.639] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[15:32:47.248] INFO: Resuming triggers.
[15:32:58.766] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[15:33:28.434] INFO: Resuming triggers.
[15:33:36.628] INFO: data taking finished, elapsed time: 100 seconds.
[15:33:57.943] INFO: PixTest:: pg_setup set to default.
[15:33:57.946] INFO: PixTestXray::doPhRun() done
[15:33:58.083] INFO: enter test to run
[15:34:51.084] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:34:51.084] INFO: running: xray
[15:34:51.085] INFO: ----------------------------------------------------------------------
[15:34:51.085] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:34:51.085] INFO: ----------------------------------------------------------------------
[15:34:52.049] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:34:58.817] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:35:29.280] INFO: Resuming triggers.
[15:35:36.053] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[15:36:06.525] INFO: Resuming triggers.
[15:36:13.299] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[15:36:44.588] INFO: Resuming triggers.
[15:36:51.362] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[15:37:22.702] INFO: Resuming triggers.
[15:37:29.474] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[15:38:00.900] INFO: Resuming triggers.
[15:38:07.668] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[15:38:38.488] INFO: Resuming triggers.
[15:38:45.255] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[15:39:16.811] INFO: Resuming triggers.
[15:39:23.584] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[15:39:55.316] INFO: Resuming triggers.
[15:40:02.088] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[15:40:33.988] INFO: Resuming triggers.
[15:40:40.760] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[15:41:11.227] INFO: Resuming triggers.
[15:41:17.003] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[15:41:48.499] INFO: Resuming triggers.
[15:41:55.273] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[15:42:25.674] INFO: Resuming triggers.
[15:42:32.445] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[15:43:02.916] INFO: Resuming triggers.
[15:43:09.692] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[15:43:40.068] INFO: Resuming triggers.
[15:43:45.618] INFO: data taking finished, elapsed time: 100 seconds.
[15:44:10.753] INFO: PixTest:: pg_setup set to default.
[15:44:10.756] INFO: PixTestXray::doPhRun() done
[15:44:10.909] INFO: enter test to run
[15:45:01.584] INFO: test: HighRate no parameter change
[15:45:01.584] INFO: running: highrate
[15:45:01.585] INFO: ----------------------------------------------------------------------
[15:45:01.585] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:45:01.585] INFO: ----------------------------------------------------------------------
[15:45:01.726] INFO: Expecting 768 events.
[15:45:02.860] INFO: 768 events read in total (418ms).
[15:45:02.860] INFO: Test took 1268ms.
[15:45:03.669] INFO: Expecting 41600 events.
[15:45:06.753] INFO: 41600 events read in total (2557ms).
[15:45:06.754] INFO: Test took 3886ms.
[15:45:06.795] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:07.516] INFO: Expecting 41600 events.
[15:45:10.704] INFO: 41600 events read in total (2662ms).
[15:45:10.705] INFO: Test took 3891ms.
[15:45:10.739] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:11.467] INFO: Expecting 41600 events.
[15:45:14.698] INFO: 41600 events read in total (2704ms).
[15:45:14.698] INFO: Test took 3941ms.
[15:45:14.733] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:15.453] INFO: Expecting 41600 events.
[15:45:18.695] INFO: 41600 events read in total (2715ms).
[15:45:18.696] INFO: Test took 3946ms.
[15:45:18.730] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:19.453] INFO: Expecting 41600 events.
[15:45:22.690] INFO: 41600 events read in total (2710ms).
[15:45:22.691] INFO: Test took 3942ms.
[15:45:22.724] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:23.446] INFO: Expecting 41600 events.
[15:45:26.665] INFO: 41600 events read in total (2692ms).
[15:45:26.666] INFO: Test took 3923ms.
[15:45:26.701] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:27.426] INFO: Expecting 41600 events.
[15:45:30.671] INFO: 41600 events read in total (2718ms).
[15:45:30.672] INFO: Test took 3952ms.
[15:45:30.705] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:31.430] INFO: Expecting 41600 events.
[15:45:34.678] INFO: 41600 events read in total (2721ms).
[15:45:34.679] INFO: Test took 3957ms.
[15:45:34.714] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:35.434] INFO: Expecting 41600 events.
[15:45:38.663] INFO: 41600 events read in total (2702ms).
[15:45:38.664] INFO: Test took 3931ms.
[15:45:38.698] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:39.422] INFO: Expecting 41600 events.
[15:45:42.662] INFO: 41600 events read in total (2713ms).
[15:45:42.663] INFO: Test took 3948ms.
[15:45:42.696] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:43.424] INFO: Expecting 41600 events.
[15:45:46.671] INFO: 41600 events read in total (2720ms).
[15:45:46.672] INFO: Test took 3957ms.
[15:45:46.705] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:47.431] INFO: Expecting 41600 events.
[15:45:50.678] INFO: 41600 events read in total (2721ms).
[15:45:50.679] INFO: Test took 3955ms.
[15:45:50.712] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:51.438] INFO: Expecting 41600 events.
[15:45:54.673] INFO: 41600 events read in total (2709ms).
[15:45:54.674] INFO: Test took 3944ms.
[15:45:54.707] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:55.433] INFO: Expecting 41600 events.
[15:45:58.667] INFO: 41600 events read in total (2707ms).
[15:45:58.668] INFO: Test took 3942ms.
[15:45:58.703] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:59.424] INFO: Expecting 41600 events.
[15:46:02.674] INFO: 41600 events read in total (2723ms).
[15:46:02.675] INFO: Test took 3953ms.
[15:46:02.708] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:03.429] INFO: Expecting 41600 events.
[15:46:06.673] INFO: 41600 events read in total (2717ms).
[15:46:06.674] INFO: Test took 3948ms.
[15:46:06.708] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:07.434] INFO: Expecting 41600 events.
[15:46:10.669] INFO: 41600 events read in total (2708ms).
[15:46:10.670] INFO: Test took 3944ms.
[15:46:10.704] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:11.429] INFO: Expecting 41600 events.
[15:46:14.675] INFO: 41600 events read in total (2719ms).
[15:46:14.676] INFO: Test took 3954ms.
[15:46:14.710] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:15.434] INFO: Expecting 41600 events.
[15:46:18.674] INFO: 41600 events read in total (2713ms).
[15:46:18.675] INFO: Test took 3946ms.
[15:46:18.708] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:19.435] INFO: Expecting 41600 events.
[15:46:22.520] INFO: 41600 events read in total (2558ms).
[15:46:22.521] INFO: Test took 3794ms.
[15:46:22.554] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:22.918] INFO: enter test to run
[15:46:35.847] INFO: test: HighRate no parameter change
[15:46:35.847] INFO: running: highrate
[15:46:35.848] INFO: ----------------------------------------------------------------------
[15:46:35.849] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:46:35.849] INFO: ----------------------------------------------------------------------
[15:46:36.464] INFO: Expecting 208000 events.
[15:46:48.285] INFO: 208000 events read in total (11294ms).
[15:46:48.288] INFO: Test took 12431ms.
[15:46:48.429] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:48.679] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 2 0 0 0 0
[15:46:48.679] INFO: number of red-efficiency pixels: 76 76 101 145 130 136 159 99 77 134 136 111 114 55 20 28
[15:46:48.679] INFO: number of X-ray hits detected: 65904 45417 67772 103626 107525 111829 110086 75449 72830 97954 94008 84012 86209 51644 22196 28533
[15:46:48.680] 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:46:48.680] INFO: number of Vcal hits detected: 207922 207924 207895 207852 207869 207860 207837 207900 207921 207862 207861 207518 207884 207943 207980 207972
[15:46:48.680] 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 99.8 99.9 100.0 100.0 100.0
[15:46:48.680] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.8 99.9 100.0 100.0 100.0
[15:46:48.680] INFO: X-ray hit rate [MHz/cm2]: 19.3 13.3 19.9 30.4 31.5 32.8 32.3 22.1 21.3 28.7 27.6 24.6 25.3 15.1 6.5 8.4
[15:46:48.680] INFO: PixTestHighRate::doXPixelAlive() done
[15:46:48.726] INFO: PixTest:: pg_setup set to default.
[15:46:48.743] INFO: enter test to run
[15:47:12.311] INFO: test: HighRate no parameter change
[15:47:12.311] INFO: running: highrate
[15:47:12.312] INFO: ----------------------------------------------------------------------
[15:47:12.312] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:47:12.312] INFO: ----------------------------------------------------------------------
[15:47:12.929] INFO: Expecting 208000 events.
[15:47:26.520] INFO: 208000 events read in total (13064ms).
[15:47:26.526] INFO: Test took 14203ms.
[15:47:26.818] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:27.117] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 45 0 0 0 0
[15:47:27.117] INFO: number of red-efficiency pixels: 256 158 319 487 493 466 553 299 230 417 379 421 344 149 55 63
[15:47:27.117] INFO: number of X-ray hits detected: 136719 94719 141132 216537 225966 233854 229498 158101 153017 202904 196563 174814 179605 107598 46339 59192
[15:47:27.117] 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:27.117] INFO: number of Vcal hits detected: 207727 207832 207646 207469 207465 207492 207383 207677 207759 207553 207587 202547 207629 207842 207944 207937
[15:47:27.117] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.8 99.7 99.9 99.9 99.8 99.8 98.4 99.8 99.9 100.0 100.0
[15:47:27.117] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.8 99.7 99.8 99.9 99.8 99.8 97.4 99.8 99.9 100.0 100.0
[15:47:27.117] INFO: X-ray hit rate [MHz/cm2]: 40.1 27.8 41.4 63.5 66.2 68.5 67.3 46.3 44.9 59.5 57.6 51.2 52.6 31.5 13.6 17.3
[15:47:27.117] INFO: PixTestHighRate::doXPixelAlive() done
[15:47:27.173] INFO: PixTest:: pg_setup set to default.
[15:47:27.187] INFO: enter test to run
[15:47:49.807] INFO: test: HighRate no parameter change
[15:47:49.807] INFO: running: highrate
[15:47:49.808] INFO: ----------------------------------------------------------------------
[15:47:49.808] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:47:49.808] INFO: ----------------------------------------------------------------------
[15:47:50.430] INFO: Expecting 208000 events.
[15:48:05.789] INFO: 208000 events read in total (14832ms).
[15:48:05.796] INFO: Test took 15977ms.
[15:48:06.236] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:06.583] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 6 0 0 0 0
[15:48:06.583] INFO: number of red-efficiency pixels: 539 313 719 1111 1047 1053 1306 728 454 1007 921 741 821 326 103 119
[15:48:06.583] INFO: number of X-ray hits detected: 204930 141980 211136 323478 338282 350364 344726 236823 229966 304928 293621 261569 268506 161495 69234 89124
[15:48:06.583] 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:06.583] INFO: number of Vcal hits detected: 207318 207659 207048 206576 206700 206652 206253 207095 207490 206771 206902 200374 207072 207642 207895 207876
[15:48:06.583] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.6 99.4 99.4 99.4 99.3 99.6 99.8 99.5 99.5 96.4 99.6 99.8 100.0 99.9
[15:48:06.583] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.5 99.3 99.4 99.4 99.2 99.6 99.8 99.4 99.5 96.3 99.6 99.8 99.9 99.9
[15:48:06.583] INFO: X-ray hit rate [MHz/cm2]: 60.1 41.6 61.9 94.8 99.2 102.7 101.0 69.4 67.4 89.4 86.1 76.7 78.7 47.3 20.3 26.1
[15:48:06.583] INFO: PixTestHighRate::doXPixelAlive() done
[15:48:06.635] INFO: PixTest:: pg_setup set to default.
[15:48:06.653] INFO: enter test to run
[15:48:44.174] INFO: test: exit no parameter change
[15:48:44.596] QUIET: Connection to board 33 closed.
[15:48:44.617] INFO: pXar: this is the end, my friend