[11:25:42.023] INFO: *** Welcome to pxar ***
[11:25:42.023] INFO: *** Today: 2016/05/09
[11:25:42.042] INFO: *** Version: v1.9.0-796-gef167-dirty
[11:25:42.042] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//dacParameters35_C15.dat
[11:25:42.043] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:25:42.043] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//defaultMaskFile.dat
[11:25:42.043] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C15.dat
[11:25:42.120] INFO: clk: 4
[11:25:42.120] INFO: ctr: 4
[11:25:42.120] INFO: sda: 19
[11:25:42.120] INFO: tin: 9
[11:25:42.120] INFO: level: 15
[11:25:42.120] INFO: triggerdelay: 0
[11:25:42.120] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[11:25:42.120] INFO: Log level: INFO
[11:25:42.134] QUIET: Connection to board DTB_WREKRL opened.
[11:25:42.138] 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:
------------------------------------------------------
[11:25:42.140] INFO: RPC call hashes of host and DTB match: 398089610
[11:25:43.670] INFO: DUT info:
[11:25:43.670] INFO: The DUT currently contains the following objects:
[11:25:43.670] INFO: 2 TBM Cores tbm08c (2 ON)
[11:25:43.670] INFO: TBM Core alpha (0): 7 registers set
[11:25:43.670] INFO: TBM Core beta (1): 7 registers set
[11:25:43.670] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:25:43.670] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.670] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.670] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.670] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.670] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.671] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.671] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.671] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.671] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.671] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.671] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.671] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.671] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.671] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.671] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:43.671] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:25:44.074] INFO: enter 'restricted' command line mode
[11:25:44.074] INFO: enter test to run
[11:26:00.304] INFO: test: timing no parameter change
[11:26:00.304] INFO: running: timing
[11:26:00.313] INFO: ######################################################################
[11:26:00.313] INFO: PixTestTiming::doTest()
[11:26:00.339] INFO: ######################################################################
[11:26:00.340] INFO: ----------------------------------------------------------------------
[11:26:00.340] INFO: PixTestTiming::TBMPhaseScan()
[11:26:00.340] INFO: ----------------------------------------------------------------------
[11:30:30.242] INFO: TBM Phase Settings: 240
[11:30:30.242] INFO: 400MHz Phase: 4
[11:30:30.242] INFO: 160MHz Phase: 7
[11:30:30.242] INFO: Functional Phase Area: 4
[11:30:30.245] INFO: Test took 269905 ms.
[11:30:30.245] INFO: PixTestTiming::TBMPhaseScan() done.
[11:30:30.246] INFO: ----------------------------------------------------------------------
[11:30:30.246] INFO: PixTestTiming::ROCDelayScan()
[11:30:30.246] INFO: ----------------------------------------------------------------------
[11:32:35.478] INFO: ROC Delay Settings: 228
[11:32:35.478] INFO: ROC Header-Trailer/Token Delay: 11
[11:32:35.478] INFO: ROC Port 0 Delay: 4
[11:32:35.478] INFO: ROC Port 1 Delay: 4
[11:32:35.478] INFO: Functional ROC Area: 4
[11:32:35.481] INFO: Test took 125236 ms.
[11:32:35.481] INFO: PixTestTiming::ROCDelayScan() done.
[11:32:35.482] INFO: ----------------------------------------------------------------------
[11:32:35.482] INFO: PixTestTiming::TimingTest()
[11:32:35.482] INFO: ----------------------------------------------------------------------
[11:32:51.635] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:33:06.615] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:33:21.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:33:36.547] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:33:51.519] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:34:06.483] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:34:21.436] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:34:36.401] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:34:51.375] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:35:06.328] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:35:06.706] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:35:06.723] INFO: ----------------------------------------------------------------------
[11:35:06.723] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:35:06.723] INFO: ----------------------------------------------------------------------
[11:35:06.723] INFO: ----------------------------------------------------------------------
[11:35:06.723] INFO: Read back bit status: 1
[11:35:06.723] INFO: ----------------------------------------------------------------------
[11:35:06.723] INFO: ----------------------------------------------------------------------
[11:35:06.723] INFO: Timings are good!
[11:35:06.723] INFO: ----------------------------------------------------------------------
[11:35:06.723] INFO: Test took 151241 ms.
[11:35:06.723] INFO: PixTestTiming::TimingTest() done.
[11:35:06.742] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:35:06.742] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:35:06.743] INFO: PixTestTiming::doTest took 546435 ms.
[11:35:06.743] INFO: PixTestTiming::doTest() done
[11:35:06.743] INFO: Write out TBMPhaseScan_0_V0
[11:35:06.776] INFO: Write out TBMPhaseScan_1_V0
[11:35:06.776] INFO: Write out CombinedTBMPhaseScan_V0
[11:35:06.777] INFO: Write out ROCDelayScan3_V0
[11:35:06.777] INFO: enter test to run
[11:35:17.284] INFO: test: PixelAlive no parameter change
[11:35:17.284] INFO: running: pixelalive
[11:35:17.289] INFO: ----------------------------------------------------------------------
[11:35:17.289] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:35:17.289] INFO: ----------------------------------------------------------------------
[11:35:17.608] INFO: Expecting 41600 events.
[11:35:21.924] INFO: 41600 events read in total (3601ms).
[11:35:21.925] INFO: Test took 4634ms.
[11:35:21.931] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:35:22.327] INFO: PixTestAlive::aliveTest() done
[11:35:22.327] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 77 0 0 0 0 0
[11:35:22.331] INFO: enter test to run
[11:35:45.356] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:35:45.356] INFO: running: highrate
[11:35:45.356] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:35:45.506] INFO: ----------------------------------------------------------------------
[11:35:45.506] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:35:45.506] INFO: ----------------------------------------------------------------------
[11:35:45.506] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:35:45.506] INFO: edge/corner pixel THR is adjusted
[11:35:45.506] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:35:46.464] INFO: Collecting data for 5 seconds...
[11:35:51.480] INFO: Done with hot pixel readout
[11:36:03.414] INFO: PixTest:: pg_setup set to default.
[11:36:03.415] INFO: 3 hot pixels found in step 0
[11:36:04.408] INFO: Collecting data for 5 seconds...
[11:36:09.424] INFO: Done with hot pixel readout
[11:36:21.388] INFO: PixTest:: pg_setup set to default.
[11:36:21.389] INFO: 6 hot pixels found in step 1
[11:36:22.383] INFO: Collecting data for 5 seconds...
[11:36:27.399] INFO: Done with hot pixel readout
[11:36:39.338] INFO: PixTest:: pg_setup set to default.
[11:36:39.339] INFO: 4 hot pixels found in step 2
[11:36:40.332] INFO: Collecting data for 5 seconds...
[11:36:45.349] INFO: Done with hot pixel readout
[11:36:57.313] INFO: PixTest:: pg_setup set to default.
[11:36:57.314] INFO: 5 hot pixels found in step 3
[11:36:58.307] INFO: Collecting data for 5 seconds...
[11:37:03.323] INFO: Done with hot pixel readout
[11:37:15.278] INFO: PixTest:: pg_setup set to default.
[11:37:15.279] INFO: 4 hot pixels found in step 4
[11:37:16.273] INFO: Collecting data for 5 seconds...
[11:37:21.289] INFO: Done with hot pixel readout
[11:37:33.235] INFO: PixTest:: pg_setup set to default.
[11:37:33.235] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:37:33.235] INFO: 8 hot pixels found in step 5
[11:37:34.228] INFO: Collecting data for 5 seconds...
[11:37:39.244] INFO: Done with hot pixel readout
[11:37:51.196] INFO: PixTest:: pg_setup set to default.
[11:37:51.197] INFO: 2 hot pixels found in step 6
[11:37:52.190] INFO: Collecting data for 5 seconds...
[11:37:57.206] INFO: Done with hot pixel readout
[11:38:09.171] INFO: PixTest:: pg_setup set to default.
[11:38:09.171] INFO: 1 hot pixels found in step 7
[11:38:10.165] INFO: Collecting data for 5 seconds...
[11:38:15.181] INFO: Done with hot pixel readout
[11:38:27.132] INFO: PixTest:: pg_setup set to default.
[11:38:27.132] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:38:27.133] INFO: 2 hot pixels found in step 8
[11:38:28.126] INFO: Collecting data for 5 seconds...
[11:38:33.143] INFO: Done with hot pixel readout
[11:38:45.098] INFO: PixTest:: pg_setup set to default.
[11:38:45.098] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:38:45.099] INFO: 1 hot pixels found in step 9
[11:38:45.135] INFO: 1 hot pixels could not be trimmed and have been masked.
[11:38:45.139] INFO: PixTest::trimHotPixels() done
[11:38:45.139] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C0.dat
[11:38:45.144] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C1.dat
[11:38:45.151] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C2.dat
[11:38:45.157] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C3.dat
[11:38:45.163] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C4.dat
[11:38:45.168] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C5.dat
[11:38:45.173] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C6.dat
[11:38:45.178] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C7.dat
[11:38:45.183] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C8.dat
[11:38:45.188] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C9.dat
[11:38:45.193] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C10.dat
[11:38:45.199] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C11.dat
[11:38:45.204] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C12.dat
[11:38:45.209] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C13.dat
[11:38:45.214] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C14.dat
[11:38:45.219] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C15.dat
[11:38:45.242] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//defaultMaskFile.dat
[11:38:45.256] INFO: enter test to run
[11:39:51.082] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:39:51.082] INFO: running: highrate
[11:39:51.087] INFO: ----------------------------------------------------------------------
[11:39:51.087] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:39:51.087] INFO: ----------------------------------------------------------------------
[11:39:51.087] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:39:51.087] INFO: edge/corner pixel THR is adjusted
[11:39:51.087] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:39:52.045] INFO: Collecting data for 1 seconds...
[11:39:53.048] INFO: Done with hot pixel readout
[11:39:57.085] INFO: PixTest:: pg_setup set to default.
[11:39:57.086] INFO: 0 hot pixels found in step 0
[11:39:57.091] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:39:57.180] INFO: PixTest::trimHotPixels() done
[11:39:57.180] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C0.dat
[11:39:57.192] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C1.dat
[11:39:57.198] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C2.dat
[11:39:57.203] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C3.dat
[11:39:57.208] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C4.dat
[11:39:57.214] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C5.dat
[11:39:57.219] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C6.dat
[11:39:57.224] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C7.dat
[11:39:57.229] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C8.dat
[11:39:57.234] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C9.dat
[11:39:57.239] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C10.dat
[11:39:57.244] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C11.dat
[11:39:57.249] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C12.dat
[11:39:57.255] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C13.dat
[11:39:57.260] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C14.dat
[11:39:57.265] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//trimParameters35_C15.dat
[11:39:57.270] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-41_FPIXTest-17C-FNAL-160503-1254_2016-05-03_12h54m_1462298098/000_FPIXTest_p17//defaultMaskFile.dat
[11:39:57.280] INFO: enter test to run
[11:40:17.930] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:40:17.930] INFO: running: xray
[11:40:17.931] INFO: ----------------------------------------------------------------------
[11:40:17.931] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:40:17.931] INFO: ----------------------------------------------------------------------
[11:40:18.895] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:40:30.498] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:41:00.249] INFO: Resuming triggers.
[11:41:11.860] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[11:41:41.250] INFO: Resuming triggers.
[11:41:52.856] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:42:22.871] INFO: Resuming triggers.
[11:42:34.477] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:43:04.596] INFO: Resuming triggers.
[11:43:16.201] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[11:43:45.637] INFO: Resuming triggers.
[11:43:57.241] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[11:44:26.588] INFO: Resuming triggers.
[11:44:38.197] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:45:07.616] INFO: Resuming triggers.
[11:45:19.221] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[11:45:48.600] INFO: Resuming triggers.
[11:45:56.110] INFO: data taking finished, elapsed time: 100 seconds.
[11:46:15.330] INFO: PixTest:: pg_setup set to default.
[11:46:15.333] INFO: PixTestXray::doPhRun() done
[11:46:15.480] INFO: enter test to run
[11:51:40.317] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:51:40.317] INFO: running: xray
[11:51:40.318] INFO: ----------------------------------------------------------------------
[11:51:40.318] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:51:40.318] INFO: ----------------------------------------------------------------------
[11:51:41.281] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:51:47.965] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:52:18.507] INFO: Resuming triggers.
[11:52:25.190] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[11:52:55.733] INFO: Resuming triggers.
[11:53:02.415] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[11:53:33.281] INFO: Resuming triggers.
[11:53:39.968] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[11:54:11.272] INFO: Resuming triggers.
[11:54:17.960] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[11:54:48.213] INFO: Resuming triggers.
[11:54:54.892] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[11:55:25.175] INFO: Resuming triggers.
[11:55:31.860] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:56:02.032] INFO: Resuming triggers.
[11:56:08.716] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[11:56:38.927] INFO: Resuming triggers.
[11:56:45.609] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[11:57:16.006] INFO: Resuming triggers.
[11:57:22.686] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[11:57:53.422] INFO: Resuming triggers.
[11:58:00.100] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[11:58:30.112] INFO: Resuming triggers.
[11:58:36.790] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[11:59:07.041] INFO: Resuming triggers.
[11:59:13.721] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[11:59:43.958] INFO: Resuming triggers.
[11:59:50.639] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[12:00:20.785] INFO: Resuming triggers.
[12:00:27.466] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[12:00:57.585] INFO: Resuming triggers.
[12:00:57.701] INFO: data taking finished, elapsed time: 100 seconds.
[12:00:58.683] INFO: PixTest:: pg_setup set to default.
[12:00:58.686] INFO: PixTestXray::doPhRun() done
[12:00:58.843] INFO: enter test to run
[12:01:44.040] INFO: test: HighRate no parameter change
[12:01:44.041] INFO: running: highrate
[12:01:44.058] INFO: ----------------------------------------------------------------------
[12:01:44.058] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:01:44.058] INFO: ----------------------------------------------------------------------
[12:01:44.221] INFO: Expecting 768 events.
[12:01:45.363] INFO: 768 events read in total (419ms).
[12:01:45.363] INFO: Test took 1276ms.
[12:01:46.166] INFO: Expecting 41600 events.
[12:01:49.318] INFO: 41600 events read in total (2625ms).
[12:01:49.319] INFO: Test took 3948ms.
[12:01:49.353] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:50.078] INFO: Expecting 41600 events.
[12:01:53.291] INFO: 41600 events read in total (2686ms).
[12:01:53.292] INFO: Test took 3921ms.
[12:01:53.327] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:54.050] INFO: Expecting 41600 events.
[12:01:57.303] INFO: 41600 events read in total (2726ms).
[12:01:57.304] INFO: Test took 3959ms.
[12:01:57.338] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:58.063] INFO: Expecting 41600 events.
[12:02:01.310] INFO: 41600 events read in total (2720ms).
[12:02:01.311] INFO: Test took 3954ms.
[12:02:01.346] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:02.071] INFO: Expecting 41600 events.
[12:02:05.315] INFO: 41600 events read in total (2717ms).
[12:02:05.316] INFO: Test took 3951ms.
[12:02:05.351] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:06.073] INFO: Expecting 41600 events.
[12:02:09.337] INFO: 41600 events read in total (2737ms).
[12:02:09.338] INFO: Test took 3968ms.
[12:02:09.372] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:10.095] INFO: Expecting 41600 events.
[12:02:13.358] INFO: 41600 events read in total (2736ms).
[12:02:13.359] INFO: Test took 3970ms.
[12:02:13.394] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:14.118] INFO: Expecting 41600 events.
[12:02:17.365] INFO: 41600 events read in total (2720ms).
[12:02:17.366] INFO: Test took 3953ms.
[12:02:17.401] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:18.124] INFO: Expecting 41600 events.
[12:02:21.383] INFO: 41600 events read in total (2732ms).
[12:02:21.384] INFO: Test took 3964ms.
[12:02:21.419] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:22.139] INFO: Expecting 41600 events.
[12:02:25.405] INFO: 41600 events read in total (2739ms).
[12:02:25.406] INFO: Test took 3968ms.
[12:02:25.441] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:26.164] INFO: Expecting 41600 events.
[12:02:29.417] INFO: 41600 events read in total (2726ms).
[12:02:29.418] INFO: Test took 3960ms.
[12:02:29.453] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:30.176] INFO: Expecting 41600 events.
[12:02:33.443] INFO: 41600 events read in total (2740ms).
[12:02:33.444] INFO: Test took 3973ms.
[12:02:33.480] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:34.197] INFO: Expecting 41600 events.
[12:02:37.492] INFO: 41600 events read in total (2768ms).
[12:02:37.493] INFO: Test took 3994ms.
[12:02:37.529] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:38.251] INFO: Expecting 41600 events.
[12:02:41.460] INFO: 41600 events read in total (2682ms).
[12:02:41.461] INFO: Test took 3914ms.
[12:02:41.497] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:42.215] INFO: Expecting 41600 events.
[12:02:45.443] INFO: 41600 events read in total (2701ms).
[12:02:45.444] INFO: Test took 3929ms.
[12:02:45.481] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:46.197] INFO: Expecting 41600 events.
[12:02:49.514] INFO: 41600 events read in total (2790ms).
[12:02:49.515] INFO: Test took 4016ms.
[12:02:49.550] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:50.268] INFO: Expecting 41600 events.
[12:02:53.520] INFO: 41600 events read in total (2725ms).
[12:02:53.521] INFO: Test took 3953ms.
[12:02:53.557] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:54.276] INFO: Expecting 41600 events.
[12:02:57.590] INFO: 41600 events read in total (2787ms).
[12:02:57.591] INFO: Test took 4014ms.
[12:02:57.627] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:58.347] INFO: Expecting 41600 events.
[12:03:01.562] INFO: 41600 events read in total (2688ms).
[12:03:01.563] INFO: Test took 3918ms.
[12:03:01.598] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:02.319] INFO: Expecting 41600 events.
[12:03:05.364] INFO: 41600 events read in total (2518ms).
[12:03:05.365] INFO: Test took 3748ms.
[12:03:05.400] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:05.769] INFO: enter test to run
[12:03:18.584] INFO: test: HighRate no parameter change
[12:03:18.584] INFO: running: highrate
[12:03:18.585] INFO: ----------------------------------------------------------------------
[12:03:18.585] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:03:18.585] INFO: ----------------------------------------------------------------------
[12:03:19.258] INFO: Expecting 208000 events.
[12:03:31.174] INFO: 208000 events read in total (11389ms).
[12:03:31.177] INFO: Test took 12581ms.
[12:03:31.333] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:31.587] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 77 0 0 0 0 0
[12:03:31.587] INFO: number of red-efficiency pixels: 77 50 81 121 159 138 171 102 92 110 191 83 110 61 33 22
[12:03:31.587] INFO: number of X-ray hits detected: 67575 43934 68711 108133 119490 124091 119017 92025 81735 102547 94187 82082 89623 52549 20485 23307
[12:03:31.587] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:03:31.587] INFO: number of Vcal hits detected: 207923 207950 207908 207875 207831 207857 207827 207893 207906 207889 204014 207917 207888 207937 207967 207978
[12:03:31.587] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[12:03:31.587] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 98.1 100.0 99.9 100.0 100.0 100.0
[12:03:31.587] INFO: X-ray hit rate [MHz/cm2]: 19.8 12.9 20.1 31.7 35.0 36.4 34.9 27.0 24.0 30.1 27.6 24.1 26.3 15.4 6.0 6.8
[12:03:31.587] INFO: PixTestHighRate::doXPixelAlive() done
[12:03:31.632] INFO: PixTest:: pg_setup set to default.
[12:03:31.647] INFO: enter test to run
[12:04:07.767] INFO: test: HighRate no parameter change
[12:04:07.768] INFO: running: highrate
[12:04:07.769] INFO: ----------------------------------------------------------------------
[12:04:07.769] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:04:07.769] INFO: ----------------------------------------------------------------------
[12:04:08.388] INFO: Expecting 208000 events.
[12:04:22.292] INFO: 208000 events read in total (13378ms).
[12:04:22.297] INFO: Test took 14520ms.
[12:04:22.596] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:04:22.907] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 77 0 0 0 0 0
[12:04:22.907] INFO: number of red-efficiency pixels: 248 118 214 502 428 495 564 292 321 439 450 234 335 188 46 46
[12:04:22.907] INFO: number of X-ray hits detected: 134489 89141 136234 217628 238078 248522 238867 184614 165121 205430 188272 163910 177854 105333 41371 46601
[12:04:22.907] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:04:22.907] INFO: number of Vcal hits detected: 207730 207877 207763 207456 207516 207454 207385 207691 207665 207526 203723 207756 207645 207802 207954 207954
[12:04:22.907] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.7 99.9 99.8 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[12:04:22.907] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.7 99.8 99.7 99.7 99.9 99.8 99.8 97.9 99.9 99.8 99.9 100.0 100.0
[12:04:22.907] INFO: X-ray hit rate [MHz/cm2]: 39.4 26.1 39.9 63.8 69.8 72.8 70.0 54.1 48.4 60.2 55.2 48.0 52.1 30.9 12.1 13.7
[12:04:22.907] INFO: PixTestHighRate::doXPixelAlive() done
[12:04:22.952] INFO: PixTest:: pg_setup set to default.
[12:04:22.964] INFO: enter test to run
[12:04:40.239] INFO: test: HighRate no parameter change
[12:04:40.239] INFO: running: highrate
[12:04:40.241] INFO: ----------------------------------------------------------------------
[12:04:40.241] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:04:40.241] INFO: ----------------------------------------------------------------------
[12:04:40.858] INFO: Expecting 208000 events.
[12:04:56.724] INFO: 208000 events read in total (15339ms).
[12:04:56.732] INFO: Test took 16483ms.
[12:04:57.208] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:04:57.561] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 77 0 0 0 0 0
[12:04:57.561] INFO: number of red-efficiency pixels: 512 241 468 1138 1060 1205 1359 661 654 981 957 503 805 425 74 84
[12:04:57.561] INFO: number of X-ray hits detected: 205137 136212 208639 334618 366314 379718 365599 282648 252642 315078 287043 251592 273326 161922 63654 72256
[12:04:57.561] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:04:57.561] INFO: number of Vcal hits detected: 207385 207734 207398 206553 206636 206433 206182 207217 207263 206783 203055 207434 207068 207491 207926 207915
[12:04:57.561] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.7 99.4 99.4 99.3 99.2 99.7 99.7 99.5 99.5 99.8 99.6 99.8 100.0 100.0
[12:04:57.562] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.3 99.3 99.2 99.1 99.6 99.6 99.4 97.6 99.7 99.6 99.8 100.0 100.0
[12:04:57.562] INFO: X-ray hit rate [MHz/cm2]: 60.1 39.9 61.2 98.1 107.4 111.3 107.2 82.8 74.1 92.4 84.1 73.7 80.1 47.5 18.7 21.2
[12:04:57.562] INFO: PixTestHighRate::doXPixelAlive() done
[12:04:57.608] INFO: PixTest:: pg_setup set to default.
[12:04:57.619] INFO: enter test to run
[12:05:01.647] INFO: test: exit no parameter change
[12:05:02.034] QUIET: Connection to board 33 closed.
[12:05:02.046] INFO: pXar: this is the end, my friend