[12:50:32.227] INFO: *** Welcome to pxar ***
[12:50:32.227] INFO: *** Today: 2016/05/23
[12:50:32.262] INFO: *** Version: v1.9.0-796-gef167-dirty
[12:50:32.262] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//dacParameters35_C15.dat
[12:50:32.262] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:50:32.263] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//defaultMaskFile.dat
[12:50:32.263] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C15.dat
[12:50:32.329] INFO: clk: 4
[12:50:32.329] INFO: ctr: 4
[12:50:32.329] INFO: sda: 19
[12:50:32.329] INFO: tin: 9
[12:50:32.329] INFO: level: 15
[12:50:32.329] INFO: triggerdelay: 0
[12:50:32.329] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[12:50:32.329] INFO: Log level: INFO
[12:50:32.347] QUIET: Connection to board DTB_WREK4U opened.
[12:50:32.350] 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:
------------------------------------------------------
[12:50:32.353] INFO: RPC call hashes of host and DTB match: 398089610
[12:50:33.885] INFO: DUT info:
[12:50:33.885] INFO: The DUT currently contains the following objects:
[12:50:33.885] INFO: 2 TBM Cores tbm08c (2 ON)
[12:50:33.885] INFO: TBM Core alpha (0): 7 registers set
[12:50:33.885] INFO: TBM Core beta (1): 7 registers set
[12:50:33.885] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:50:33.885] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.885] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:33.886] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:50:34.289] INFO: enter 'restricted' command line mode
[12:50:34.289] INFO: enter test to run
[12:50:36.345] INFO: test: timing no parameter change
[12:50:36.346] INFO: running: timing
[12:50:36.374] INFO: ######################################################################
[12:50:36.374] INFO: PixTestTiming::doTest()
[12:50:36.377] INFO: ######################################################################
[12:50:36.377] INFO: ----------------------------------------------------------------------
[12:50:36.377] INFO: PixTestTiming::TBMPhaseScan()
[12:50:36.377] INFO: ----------------------------------------------------------------------
[12:59:59.582] INFO: TBM Phase Settings: 240
[12:59:59.582] INFO: 400MHz Phase: 4
[12:59:59.582] INFO: 160MHz Phase: 7
[12:59:59.582] INFO: Functional Phase Area: 5
[12:59:59.585] INFO: Test took 563208 ms.
[12:59:59.585] INFO: PixTestTiming::TBMPhaseScan() done.
[12:59:59.585] INFO: ----------------------------------------------------------------------
[12:59:59.585] INFO: PixTestTiming::ROCDelayScan()
[12:59:59.585] INFO: ----------------------------------------------------------------------
[13:02:38.713] INFO: ROC Delay Settings: 228
[13:02:38.713] INFO: ROC Header-Trailer/Token Delay: 11
[13:02:38.713] INFO: ROC Port 0 Delay: 4
[13:02:38.713] INFO: ROC Port 1 Delay: 4
[13:02:38.713] INFO: Functional ROC Area: 5
[13:02:38.716] INFO: Test took 159131 ms.
[13:02:38.716] INFO: PixTestTiming::ROCDelayScan() done.
[13:02:38.716] INFO: ----------------------------------------------------------------------
[13:02:38.716] INFO: PixTestTiming::TimingTest()
[13:02:38.716] INFO: ----------------------------------------------------------------------
[13:02:54.832] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:09.700] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:24.644] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:39.584] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:03:54.503] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:04:09.452] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:04:24.342] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:04:39.259] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:04:54.164] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:05:08.786] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:05:09.169] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:05:09.187] INFO: ----------------------------------------------------------------------
[13:05:09.187] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[13:05:09.187] INFO: ----------------------------------------------------------------------
[13:05:09.187] INFO: ----------------------------------------------------------------------
[13:05:09.187] INFO: Read back bit status: 1
[13:05:09.187] INFO: ----------------------------------------------------------------------
[13:05:09.187] INFO: ----------------------------------------------------------------------
[13:05:09.187] INFO: Timings are good!
[13:05:09.187] INFO: ----------------------------------------------------------------------
[13:05:09.187] INFO: Test took 150471 ms.
[13:05:09.187] INFO: PixTestTiming::TimingTest() done.
[13:05:09.199] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//tbmParameters_C0a.dat
[13:05:09.199] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:05:09.199] INFO: PixTestTiming::doTest took 872831 ms.
[13:05:09.199] INFO: PixTestTiming::doTest() done
[13:05:09.199] INFO: Write out TBMPhaseScan_0_V0
[13:05:09.225] INFO: Write out TBMPhaseScan_1_V0
[13:05:09.225] INFO: Write out CombinedTBMPhaseScan_V0
[13:05:09.225] INFO: Write out ROCDelayScan3_V0
[13:05:09.226] INFO: enter test to run
[13:06:16.179] INFO: test: PixelAlive no parameter change
[13:06:16.179] INFO: running: pixelalive
[13:06:16.183] INFO: ----------------------------------------------------------------------
[13:06:16.183] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[13:06:16.183] INFO: ----------------------------------------------------------------------
[13:06:16.506] INFO: Expecting 41600 events.
[13:06:20.834] INFO: 41600 events read in total (3612ms).
[13:06:20.834] INFO: Test took 4647ms.
[13:06:20.841] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:06:21.242] INFO: PixTestAlive::aliveTest() done
[13:06:21.242] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:06:21.244] INFO: enter test to run
[13:07:47.242] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:07:47.242] INFO: running: highrate
[13:07:47.242] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:07:47.401] INFO: ----------------------------------------------------------------------
[13:07:47.401] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:07:47.401] INFO: ----------------------------------------------------------------------
[13:07:47.401] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:07:47.401] INFO: edge/corner pixel THR is adjusted
[13:07:47.401] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:07:48.358] INFO: Collecting data for 5 seconds...
[13:07:53.377] INFO: Done with hot pixel readout
[13:08:05.135] INFO: PixTest:: pg_setup set to default.











[13:08:05.136] INFO: 35 hot pixels found in step 0
[13:08:06.135] INFO: Collecting data for 5 seconds...
[13:08:11.153] INFO: Done with hot pixel readout
[13:08:23.093] INFO: PixTest:: pg_setup set to default.















[13:08:23.094] INFO: 34 hot pixels found in step 1
[13:08:24.092] INFO: Collecting data for 5 seconds...
[13:08:29.111] INFO: Done with hot pixel readout
[13:08:41.173] INFO: PixTest:: pg_setup set to default.







[13:08:41.174] INFO: 30 hot pixels found in step 2
[13:08:42.172] INFO: Collecting data for 5 seconds...
[13:08:47.191] INFO: Done with hot pixel readout
[13:08:59.323] INFO: PixTest:: pg_setup set to default.









[13:08:59.324] INFO: 27 hot pixels found in step 3
[13:09:00.323] INFO: Collecting data for 5 seconds...
[13:09:05.341] INFO: Done with hot pixel readout
[13:09:16.935] INFO: PixTest:: pg_setup set to default.







[13:09:16.936] INFO: 28 hot pixels found in step 4
[13:09:17.936] INFO: Collecting data for 5 seconds...
[13:09:22.955] INFO: Done with hot pixel readout
[13:09:35.330] INFO: PixTest:: pg_setup set to default.







[13:09:35.331] INFO: 25 hot pixels found in step 5
[13:09:36.330] INFO: Collecting data for 5 seconds...
[13:09:41.348] INFO: Done with hot pixel readout
[13:09:53.573] INFO: PixTest:: pg_setup set to default.









[13:09:53.574] INFO: 31 hot pixels found in step 6
[13:09:54.573] INFO: Collecting data for 5 seconds...
[13:09:59.593] INFO: Done with hot pixel readout
[13:10:11.942] INFO: PixTest:: pg_setup set to default.






[13:10:11.943] INFO: 33 hot pixels found in step 7
[13:10:12.945] INFO: Collecting data for 5 seconds...
[13:10:17.962] INFO: Done with hot pixel readout
[13:10:30.581] INFO: PixTest:: pg_setup set to default.









[13:10:30.582] INFO: 32 hot pixels found in step 8
[13:10:31.581] INFO: Collecting data for 5 seconds...
[13:10:36.598] INFO: Done with hot pixel readout
[13:10:49.199] INFO: PixTest:: pg_setup set to default.










[13:10:49.200] INFO: 31 hot pixels found in step 9
[13:10:50.198] INFO: Collecting data for 5 seconds...
[13:10:55.215] INFO: Done with hot pixel readout
[13:11:07.807] INFO: PixTest:: pg_setup set to default.











[13:11:07.808] INFO: 34 hot pixels found in step 10
[13:11:08.806] INFO: Collecting data for 5 seconds...
[13:11:13.824] INFO: Done with hot pixel readout
[13:11:26.469] INFO: PixTest:: pg_setup set to default.







[13:11:26.470] INFO: 31 hot pixels found in step 11
[13:11:27.470] INFO: Collecting data for 5 seconds...
[13:11:32.487] INFO: Done with hot pixel readout
[13:11:45.103] INFO: PixTest:: pg_setup set to default.





[13:11:45.104] INFO: 29 hot pixels found in step 12
[13:11:46.102] INFO: Collecting data for 5 seconds...
[13:11:51.119] INFO: Done with hot pixel readout
[13:12:03.741] INFO: PixTest:: pg_setup set to default.










[13:12:03.742] INFO: 22 hot pixels found in step 13
[13:12:04.740] INFO: Collecting data for 5 seconds...
[13:12:09.758] INFO: Done with hot pixel readout
[13:12:22.351] INFO: PixTest:: pg_setup set to default.









[13:12:22.352] INFO: 27 hot pixels found in step 14
[13:12:22.394] INFO: 27 hot pixels could not be trimmed and have been masked.
[13:12:22.397] INFO: PixTest::trimHotPixels() done
[13:12:22.398] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C0.dat
[13:12:22.410] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C1.dat
[13:12:22.418] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C2.dat
[13:12:22.424] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C3.dat
[13:12:22.429] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C4.dat
[13:12:22.434] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C5.dat
[13:12:22.440] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C6.dat
[13:12:22.445] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C7.dat
[13:12:22.451] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C8.dat
[13:12:22.456] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C9.dat
[13:12:22.461] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C10.dat
[13:12:22.466] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C11.dat
[13:12:22.472] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C12.dat
[13:12:22.477] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C13.dat
[13:12:22.482] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C14.dat
[13:12:22.488] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C15.dat
[13:12:22.493] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//defaultMaskFile.dat
[13:12:22.503] INFO: enter test to run
[13:17:41.422] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[13:17:41.422] INFO: running: highrate
[13:17:41.426] INFO: ----------------------------------------------------------------------
[13:17:41.426] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[13:17:41.426] INFO: ----------------------------------------------------------------------
[13:17:41.426] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[13:17:41.426] INFO: edge/corner pixel THR is adjusted
[13:17:41.426] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:17:42.385] INFO: Collecting data for 1 seconds...
[13:17:43.389] INFO: Done with hot pixel readout
[13:17:47.774] INFO: PixTest:: pg_setup set to default.
[13:17:47.775] INFO: 0 hot pixels found in step 0
[13:17:47.780] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:17:47.858] INFO: PixTest::trimHotPixels() done
[13:17:47.858] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C0.dat
[13:17:47.870] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C1.dat
[13:17:47.875] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C2.dat
[13:17:47.880] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C3.dat
[13:17:47.886] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C4.dat
[13:17:47.891] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C5.dat
[13:17:47.896] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C6.dat
[13:17:47.901] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C7.dat
[13:17:47.907] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C8.dat
[13:17:47.912] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C9.dat
[13:17:47.917] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C10.dat
[13:17:47.923] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C11.dat
[13:17:47.928] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C12.dat
[13:17:47.933] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C13.dat
[13:17:47.938] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C14.dat
[13:17:47.944] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//trimParameters35_C15.dat
[13:17:47.949] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-F-NJ_FPIXTest-17C-FNAL-160517-0929_2016-05-17_09h29m_1463495357/000_FPIXTest_p17//defaultMaskFile.dat
[13:17:47.959] INFO: enter test to run
[13:18:21.933] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:18:21.933] INFO: running: xray
[13:18:21.935] INFO: ----------------------------------------------------------------------
[13:18:21.935] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:18:21.935] INFO: ----------------------------------------------------------------------
[13:18:22.898] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:18:33.619] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[13:19:03.142] INFO: Resuming triggers.
[13:19:13.864] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[13:19:44.088] INFO: Resuming triggers.
[13:19:54.805] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[13:20:24.553] INFO: Resuming triggers.
[13:20:35.276] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[13:21:05.628] INFO: Resuming triggers.
[13:21:16.349] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[13:21:45.828] INFO: Resuming triggers.
[13:21:56.547] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[13:22:26.249] INFO: Resuming triggers.
[13:22:36.968] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[13:23:06.777] INFO: Resuming triggers.
[13:23:17.499] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[13:23:47.215] INFO: Resuming triggers.
[13:23:57.934] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[13:24:27.616] INFO: Resuming triggers.
[13:24:31.502] INFO: data taking finished, elapsed time: 100 seconds.
[13:24:42.596] INFO: PixTest:: pg_setup set to default.
[13:24:42.599] INFO: PixTestXray::doPhRun() done
[13:24:42.738] INFO: enter test to run
[13:28:14.225] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[13:28:14.225] INFO: running: xray
[13:28:14.226] INFO: ----------------------------------------------------------------------
[13:28:14.226] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:28:14.226] INFO: ----------------------------------------------------------------------
[13:28:15.190] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:28:21.174] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[13:28:51.071] INFO: Resuming triggers.
[13:28:57.060] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[13:29:26.999] INFO: Resuming triggers.
[13:29:32.983] INFO: run duration 17 seconds, buffer almost full (81%), pausing triggers.
[13:30:02.794] INFO: Resuming triggers.
[13:30:08.778] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[13:30:39.277] INFO: Resuming triggers.
[13:30:45.259] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[13:31:16.632] INFO: Resuming triggers.
[13:31:22.615] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[13:31:54.277] INFO: Resuming triggers.
[13:32:00.259] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[13:32:30.870] INFO: Resuming triggers.
[13:32:36.852] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[13:33:07.107] INFO: Resuming triggers.
[13:33:13.090] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[13:33:43.319] INFO: Resuming triggers.
[13:33:49.302] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[13:34:19.543] INFO: Resuming triggers.
[13:34:25.527] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[13:34:55.783] INFO: Resuming triggers.
[13:35:01.768] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[13:35:32.080] INFO: Resuming triggers.
[13:35:38.061] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[13:36:08.020] INFO: Resuming triggers.
[13:36:14.005] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[13:36:44.251] INFO: Resuming triggers.
[13:36:50.234] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[13:37:20.511] INFO: Resuming triggers.
[13:37:26.494] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[13:37:56.753] INFO: Resuming triggers.
[13:38:01.367] INFO: data taking finished, elapsed time: 100 seconds.
[13:38:24.927] INFO: PixTest:: pg_setup set to default.
[13:38:24.930] INFO: PixTestXray::doPhRun() done
[13:38:25.078] INFO: enter test to run
[13:39:26.284] INFO: test: HighRate no parameter change
[13:39:26.284] INFO: running: highrate
[13:39:26.299] INFO: ----------------------------------------------------------------------
[13:39:26.299] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:39:26.299] INFO: ----------------------------------------------------------------------
[13:39:26.454] INFO: Expecting 768 events.
[13:39:27.588] INFO: 768 events read in total (418ms).
[13:39:27.589] INFO: Test took 1269ms.
[13:39:28.392] INFO: Expecting 41600 events.
[13:39:31.547] INFO: 41600 events read in total (2628ms).
[13:39:31.548] INFO: Test took 3952ms.
[13:39:31.586] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:32.303] INFO: Expecting 41600 events.
[13:39:35.570] INFO: 41600 events read in total (2740ms).
[13:39:35.571] INFO: Test took 3966ms.
[13:39:35.611] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:36.325] INFO: Expecting 41600 events.
[13:39:39.614] INFO: 41600 events read in total (2762ms).
[13:39:39.615] INFO: Test took 3983ms.
[13:39:39.654] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:40.365] INFO: Expecting 41600 events.
[13:39:43.648] INFO: 41600 events read in total (2756ms).
[13:39:43.649] INFO: Test took 3975ms.
[13:39:43.688] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:44.401] INFO: Expecting 41600 events.
[13:39:47.702] INFO: 41600 events read in total (2774ms).
[13:39:47.703] INFO: Test took 3995ms.
[13:39:47.742] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:48.453] INFO: Expecting 41600 events.
[13:39:51.761] INFO: 41600 events read in total (2781ms).
[13:39:51.762] INFO: Test took 4000ms.
[13:39:51.803] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:52.515] INFO: Expecting 41600 events.
[13:39:55.818] INFO: 41600 events read in total (2777ms).
[13:39:55.819] INFO: Test took 3995ms.
[13:39:55.859] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:39:56.574] INFO: Expecting 41600 events.
[13:39:59.876] INFO: 41600 events read in total (2775ms).
[13:39:59.877] INFO: Test took 3999ms.
[13:39:59.916] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:00.631] INFO: Expecting 41600 events.
[13:40:03.915] INFO: 41600 events read in total (2757ms).
[13:40:03.916] INFO: Test took 3979ms.
[13:40:03.957] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:04.669] INFO: Expecting 41600 events.
[13:40:07.984] INFO: 41600 events read in total (2789ms).
[13:40:07.985] INFO: Test took 4008ms.
[13:40:08.025] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:08.737] INFO: Expecting 41600 events.
[13:40:12.050] INFO: 41600 events read in total (2786ms).
[13:40:12.051] INFO: Test took 4005ms.
[13:40:12.090] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:12.801] INFO: Expecting 41600 events.
[13:40:16.111] INFO: 41600 events read in total (2783ms).
[13:40:16.112] INFO: Test took 4000ms.
[13:40:16.152] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:16.866] INFO: Expecting 41600 events.
[13:40:20.189] INFO: 41600 events read in total (2796ms).
[13:40:20.190] INFO: Test took 4017ms.
[13:40:20.230] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:20.944] INFO: Expecting 41600 events.
[13:40:24.234] INFO: 41600 events read in total (2764ms).
[13:40:24.235] INFO: Test took 3984ms.
[13:40:24.275] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:24.989] INFO: Expecting 41600 events.
[13:40:28.285] INFO: 41600 events read in total (2769ms).
[13:40:28.286] INFO: Test took 3991ms.
[13:40:28.326] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:29.037] INFO: Expecting 41600 events.
[13:40:32.333] INFO: 41600 events read in total (2770ms).
[13:40:32.335] INFO: Test took 3990ms.
[13:40:32.374] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:33.086] INFO: Expecting 41600 events.
[13:40:36.377] INFO: 41600 events read in total (2764ms).
[13:40:36.378] INFO: Test took 3984ms.
[13:40:36.418] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:37.131] INFO: Expecting 41600 events.
[13:40:40.447] INFO: 41600 events read in total (2789ms).
[13:40:40.448] INFO: Test took 4009ms.
[13:40:40.489] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:41.201] INFO: Expecting 41600 events.
[13:40:44.476] INFO: 41600 events read in total (2749ms).
[13:40:44.477] INFO: Test took 3968ms.
[13:40:44.517] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:45.231] INFO: Expecting 41600 events.
[13:40:48.370] INFO: 41600 events read in total (2612ms).
[13:40:48.371] INFO: Test took 3833ms.
[13:40:48.412] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:40:48.749] INFO: enter test to run
[13:41:31.099] INFO: test: HighRate no parameter change
[13:41:31.099] INFO: running: highrate
[13:41:31.100] INFO: ----------------------------------------------------------------------
[13:41:31.100] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:41:31.100] INFO: ----------------------------------------------------------------------
[13:41:31.716] INFO: Expecting 208000 events.
[13:41:43.556] INFO: 208000 events read in total (11313ms).
[13:41:43.559] INFO: Test took 12451ms.
[13:41:43.739] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:41:43.001] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:41:43.001] INFO: number of red-efficiency pixels: 97 87 100 195 176 243 202 122 95 144 132 115 128 86 27 31
[13:41:43.001] INFO: number of X-ray hits detected: 78571 55625 85300 138200 142585 142071 146079 103528 86564 113988 106460 98187 98298 60542 28390 29367
[13:41:43.001] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:41:43.001] INFO: number of Vcal hits detected: 207901 207912 207896 207797 207814 207752 207793 207877 207902 207851 207863 207884 207869 207913 207972 207969
[13:41:43.001] 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 99.9 100.0 100.0 100.0
[13:41:43.001] 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 99.9 99.9 99.9 100.0 100.0 100.0
[13:41:43.001] INFO: X-ray hit rate [MHz/cm2]: 23.0 16.3 25.0 40.5 41.8 41.6 42.8 30.3 25.4 33.4 31.2 28.8 28.8 17.7 8.3 8.6
[13:41:43.001] INFO: PixTestHighRate::doXPixelAlive() done
[13:41:44.048] INFO: PixTest:: pg_setup set to default.
[13:41:44.058] INFO: enter test to run
[13:42:28.435] INFO: test: HighRate no parameter change
[13:42:28.435] INFO: running: highrate
[13:42:28.436] INFO: ----------------------------------------------------------------------
[13:42:28.436] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:42:28.436] INFO: ----------------------------------------------------------------------
[13:42:29.060] INFO: Expecting 208000 events.
[13:42:42.844] INFO: 208000 events read in total (13257ms).
[13:42:42.850] INFO: Test took 14405ms.
[13:42:43.201] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:42:43.521] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:42:43.521] INFO: number of red-efficiency pixels: 286 202 316 680 704 831 839 377 280 516 453 320 374 255 73 54
[13:42:43.521] INFO: number of X-ray hits detected: 156956 111948 171980 276968 285963 285958 291971 208330 175437 228399 215083 196855 197264 121419 57211 59397
[13:42:43.521] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:42:43.521] INFO: number of Vcal hits detected: 207688 207780 207640 207228 207198 207039 207032 207577 207703 207436 207513 207666 207609 207725 207925 207944
[13:42:43.521] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.6 99.6 99.6 99.8 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[13:42:43.521] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.6 99.6 99.5 99.5 99.8 99.9 99.7 99.8 99.8 99.8 99.9 100.0 100.0
[13:42:43.521] INFO: X-ray hit rate [MHz/cm2]: 46.0 32.8 50.4 81.2 83.8 83.8 85.6 61.1 51.4 66.9 63.0 57.7 57.8 35.6 16.8 17.4
[13:42:43.521] INFO: PixTestHighRate::doXPixelAlive() done
[13:42:43.568] INFO: PixTest:: pg_setup set to default.
[13:42:43.584] INFO: enter test to run
[13:44:47.586] INFO: test: HighRate no parameter change
[13:44:47.586] INFO: running: highrate
[13:44:47.587] INFO: ----------------------------------------------------------------------
[13:44:47.587] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:44:47.587] INFO: ----------------------------------------------------------------------
[13:44:48.200] INFO: Expecting 208000 events.
[13:45:04.483] INFO: 208000 events read in total (15756ms).
[13:45:04.491] INFO: Test took 16895ms.
[13:45:04.003] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:45:05.374] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[13:45:05.374] INFO: number of red-efficiency pixels: 656 411 708 1469 1609 1841 1954 801 540 1179 1009 728 872 539 125 114
[13:45:05.375] INFO: number of X-ray hits detected: 235614 167460 257525 411929 427731 428832 438799 310767 262733 343473 321159 294083 295135 182673 86503 89282
[13:45:05.375] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:45:05.375] INFO: number of Vcal hits detected: 207189 207529 207013 206017 205676 205200 205025 206987 207405 206520 206760 207151 206958 207353 207868 207884
[13:45:05.375] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.6 99.1 99.0 98.8 98.7 99.5 99.7 99.3 99.5 99.6 99.5 99.7 99.9 99.9
[13:45:05.375] INFO: Vcal hit overall efficiency (%): 99.6 99.8 99.5 99.0 98.9 98.7 98.6 99.5 99.7 99.3 99.4 99.6 99.5 99.7 99.9 99.9
[13:45:05.375] INFO: X-ray hit rate [MHz/cm2]: 69.1 49.1 75.5 120.7 125.4 125.7 128.6 91.1 77.0 100.7 94.1 86.2 86.5 53.5 25.4 26.2
[13:45:05.375] INFO: PixTestHighRate::doXPixelAlive() done
[13:45:05.420] INFO: PixTest:: pg_setup set to default.
[13:45:05.433] INFO: enter test to run
[13:47:22.449] INFO: test: exit no parameter change
[13:47:22.825] QUIET: Connection to board 32 closed.
[13:47:22.841] INFO: pXar: this is the end, my friend