[14:52:00.188] INFO: *** Welcome to pxar ***
[14:52:00.188] INFO: *** Today: 2016/05/20
[14:52:00.206] INFO: *** Version: v1.9.0-796-gef167-dirty
[14:52:00.206] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//dacParameters35_C15.dat
[14:52:00.207] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:52:00.207] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//defaultMaskFile.dat
[14:52:00.207] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C15.dat
[14:52:00.281] INFO: clk: 4
[14:52:00.281] INFO: ctr: 4
[14:52:00.281] INFO: sda: 19
[14:52:00.281] INFO: tin: 9
[14:52:00.281] INFO: level: 15
[14:52:00.281] INFO: triggerdelay: 0
[14:52:00.281] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[14:52:00.281] INFO: Log level: INFO
[14:52:00.297] QUIET: Connection to board DTB_WREK4U opened.
[14:52:00.300] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 32
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREK4U
MAC address: 40D855118020
Hostname: pixelDTB032
Comment:
------------------------------------------------------
[14:52:00.303] INFO: RPC call hashes of host and DTB match: 398089610
[14:52:01.838] INFO: DUT info:
[14:52:01.838] INFO: The DUT currently contains the following objects:
[14:52:01.838] INFO: 2 TBM Cores tbm08c (2 ON)
[14:52:01.838] INFO: TBM Core alpha (0): 7 registers set
[14:52:01.838] INFO: TBM Core beta (1): 7 registers set
[14:52:01.838] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[14:52:01.838] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:01.838] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[14:52:02.241] INFO: enter 'restricted' command line mode
[14:52:02.241] INFO: enter test to run
[14:52:37.742] INFO: test: timing no parameter change
[14:52:37.742] INFO: running: timing
[14:52:37.772] INFO: ######################################################################
[14:52:37.772] INFO: PixTestTiming::doTest()
[14:52:37.776] INFO: ######################################################################
[14:52:37.776] INFO: ----------------------------------------------------------------------
[14:52:37.776] INFO: PixTestTiming::TBMPhaseScan()
[14:52:37.776] INFO: ----------------------------------------------------------------------
[14:57:12.139] INFO: TBM Phase Settings: 236
[14:57:12.139] INFO: 400MHz Phase: 3
[14:57:12.139] INFO: 160MHz Phase: 7
[14:57:12.139] INFO: Functional Phase Area: 4
[14:57:12.142] INFO: Test took 274366 ms.
[14:57:12.142] INFO: PixTestTiming::TBMPhaseScan() done.
[14:57:12.143] INFO: ----------------------------------------------------------------------
[14:57:12.143] INFO: PixTestTiming::ROCDelayScan()
[14:57:12.143] INFO: ----------------------------------------------------------------------
[14:59:18.055] INFO: ROC Delay Settings: 228
[14:59:18.055] INFO: ROC Header-Trailer/Token Delay: 11
[14:59:18.056] INFO: ROC Port 0 Delay: 4
[14:59:18.056] INFO: ROC Port 1 Delay: 4
[14:59:18.056] INFO: Functional ROC Area: 5
[14:59:18.059] INFO: Test took 125917 ms.
[14:59:18.059] INFO: PixTestTiming::ROCDelayScan() done.
[14:59:18.059] INFO: ----------------------------------------------------------------------
[14:59:18.059] INFO: PixTestTiming::TimingTest()
[14:59:18.059] INFO: ----------------------------------------------------------------------
[14:59:34.213] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:49.250] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:04.095] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:19.108] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:34.013] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:49.022] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:04.037] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:19.196] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:34.389] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:49.663] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:50.046] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:50.062] INFO: ----------------------------------------------------------------------
[15:01:50.063] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:01:50.063] INFO: ----------------------------------------------------------------------
[15:01:50.063] INFO: ----------------------------------------------------------------------
[15:01:50.063] INFO: Read back bit status: 1
[15:01:50.063] INFO: ----------------------------------------------------------------------
[15:01:50.063] INFO: ----------------------------------------------------------------------
[15:01:50.063] INFO: Timings are good!
[15:01:50.063] INFO: ----------------------------------------------------------------------
[15:01:50.063] INFO: Test took 152004 ms.
[15:01:50.063] INFO: PixTestTiming::TimingTest() done.
[15:01:50.079] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:01:50.079] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:01:50.079] INFO: PixTestTiming::doTest took 552311 ms.
[15:01:50.079] INFO: PixTestTiming::doTest() done
[15:01:50.079] INFO: Write out TBMPhaseScan_0_V0
[15:01:50.124] INFO: Write out TBMPhaseScan_1_V0
[15:01:50.124] INFO: Write out CombinedTBMPhaseScan_V0
[15:01:50.145] INFO: Write out ROCDelayScan3_V0
[15:01:50.147] INFO: enter test to run
[15:02:00.562] INFO: test: PixelAlive no parameter change
[15:02:00.562] INFO: running: pixelalive
[15:02:00.566] INFO: ----------------------------------------------------------------------
[15:02:00.566] 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:02:00.566] INFO: ----------------------------------------------------------------------
[15:02:00.894] INFO: Expecting 41600 events.
[15:02:05.232] INFO: 41600 events read in total (3623ms).
[15:02:05.233] INFO: Test took 4664ms.
[15:02:05.240] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:02:05.634] INFO: PixTestAlive::aliveTest() done
[15:02:05.634] INFO: number of dead pixels (per ROC): 0 0 0 1 2 0 2 0 0 0 0 0 0 0 0 0
[15:02:05.638] INFO: enter test to run
[15:03:32.889] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:03:32.889] INFO: running: highrate
[15:03:32.889] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:03:33.045] INFO: ----------------------------------------------------------------------
[15:03:33.045] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:03:33.045] INFO: ----------------------------------------------------------------------
[15:03:33.045] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:03:33.045] INFO: edge/corner pixel THR is adjusted
[15:03:33.045] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:03:33.004] INFO: Collecting data for 5 seconds...
[15:03:39.021] INFO: Done with hot pixel readout
[15:03:51.029] INFO: PixTest:: pg_setup set to default.
[15:03:51.030] INFO: 17 hot pixels found in step 0
[15:03:52.023] INFO: Collecting data for 5 seconds...
[15:03:57.040] INFO: Done with hot pixel readout
[15:04:09.046] INFO: PixTest:: pg_setup set to default.
[15:04:09.047] INFO: 18 hot pixels found in step 1
[15:04:10.041] INFO: Collecting data for 5 seconds...
[15:04:15.058] INFO: Done with hot pixel readout
[15:04:27.162] INFO: PixTest:: pg_setup set to default.
[15:04:27.163] INFO: 19 hot pixels found in step 2
[15:04:28.157] INFO: Collecting data for 5 seconds...
[15:04:33.173] INFO: Done with hot pixel readout
[15:04:45.182] INFO: PixTest:: pg_setup set to default.

[15:04:45.183] INFO: 20 hot pixels found in step 3
[15:04:46.178] INFO: Collecting data for 5 seconds...
[15:04:51.195] INFO: Done with hot pixel readout
[15:05:03.243] INFO: PixTest:: pg_setup set to default.
[15:05:03.244] INFO: 13 hot pixels found in step 4
[15:05:04.238] INFO: Collecting data for 5 seconds...
[15:05:09.254] INFO: Done with hot pixel readout
[15:05:21.379] INFO: PixTest:: pg_setup set to default.
[15:05:21.380] INFO: 12 hot pixels found in step 5
[15:05:22.374] INFO: Collecting data for 5 seconds...
[15:05:27.391] INFO: Done with hot pixel readout
[15:05:39.501] INFO: PixTest:: pg_setup set to default.
[15:05:39.502] INFO: 14 hot pixels found in step 6
[15:05:40.495] INFO: Collecting data for 5 seconds...
[15:05:45.512] INFO: Done with hot pixel readout
[15:05:57.571] INFO: PixTest:: pg_setup set to default.
[15:05:57.572] INFO: 7 hot pixels found in step 7
[15:05:58.566] INFO: Collecting data for 5 seconds...
[15:06:03.583] INFO: Done with hot pixel readout
[15:06:15.667] INFO: PixTest:: pg_setup set to default.

[15:06:15.668] INFO: 13 hot pixels found in step 8
[15:06:16.662] INFO: Collecting data for 5 seconds...
[15:06:21.679] INFO: Done with hot pixel readout
[15:06:33.775] INFO: PixTest:: pg_setup set to default.
[15:06:33.776] INFO: 13 hot pixels found in step 9
[15:06:34.770] INFO: Collecting data for 5 seconds...
[15:06:39.786] INFO: Done with hot pixel readout
[15:06:51.869] INFO: PixTest:: pg_setup set to default.
[15:06:51.870] INFO: 6 hot pixels found in step 10
[15:06:52.863] INFO: Collecting data for 5 seconds...
[15:06:57.880] INFO: Done with hot pixel readout
[15:07:09.969] INFO: PixTest:: pg_setup set to default.

[15:07:09.970] INFO: 5 hot pixels found in step 11
[15:07:10.963] INFO: Collecting data for 5 seconds...
[15:07:15.979] INFO: Done with hot pixel readout
[15:07:28.075] INFO: PixTest:: pg_setup set to default.
[15:07:28.076] INFO: 9 hot pixels found in step 12
[15:07:29.069] INFO: Collecting data for 5 seconds...
[15:07:34.087] INFO: Done with hot pixel readout
[15:07:46.168] INFO: PixTest:: pg_setup set to default.



[15:07:46.169] INFO: 8 hot pixels found in step 13
[15:07:47.162] INFO: Collecting data for 5 seconds...
[15:07:52.179] INFO: Done with hot pixel readout
[15:08:04.249] INFO: PixTest:: pg_setup set to default.

[15:08:04.250] INFO: 4 hot pixels found in step 14
[15:08:04.287] INFO: 4 hot pixels could not be trimmed and have been masked.
[15:08:04.290] INFO: PixTest::trimHotPixels() done
[15:08:04.291] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C0.dat
[15:08:04.296] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C1.dat
[15:08:04.302] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C2.dat
[15:08:04.308] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C3.dat
[15:08:04.313] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C4.dat
[15:08:04.318] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C5.dat
[15:08:04.324] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C6.dat
[15:08:04.329] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C7.dat
[15:08:04.334] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C8.dat
[15:08:04.339] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C9.dat
[15:08:04.344] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C10.dat
[15:08:04.350] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C11.dat
[15:08:04.355] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C12.dat
[15:08:04.360] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C13.dat
[15:08:04.365] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C14.dat
[15:08:04.370] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C15.dat
[15:08:04.376] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//defaultMaskFile.dat
[15:08:04.386] INFO: enter test to run
[15:08:27.991] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:08:27.991] INFO: running: highrate
[15:08:27.995] INFO: ----------------------------------------------------------------------
[15:08:27.995] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:08:27.995] INFO: ----------------------------------------------------------------------
[15:08:27.995] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:08:27.995] INFO: edge/corner pixel THR is adjusted
[15:08:27.996] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:08:28.954] INFO: Collecting data for 1 seconds...
[15:08:29.958] INFO: Done with hot pixel readout
[15:08:34.098] INFO: PixTest:: pg_setup set to default.
[15:08:34.099] INFO: 0 hot pixels found in step 0
[15:08:34.104] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:08:34.192] INFO: PixTest::trimHotPixels() done
[15:08:34.192] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C0.dat
[15:08:34.203] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C1.dat
[15:08:34.208] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C2.dat
[15:08:34.214] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C3.dat
[15:08:34.220] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C4.dat
[15:08:34.225] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C5.dat
[15:08:34.230] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C6.dat
[15:08:34.235] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C7.dat
[15:08:34.241] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C8.dat
[15:08:34.246] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C9.dat
[15:08:34.252] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C10.dat
[15:08:34.257] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C11.dat
[15:08:34.262] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C12.dat
[15:08:34.267] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C13.dat
[15:08:34.273] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C14.dat
[15:08:34.278] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//trimParameters35_C15.dat
[15:08:34.284] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-G-3-16_FPIXTest-17C-FNAL-160517-1426_2016-05-17_14h26m_1463513180/000_FPIXTest_p17//defaultMaskFile.dat
[15:08:34.293] INFO: enter test to run
[15:08:56.247] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:08:56.247] INFO: running: xray
[15:08:56.248] INFO: ----------------------------------------------------------------------
[15:08:56.248] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:08:56.248] INFO: ----------------------------------------------------------------------
[15:08:57.211] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:09:08.229] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[15:09:37.878] INFO: Resuming triggers.
[15:09:48.903] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[15:10:18.185] INFO: Resuming triggers.
[15:10:29.205] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[15:10:58.807] INFO: Resuming triggers.
[15:11:09.829] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[15:11:39.561] INFO: Resuming triggers.
[15:11:50.583] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[15:12:20.368] INFO: Resuming triggers.
[15:12:31.387] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[15:13:01.542] INFO: Resuming triggers.
[15:13:12.561] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[15:13:42.876] INFO: Resuming triggers.
[15:13:53.899] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[15:14:23.341] INFO: Resuming triggers.
[15:14:34.360] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[15:15:03.967] INFO: Resuming triggers.
[15:15:05.128] INFO: data taking finished, elapsed time: 100 seconds.
[15:15:08.578] INFO: PixTest:: pg_setup set to default.
[15:15:08.581] INFO: PixTestXray::doPhRun() done
[15:15:08.720] INFO: enter test to run
[15:16:03.707] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:16:03.708] INFO: running: xray
[15:16:03.709] INFO: ----------------------------------------------------------------------
[15:16:03.709] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:16:03.709] INFO: ----------------------------------------------------------------------
[15:16:04.689] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:16:11.096] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:16:41.218] INFO: Resuming triggers.
[15:16:47.626] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[15:17:17.769] INFO: Resuming triggers.
[15:17:24.172] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[15:17:54.272] INFO: Resuming triggers.
[15:18:00.676] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[15:18:30.795] INFO: Resuming triggers.
[15:18:37.201] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[15:19:07.325] INFO: Resuming triggers.
[15:19:13.731] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[15:19:43.823] INFO: Resuming triggers.
[15:19:50.228] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[15:20:19.002] INFO: Resuming triggers.
[15:20:26.406] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[15:20:56.554] INFO: Resuming triggers.
[15:21:02.960] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[15:21:33.096] INFO: Resuming triggers.
[15:21:39.502] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[15:22:09.648] INFO: Resuming triggers.
[15:22:16.053] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[15:22:47.130] INFO: Resuming triggers.
[15:22:53.536] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[15:23:24.324] INFO: Resuming triggers.
[15:23:30.727] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[15:24:01.952] INFO: Resuming triggers.
[15:24:08.358] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[15:24:39.957] INFO: Resuming triggers.
[15:24:46.360] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[15:25:16.874] INFO: Resuming triggers.
[15:25:21.144] INFO: data taking finished, elapsed time: 100 seconds.
[15:25:41.477] INFO: PixTest:: pg_setup set to default.
[15:25:41.480] INFO: PixTestXray::doPhRun() done
[15:25:41.630] INFO: enter test to run
[15:26:02.191] INFO: test: HighRate no parameter change
[15:26:02.191] INFO: running: highrate
[15:26:02.205] INFO: ----------------------------------------------------------------------
[15:26:02.205] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:26:02.205] INFO: ----------------------------------------------------------------------
[15:26:02.368] INFO: Expecting 768 events.
[15:26:03.502] INFO: 768 events read in total (418ms).
[15:26:03.503] INFO: Test took 1269ms.
[15:26:04.306] INFO: Expecting 41600 events.
[15:26:07.483] INFO: 41600 events read in total (2650ms).
[15:26:07.484] INFO: Test took 3973ms.
[15:26:07.523] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:08.234] INFO: Expecting 41600 events.
[15:26:11.472] INFO: 41600 events read in total (2711ms).
[15:26:11.473] INFO: Test took 3931ms.
[15:26:11.511] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:12.227] INFO: Expecting 41600 events.
[15:26:15.508] INFO: 41600 events read in total (2754ms).
[15:26:15.509] INFO: Test took 3979ms.
[15:26:15.546] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:16.266] INFO: Expecting 41600 events.
[15:26:19.550] INFO: 41600 events read in total (2757ms).
[15:26:19.551] INFO: Test took 3985ms.
[15:26:19.589] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:20.305] INFO: Expecting 41600 events.
[15:26:23.580] INFO: 41600 events read in total (2748ms).
[15:26:23.581] INFO: Test took 3972ms.
[15:26:23.618] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:24.335] INFO: Expecting 41600 events.
[15:26:27.624] INFO: 41600 events read in total (2762ms).
[15:26:27.625] INFO: Test took 3989ms.
[15:26:27.662] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:28.377] INFO: Expecting 41600 events.
[15:26:31.669] INFO: 41600 events read in total (2766ms).
[15:26:31.670] INFO: Test took 3989ms.
[15:26:31.708] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:32.426] INFO: Expecting 41600 events.
[15:26:35.724] INFO: 41600 events read in total (2771ms).
[15:26:35.725] INFO: Test took 3998ms.
[15:26:35.762] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:36.476] INFO: Expecting 41600 events.
[15:26:39.762] INFO: 41600 events read in total (2759ms).
[15:26:39.763] INFO: Test took 3982ms.
[15:26:39.800] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:40.520] INFO: Expecting 41600 events.
[15:26:43.815] INFO: 41600 events read in total (2768ms).
[15:26:43.816] INFO: Test took 3998ms.
[15:26:43.853] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:44.570] INFO: Expecting 41600 events.
[15:26:47.856] INFO: 41600 events read in total (2759ms).
[15:26:47.857] INFO: Test took 3983ms.
[15:26:47.896] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:48.609] INFO: Expecting 41600 events.
[15:26:51.901] INFO: 41600 events read in total (2765ms).
[15:26:51.902] INFO: Test took 3986ms.
[15:26:51.940] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:52.657] INFO: Expecting 41600 events.
[15:26:55.957] INFO: 41600 events read in total (2773ms).
[15:26:55.958] INFO: Test took 3998ms.
[15:26:55.996] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:26:56.712] INFO: Expecting 41600 events.
[15:27:00.006] INFO: 41600 events read in total (2767ms).
[15:27:00.007] INFO: Test took 3991ms.
[15:27:00.044] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:00.763] INFO: Expecting 41600 events.
[15:27:04.058] INFO: 41600 events read in total (2768ms).
[15:27:04.059] INFO: Test took 3994ms.
[15:27:04.096] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:04.815] INFO: Expecting 41600 events.
[15:27:08.116] INFO: 41600 events read in total (2775ms).
[15:27:08.117] INFO: Test took 4001ms.
[15:27:08.154] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:08.872] INFO: Expecting 41600 events.
[15:27:12.169] INFO: 41600 events read in total (2770ms).
[15:27:12.170] INFO: Test took 3996ms.
[15:27:12.208] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:12.925] INFO: Expecting 41600 events.
[15:27:16.216] INFO: 41600 events read in total (2764ms).
[15:27:16.217] INFO: Test took 3989ms.
[15:27:16.255] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:16.973] INFO: Expecting 41600 events.
[15:27:20.247] INFO: 41600 events read in total (2747ms).
[15:27:20.248] INFO: Test took 3973ms.
[15:27:20.285] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:20.004] INFO: Expecting 41600 events.
[15:27:24.189] INFO: 41600 events read in total (2658ms).
[15:27:24.190] INFO: Test took 3884ms.
[15:27:24.227] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:24.584] INFO: enter test to run
[15:27:33.535] INFO: test: HighRate no parameter change
[15:27:33.535] INFO: running: highrate
[15:27:33.536] INFO: ----------------------------------------------------------------------
[15:27:33.536] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:27:33.536] INFO: ----------------------------------------------------------------------
[15:27:34.148] INFO: Expecting 208000 events.
[15:27:46.242] INFO: 208000 events read in total (11568ms).
[15:27:46.246] INFO: Test took 12703ms.
[15:27:46.406] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:27:46.663] INFO: number of dead pixels (per ROC): 0 0 0 1 2 0 2 0 0 0 0 0 0 0 0 0
[15:27:46.663] INFO: number of red-efficiency pixels: 80 42 109 150 161 184 161 93 74 127 149 100 138 64 27 28
[15:27:46.663] INFO: number of X-ray hits detected: 68142 47642 76610 125814 129871 137098 136087 89807 80606 110906 106206 94013 96900 56616 25093 30415
[15:27:46.663] 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:27:46.663] INFO: number of Vcal hits detected: 207918 207958 207886 207796 207739 207811 207738 207906 207925 207873 207845 207896 207860 207935 207972 207972
[15:27:46.663] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[15:27:46.663] 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 100.0 99.9 100.0 100.0 100.0
[15:27:46.663] INFO: X-ray hit rate [MHz/cm2]: 20.0 14.0 22.5 36.9 38.1 40.2 39.9 26.3 23.6 32.5 31.1 27.6 28.4 16.6 7.4 8.9
[15:27:46.663] INFO: PixTestHighRate::doXPixelAlive() done
[15:27:46.710] INFO: PixTest:: pg_setup set to default.
[15:27:46.727] INFO: enter test to run
[15:28:15.286] INFO: test: HighRate no parameter change
[15:28:15.286] INFO: running: highrate
[15:28:15.288] INFO: ----------------------------------------------------------------------
[15:28:15.288] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:28:15.288] INFO: ----------------------------------------------------------------------
[15:28:15.900] INFO: Expecting 208000 events.
[15:28:29.663] INFO: 208000 events read in total (13236ms).
[15:28:29.669] INFO: Test took 14373ms.
[15:28:29.967] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:28:30.271] INFO: number of dead pixels (per ROC): 0 0 0 1 2 0 2 0 0 0 0 0 0 0 0 0
[15:28:30.271] INFO: number of red-efficiency pixels: 200 112 307 391 482 486 500 287 250 347 424 281 350 168 64 84
[15:28:30.271] INFO: number of X-ray hits detected: 130432 91430 146883 238752 245939 260472 258875 171002 153951 211144 203070 179940 185310 107466 48473 58178
[15:28:30.271] 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:28:30.271] INFO: number of Vcal hits detected: 207785 207883 207674 207516 207387 207470 207350 207689 207737 207633 207557 207707 207630 207824 207933 207915
[15:28:30.271] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[15:28:30.271] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.7 99.7 99.7 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[15:28:30.271] INFO: X-ray hit rate [MHz/cm2]: 38.2 26.8 43.1 70.0 72.1 76.3 75.9 50.1 45.1 61.9 59.5 52.7 54.3 31.5 14.2 17.1
[15:28:30.271] INFO: PixTestHighRate::doXPixelAlive() done
[15:28:30.318] INFO: PixTest:: pg_setup set to default.
[15:28:30.337] INFO: enter test to run
[15:28:49.566] INFO: test: HighRate no parameter change
[15:28:49.566] INFO: running: highrate
[15:28:49.567] INFO: ----------------------------------------------------------------------
[15:28:49.567] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:28:49.567] INFO: ----------------------------------------------------------------------
[15:28:50.182] INFO: Expecting 208000 events.
[15:29:06.159] INFO: 208000 events read in total (15450ms).
[15:29:06.167] INFO: Test took 16590ms.
[15:29:06.668] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:29:07.027] INFO: number of dead pixels (per ROC): 0 0 0 1 2 0 2 0 0 0 0 0 0 0 0 0
[15:29:07.027] INFO: number of red-efficiency pixels: 493 254 682 1101 1163 1301 1240 673 579 858 1016 693 845 336 117 116
[15:29:07.027] INFO: number of X-ray hits detected: 202966 141920 229027 372111 384552 407368 403365 267586 241161 330754 317162 279921 290135 167739 75759 91045
[15:29:07.027] 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:29:07.027] INFO: number of Vcal hits detected: 207418 207726 207053 206582 206416 206354 206294 207211 207337 207012 206753 207186 207007 207615 207879 207880
[15:29:07.027] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.4 99.4 99.3 99.3 99.7 99.7 99.6 99.4 99.7 99.6 99.8 99.9 99.9
[15:29:07.027] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.5 99.3 99.2 99.2 99.2 99.6 99.7 99.5 99.4 99.6 99.5 99.8 99.9 99.9
[15:29:07.027] INFO: X-ray hit rate [MHz/cm2]: 59.5 41.6 67.1 109.1 112.7 119.4 118.2 78.4 70.7 96.9 93.0 82.0 85.0 49.2 22.2 26.7
[15:29:07.027] INFO: PixTestHighRate::doXPixelAlive() done
[15:29:07.072] INFO: PixTest:: pg_setup set to default.
[15:29:07.087] INFO: enter test to run
[15:29:10.542] INFO: test: exit no parameter change
[15:29:10.946] QUIET: Connection to board 32 closed.
[15:29:10.960] INFO: pXar: this is the end, my friend