[15:10:09.940] INFO: *** Welcome to pxar ***
[15:10:09.940] INFO: *** Today: 2016/05/05
[15:10:09.957] INFO: *** Version: v1.9.0-796-gef167-dirty
[15:10:09.957] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//dacParameters35_C15.dat
[15:10:09.984] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:10:09.984] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//defaultMaskFile.dat
[15:10:09.984] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C15.dat
[15:10:10.135] INFO: clk: 4
[15:10:10.135] INFO: ctr: 4
[15:10:10.135] INFO: sda: 19
[15:10:10.135] INFO: tin: 9
[15:10:10.135] INFO: level: 15
[15:10:10.135] INFO: triggerdelay: 0
[15:10:10.135] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[15:10:10.135] INFO: Log level: INFO
[15:10:10.153] QUIET: Connection to board DTB_WREKRL opened.
[15:10:10.156] 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:10:10.159] INFO: RPC call hashes of host and DTB match: 398089610
[15:10:11.690] INFO: DUT info:
[15:10:11.690] INFO: The DUT currently contains the following objects:
[15:10:11.690] INFO: 2 TBM Cores tbm08c (2 ON)
[15:10:11.690] INFO: TBM Core alpha (0): 7 registers set
[15:10:11.690] INFO: TBM Core beta (1): 7 registers set
[15:10:11.690] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:10:11.690] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:11.691] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:10:12.105] INFO: enter 'restricted' command line mode
[15:10:12.105] INFO: enter test to run
[15:10:19.192] INFO: test: timing no parameter change
[15:10:19.192] INFO: running: timing
[15:10:19.201] INFO: ######################################################################
[15:10:19.201] INFO: PixTestTiming::doTest()
[15:10:19.201] INFO: ######################################################################
[15:10:19.201] INFO: ----------------------------------------------------------------------
[15:10:19.202] INFO: PixTestTiming::TBMPhaseScan()
[15:10:19.202] INFO: ----------------------------------------------------------------------
[15:15:04.256] INFO: TBM Phase Settings: 236
[15:15:04.256] INFO: 400MHz Phase: 3
[15:15:04.257] INFO: 160MHz Phase: 7
[15:15:04.257] INFO: Functional Phase Area: 4
[15:15:04.260] INFO: Test took 285059 ms.
[15:15:04.260] INFO: PixTestTiming::TBMPhaseScan() done.
[15:15:04.260] INFO: ----------------------------------------------------------------------
[15:15:04.260] INFO: PixTestTiming::ROCDelayScan()
[15:15:04.260] INFO: ----------------------------------------------------------------------
[15:17:03.168] INFO: ROC Delay Settings: 228
[15:17:03.168] INFO: ROC Header-Trailer/Token Delay: 11
[15:17:03.169] INFO: ROC Port 0 Delay: 4
[15:17:03.169] INFO: ROC Port 1 Delay: 4
[15:17:03.169] INFO: Functional ROC Area: 3
[15:17:03.172] INFO: Test took 118912 ms.
[15:17:03.172] INFO: PixTestTiming::ROCDelayScan() done.
[15:17:03.173] INFO: ----------------------------------------------------------------------
[15:17:03.173] INFO: PixTestTiming::TimingTest()
[15:17:03.173] INFO: ----------------------------------------------------------------------
[15:17:19.310] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:34.288] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:17:49.253] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:18:04.228] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:18:19.215] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:18:34.191] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:18:49.183] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:04.301] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:19.400] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:34.390] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:34.769] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:19:34.787] INFO: ----------------------------------------------------------------------
[15:19:34.787] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:19:34.787] INFO: ----------------------------------------------------------------------
[15:19:34.787] INFO: ----------------------------------------------------------------------
[15:19:34.787] INFO: Read back bit status: 1
[15:19:34.787] INFO: ----------------------------------------------------------------------
[15:19:34.787] INFO: ----------------------------------------------------------------------
[15:19:34.787] INFO: Timings are good!
[15:19:34.787] INFO: ----------------------------------------------------------------------
[15:19:34.787] INFO: Test took 151614 ms.
[15:19:34.787] INFO: PixTestTiming::TimingTest() done.
[15:19:34.787] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:19:34.787] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:19:34.787] INFO: PixTestTiming::doTest took 555591 ms.
[15:19:34.787] INFO: PixTestTiming::doTest() done
[15:19:34.787] INFO: Write out TBMPhaseScan_0_V0
[15:19:34.814] INFO: Write out TBMPhaseScan_1_V0
[15:19:34.814] INFO: Write out CombinedTBMPhaseScan_V0
[15:19:34.815] INFO: Write out ROCDelayScan3_V0
[15:19:34.816] INFO: enter test to run
[15:21:19.715] INFO: test: PixelAlive no parameter change
[15:21:19.715] INFO: running: pixelalive
[15:21:19.720] INFO: ----------------------------------------------------------------------
[15:21:19.720] 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:21:19.720] INFO: ----------------------------------------------------------------------
[15:21:20.037] INFO: Expecting 41600 events.
[15:21:24.340] INFO: 41600 events read in total (3588ms).
[15:21:24.341] INFO: Test took 4617ms.
[15:21:24.347] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:24.747] INFO: PixTestAlive::aliveTest() done
[15:21:24.747] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:21:24.751] INFO: enter test to run
[15:21:51.923] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:21:51.923] INFO: running: highrate
[15:21:51.924] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:21:52.178] INFO: ----------------------------------------------------------------------
[15:21:52.178] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:21:52.178] INFO: ----------------------------------------------------------------------
[15:21:52.178] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:21:52.178] INFO: edge/corner pixel THR is adjusted
[15:21:52.178] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:21:53.136] INFO: Collecting data for 5 seconds...
[15:21:58.152] INFO: Done with hot pixel readout
[15:22:09.467] INFO: PixTest:: pg_setup set to default.
[15:22:09.468] INFO: 17 hot pixels found in step 0
[15:22:10.456] INFO: Collecting data for 5 seconds...
[15:22:15.473] INFO: Done with hot pixel readout
[15:22:26.809] INFO: PixTest:: pg_setup set to default.
[15:22:26.810] INFO: 16 hot pixels found in step 1
[15:22:27.798] INFO: Collecting data for 5 seconds...
[15:22:32.815] INFO: Done with hot pixel readout
[15:22:44.127] INFO: PixTest:: pg_setup set to default.
[15:22:44.127] INFO: 13 hot pixels found in step 2
[15:22:45.116] INFO: Collecting data for 5 seconds...
[15:22:50.133] INFO: Done with hot pixel readout
[15:23:01.428] INFO: PixTest:: pg_setup set to default.

[15:23:01.428] INFO: 12 hot pixels found in step 3
[15:23:02.416] INFO: Collecting data for 5 seconds...
[15:23:07.433] INFO: Done with hot pixel readout
[15:23:18.779] INFO: PixTest:: pg_setup set to default.

[15:23:18.780] INFO: 12 hot pixels found in step 4
[15:23:19.768] INFO: Collecting data for 5 seconds...
[15:23:24.785] INFO: Done with hot pixel readout
[15:23:36.106] INFO: PixTest:: pg_setup set to default.


[15:23:36.106] INFO: 11 hot pixels found in step 5
[15:23:37.095] INFO: Collecting data for 5 seconds...
[15:23:42.112] INFO: Done with hot pixel readout
[15:23:53.426] INFO: PixTest:: pg_setup set to default.


[15:23:53.427] INFO: 9 hot pixels found in step 6
[15:23:54.416] INFO: Collecting data for 5 seconds...
[15:23:59.433] INFO: Done with hot pixel readout
[15:24:10.755] INFO: PixTest:: pg_setup set to default.


[15:24:10.756] INFO: 10 hot pixels found in step 7
[15:24:11.745] INFO: Collecting data for 5 seconds...
[15:24:16.762] INFO: Done with hot pixel readout
[15:24:28.063] INFO: PixTest:: pg_setup set to default.



[15:24:28.064] INFO: 8 hot pixels found in step 8
[15:24:29.053] INFO: Collecting data for 5 seconds...
[15:24:34.071] INFO: Done with hot pixel readout
[15:24:45.419] INFO: PixTest:: pg_setup set to default.


[15:24:45.420] INFO: 5 hot pixels found in step 9
[15:24:46.408] INFO: Collecting data for 5 seconds...
[15:24:51.425] INFO: Done with hot pixel readout
[15:25:02.736] INFO: PixTest:: pg_setup set to default.




[15:25:02.737] INFO: 7 hot pixels found in step 10
[15:25:03.726] INFO: Collecting data for 5 seconds...
[15:25:08.742] INFO: Done with hot pixel readout
[15:25:20.053] INFO: PixTest:: pg_setup set to default.




[15:25:20.054] INFO: 7 hot pixels found in step 11
[15:25:21.043] INFO: Collecting data for 5 seconds...
[15:25:26.060] INFO: Done with hot pixel readout
[15:25:37.312] INFO: PixTest:: pg_setup set to default.



[15:25:37.313] INFO: 3 hot pixels found in step 12
[15:25:37.345] INFO: 3 hot pixels could not be trimmed and have been masked.
[15:25:37.349] INFO: PixTest::trimHotPixels() done
[15:25:37.367] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C0.dat
[15:25:37.380] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C1.dat
[15:25:37.386] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C2.dat
[15:25:37.417] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C3.dat
[15:25:37.422] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C4.dat
[15:25:37.427] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C5.dat
[15:25:37.434] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C6.dat
[15:25:37.439] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C7.dat
[15:25:37.444] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C8.dat
[15:25:37.449] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C9.dat
[15:25:37.455] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C10.dat
[15:25:37.460] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C11.dat
[15:25:37.466] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C12.dat
[15:25:37.471] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C13.dat
[15:25:37.476] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C14.dat
[15:25:37.481] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C15.dat
[15:25:37.486] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//defaultMaskFile.dat
[15:25:37.497] INFO: enter test to run
[15:26:34.969] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:26:34.969] INFO: running: highrate
[15:26:34.974] INFO: ----------------------------------------------------------------------
[15:26:34.974] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:26:34.974] INFO: ----------------------------------------------------------------------
[15:26:34.974] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:26:34.974] INFO: edge/corner pixel THR is adjusted
[15:26:34.974] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:26:35.932] INFO: Collecting data for 1 seconds...
[15:26:36.935] INFO: Done with hot pixel readout
[15:26:40.866] INFO: PixTest:: pg_setup set to default.
[15:26:40.867] INFO: 0 hot pixels found in step 0
[15:26:40.873] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:26:40.963] INFO: PixTest::trimHotPixels() done
[15:26:40.963] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C0.dat
[15:26:40.972] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C1.dat
[15:26:40.981] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C2.dat
[15:26:40.987] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C3.dat
[15:26:40.992] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C4.dat
[15:26:40.997] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C5.dat
[15:26:41.003] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C6.dat
[15:26:41.008] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C7.dat
[15:26:41.013] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C8.dat
[15:26:41.019] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C9.dat
[15:26:41.024] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C10.dat
[15:26:41.029] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C11.dat
[15:26:41.034] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C12.dat
[15:26:41.039] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C13.dat
[15:26:41.045] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C14.dat
[15:26:41.050] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//trimParameters35_C15.dat
[15:26:41.055] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-3-03_FPIXTest-17C-FNAL-160429-1212_2016-04-29_12h12m_1461949956/000_FPIXTest_p17//defaultMaskFile.dat
[15:26:41.065] INFO: enter test to run
[15:27:47.337] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:27:47.337] INFO: running: xray
[15:27:47.338] INFO: ----------------------------------------------------------------------
[15:27:47.338] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:27:47.338] INFO: ----------------------------------------------------------------------
[15:27:48.301] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:28:00.191] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:28:29.680] INFO: Resuming triggers.
[15:28:41.568] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[15:29:10.792] INFO: Resuming triggers.
[15:29:22.682] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[15:29:51.875] INFO: Resuming triggers.
[15:30:03.766] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[15:30:32.633] INFO: Resuming triggers.
[15:30:44.522] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[15:31:13.268] INFO: Resuming triggers.
[15:31:25.159] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[15:31:54.323] INFO: Resuming triggers.
[15:32:06.214] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[15:32:35.445] INFO: Resuming triggers.
[15:32:47.338] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[15:33:16.489] INFO: Resuming triggers.
[15:33:21.701] INFO: data taking finished, elapsed time: 100 seconds.
[15:33:34.729] INFO: PixTest:: pg_setup set to default.
[15:33:34.732] INFO: PixTestXray::doPhRun() done
[15:33:34.864] INFO: enter test to run
[15:34:19.046] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:34:19.046] INFO: running: xray
[15:34:19.047] INFO: ----------------------------------------------------------------------
[15:34:19.047] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:34:19.047] INFO: ----------------------------------------------------------------------
[15:34:20.020] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:34:27.146] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[15:34:57.168] INFO: Resuming triggers.
[15:35:04.300] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[15:35:34.323] INFO: Resuming triggers.
[15:35:41.451] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[15:36:11.431] INFO: Resuming triggers.
[15:36:18.560] INFO: run duration 28 seconds, buffer almost full (81%), pausing triggers.
[15:36:48.576] INFO: Resuming triggers.
[15:36:55.706] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[15:37:26.002] INFO: Resuming triggers.
[15:37:33.131] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[15:38:04.151] INFO: Resuming triggers.
[15:38:11.282] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[15:38:42.458] INFO: Resuming triggers.
[15:38:49.586] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[15:39:19.962] INFO: Resuming triggers.
[15:39:27.091] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[15:39:57.092] INFO: Resuming triggers.
[15:40:04.223] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[15:40:34.201] INFO: Resuming triggers.
[15:40:41.330] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[15:41:11.485] INFO: Resuming triggers.
[15:41:18.614] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[15:41:49.447] INFO: Resuming triggers.
[15:41:56.578] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[15:42:27.955] INFO: Resuming triggers.
[15:42:35.081] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[15:43:03.969] INFO: Resuming triggers.
[15:43:04.512] INFO: data taking finished, elapsed time: 100 seconds.
[15:43:07.139] INFO: PixTest:: pg_setup set to default.
[15:43:07.142] INFO: PixTestXray::doPhRun() done
[15:43:07.294] INFO: enter test to run
[15:43:32.330] INFO: test: HighRate no parameter change
[15:43:32.330] INFO: running: highrate
[15:43:32.331] INFO: ----------------------------------------------------------------------
[15:43:32.331] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:43:32.331] INFO: ----------------------------------------------------------------------
[15:43:32.471] INFO: Expecting 768 events.
[15:43:33.604] INFO: 768 events read in total (418ms).
[15:43:33.605] INFO: Test took 1268ms.
[15:43:34.408] INFO: Expecting 41600 events.
[15:43:37.481] INFO: 41600 events read in total (2546ms).
[15:43:37.482] INFO: Test took 3870ms.
[15:43:37.512] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:38.243] INFO: Expecting 41600 events.
[15:43:41.418] INFO: 41600 events read in total (2648ms).
[15:43:41.419] INFO: Test took 3892ms.
[15:43:41.451] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:42.178] INFO: Expecting 41600 events.
[15:43:45.382] INFO: 41600 events read in total (2677ms).
[15:43:45.383] INFO: Test took 3915ms.
[15:43:45.415] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:46.145] INFO: Expecting 41600 events.
[15:43:49.342] INFO: 41600 events read in total (2670ms).
[15:43:49.343] INFO: Test took 3910ms.
[15:43:49.374] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:50.104] INFO: Expecting 41600 events.
[15:43:53.314] INFO: 41600 events read in total (2683ms).
[15:43:53.315] INFO: Test took 3924ms.
[15:43:53.347] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:54.073] INFO: Expecting 41600 events.
[15:43:57.298] INFO: 41600 events read in total (2698ms).
[15:43:57.299] INFO: Test took 3935ms.
[15:43:57.330] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:58.058] INFO: Expecting 41600 events.
[15:44:01.280] INFO: 41600 events read in total (2695ms).
[15:44:01.281] INFO: Test took 3934ms.
[15:44:01.313] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:02.041] INFO: Expecting 41600 events.
[15:44:05.256] INFO: 41600 events read in total (2688ms).
[15:44:05.257] INFO: Test took 3927ms.
[15:44:05.288] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:06.018] INFO: Expecting 41600 events.
[15:44:09.235] INFO: 41600 events read in total (2690ms).
[15:44:09.236] INFO: Test took 3930ms.
[15:44:09.267] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:09.993] INFO: Expecting 41600 events.
[15:44:13.210] INFO: 41600 events read in total (2690ms).
[15:44:13.211] INFO: Test took 3926ms.
[15:44:13.242] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:13.971] INFO: Expecting 41600 events.
[15:44:17.194] INFO: 41600 events read in total (2696ms).
[15:44:17.195] INFO: Test took 3936ms.
[15:44:17.226] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:17.956] INFO: Expecting 41600 events.
[15:44:21.168] INFO: 41600 events read in total (2685ms).
[15:44:21.169] INFO: Test took 3925ms.
[15:44:21.200] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:21.931] INFO: Expecting 41600 events.
[15:44:25.151] INFO: 41600 events read in total (2693ms).
[15:44:25.152] INFO: Test took 3935ms.
[15:44:25.184] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:25.914] INFO: Expecting 41600 events.
[15:44:29.132] INFO: 41600 events read in total (2691ms).
[15:44:29.133] INFO: Test took 3932ms.
[15:44:29.165] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:29.888] INFO: Expecting 41600 events.
[15:44:33.096] INFO: 41600 events read in total (2681ms).
[15:44:33.097] INFO: Test took 3916ms.
[15:44:33.128] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:33.859] INFO: Expecting 41600 events.
[15:44:37.053] INFO: 41600 events read in total (2667ms).
[15:44:37.054] INFO: Test took 3909ms.
[15:44:37.085] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:37.814] INFO: Expecting 41600 events.
[15:44:41.048] INFO: 41600 events read in total (2707ms).
[15:44:41.049] INFO: Test took 3948ms.
[15:44:41.080] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:41.806] INFO: Expecting 41600 events.
[15:44:45.011] INFO: 41600 events read in total (2679ms).
[15:44:45.012] INFO: Test took 3914ms.
[15:44:45.044] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:45.774] INFO: Expecting 41600 events.
[15:44:48.979] INFO: 41600 events read in total (2678ms).
[15:44:48.980] INFO: Test took 3919ms.
[15:44:49.011] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:49.737] INFO: Expecting 41600 events.
[15:44:52.792] INFO: 41600 events read in total (2528ms).
[15:44:52.793] INFO: Test took 3764ms.
[15:44:52.823] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:53.184] INFO: enter test to run
[15:45:06.865] INFO: test: HighRate no parameter change
[15:45:06.865] INFO: running: highrate
[15:45:06.866] INFO: ----------------------------------------------------------------------
[15:45:06.866] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:45:06.866] INFO: ----------------------------------------------------------------------
[15:45:07.482] INFO: Expecting 208000 events.
[15:45:19.191] INFO: 208000 events read in total (11182ms).
[15:45:19.194] INFO: Test took 12319ms.
[15:45:19.327] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:19.574] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:45:19.574] INFO: number of red-efficiency pixels: 82 43 63 128 119 133 107 106 75 95 88 77 95 49 17 21
[15:45:19.574] INFO: number of X-ray hits detected: 67958 41382 62314 97295 107004 103064 106546 71885 62966 87159 86237 73488 71487 43530 19147 23344
[15:45:19.574] 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:45:19.574] INFO: number of Vcal hits detected: 207915 207957 207937 207869 207880 207866 207892 207894 207924 207904 207911 207922 207903 207950 207983 207978
[15:45:19.574] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[15:45:19.574] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[15:45:19.574] INFO: X-ray hit rate [MHz/cm2]: 19.9 12.1 18.3 28.5 31.4 30.2 31.2 21.1 18.5 25.5 25.3 21.5 21.0 12.8 5.6 6.8
[15:45:19.575] INFO: PixTestHighRate::doXPixelAlive() done
[15:45:19.629] INFO: PixTest:: pg_setup set to default.
[15:45:19.639] INFO: enter test to run
[15:45:41.089] INFO: test: HighRate no parameter change
[15:45:41.089] INFO: running: highrate
[15:45:41.090] INFO: ----------------------------------------------------------------------
[15:45:41.090] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:45:41.090] INFO: ----------------------------------------------------------------------
[15:45:41.706] INFO: Expecting 208000 events.
[15:45:54.998] INFO: 208000 events read in total (12765ms).
[15:45:55.005] INFO: Test took 13907ms.
[15:45:55.270] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:55.560] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:45:55.560] INFO: number of red-efficiency pixels: 271 105 195 401 336 437 349 252 203 263 251 259 254 138 46 50
[15:45:55.560] INFO: number of X-ray hits detected: 139958 85218 128851 202169 222138 214357 219414 147145 130417 179075 179143 151033 147697 91442 39366 47561
[15:45:55.560] 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:45:55.560] INFO: number of Vcal hits detected: 207715 207892 207799 207567 207638 207538 207631 207729 207786 207727 207734 207733 207733 207857 207952 207950
[15:45:55.560] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[15:45:55.560] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[15:45:55.560] INFO: X-ray hit rate [MHz/cm2]: 41.0 25.0 37.8 59.3 65.1 62.8 64.3 43.1 38.2 52.5 52.5 44.3 43.3 26.8 11.5 13.9
[15:45:55.560] INFO: PixTestHighRate::doXPixelAlive() done
[15:45:55.610] INFO: PixTest:: pg_setup set to default.
[15:45:55.625] INFO: enter test to run
[15:46:18.112] INFO: test: HighRate no parameter change
[15:46:18.113] INFO: running: highrate
[15:46:18.114] INFO: ----------------------------------------------------------------------
[15:46:18.114] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:46:18.114] INFO: ----------------------------------------------------------------------
[15:46:18.726] INFO: Expecting 208000 events.
[15:46:33.678] INFO: 208000 events read in total (14425ms).
[15:46:33.685] INFO: Test took 15562ms.
[15:46:34.084] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:34.419] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:46:34.420] INFO: number of red-efficiency pixels: 540 221 433 956 839 1131 800 627 406 598 529 584 571 323 71 90
[15:46:34.420] INFO: number of X-ray hits detected: 213625 130620 196849 306535 339018 325228 334296 224794 198453 272904 273379 231335 224357 138866 60918 73274
[15:46:34.420] 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:34.420] INFO: number of Vcal hits detected: 207313 207770 207475 206842 207035 206568 207044 207232 207552 207332 207411 207348 207378 207640 207928 207909
[15:46:34.420] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.8 99.5 99.6 99.4 99.6 99.7 99.8 99.7 99.7 99.7 99.7 99.8 100.0 100.0
[15:46:34.420] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.4 99.5 99.3 99.5 99.6 99.8 99.7 99.7 99.7 99.7 99.8 100.0 100.0
[15:46:34.420] INFO: X-ray hit rate [MHz/cm2]: 62.6 38.3 57.7 89.8 99.4 95.3 98.0 65.9 58.2 80.0 80.1 67.8 65.8 40.7 17.9 21.5
[15:46:34.420] INFO: PixTestHighRate::doXPixelAlive() done
[15:46:34.465] INFO: PixTest:: pg_setup set to default.
[15:46:34.481] INFO: enter test to run
[15:46:37.688] INFO: test: exit no parameter change
[15:46:38.091] QUIET: Connection to board 33 closed.
[15:46:38.092] INFO: pXar: this is the end, my friend