[16:04:08.509] INFO: *** Welcome to pxar ***
[16:04:08.509] INFO: *** Today: 2016/04/21
[16:04:08.530] INFO: *** Version: v1.9.0-796-gef167-dirty
[16:04:08.530] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//dacParameters35_C15.dat
[16:04:08.560] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:04:08.560] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//defaultMaskFile.dat
[16:04:08.560] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C15.dat
[16:04:08.671] INFO: clk: 4
[16:04:08.671] INFO: ctr: 4
[16:04:08.671] INFO: sda: 19
[16:04:08.671] INFO: tin: 9
[16:04:08.671] INFO: level: 15
[16:04:08.671] INFO: triggerdelay: 0
[16:04:08.671] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[16:04:08.671] INFO: Log level: INFO
[16:04:08.688] QUIET: Connection to board DTB_WREK4U opened.
[16:04:08.691] 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:
------------------------------------------------------
[16:04:08.694] INFO: RPC call hashes of host and DTB match: 398089610
[16:04:10.220] INFO: DUT info:
[16:04:10.220] INFO: The DUT currently contains the following objects:
[16:04:10.220] INFO: 2 TBM Cores tbm08c (2 ON)
[16:04:10.220] INFO: TBM Core alpha (0): 7 registers set
[16:04:10.220] INFO: TBM Core beta (1): 7 registers set
[16:04:10.220] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[16:04:10.220] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.220] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.220] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.220] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.220] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.220] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.220] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.221] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.221] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.221] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.221] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.221] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.221] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.221] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.221] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.221] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[16:04:10.624] INFO: enter 'restricted' command line mode
[16:04:10.625] INFO: enter test to run
[16:04:23.090] INFO: test: timing no parameter change
[16:04:23.091] INFO: running: timing
[16:04:23.100] INFO: ######################################################################
[16:04:23.100] INFO: PixTestTiming::doTest()
[16:04:23.100] INFO: ######################################################################
[16:04:23.100] INFO: ----------------------------------------------------------------------
[16:04:23.100] INFO: PixTestTiming::TBMPhaseScan()
[16:04:23.100] INFO: ----------------------------------------------------------------------
[16:08:56.396] INFO: TBM Phase Settings: 248
[16:08:56.396] INFO: 400MHz Phase: 6
[16:08:56.396] INFO: 160MHz Phase: 7
[16:08:56.396] INFO: Functional Phase Area: 4
[16:08:56.400] INFO: Test took 273300 ms.
[16:08:56.400] INFO: PixTestTiming::TBMPhaseScan() done.
[16:08:56.400] INFO: ----------------------------------------------------------------------
[16:08:56.400] INFO: PixTestTiming::ROCDelayScan()
[16:08:56.400] INFO: ----------------------------------------------------------------------
[16:11:32.896] INFO: ROC Delay Settings: 228
[16:11:32.896] INFO: ROC Header-Trailer/Token Delay: 11
[16:11:32.896] INFO: ROC Port 0 Delay: 4
[16:11:32.896] INFO: ROC Port 1 Delay: 4
[16:11:32.896] INFO: Functional ROC Area: 5
[16:11:32.900] INFO: Test took 156500 ms.
[16:11:32.900] INFO: PixTestTiming::ROCDelayScan() done.
[16:11:32.900] INFO: ----------------------------------------------------------------------
[16:11:32.900] INFO: PixTestTiming::TimingTest()
[16:11:32.900] INFO: ----------------------------------------------------------------------
[16:11:49.035] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:04.008] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:18.910] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:33.924] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:12:48.936] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:13:03.933] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:13:18.925] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:13:33.896] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:13:48.863] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:14:03.764] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:14:04.142] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:14:04.162] INFO: ----------------------------------------------------------------------
[16:14:04.162] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:14:04.162] INFO: ----------------------------------------------------------------------
[16:14:04.162] INFO: ----------------------------------------------------------------------
[16:14:04.162] INFO: Read back bit status: 1
[16:14:04.162] INFO: ----------------------------------------------------------------------
[16:14:04.162] INFO: ----------------------------------------------------------------------
[16:14:04.162] INFO: Timings are good!
[16:14:04.162] INFO: ----------------------------------------------------------------------
[16:14:04.162] INFO: Test took 151262 ms.
[16:14:04.162] INFO: PixTestTiming::TimingTest() done.
[16:14:04.180] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:14:04.180] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:14:04.181] INFO: PixTestTiming::doTest took 581086 ms.
[16:14:04.181] INFO: PixTestTiming::doTest() done
[16:14:04.181] INFO: Write out TBMPhaseScan_0_V0
[16:14:04.214] INFO: Write out TBMPhaseScan_1_V0
[16:14:04.215] INFO: Write out CombinedTBMPhaseScan_V0
[16:14:04.215] INFO: Write out ROCDelayScan3_V0
[16:14:04.216] INFO: enter test to run
[16:16:21.221] INFO: test: PixelAlive no parameter change
[16:16:21.221] INFO: running: pixelalive
[16:16:21.226] INFO: ----------------------------------------------------------------------
[16:16:21.226] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[16:16:21.226] INFO: ----------------------------------------------------------------------
[16:16:21.549] INFO: Expecting 41600 events.
[16:16:25.512] INFO: 41600 events read in total (3248ms).
[16:16:25.513] INFO: Test took 4284ms.
[16:16:25.519] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:25.921] INFO: PixTestAlive::aliveTest() done
[16:16:25.921] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0 0
[16:16:25.923] INFO: enter test to run
[16:16:58.749] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:16:58.749] INFO: running: highrate
[16:16:58.749] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:16:59.027] INFO: ----------------------------------------------------------------------
[16:16:59.027] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:16:59.027] INFO: ----------------------------------------------------------------------
[16:16:59.027] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:16:59.027] INFO: edge/corner pixel THR is adjusted
[16:16:59.027] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:16:59.986] INFO: Collecting data for 5 seconds...
[16:17:05.002] INFO: Done with hot pixel readout
[16:17:16.866] INFO: PixTest:: pg_setup set to default.
[16:17:16.867] INFO: 10 hot pixels found in step 0
[16:17:17.860] INFO: Collecting data for 5 seconds...
[16:17:22.876] INFO: Done with hot pixel readout
[16:17:34.729] INFO: PixTest:: pg_setup set to default.
[16:17:34.730] INFO: 10 hot pixels found in step 1
[16:17:35.724] INFO: Collecting data for 5 seconds...
[16:17:40.741] INFO: Done with hot pixel readout
[16:17:52.582] INFO: PixTest:: pg_setup set to default.
[16:17:52.583] INFO: 11 hot pixels found in step 2
[16:17:53.575] INFO: Collecting data for 5 seconds...
[16:17:58.591] INFO: Done with hot pixel readout
[16:18:10.502] INFO: PixTest:: pg_setup set to default.

[16:18:10.503] INFO: 8 hot pixels found in step 3
[16:18:11.496] INFO: Collecting data for 5 seconds...
[16:18:16.512] INFO: Done with hot pixel readout
[16:18:28.346] INFO: PixTest:: pg_setup set to default.
[16:18:28.347] INFO: 8 hot pixels found in step 4
[16:18:29.340] INFO: Collecting data for 5 seconds...
[16:18:34.357] INFO: Done with hot pixel readout
[16:18:46.205] INFO: PixTest:: pg_setup set to default.


[16:18:46.206] INFO: 7 hot pixels found in step 5
[16:18:47.199] INFO: Collecting data for 5 seconds...
[16:18:52.216] INFO: Done with hot pixel readout
[16:19:04.045] INFO: PixTest:: pg_setup set to default.


[16:19:04.046] INFO: 6 hot pixels found in step 6
[16:19:05.040] INFO: Collecting data for 5 seconds...
[16:19:10.056] INFO: Done with hot pixel readout
[16:19:21.916] INFO: PixTest:: pg_setup set to default.


[16:19:21.917] INFO: 5 hot pixels found in step 7
[16:19:22.911] INFO: Collecting data for 5 seconds...
[16:19:27.927] INFO: Done with hot pixel readout
[16:19:39.792] INFO: PixTest:: pg_setup set to default.



[16:19:39.793] INFO: 6 hot pixels found in step 8
[16:19:40.787] INFO: Collecting data for 5 seconds...
[16:19:45.804] INFO: Done with hot pixel readout
[16:19:57.625] INFO: PixTest:: pg_setup set to default.

[16:19:57.626] INFO: 2 hot pixels found in step 9
[16:19:58.619] INFO: Collecting data for 5 seconds...
[16:20:03.635] INFO: Done with hot pixel readout
[16:20:15.497] INFO: PixTest:: pg_setup set to default.


[16:20:15.498] INFO: 2 hot pixels found in step 10
[16:20:15.535] INFO: 2 hot pixels could not be trimmed and have been masked.
[16:20:15.538] INFO: PixTest::trimHotPixels() done
[16:20:15.538] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C0.dat
[16:20:15.544] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C1.dat
[16:20:15.550] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C2.dat
[16:20:15.556] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C3.dat
[16:20:15.562] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C4.dat
[16:20:15.567] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C5.dat
[16:20:15.572] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C6.dat
[16:20:15.577] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C7.dat
[16:20:15.582] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C8.dat
[16:20:15.587] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C9.dat
[16:20:15.593] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C10.dat
[16:20:15.598] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C11.dat
[16:20:15.603] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C12.dat
[16:20:15.608] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C13.dat
[16:20:15.613] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C14.dat
[16:20:15.619] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C15.dat
[16:20:15.624] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//defaultMaskFile.dat
[16:20:15.634] INFO: enter test to run
[16:20:46.739] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:20:46.739] INFO: running: highrate
[16:20:46.744] INFO: ----------------------------------------------------------------------
[16:20:46.744] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:20:46.744] INFO: ----------------------------------------------------------------------
[16:20:46.744] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:20:46.744] INFO: edge/corner pixel THR is adjusted
[16:20:46.744] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:20:47.701] INFO: Collecting data for 1 seconds...
[16:20:48.705] INFO: Done with hot pixel readout
[16:20:52.810] INFO: PixTest:: pg_setup set to default.
[16:20:52.811] INFO: 0 hot pixels found in step 0
[16:20:52.816] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:20:52.906] INFO: PixTest::trimHotPixels() done
[16:20:52.906] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C0.dat
[16:20:52.916] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C1.dat
[16:20:52.921] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C2.dat
[16:20:52.926] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C3.dat
[16:20:52.931] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C4.dat
[16:20:52.937] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C5.dat
[16:20:52.942] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C6.dat
[16:20:52.947] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C7.dat
[16:20:52.952] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C8.dat
[16:20:52.958] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C9.dat
[16:20:52.963] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C10.dat
[16:20:52.968] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C11.dat
[16:20:52.973] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C12.dat
[16:20:52.978] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C13.dat
[16:20:52.983] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C14.dat
[16:20:52.989] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C15.dat
[16:20:52.994] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-3-12_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//defaultMaskFile.dat
[16:20:53.010] INFO: enter test to run
[16:21:19.787] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:21:19.787] INFO: running: xray
[16:21:19.788] INFO: ----------------------------------------------------------------------
[16:21:19.788] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:21:19.788] INFO: ----------------------------------------------------------------------
[16:21:20.751] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:21:32.080] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[16:22:01.477] INFO: Resuming triggers.
[16:22:12.811] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[16:22:41.962] INFO: Resuming triggers.
[16:22:53.292] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[16:23:22.758] INFO: Resuming triggers.
[16:23:34.092] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[16:24:03.457] INFO: Resuming triggers.
[16:24:14.788] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[16:24:44.231] INFO: Resuming triggers.
[16:24:55.561] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[16:25:24.953] INFO: Resuming triggers.
[16:25:36.284] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[16:26:05.683] INFO: Resuming triggers.
[16:26:17.012] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[16:26:43.509] INFO: Resuming triggers.
[16:26:53.184] INFO: data taking finished, elapsed time: 100 seconds.
[16:27:18.369] INFO: PixTest:: pg_setup set to default.
[16:27:18.372] INFO: PixTestXray::doPhRun() done
[16:27:18.510] INFO: enter test to run
[16:27:48.720] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:27:48.720] INFO: running: xray
[16:27:48.721] INFO: ----------------------------------------------------------------------
[16:27:48.721] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:27:48.721] INFO: ----------------------------------------------------------------------
[16:27:49.700] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:27:56.273] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[16:28:26.303] INFO: Resuming triggers.
[16:28:32.877] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[16:29:02.849] INFO: Resuming triggers.
[16:29:09.425] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[16:29:39.280] INFO: Resuming triggers.
[16:29:45.853] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[16:30:15.799] INFO: Resuming triggers.
[16:30:22.376] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[16:30:52.038] INFO: Resuming triggers.
[16:30:58.615] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[16:31:28.586] INFO: Resuming triggers.
[16:31:35.161] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[16:32:05.125] INFO: Resuming triggers.
[16:32:11.700] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[16:32:41.680] INFO: Resuming triggers.
[16:32:48.258] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[16:33:18.492] INFO: Resuming triggers.
[16:33:25.068] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[16:33:55.026] INFO: Resuming triggers.
[16:34:01.602] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[16:34:31.522] INFO: Resuming triggers.
[16:34:38.098] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[16:35:08.074] INFO: Resuming triggers.
[16:35:14.649] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[16:35:44.654] INFO: Resuming triggers.
[16:35:51.229] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[16:36:21.282] INFO: Resuming triggers.
[16:36:27.855] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[16:36:54.849] INFO: Resuming triggers.
[16:36:56.541] INFO: data taking finished, elapsed time: 100 seconds.
[16:37:04.602] INFO: PixTest:: pg_setup set to default.
[16:37:04.605] INFO: PixTestXray::doPhRun() done
[16:37:04.757] INFO: enter test to run
[16:38:29.115] INFO: test: HighRate no parameter change
[16:38:29.116] INFO: running: highrate
[16:38:29.117] INFO: ----------------------------------------------------------------------
[16:38:29.117] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:38:29.117] INFO: ----------------------------------------------------------------------
[16:38:29.257] INFO: Expecting 768 events.
[16:38:30.391] INFO: 768 events read in total (418ms).
[16:38:30.392] INFO: Test took 1269ms.
[16:38:31.194] INFO: Expecting 41600 events.
[16:38:34.260] INFO: 41600 events read in total (2539ms).
[16:38:34.261] INFO: Test took 3860ms.
[16:38:34.295] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:35.023] INFO: Expecting 41600 events.
[16:38:38.225] INFO: 41600 events read in total (2675ms).
[16:38:38.226] INFO: Test took 3914ms.
[16:38:38.261] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:38.987] INFO: Expecting 41600 events.
[16:38:42.230] INFO: 41600 events read in total (2716ms).
[16:38:42.230] INFO: Test took 3951ms.
[16:38:42.265] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:42.985] INFO: Expecting 41600 events.
[16:38:46.240] INFO: 41600 events read in total (2728ms).
[16:38:46.241] INFO: Test took 3958ms.
[16:38:46.275] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:46.997] INFO: Expecting 41600 events.
[16:38:50.238] INFO: 41600 events read in total (2714ms).
[16:38:50.239] INFO: Test took 3947ms.
[16:38:50.274] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:50.998] INFO: Expecting 41600 events.
[16:38:54.231] INFO: 41600 events read in total (2706ms).
[16:38:54.232] INFO: Test took 3940ms.
[16:38:54.267] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:54.988] INFO: Expecting 41600 events.
[16:38:58.241] INFO: 41600 events read in total (2726ms).
[16:38:58.242] INFO: Test took 3956ms.
[16:38:58.276] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:38:58.001] INFO: Expecting 41600 events.
[16:39:02.251] INFO: 41600 events read in total (2723ms).
[16:39:02.252] INFO: Test took 3959ms.
[16:39:02.287] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:03.012] INFO: Expecting 41600 events.
[16:39:06.259] INFO: 41600 events read in total (2720ms).
[16:39:06.260] INFO: Test took 3956ms.
[16:39:06.295] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:07.019] INFO: Expecting 41600 events.
[16:39:10.264] INFO: 41600 events read in total (2718ms).
[16:39:10.265] INFO: Test took 3953ms.
[16:39:10.300] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:11.023] INFO: Expecting 41600 events.
[16:39:14.273] INFO: 41600 events read in total (2723ms).
[16:39:14.274] INFO: Test took 3955ms.
[16:39:14.308] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:15.031] INFO: Expecting 41600 events.
[16:39:18.270] INFO: 41600 events read in total (2712ms).
[16:39:18.271] INFO: Test took 3945ms.
[16:39:18.305] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:19.029] INFO: Expecting 41600 events.
[16:39:22.277] INFO: 41600 events read in total (2721ms).
[16:39:22.279] INFO: Test took 3955ms.
[16:39:22.312] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:23.038] INFO: Expecting 41600 events.
[16:39:26.271] INFO: 41600 events read in total (2706ms).
[16:39:26.271] INFO: Test took 3941ms.
[16:39:26.306] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:27.027] INFO: Expecting 41600 events.
[16:39:30.258] INFO: 41600 events read in total (2704ms).
[16:39:30.259] INFO: Test took 3934ms.
[16:39:30.294] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:31.018] INFO: Expecting 41600 events.
[16:39:34.254] INFO: 41600 events read in total (2709ms).
[16:39:34.255] INFO: Test took 3944ms.
[16:39:34.290] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:35.014] INFO: Expecting 41600 events.
[16:39:38.250] INFO: 41600 events read in total (2709ms).
[16:39:38.251] INFO: Test took 3942ms.
[16:39:38.285] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:39.011] INFO: Expecting 41600 events.
[16:39:42.258] INFO: 41600 events read in total (2720ms).
[16:39:42.259] INFO: Test took 3955ms.
[16:39:42.293] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:43.016] INFO: Expecting 41600 events.
[16:39:46.237] INFO: 41600 events read in total (2694ms).
[16:39:46.238] INFO: Test took 3925ms.
[16:39:46.272] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:46.992] INFO: Expecting 41600 events.
[16:39:50.123] INFO: 41600 events read in total (2604ms).
[16:39:50.124] INFO: Test took 3833ms.
[16:39:50.159] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:50.513] INFO: enter test to run
[16:40:17.219] INFO: test: HighRate no parameter change
[16:40:17.219] INFO: running: highrate
[16:40:17.220] INFO: ----------------------------------------------------------------------
[16:40:17.220] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:40:17.220] INFO: ----------------------------------------------------------------------
[16:40:17.836] INFO: Expecting 208000 events.
[16:40:29.698] INFO: 208000 events read in total (11335ms).
[16:40:29.701] INFO: Test took 12472ms.
[16:40:29.846] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:30.099] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0 0
[16:40:30.099] INFO: number of red-efficiency pixels: 60 51 86 174 136 129 147 92 83 109 108 85 121 123 36 18
[16:40:30.099] INFO: number of X-ray hits detected: 66569 43414 70393 118248 110977 115607 119070 82175 75543 96800 93221 84491 89081 51732 23005 24944
[16:40:30.099] 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:40:30.099] INFO: number of Vcal hits detected: 207939 207949 207914 207824 207859 207866 207851 207901 207916 207890 207891 207913 207877 207827 207964 207982
[16:40:30.099] 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 99.9 100.0 99.9 99.9 100.0 100.0
[16:40:30.099] INFO: Vcal hit overall 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 99.9 100.0 100.0
[16:40:30.099] INFO: X-ray hit rate [MHz/cm2]: 19.5 12.7 20.6 34.7 32.5 33.9 34.9 24.1 22.1 28.4 27.3 24.8 26.1 15.2 6.7 7.3
[16:40:30.099] INFO: PixTestHighRate::doXPixelAlive() done
[16:40:30.149] INFO: PixTest:: pg_setup set to default.
[16:40:30.157] INFO: enter test to run
[16:40:56.898] INFO: test: HighRate no parameter change
[16:40:56.898] INFO: running: highrate
[16:40:56.899] INFO: ----------------------------------------------------------------------
[16:40:56.899] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:40:56.899] INFO: ----------------------------------------------------------------------
[16:40:57.512] INFO: Expecting 208000 events.
[16:41:11.259] INFO: 208000 events read in total (13220ms).
[16:41:11.265] INFO: Test took 14357ms.
[16:41:11.567] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:41:11.869] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0 0
[16:41:11.869] INFO: number of red-efficiency pixels: 234 123 308 589 361 435 646 315 207 339 365 356 355 277 53 57
[16:41:11.869] INFO: number of X-ray hits detected: 141096 91329 147493 249026 233059 242872 250518 174624 159732 204733 195510 178377 188470 108636 48058 52875
[16:41:11.869] 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:41:11.870] INFO: number of Vcal hits detected: 207753 207875 207666 207346 207604 207536 207277 207641 207787 207630 207614 207628 207626 207655 207947 207943
[16:41:11.870] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.7 99.8 99.8 99.7 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[16:41:11.870] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.8 99.8 99.7 99.8 99.9 99.8 99.8 99.8 99.8 99.8 100.0 100.0
[16:41:11.870] INFO: X-ray hit rate [MHz/cm2]: 41.4 26.8 43.2 73.0 68.3 71.2 73.4 51.2 46.8 60.0 57.3 52.3 55.2 31.8 14.1 15.5
[16:41:11.870] INFO: PixTestHighRate::doXPixelAlive() done
[16:41:11.917] INFO: PixTest:: pg_setup set to default.
[16:41:11.928] INFO: enter test to run
[16:41:37.746] INFO: test: HighRate no parameter change
[16:41:37.746] INFO: running: highrate
[16:41:37.747] INFO: ----------------------------------------------------------------------
[16:41:37.747] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:41:37.747] INFO: ----------------------------------------------------------------------
[16:41:38.363] INFO: Expecting 208000 events.
[16:41:54.002] INFO: 208000 events read in total (15112ms).
[16:41:54.010] INFO: Test took 16254ms.
[16:41:54.472] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:41:54.824] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0 0
[16:41:54.824] INFO: number of red-efficiency pixels: 551 209 657 1245 908 997 1475 632 447 786 876 761 831 462 107 105
[16:41:54.824] INFO: number of X-ray hits detected: 211787 138453 222714 373687 349816 366878 376361 261980 240962 307978 296112 268097 283596 163742 72640 80268
[16:41:54.824] 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:41:54.824] INFO: number of Vcal hits detected: 207318 207774 207127 206383 206929 206785 205961 207205 207513 207078 206986 207108 207049 207414 207889 207893
[16:41:54.824] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.3 99.5 99.5 99.1 99.6 99.8 99.6 99.5 99.6 99.6 99.8 100.0 100.0
[16:41:54.824] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.6 99.2 99.5 99.4 99.0 99.6 99.8 99.6 99.5 99.6 99.5 99.7 99.9 99.9
[16:41:54.824] INFO: X-ray hit rate [MHz/cm2]: 62.1 40.6 65.3 109.5 102.5 107.5 110.3 76.8 70.6 90.3 86.8 78.6 83.1 48.0 21.3 23.5
[16:41:54.824] INFO: PixTestHighRate::doXPixelAlive() done
[16:41:54.873] INFO: PixTest:: pg_setup set to default.
[16:41:54.887] INFO: enter test to run
[16:42:58.937] INFO: test: exit no parameter change
[16:42:59.347] QUIET: Connection to board 32 closed.
[16:42:59.349] INFO: pXar: this is the end, my friend