[15:28:46.173] INFO: *** Welcome to pxar ***
[15:28:46.173] INFO: *** Today: 2016/04/26
[15:28:46.190] INFO: *** Version: v1.9.0-796-gef167-dirty
[15:28:46.190] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//dacParameters35_C15.dat
[15:28:46.216] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:28:46.216] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//defaultMaskFile.dat
[15:28:46.216] INFO: MASKED Roc 0 col/row: 0 3
[15:28:46.216] INFO: MASKED Roc 0 col/row: 2 4
[15:28:46.216] INFO: MASKED Roc 0 col/row: 2 7
[15:28:46.216] INFO: MASKED Roc 3 col/row: 9 43
[15:28:46.216] INFO: MASKED Roc 3 col/row: 47 33
[15:28:46.216] INFO: MASKED Roc 5 col/row: 5 17
[15:28:46.217] INFO: MASKED Roc 5 col/row: 9 58
[15:28:46.217] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C15.dat
[15:28:46.217] INFO: masking Roc 0 col/row: 0 3
[15:28:46.217] INFO: masking Roc 0 col/row: 2 4
[15:28:46.217] INFO: masking Roc 0 col/row: 2 7
[15:28:46.237] INFO: masking Roc 3 col/row: 9 43
[15:28:46.237] INFO: masking Roc 3 col/row: 47 33
[15:28:46.246] INFO: masking Roc 5 col/row: 5 17
[15:28:46.246] INFO: masking Roc 5 col/row: 9 58
[15:28:46.298] INFO: clk: 4
[15:28:46.298] INFO: ctr: 4
[15:28:46.298] INFO: sda: 19
[15:28:46.298] INFO: tin: 9
[15:28:46.298] INFO: level: 15
[15:28:46.298] INFO: triggerdelay: 0
[15:28:46.298] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[15:28:46.298] INFO: Log level: INFO
[15:28:46.316] QUIET: Connection to board DTB_WREK4U opened.
[15:28:46.319] 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:
------------------------------------------------------
[15:28:46.322] INFO: RPC call hashes of host and DTB match: 398089610
[15:28:47.850] INFO: DUT info:
[15:28:47.850] INFO: The DUT currently contains the following objects:
[15:28:47.850] INFO: 2 TBM Cores tbm08c (2 ON)
[15:28:47.850] INFO: TBM Core alpha (0): 7 registers set
[15:28:47.850] INFO: TBM Core beta (1): 7 registers set
[15:28:47.850] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:28:47.850] INFO: ROC 0: 19 DACs set, Pixels: 3 masked, 0 active.
[15:28:47.850] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.850] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.850] INFO: ROC 3: 19 DACs set, Pixels: 2 masked, 0 active.
[15:28:47.850] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.850] INFO: ROC 5: 19 DACs set, Pixels: 2 masked, 0 active.
[15:28:47.850] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.850] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.851] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.851] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.851] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.851] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.851] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.851] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.851] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:47.851] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:28:48.267] INFO: enter 'restricted' command line mode
[15:28:48.267] INFO: enter test to run
[15:28:53.431] INFO: test: timing no parameter change
[15:28:53.431] INFO: running: timing
[15:28:53.440] INFO: ######################################################################
[15:28:53.440] INFO: PixTestTiming::doTest()
[15:28:53.440] INFO: ######################################################################
[15:28:53.440] INFO: ----------------------------------------------------------------------
[15:28:53.440] INFO: PixTestTiming::TBMPhaseScan()
[15:28:53.440] INFO: ----------------------------------------------------------------------
[15:34:12.903] INFO: TBM Phase Settings: 232
[15:34:12.903] INFO: 400MHz Phase: 2
[15:34:12.903] INFO: 160MHz Phase: 7
[15:34:12.903] INFO: Functional Phase Area: 3
[15:34:12.906] INFO: Test took 319466 ms.
[15:34:12.906] INFO: PixTestTiming::TBMPhaseScan() done.
[15:34:12.906] INFO: ROC 0 masking pixel 0/3
[15:34:12.906] INFO: ROC 0 masking pixel 2/4
[15:34:12.906] INFO: ROC 0 masking pixel 2/7
[15:34:12.906] INFO: ROC 3 masking pixel 9/43
[15:34:12.906] INFO: ROC 3 masking pixel 47/33
[15:34:12.906] INFO: ROC 5 masking pixel 5/17
[15:34:12.906] INFO: ROC 5 masking pixel 9/58
[15:34:12.906] INFO: ----------------------------------------------------------------------
[15:34:12.906] INFO: PixTestTiming::ROCDelayScan()
[15:34:12.906] INFO: ----------------------------------------------------------------------
[15:36:24.389] INFO: ROC Delay Settings: 228
[15:36:24.390] INFO: ROC Header-Trailer/Token Delay: 11
[15:36:24.390] INFO: ROC Port 0 Delay: 4
[15:36:24.390] INFO: ROC Port 1 Delay: 4
[15:36:24.390] INFO: Functional ROC Area: 5
[15:36:24.393] INFO: Test took 131487 ms.
[15:36:24.393] INFO: PixTestTiming::ROCDelayScan() done.
[15:36:24.393] INFO: ROC 0 masking pixel 0/3
[15:36:24.393] INFO: ROC 0 masking pixel 2/4
[15:36:24.393] INFO: ROC 0 masking pixel 2/7
[15:36:24.393] INFO: ROC 3 masking pixel 9/43
[15:36:24.393] INFO: ROC 3 masking pixel 47/33
[15:36:24.393] INFO: ROC 5 masking pixel 5/17
[15:36:24.393] INFO: ROC 5 masking pixel 9/58
[15:36:24.393] INFO: ----------------------------------------------------------------------
[15:36:24.393] INFO: PixTestTiming::TimingTest()
[15:36:24.393] INFO: ----------------------------------------------------------------------
[15:36:40.126] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:54.814] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:37:09.607] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:37:24.501] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:37:39.317] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:37:54.224] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:09.186] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:23.819] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:38.711] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:53.688] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:54.067] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:54.087] INFO: ----------------------------------------------------------------------
[15:38:54.087] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:38:54.087] INFO: ----------------------------------------------------------------------
[15:38:54.088] INFO: ----------------------------------------------------------------------
[15:38:54.088] INFO: Read back bit status: 1
[15:38:54.088] INFO: ----------------------------------------------------------------------
[15:38:54.088] INFO: ----------------------------------------------------------------------
[15:38:54.088] INFO: Timings are good!
[15:38:54.088] INFO: ----------------------------------------------------------------------
[15:38:54.088] INFO: Test took 149695 ms.
[15:38:54.088] INFO: PixTestTiming::TimingTest() done.
[15:38:54.088] INFO: ROC 0 masking pixel 0/3
[15:38:54.088] INFO: ROC 0 masking pixel 2/4
[15:38:54.088] INFO: ROC 0 masking pixel 2/7
[15:38:54.088] INFO: ROC 3 masking pixel 9/43
[15:38:54.088] INFO: ROC 3 masking pixel 47/33
[15:38:54.088] INFO: ROC 5 masking pixel 5/17
[15:38:54.088] INFO: ROC 5 masking pixel 9/58
[15:38:54.104] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:38:54.105] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:38:54.105] INFO: PixTestTiming::doTest took 600670 ms.
[15:38:54.105] INFO: PixTestTiming::doTest() done
[15:38:54.105] INFO: ROC 0 masking pixel 0/3
[15:38:54.105] INFO: ROC 0 masking pixel 2/4
[15:38:54.105] INFO: ROC 0 masking pixel 2/7
[15:38:54.105] INFO: ROC 3 masking pixel 9/43
[15:38:54.105] INFO: ROC 3 masking pixel 47/33
[15:38:54.105] INFO: ROC 5 masking pixel 5/17
[15:38:54.105] INFO: ROC 5 masking pixel 9/58
[15:38:54.105] INFO: Write out TBMPhaseScan_0_V0
[15:38:54.132] INFO: Write out TBMPhaseScan_1_V0
[15:38:54.132] INFO: Write out CombinedTBMPhaseScan_V0
[15:38:54.159] INFO: Write out ROCDelayScan3_V0
[15:38:54.161] INFO: enter test to run
[15:40:00.522] INFO: test: PixelAlive no parameter change
[15:40:00.522] INFO: running: pixelalive
[15:40:00.526] INFO: ----------------------------------------------------------------------
[15:40:00.526] 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:40:00.526] INFO: ----------------------------------------------------------------------
[15:40:00.528] INFO: ROC 0 masking pixel 0/3
[15:40:00.529] INFO: ROC 0 masking pixel 2/4
[15:40:00.529] INFO: ROC 0 masking pixel 2/7
[15:40:00.529] INFO: ROC 3 masking pixel 9/43
[15:40:00.529] INFO: ROC 3 masking pixel 47/33
[15:40:00.529] INFO: ROC 5 masking pixel 5/17
[15:40:00.529] INFO: ROC 5 masking pixel 9/58
[15:40:00.849] INFO: Expecting 41600 events.
[15:40:05.143] INFO: 41600 events read in total (3578ms).
[15:40:05.143] INFO: Test took 4614ms.
[15:40:05.149] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:05.546] INFO: PixTestAlive::aliveTest() done
[15:40:05.546] INFO: number of dead pixels (per ROC): 3 0 0 2 0 2 0 0 0 0 0 0 1 0 0 0
[15:40:05.546] INFO: ROC 0 masking pixel 0/3
[15:40:05.547] INFO: ROC 0 masking pixel 2/4
[15:40:05.547] INFO: ROC 0 masking pixel 2/7
[15:40:05.547] INFO: ROC 3 masking pixel 9/43
[15:40:05.547] INFO: ROC 3 masking pixel 47/33
[15:40:05.547] INFO: ROC 5 masking pixel 5/17
[15:40:05.547] INFO: ROC 5 masking pixel 9/58
[15:40:05.550] INFO: enter test to run
[15:40:29.770] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:40:29.770] INFO: running: highrate
[15:40:29.770] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:40:30.028] INFO: ----------------------------------------------------------------------
[15:40:30.028] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:40:30.028] INFO: ----------------------------------------------------------------------
[15:40:30.028] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:40:30.028] INFO: edge/corner pixel THR is adjusted
[15:40:30.028] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:40:30.987] INFO: Collecting data for 5 seconds...
[15:40:36.004] INFO: Done with hot pixel readout
[15:40:47.297] INFO: PixTest:: pg_setup set to default.
[15:40:47.298] INFO: 0 hot pixels found in step 0
[15:40:47.344] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:40:47.347] INFO: PixTest::trimHotPixels() done
[15:40:47.347] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C0.dat
[15:40:47.353] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C1.dat
[15:40:47.358] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C2.dat
[15:40:47.364] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C3.dat
[15:40:47.369] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C4.dat
[15:40:47.374] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C5.dat
[15:40:47.379] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C6.dat
[15:40:47.385] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C7.dat
[15:40:47.390] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C8.dat
[15:40:47.395] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C9.dat
[15:40:47.400] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C10.dat
[15:40:47.406] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C11.dat
[15:40:47.411] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C12.dat
[15:40:47.416] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C13.dat
[15:40:47.422] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C14.dat
[15:40:47.427] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C15.dat
[15:40:47.432] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//defaultMaskFile.dat
[15:40:47.442] INFO: enter test to run
[15:42:04.953] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:42:04.953] INFO: running: highrate
[15:42:04.957] INFO: ----------------------------------------------------------------------
[15:42:04.957] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:42:04.957] INFO: ----------------------------------------------------------------------
[15:42:04.957] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:42:04.957] INFO: edge/corner pixel THR is adjusted
[15:42:04.957] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:42:05.915] INFO: Collecting data for 1 seconds...
[15:42:06.919] INFO: Done with hot pixel readout
[15:42:11.097] INFO: PixTest:: pg_setup set to default.
[15:42:11.098] INFO: 0 hot pixels found in step 0
[15:42:11.104] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:42:11.182] INFO: PixTest::trimHotPixels() done
[15:42:11.183] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C0.dat
[15:42:11.195] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C1.dat
[15:42:11.207] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C2.dat
[15:42:11.216] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C3.dat
[15:42:11.221] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C4.dat
[15:42:11.227] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C5.dat
[15:42:11.232] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C6.dat
[15:42:11.237] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C7.dat
[15:42:11.243] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C8.dat
[15:42:11.248] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C9.dat
[15:42:11.254] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C10.dat
[15:42:11.259] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C11.dat
[15:42:11.264] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C12.dat
[15:42:11.270] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C13.dat
[15:42:11.275] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C14.dat
[15:42:11.280] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//trimParameters35_C15.dat
[15:42:11.286] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-3-24_FPIXTest-17C-FNAL-160421-1034_2016-04-21_10h34m_1461252897/000_FPIXTest_p17//defaultMaskFile.dat
[15:42:11.302] INFO: enter test to run
[15:42:27.785] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:42:27.785] INFO: running: xray
[15:42:27.786] INFO: ----------------------------------------------------------------------
[15:42:27.786] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:42:27.786] INFO: ----------------------------------------------------------------------
[15:42:27.789] INFO: ROC 0 masking pixel 0/3
[15:42:27.789] INFO: ROC 0 masking pixel 2/4
[15:42:27.789] INFO: ROC 0 masking pixel 2/7
[15:42:27.789] INFO: ROC 3 masking pixel 9/43
[15:42:27.789] INFO: ROC 3 masking pixel 47/33
[15:42:27.790] INFO: ROC 5 masking pixel 5/17
[15:42:27.790] INFO: ROC 5 masking pixel 9/58
[15:42:28.750] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:42:39.866] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:43:08.674] INFO: Resuming triggers.
[15:43:19.794] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:43:47.354] INFO: Resuming triggers.
[15:43:58.474] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[15:44:27.082] INFO: Resuming triggers.
[15:44:38.201] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[15:45:06.783] INFO: Resuming triggers.
[15:45:17.902] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[15:45:42.654] INFO: Resuming triggers.
[15:45:53.772] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[15:46:23.090] INFO: Resuming triggers.
[15:46:34.208] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[15:47:03.119] INFO: Resuming triggers.
[15:47:14.235] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[15:47:43.024] INFO: Resuming triggers.
[15:47:54.141] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[15:48:21.713] INFO: Resuming triggers.
[15:48:21.978] INFO: data taking finished, elapsed time: 100 seconds.
[15:48:23.108] INFO: PixTest:: pg_setup set to default.
[15:48:23.112] INFO: PixTestXray::doPhRun() done
[15:48:23.311] INFO: enter test to run
[15:49:00.494] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:49:00.494] INFO: running: xray
[15:49:00.495] INFO: ----------------------------------------------------------------------
[15:49:00.495] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:49:00.495] INFO: ----------------------------------------------------------------------
[15:49:00.517] INFO: ROC 0 masking pixel 0/3
[15:49:00.517] INFO: ROC 0 masking pixel 2/4
[15:49:00.517] INFO: ROC 0 masking pixel 2/7
[15:49:00.517] INFO: ROC 3 masking pixel 9/43
[15:49:00.517] INFO: ROC 3 masking pixel 47/33
[15:49:00.517] INFO: ROC 5 masking pixel 5/17
[15:49:00.517] INFO: ROC 5 masking pixel 9/58
[15:49:01.476] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:49:08.025] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:49:38.000] INFO: Resuming triggers.
[15:49:45.546] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[15:50:14.719] INFO: Resuming triggers.
[15:50:21.261] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[15:50:51.924] INFO: Resuming triggers.
[15:50:58.468] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[15:51:28.544] INFO: Resuming triggers.
[15:51:35.087] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[15:52:05.467] INFO: Resuming triggers.
[15:52:12.010] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[15:52:40.862] INFO: Resuming triggers.
[15:52:47.405] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:53:16.909] INFO: Resuming triggers.
[15:53:23.454] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[15:53:54.114] INFO: Resuming triggers.
[15:54:00.661] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[15:54:31.027] INFO: Resuming triggers.
[15:54:37.576] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[15:55:08.124] INFO: Resuming triggers.
[15:55:14.669] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[15:55:43.258] INFO: Resuming triggers.
[15:55:49.808] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[15:56:20.273] INFO: Resuming triggers.
[15:56:26.819] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[15:56:55.086] INFO: Resuming triggers.
[15:57:01.631] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[15:57:30.859] INFO: Resuming triggers.
[15:57:37.406] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[15:58:07.688] INFO: Resuming triggers.
[15:58:09.832] INFO: data taking finished, elapsed time: 100 seconds.
[15:58:20.336] INFO: PixTest:: pg_setup set to default.
[15:58:20.339] INFO: PixTestXray::doPhRun() done
[15:58:20.493] INFO: enter test to run
[15:59:10.217] INFO: test: HighRate no parameter change
[15:59:10.217] INFO: running: highrate
[15:59:10.234] INFO: ----------------------------------------------------------------------
[15:59:10.234] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:59:10.234] INFO: ----------------------------------------------------------------------
[15:59:10.390] INFO: Expecting 768 events.
[15:59:11.524] INFO: 768 events read in total (419ms).
[15:59:11.524] INFO: Test took 1269ms.
[15:59:11.527] INFO: ROC 0 masking pixel 0/3
[15:59:11.527] INFO: ROC 0 masking pixel 2/4
[15:59:11.527] INFO: ROC 0 masking pixel 2/7
[15:59:11.527] INFO: ROC 3 masking pixel 9/43
[15:59:11.527] INFO: ROC 3 masking pixel 47/33
[15:59:11.527] INFO: ROC 5 masking pixel 5/17
[15:59:11.527] INFO: ROC 5 masking pixel 9/58
[15:59:12.327] INFO: Expecting 41600 events.
[15:59:15.431] INFO: 41600 events read in total (2577ms).
[15:59:15.432] INFO: Test took 3902ms.
[15:59:15.465] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:16.191] INFO: Expecting 41600 events.
[15:59:19.394] INFO: 41600 events read in total (2676ms).
[15:59:19.395] INFO: Test took 3912ms.
[15:59:19.429] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:20.151] INFO: Expecting 41600 events.
[15:59:23.299] INFO: 41600 events read in total (2621ms).
[15:59:23.300] INFO: Test took 3853ms.
[15:59:23.335] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:24.056] INFO: Expecting 41600 events.
[15:59:27.277] INFO: 41600 events read in total (2694ms).
[15:59:27.278] INFO: Test took 3924ms.
[15:59:27.312] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:28.034] INFO: Expecting 41600 events.
[15:59:31.266] INFO: 41600 events read in total (2705ms).
[15:59:31.267] INFO: Test took 3937ms.
[15:59:31.301] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:32.026] INFO: Expecting 41600 events.
[15:59:35.250] INFO: 41600 events read in total (2697ms).
[15:59:35.251] INFO: Test took 3931ms.
[15:59:35.286] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:36.011] INFO: Expecting 41600 events.
[15:59:39.243] INFO: 41600 events read in total (2705ms).
[15:59:39.244] INFO: Test took 3941ms.
[15:59:39.278] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:39.998] INFO: Expecting 41600 events.
[15:59:43.238] INFO: 41600 events read in total (2713ms).
[15:59:43.239] INFO: Test took 3942ms.
[15:59:43.273] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:43.993] INFO: Expecting 41600 events.
[15:59:47.234] INFO: 41600 events read in total (2714ms).
[15:59:47.235] INFO: Test took 3944ms.
[15:59:47.269] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:47.990] INFO: Expecting 41600 events.
[15:59:51.231] INFO: 41600 events read in total (2714ms).
[15:59:51.232] INFO: Test took 3945ms.
[15:59:51.266] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:51.989] INFO: Expecting 41600 events.
[15:59:55.205] INFO: 41600 events read in total (2689ms).
[15:59:55.206] INFO: Test took 3921ms.
[15:59:55.240] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:55.964] INFO: Expecting 41600 events.
[15:59:59.221] INFO: 41600 events read in total (2730ms).
[15:59:59.222] INFO: Test took 3963ms.
[15:59:59.257] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:59:59.978] INFO: Expecting 41600 events.
[16:00:03.209] INFO: 41600 events read in total (2704ms).
[16:00:03.210] INFO: Test took 3934ms.
[16:00:03.244] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:00:03.968] INFO: Expecting 41600 events.
[16:00:07.170] INFO: 41600 events read in total (2675ms).
[16:00:07.171] INFO: Test took 3908ms.
[16:00:07.204] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:00:07.930] INFO: Expecting 41600 events.
[16:00:11.187] INFO: 41600 events read in total (2730ms).
[16:00:11.188] INFO: Test took 3966ms.
[16:00:11.222] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:00:11.944] INFO: Expecting 41600 events.
[16:00:15.185] INFO: 41600 events read in total (2715ms).
[16:00:15.186] INFO: Test took 3946ms.
[16:00:15.220] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:00:15.945] INFO: Expecting 41600 events.
[16:00:19.192] INFO: 41600 events read in total (2720ms).
[16:00:19.193] INFO: Test took 3955ms.
[16:00:19.228] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:00:19.951] INFO: Expecting 41600 events.
[16:00:23.144] INFO: 41600 events read in total (2666ms).
[16:00:23.145] INFO: Test took 3898ms.
[16:00:23.179] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:00:23.903] INFO: Expecting 41600 events.
[16:00:27.102] INFO: 41600 events read in total (2672ms).
[16:00:27.103] INFO: Test took 3906ms.
[16:00:27.137] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:00:27.865] INFO: Expecting 41600 events.
[16:00:30.898] INFO: 41600 events read in total (2506ms).
[16:00:30.899] INFO: Test took 3744ms.
[16:00:30.933] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:00:31.299] INFO: enter test to run
[16:00:59.689] INFO: test: HighRate no parameter change
[16:00:59.689] INFO: running: highrate
[16:00:59.690] INFO: ----------------------------------------------------------------------
[16:00:59.690] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:00:59.690] INFO: ----------------------------------------------------------------------
[16:00:59.697] INFO: ROC 0 masking pixel 0/3
[16:00:59.697] INFO: ROC 0 masking pixel 2/4
[16:00:59.697] INFO: ROC 0 masking pixel 2/7
[16:00:59.698] INFO: ROC 3 masking pixel 9/43
[16:00:59.698] INFO: ROC 3 masking pixel 47/33
[16:00:59.698] INFO: ROC 5 masking pixel 5/17
[16:00:59.698] INFO: ROC 5 masking pixel 9/58
[16:01:00.308] INFO: Expecting 208000 events.
[16:01:12.103] INFO: 208000 events read in total (11268ms).
[16:01:12.106] INFO: Test took 12408ms.
[16:01:12.247] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:01:12.499] INFO: number of dead pixels (per ROC): 3 0 0 2 0 2 0 0 0 0 0 0 1 0 0 0
[16:01:12.499] INFO: number of red-efficiency pixels: 71 54 102 144 142 158 119 76 88 113 119 83 116 53 26 33
[16:01:12.499] INFO: number of X-ray hits detected: 64502 43649 67290 104315 113158 117162 113972 84843 76614 97641 98055 83061 88973 50639 23626 25218
[16:01:12.499] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:01:12.499] INFO: number of Vcal hits detected: 207780 207931 207898 207753 207855 207740 207877 207924 207912 207884 207879 207916 207834 207946 207974 207967
[16:01:12.499] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[16:01:12.499] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 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
[16:01:12.499] INFO: X-ray hit rate [MHz/cm2]: 18.9 12.8 19.7 30.6 33.2 34.3 33.4 24.9 22.5 28.6 28.7 24.3 26.1 14.8 6.9 7.4
[16:01:12.499] INFO: PixTestHighRate::doXPixelAlive() done
[16:01:12.549] INFO: PixTest:: pg_setup set to default.
[16:01:12.566] INFO: enter test to run
[16:01:28.200] INFO: test: HighRate no parameter change
[16:01:28.200] INFO: running: highrate
[16:01:28.201] INFO: ----------------------------------------------------------------------
[16:01:28.201] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:01:28.201] INFO: ----------------------------------------------------------------------
[16:01:28.209] INFO: ROC 0 masking pixel 0/3
[16:01:28.209] INFO: ROC 0 masking pixel 2/4
[16:01:28.209] INFO: ROC 0 masking pixel 2/7
[16:01:28.209] INFO: ROC 3 masking pixel 9/43
[16:01:28.209] INFO: ROC 3 masking pixel 47/33
[16:01:28.209] INFO: ROC 5 masking pixel 5/17
[16:01:28.209] INFO: ROC 5 masking pixel 9/58
[16:01:28.819] INFO: Expecting 208000 events.
[16:01:42.662] INFO: 208000 events read in total (13316ms).
[16:01:42.668] INFO: Test took 14458ms.
[16:01:42.985] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:01:43.292] INFO: number of dead pixels (per ROC): 3 0 0 2 0 2 0 0 0 0 0 0 1 0 0 0
[16:01:43.292] INFO: number of red-efficiency pixels: 183 132 313 495 581 558 465 282 237 454 430 275 393 186 88 66
[16:01:43.292] INFO: number of X-ray hits detected: 140642 96171 146779 228755 247681 256378 250465 185604 168747 214631 217333 183023 195603 111627 52143 54964
[16:01:43.292] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:01:43.292] INFO: number of Vcal hits detected: 207657 207844 207657 207363 207363 207297 207497 207692 207749 207510 207538 207717 207538 207802 207911 207931
[16:01:43.292] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.8 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[16:01:43.292] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.7 99.7 99.7 99.8 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[16:01:43.292] INFO: X-ray hit rate [MHz/cm2]: 41.2 28.2 43.0 67.0 72.6 75.1 73.4 54.4 49.5 62.9 63.7 53.6 57.3 32.7 15.3 16.1
[16:01:43.292] INFO: PixTestHighRate::doXPixelAlive() done
[16:01:43.342] INFO: PixTest:: pg_setup set to default.
[16:01:43.355] INFO: enter test to run
[16:01:58.176] INFO: test: HighRate no parameter change
[16:01:58.176] INFO: running: highrate
[16:01:58.177] INFO: ----------------------------------------------------------------------
[16:01:58.177] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:01:58.177] INFO: ----------------------------------------------------------------------
[16:01:58.187] INFO: ROC 0 masking pixel 0/3
[16:01:58.187] INFO: ROC 0 masking pixel 2/4
[16:01:58.187] INFO: ROC 0 masking pixel 2/7
[16:01:58.187] INFO: ROC 3 masking pixel 9/43
[16:01:58.187] INFO: ROC 3 masking pixel 47/33
[16:01:58.187] INFO: ROC 5 masking pixel 5/17
[16:01:58.187] INFO: ROC 5 masking pixel 9/58
[16:01:58.796] INFO: Expecting 208000 events.
[16:02:14.990] INFO: 208000 events read in total (15667ms).
[16:02:14.998] INFO: Test took 16810ms.
[16:02:15.508] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:02:15.873] INFO: number of dead pixels (per ROC): 3 0 0 2 0 2 0 0 0 0 0 0 1 0 0 0
[16:02:15.873] INFO: number of red-efficiency pixels: 459 255 803 1301 1522 1360 1113 693 542 1126 1133 678 1011 446 121 94
[16:02:15.873] INFO: number of X-ray hits detected: 222601 152165 233252 360087 391054 404526 394232 294546 265593 339207 342261 289775 309169 177387 82592 87447
[16:02:15.873] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:02:15.873] INFO: number of Vcal hits detected: 207327 207691 206888 206212 205930 206061 206601 207170 207375 206573 206562 207225 206718 207475 207876 207900
[16:02:15.873] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.5 99.3 99.1 99.2 99.4 99.6 99.7 99.4 99.4 99.7 99.5 99.8 99.9 100.0
[16:02:15.873] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.5 99.1 99.0 99.1 99.3 99.6 99.7 99.3 99.3 99.6 99.4 99.7 99.9 100.0
[16:02:15.873] INFO: X-ray hit rate [MHz/cm2]: 65.2 44.6 68.4 105.5 114.6 118.6 115.6 86.3 77.8 99.4 100.3 84.9 90.6 52.0 24.2 25.6
[16:02:15.873] INFO: PixTestHighRate::doXPixelAlive() done
[16:02:15.918] INFO: PixTest:: pg_setup set to default.
[16:02:15.935] INFO: enter test to run
[16:02:22.096] INFO: test: exit no parameter change
[16:02:22.589] QUIET: Connection to board 32 closed.
[16:02:22.606] INFO: pXar: this is the end, my friend