[12:36:19.550] INFO: *** Welcome to pxar ***
[12:36:19.550] INFO: *** Today: 2016/08/25
[12:36:19.568] INFO: *** Version: v1.9.0-818-g96727
[12:36:19.568] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//dacParameters35_C15.dat
[12:36:19.569] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:36:19.569] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//defaultMaskFile.dat
[12:36:19.569] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C15.dat
[12:36:19.645] INFO: clk: 4
[12:36:19.645] INFO: ctr: 4
[12:36:19.645] INFO: sda: 19
[12:36:19.645] INFO: tin: 9
[12:36:19.645] INFO: level: 15
[12:36:19.645] INFO: triggerdelay: 0
[12:36:19.645] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[12:36:19.645] INFO: Log level: INFO
[12:36:19.663] QUIET: Connection to board DTB_WREKRL opened.
[12:36:19.667] 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:
------------------------------------------------------
[12:36:19.670] INFO: RPC call hashes of host and DTB match: 398089610
[12:36:21.194] INFO: DUT info:
[12:36:21.194] INFO: The DUT currently contains the following objects:
[12:36:21.194] INFO: 2 TBM Cores tbm08c (2 ON)
[12:36:21.194] INFO: TBM Core alpha (0): 7 registers set
[12:36:21.194] INFO: TBM Core beta (1): 7 registers set
[12:36:21.194] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:36:21.194] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.194] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.194] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.195] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:36:21.598] INFO: enter 'restricted' command line mode
[12:36:21.598] INFO: enter test to run
[12:36:25.962] INFO: test: PixelAlive no parameter change
[12:36:25.962] INFO: running: pixelalive
[12:36:25.972] INFO: ----------------------------------------------------------------------
[12:36:25.972] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[12:36:25.972] INFO: ----------------------------------------------------------------------
[12:36:26.287] INFO: Expecting 41600 events.
[12:36:30.627] INFO: 41600 events read in total (3622ms).
[12:36:30.795] INFO: Test took 4822ms.
[12:36:30.808] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:31.070] INFO: PixTestAlive::aliveTest() done
[12:36:31.070] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 0
[12:36:31.101] INFO: enter test to run
[12:36:36.858] INFO: test: timing no parameter change
[12:36:36.858] INFO: running: timing
[12:36:36.876] INFO: ######################################################################
[12:36:36.876] INFO: PixTestTiming::doTest()
[12:36:36.876] INFO: ######################################################################
[12:36:36.876] INFO: ----------------------------------------------------------------------
[12:36:36.876] INFO: PixTestTiming::TBMPhaseScan()
[12:36:36.876] INFO: ----------------------------------------------------------------------
[12:42:34.251] INFO: TBM Phase Settings: 232
[12:42:34.251] INFO: 400MHz Phase: 2
[12:42:34.251] INFO: 160MHz Phase: 7
[12:42:34.251] INFO: Functional Phase Area: 3
[12:42:34.276] INFO: Test took 357400 ms.
[12:42:34.276] INFO: PixTestTiming::TBMPhaseScan() done.
[12:42:34.276] INFO: ----------------------------------------------------------------------
[12:42:34.276] INFO: PixTestTiming::ROCDelayScan()
[12:42:34.277] INFO: ----------------------------------------------------------------------
[12:44:30.330] INFO: ROC Delay Settings: 228
[12:44:30.330] INFO: ROC Header-Trailer/Token Delay: 11
[12:44:30.330] INFO: ROC Port 0 Delay: 4
[12:44:30.330] INFO: ROC Port 1 Delay: 4
[12:44:30.330] INFO: Functional ROC Area: 3
[12:44:30.333] INFO: Test took 116057 ms.
[12:44:30.333] INFO: PixTestTiming::ROCDelayScan() done.
[12:44:30.334] INFO: ----------------------------------------------------------------------
[12:44:30.334] INFO: PixTestTiming::TimingTest()
[12:44:30.334] INFO: ----------------------------------------------------------------------
[12:44:46.502] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:01.589] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:16.678] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:31.748] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:46.871] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:46:01.987] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:46:17.122] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:46:32.346] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:46:47.466] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:47:02.661] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:47:03.042] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:47:03.059] INFO: ----------------------------------------------------------------------
[12:47:03.059] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:47:03.059] INFO: ----------------------------------------------------------------------
[12:47:03.059] INFO: ----------------------------------------------------------------------
[12:47:03.059] INFO: Read back bit status: 1
[12:47:03.059] INFO: ----------------------------------------------------------------------
[12:47:03.059] INFO: ----------------------------------------------------------------------
[12:47:03.059] INFO: Timings are good!
[12:47:03.059] INFO: ----------------------------------------------------------------------
[12:47:03.059] INFO: Test took 152725 ms.
[12:47:03.059] INFO: PixTestTiming::TimingTest() done.
[12:47:03.060] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:47:03.060] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:47:03.060] INFO: PixTestTiming::doTest took 626188 ms.
[12:47:03.060] INFO: PixTestTiming::doTest() done
[12:47:03.060] INFO: Write out TBMPhaseScan_0_V0
[12:47:03.060] INFO: Write out TBMPhaseScan_1_V0
[12:47:03.060] INFO: Write out CombinedTBMPhaseScan_V0
[12:47:03.090] INFO: Write out ROCDelayScan3_V0
[12:47:03.091] INFO: enter test to run
[12:49:04.341] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:49:04.342] INFO: running: highrate
[12:49:04.342] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:49:04.499] INFO: ----------------------------------------------------------------------
[12:49:04.499] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:49:04.499] INFO: ----------------------------------------------------------------------
[12:49:04.499] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:49:04.499] INFO: edge/corner pixel THR is adjusted
[12:49:04.499] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:49:05.458] INFO: Collecting data for 5 seconds...
[12:49:10.473] INFO: Done with hot pixel readout
[12:49:22.251] INFO: PixTest:: pg_setup set to default.
[12:49:22.252] INFO: 11 hot pixels found in step 0
[12:49:23.244] INFO: Collecting data for 5 seconds...
[12:49:28.260] INFO: Done with hot pixel readout
[12:49:40.009] INFO: PixTest:: pg_setup set to default.
[12:49:40.010] INFO: 8 hot pixels found in step 1
[12:49:40.002] INFO: Collecting data for 5 seconds...
[12:49:46.018] INFO: Done with hot pixel readout
[12:49:57.768] INFO: PixTest:: pg_setup set to default.
[12:49:57.769] INFO: 10 hot pixels found in step 2
[12:49:58.761] INFO: Collecting data for 5 seconds...
[12:50:03.777] INFO: Done with hot pixel readout
[12:50:15.519] INFO: PixTest:: pg_setup set to default.
[12:50:15.520] INFO: 7 hot pixels found in step 3
[12:50:16.512] INFO: Collecting data for 5 seconds...
[12:50:21.529] INFO: Done with hot pixel readout
[12:50:33.299] INFO: PixTest:: pg_setup set to default.
[12:50:33.300] INFO: 7 hot pixels found in step 4
[12:50:34.292] INFO: Collecting data for 5 seconds...
[12:50:39.308] INFO: Done with hot pixel readout
[12:50:51.072] INFO: PixTest:: pg_setup set to default.

[12:50:51.072] INFO: 5 hot pixels found in step 5
[12:50:52.064] INFO: Collecting data for 5 seconds...
[12:50:57.081] INFO: Done with hot pixel readout
[12:51:08.848] INFO: PixTest:: pg_setup set to default.
[12:51:08.849] INFO: 6 hot pixels found in step 6
[12:51:09.840] INFO: Collecting data for 5 seconds...
[12:51:14.857] INFO: Done with hot pixel readout
[12:51:26.559] INFO: PixTest:: pg_setup set to default.

[12:51:26.560] INFO: 3 hot pixels found in step 7
[12:51:27.552] INFO: Collecting data for 5 seconds...
[12:51:32.569] INFO: Done with hot pixel readout
[12:51:44.289] INFO: PixTest:: pg_setup set to default.

[12:51:44.290] INFO: 2 hot pixels found in step 8
[12:51:45.282] INFO: Collecting data for 5 seconds...
[12:51:50.299] INFO: Done with hot pixel readout
[12:52:02.038] INFO: PixTest:: pg_setup set to default.

[12:52:02.039] INFO: 3 hot pixels found in step 9
[12:52:03.030] INFO: Collecting data for 5 seconds...
[12:52:08.046] INFO: Done with hot pixel readout
[12:52:19.790] INFO: PixTest:: pg_setup set to default.

[12:52:19.791] INFO: 3 hot pixels found in step 10
[12:52:20.783] INFO: Collecting data for 5 seconds...
[12:52:25.800] INFO: Done with hot pixel readout
[12:52:37.649] INFO: PixTest:: pg_setup set to default.
[12:52:37.650] INFO: 2 hot pixels found in step 11
[12:52:38.642] INFO: Collecting data for 5 seconds...
[12:52:43.658] INFO: Done with hot pixel readout
[12:52:55.369] INFO: PixTest:: pg_setup set to default.

[12:52:55.370] INFO: 2 hot pixels found in step 12
[12:52:56.362] INFO: Collecting data for 5 seconds...
[12:53:01.378] INFO: Done with hot pixel readout
[12:53:13.153] INFO: PixTest:: pg_setup set to default.
[12:53:13.153] INFO: 0 hot pixels found in step 13
[12:53:13.188] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:53:13.192] INFO: PixTest::trimHotPixels() done
[12:53:13.210] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C0.dat
[12:53:13.222] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C1.dat
[12:53:13.232] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C2.dat
[12:53:13.237] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C3.dat
[12:53:13.242] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C4.dat
[12:53:13.248] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C5.dat
[12:53:13.253] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C6.dat
[12:53:13.259] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C7.dat
[12:53:13.264] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C8.dat
[12:53:13.270] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C9.dat
[12:53:13.275] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C10.dat
[12:53:13.280] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C11.dat
[12:53:13.286] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C12.dat
[12:53:13.291] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C13.dat
[12:53:13.296] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C14.dat
[12:53:13.302] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C15.dat
[12:53:13.307] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//defaultMaskFile.dat
[12:53:13.323] INFO: enter test to run
[12:53:37.468] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:53:37.468] INFO: running: highrate
[12:53:37.472] INFO: ----------------------------------------------------------------------
[12:53:37.472] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:53:37.472] INFO: ----------------------------------------------------------------------
[12:53:37.472] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:53:37.472] INFO: edge/corner pixel THR is adjusted
[12:53:37.472] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:53:38.430] INFO: Collecting data for 1 seconds...
[12:53:39.434] INFO: Done with hot pixel readout
[12:53:43.388] INFO: PixTest:: pg_setup set to default.
[12:53:43.389] INFO: 0 hot pixels found in step 0
[12:53:43.394] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:53:43.486] INFO: PixTest::trimHotPixels() done
[12:53:43.486] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C0.dat
[12:53:43.494] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C1.dat
[12:53:43.499] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C2.dat
[12:53:43.504] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C3.dat
[12:53:43.510] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C4.dat
[12:53:43.515] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C5.dat
[12:53:43.520] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C6.dat
[12:53:43.525] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C7.dat
[12:53:43.530] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C8.dat
[12:53:43.536] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C9.dat
[12:53:43.541] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C10.dat
[12:53:43.546] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C11.dat
[12:53:43.551] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C12.dat
[12:53:43.557] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C13.dat
[12:53:43.562] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C14.dat
[12:53:43.567] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//trimParameters35_C15.dat
[12:53:43.572] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-A-37_FPIXTest-17C-FNAL-160823-1252-150V_2016-08-23_12h52m_1471974731/000_FPIXTest_p17//defaultMaskFile.dat
[12:53:43.581] INFO: enter test to run
[12:54:59.123] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:54:59.123] INFO: running: xray
[12:54:59.135] INFO: ----------------------------------------------------------------------
[12:54:59.135] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:54:59.135] INFO: ----------------------------------------------------------------------
[12:55:00.112] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:55:11.001] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:55:41.432] INFO: Resuming triggers.
[12:55:53.324] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[12:56:23.273] INFO: Resuming triggers.
[12:56:35.165] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[12:57:04.633] INFO: Resuming triggers.
[12:57:16.530] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[12:57:45.821] INFO: Resuming triggers.
[12:57:57.718] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[12:58:27.536] INFO: Resuming triggers.
[12:58:39.435] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[12:59:09.764] INFO: Resuming triggers.
[12:59:21.660] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[12:59:51.612] INFO: Resuming triggers.
[13:00:03.507] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[13:00:33.269] INFO: Resuming triggers.
[13:00:38.482] INFO: data taking finished, elapsed time: 100 seconds.
[13:00:51.704] INFO: PixTest:: pg_setup set to default.
[13:00:51.707] INFO: PixTestXray::doPhRun() done
[13:00:51.891] INFO: enter test to run
[13:01:51.872] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[13:01:51.872] INFO: running: xray
[13:01:51.873] INFO: ----------------------------------------------------------------------
[13:01:51.873] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:01:51.873] INFO: ----------------------------------------------------------------------
[13:01:52.837] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:01:59.745] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[13:02:30.161] INFO: Resuming triggers.
[13:02:37.070] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[13:03:07.339] INFO: Resuming triggers.
[13:03:14.250] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[13:03:44.543] INFO: Resuming triggers.
[13:03:51.453] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[13:04:21.720] INFO: Resuming triggers.
[13:04:28.629] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[13:04:58.849] INFO: Resuming triggers.
[13:05:05.758] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[13:05:36.057] INFO: Resuming triggers.
[13:05:42.965] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[13:06:13.249] INFO: Resuming triggers.
[13:06:20.160] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[13:06:50.464] INFO: Resuming triggers.
[13:06:57.377] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[13:07:27.633] INFO: Resuming triggers.
[13:07:34.548] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[13:08:04.815] INFO: Resuming triggers.
[13:08:11.730] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[13:08:42.834] INFO: Resuming triggers.
[13:08:49.752] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[13:09:20.525] INFO: Resuming triggers.
[13:09:27.442] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[13:09:58.437] INFO: Resuming triggers.
[13:10:05.354] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[13:10:36.211] INFO: Resuming triggers.
[13:10:39.773] INFO: data taking finished, elapsed time: 100 seconds.
[13:10:56.224] INFO: PixTest:: pg_setup set to default.
[13:10:56.227] INFO: PixTestXray::doPhRun() done
[13:10:56.382] INFO: enter test to run
[13:11:25.564] INFO: test: HighRate no parameter change
[13:11:25.564] INFO: running: highrate
[13:11:25.578] INFO: ----------------------------------------------------------------------
[13:11:25.578] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:11:25.578] INFO: ----------------------------------------------------------------------
[13:11:25.724] INFO: Expecting 768 events.
[13:11:26.858] INFO: 768 events read in total (418ms).
[13:11:26.859] INFO: Test took 1269ms.
[13:11:27.661] INFO: Expecting 41600 events.
[13:11:30.735] INFO: 41600 events read in total (2547ms).
[13:11:30.736] INFO: Test took 3871ms.
[13:11:30.768] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:31.492] INFO: Expecting 41600 events.
[13:11:34.773] INFO: 41600 events read in total (2754ms).
[13:11:34.774] INFO: Test took 3989ms.
[13:11:34.806] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:35.530] INFO: Expecting 41600 events.
[13:11:38.785] INFO: 41600 events read in total (2728ms).
[13:11:38.786] INFO: Test took 3964ms.
[13:11:38.818] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:39.546] INFO: Expecting 41600 events.
[13:11:42.744] INFO: 41600 events read in total (2671ms).
[13:11:42.744] INFO: Test took 3909ms.
[13:11:42.777] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:43.503] INFO: Expecting 41600 events.
[13:11:46.745] INFO: 41600 events read in total (2715ms).
[13:11:46.746] INFO: Test took 3952ms.
[13:11:46.778] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:47.497] INFO: Expecting 41600 events.
[13:11:50.735] INFO: 41600 events read in total (2712ms).
[13:11:50.736] INFO: Test took 3942ms.
[13:11:50.769] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:51.495] INFO: Expecting 41600 events.
[13:11:54.745] INFO: 41600 events read in total (2723ms).
[13:11:54.746] INFO: Test took 3961ms.
[13:11:54.779] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:55.504] INFO: Expecting 41600 events.
[13:11:58.799] INFO: 41600 events read in total (2768ms).
[13:11:58.800] INFO: Test took 4005ms.
[13:11:58.833] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:11:59.558] INFO: Expecting 41600 events.
[13:12:02.796] INFO: 41600 events read in total (2711ms).
[13:12:02.797] INFO: Test took 3947ms.
[13:12:02.829] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:03.557] INFO: Expecting 41600 events.
[13:12:06.815] INFO: 41600 events read in total (2731ms).
[13:12:06.816] INFO: Test took 3970ms.
[13:12:06.850] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:07.559] INFO: Expecting 41600 events.
[13:12:10.835] INFO: 41600 events read in total (2750ms).
[13:12:10.836] INFO: Test took 3969ms.
[13:12:10.868] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:11.595] INFO: Expecting 41600 events.
[13:12:14.821] INFO: 41600 events read in total (2700ms).
[13:12:14.822] INFO: Test took 3937ms.
[13:12:14.854] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:15.582] INFO: Expecting 41600 events.
[13:12:18.901] INFO: 41600 events read in total (2793ms).
[13:12:18.901] INFO: Test took 4030ms.
[13:12:18.934] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:19.662] INFO: Expecting 41600 events.
[13:12:22.975] INFO: 41600 events read in total (2787ms).
[13:12:22.976] INFO: Test took 4024ms.
[13:12:23.008] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:23.730] INFO: Expecting 41600 events.
[13:12:26.984] INFO: 41600 events read in total (2728ms).
[13:12:26.985] INFO: Test took 3960ms.
[13:12:27.016] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:27.741] INFO: Expecting 41600 events.
[13:12:30.967] INFO: 41600 events read in total (2699ms).
[13:12:30.968] INFO: Test took 3934ms.
[13:12:30.000] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:31.725] INFO: Expecting 41600 events.
[13:12:34.966] INFO: 41600 events read in total (2714ms).
[13:12:34.967] INFO: Test took 3950ms.
[13:12:34.999] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:35.726] INFO: Expecting 41600 events.
[13:12:38.950] INFO: 41600 events read in total (2697ms).
[13:12:38.951] INFO: Test took 3934ms.
[13:12:38.983] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:39.710] INFO: Expecting 41600 events.
[13:12:42.889] INFO: 41600 events read in total (2652ms).
[13:12:42.890] INFO: Test took 3888ms.
[13:12:42.922] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:43.650] INFO: Expecting 41600 events.
[13:12:46.701] INFO: 41600 events read in total (2525ms).
[13:12:46.702] INFO: Test took 3762ms.
[13:12:46.734] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:12:47.109] INFO: enter test to run
[13:13:11.692] INFO: test: HighRate no parameter change
[13:13:11.692] INFO: running: highrate
[13:13:11.693] INFO: ----------------------------------------------------------------------
[13:13:11.693] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:13:11.693] INFO: ----------------------------------------------------------------------
[13:13:12.308] INFO: Expecting 208000 events.
[13:13:24.159] INFO: 208000 events read in total (11324ms).
[13:13:24.162] INFO: Test took 12460ms.
[13:13:24.294] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:13:24.541] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 0
[13:13:24.541] INFO: number of red-efficiency pixels: 65 48 76 126 130 103 98 71 87 93 85 97 103 64 31 25
[13:13:24.541] INFO: number of X-ray hits detected: 63999 40769 59166 95219 102712 100740 97558 69809 64684 93428 92750 79832 84201 50864 20704 23196
[13:13:24.541] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:13:24.541] INFO: number of Vcal hits detected: 207932 207952 207924 207873 207862 207895 207899 207929 207913 207907 207912 207901 207895 207936 207871 207975
[13:13:24.541] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[13:13:24.541] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 99.9 100.0 99.9 100.0
[13:13:24.541] INFO: X-ray hit rate [MHz/cm2]: 18.8 11.9 17.3 27.9 30.1 29.5 28.6 20.5 19.0 27.4 27.2 23.4 24.7 14.9 6.1 6.8
[13:13:24.541] INFO: PixTestHighRate::doXPixelAlive() done
[13:13:24.586] INFO: PixTest:: pg_setup set to default.
[13:13:24.603] INFO: enter test to run
[13:13:42.891] INFO: test: HighRate no parameter change
[13:13:42.892] INFO: running: highrate
[13:13:42.893] INFO: ----------------------------------------------------------------------
[13:13:42.893] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:13:42.893] INFO: ----------------------------------------------------------------------
[13:13:43.508] INFO: Expecting 208000 events.
[13:13:56.999] INFO: 208000 events read in total (12965ms).
[13:13:56.004] INFO: Test took 14102ms.
[13:13:57.278] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:13:57.579] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 0
[13:13:57.579] INFO: number of red-efficiency pixels: 213 142 249 457 411 359 310 227 201 314 307 337 363 180 74 58
[13:13:57.579] INFO: number of X-ray hits detected: 139471 89361 129329 205249 221769 217018 211113 152063 140488 202946 200454 172993 181182 110207 44935 50318
[13:13:57.579] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:13:57.579] INFO: number of Vcal hits detected: 207776 207848 207727 207509 207562 207618 207667 207758 207791 207670 207673 207635 207614 207813 207827 207942
[13:13:57.579] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.8 99.8 99.9 100.0 100.0
[13:13:57.579] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 100.0
[13:13:57.579] INFO: X-ray hit rate [MHz/cm2]: 40.9 26.2 37.9 60.2 65.0 63.6 61.9 44.6 41.2 59.5 58.8 50.7 53.1 32.3 13.2 14.7
[13:13:57.579] INFO: PixTestHighRate::doXPixelAlive() done
[13:13:57.630] INFO: PixTest:: pg_setup set to default.
[13:13:57.643] INFO: enter test to run
[13:14:11.371] INFO: test: HighRate no parameter change
[13:14:11.371] INFO: running: highrate
[13:14:11.372] INFO: ----------------------------------------------------------------------
[13:14:11.372] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:14:11.372] INFO: ----------------------------------------------------------------------
[13:14:11.993] INFO: Expecting 208000 events.
[13:14:27.270] INFO: 208000 events read in total (14750ms).
[13:14:27.277] INFO: Test took 15893ms.
[13:14:27.709] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:14:28.051] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 2 0
[13:14:28.051] INFO: number of red-efficiency pixels: 431 299 547 978 891 804 772 492 453 674 715 781 786 352 126 80
[13:14:28.051] INFO: number of X-ray hits detected: 208743 133933 194945 308245 334060 325657 317135 228147 211315 305156 301742 260378 272974 165906 67429 75782
[13:14:28.051] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:14:28.051] INFO: number of Vcal hits detected: 207490 207665 207255 206790 206917 207032 207073 207418 207498 207218 207163 207082 207079 207604 207772 207919
[13:14:28.051] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.5 99.5 99.6 99.6 99.8 99.8 99.7 99.6 99.6 99.6 99.8 99.9 100.0
[13:14:28.051] INFO: Vcal hit overall efficiency (%): 99.8 99.8 99.6 99.4 99.5 99.5 99.6 99.7 99.8 99.6 99.6 99.6 99.6 99.8 99.9 100.0
[13:14:28.051] INFO: X-ray hit rate [MHz/cm2]: 61.2 39.3 57.1 90.3 97.9 95.5 93.0 66.9 61.9 89.4 88.4 76.3 80.0 48.6 19.8 22.2
[13:14:28.051] INFO: PixTestHighRate::doXPixelAlive() done
[13:14:28.099] INFO: PixTest:: pg_setup set to default.
[13:14:28.112] INFO: enter test to run
[13:14:30.467] INFO: test: exit no parameter change
[13:14:30.994] QUIET: Connection to board 33 closed.
[13:14:31.032] INFO: pXar: this is the end, my friend