[09:21:32.806] INFO: *** Welcome to pxar ***
[09:21:32.806] INFO: *** Today: 2016/05/05
[09:21:32.827] INFO: *** Version: v1.9.0-796-gef167-dirty
[09:21:32.827] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//dacParameters35_C15.dat
[09:21:32.828] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:21:32.828] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//defaultMaskFile.dat
[09:21:32.828] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C15.dat
[09:21:32.904] INFO: clk: 4
[09:21:32.904] INFO: ctr: 4
[09:21:32.904] INFO: sda: 19
[09:21:32.904] INFO: tin: 9
[09:21:32.904] INFO: level: 15
[09:21:32.904] INFO: triggerdelay: 0
[09:21:32.904] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[09:21:32.904] INFO: Log level: INFO
[09:21:32.922] QUIET: Connection to board DTB_WREK4U opened.
[09:21:32.925] 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:
------------------------------------------------------
[09:21:32.928] INFO: RPC call hashes of host and DTB match: 398089610
[09:21:34.457] INFO: DUT info:
[09:21:34.457] INFO: The DUT currently contains the following objects:
[09:21:34.457] INFO: 2 TBM Cores tbm08c (2 ON)
[09:21:34.457] INFO: TBM Core alpha (0): 7 registers set
[09:21:34.457] INFO: TBM Core beta (1): 7 registers set
[09:21:34.457] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[09:21:34.457] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.457] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.457] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.457] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.457] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.457] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.457] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.457] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.457] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.457] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.458] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.458] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.458] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.458] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.458] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.458] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[09:21:34.861] INFO: enter 'restricted' command line mode
[09:21:34.861] INFO: enter test to run
[09:21:41.802] INFO: test: timing no parameter change
[09:21:41.802] INFO: running: timing
[09:21:41.831] INFO: ######################################################################
[09:21:41.831] INFO: PixTestTiming::doTest()
[09:21:41.831] INFO: ######################################################################
[09:21:41.831] INFO: ----------------------------------------------------------------------
[09:21:41.831] INFO: PixTestTiming::TBMPhaseScan()
[09:21:41.831] INFO: ----------------------------------------------------------------------
[09:26:39.795] INFO: TBM Phase Settings: 236
[09:26:39.795] INFO: 400MHz Phase: 3
[09:26:39.795] INFO: 160MHz Phase: 7
[09:26:39.795] INFO: Functional Phase Area: 4
[09:26:39.798] INFO: Test took 297967 ms.
[09:26:39.798] INFO: PixTestTiming::TBMPhaseScan() done.
[09:26:39.799] INFO: ----------------------------------------------------------------------
[09:26:39.799] INFO: PixTestTiming::ROCDelayScan()
[09:26:39.799] INFO: ----------------------------------------------------------------------
[09:28:52.642] INFO: ROC Delay Settings: 228
[09:28:52.643] INFO: ROC Header-Trailer/Token Delay: 11
[09:28:52.643] INFO: ROC Port 0 Delay: 4
[09:28:52.643] INFO: ROC Port 1 Delay: 4
[09:28:52.643] INFO: Functional ROC Area: 5
[09:28:52.646] INFO: Test took 132847 ms.
[09:28:52.646] INFO: PixTestTiming::ROCDelayScan() done.
[09:28:52.646] INFO: ----------------------------------------------------------------------
[09:28:52.646] INFO: PixTestTiming::TimingTest()
[09:28:52.646] INFO: ----------------------------------------------------------------------
[09:29:08.786] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:29:23.755] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:29:38.687] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:29:53.611] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:30:08.563] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:30:23.506] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:30:38.452] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:30:53.381] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:31:08.343] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:31:23.300] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:31:23.682] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:31:23.699] INFO: ----------------------------------------------------------------------
[09:31:23.699] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[09:31:23.699] INFO: ----------------------------------------------------------------------
[09:31:23.699] INFO: ----------------------------------------------------------------------
[09:31:23.699] INFO: Read back bit status: 1
[09:31:23.700] INFO: ----------------------------------------------------------------------
[09:31:23.700] INFO: ----------------------------------------------------------------------
[09:31:23.700] INFO: Timings are good!
[09:31:23.700] INFO: ----------------------------------------------------------------------
[09:31:23.700] INFO: Test took 151054 ms.
[09:31:23.700] INFO: PixTestTiming::TimingTest() done.
[09:31:23.700] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//tbmParameters_C0a.dat
[09:31:23.700] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:31:23.700] INFO: PixTestTiming::doTest took 581874 ms.
[09:31:23.700] INFO: PixTestTiming::doTest() done
[09:31:23.700] INFO: Write out TBMPhaseScan_0_V0
[09:31:23.726] INFO: Write out TBMPhaseScan_1_V0
[09:31:23.727] INFO: Write out CombinedTBMPhaseScan_V0
[09:31:23.742] INFO: Write out ROCDelayScan3_V0
[09:31:23.744] INFO: enter test to run
[09:32:21.373] INFO: test: PixelAlive no parameter change
[09:32:21.373] INFO: running: pixelalive
[09:32:21.377] INFO: ----------------------------------------------------------------------
[09:32:21.377] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[09:32:21.377] INFO: ----------------------------------------------------------------------
[09:32:21.694] INFO: Expecting 41600 events.
[09:32:26.032] INFO: 41600 events read in total (3622ms).
[09:32:26.032] INFO: Test took 4653ms.
[09:32:26.039] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:32:26.437] INFO: PixTestAlive::aliveTest() done
[09:32:26.437] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[09:32:26.441] INFO: enter test to run
[09:32:57.221] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[09:32:57.221] INFO: running: highrate
[09:32:57.221] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[09:32:57.379] INFO: ----------------------------------------------------------------------
[09:32:57.379] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[09:32:57.379] INFO: ----------------------------------------------------------------------
[09:32:57.379] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[09:32:57.379] INFO: edge/corner pixel THR is adjusted
[09:32:57.379] INFO: PixTestHighRate::trimHotPixels: step 0...
[09:32:58.337] INFO: Collecting data for 5 seconds...
[09:33:03.354] INFO: Done with hot pixel readout
[09:33:15.745] INFO: PixTest:: pg_setup set to default.
[09:33:15.746] INFO: 3 hot pixels found in step 0
[09:33:16.744] INFO: Collecting data for 5 seconds...
[09:33:21.763] INFO: Done with hot pixel readout
[09:33:34.197] INFO: PixTest:: pg_setup set to default.



[09:33:34.198] INFO: 5 hot pixels found in step 1
[09:33:35.197] INFO: Collecting data for 5 seconds...
[09:33:40.216] INFO: Done with hot pixel readout
[09:33:52.744] INFO: PixTest:: pg_setup set to default.




[09:33:52.745] INFO: 14 hot pixels found in step 2
[09:33:53.743] INFO: Collecting data for 5 seconds...
[09:33:58.761] INFO: Done with hot pixel readout
[09:34:11.232] INFO: PixTest:: pg_setup set to default.




[09:34:11.233] INFO: 12 hot pixels found in step 3
[09:34:12.231] INFO: Collecting data for 5 seconds...
[09:34:17.253] INFO: Done with hot pixel readout
[09:34:29.828] INFO: PixTest:: pg_setup set to default.



[09:34:29.829] INFO: 5 hot pixels found in step 4
[09:34:30.828] INFO: Collecting data for 5 seconds...
[09:34:35.846] INFO: Done with hot pixel readout
[09:34:48.454] INFO: PixTest:: pg_setup set to default.




[09:34:48.455] INFO: 8 hot pixels found in step 5
[09:34:49.453] INFO: Collecting data for 5 seconds...
[09:34:54.472] INFO: Done with hot pixel readout
[09:35:06.954] INFO: PixTest:: pg_setup set to default.





[09:35:06.955] INFO: 7 hot pixels found in step 6
[09:35:07.953] INFO: Collecting data for 5 seconds...
[09:35:12.972] INFO: Done with hot pixel readout
[09:35:25.341] INFO: PixTest:: pg_setup set to default.





[09:35:25.343] INFO: 11 hot pixels found in step 7
[09:35:26.339] INFO: Collecting data for 5 seconds...
[09:35:31.355] INFO: Done with hot pixel readout
[09:35:43.740] INFO: PixTest:: pg_setup set to default.



[09:35:43.741] INFO: 7 hot pixels found in step 8
[09:35:44.738] INFO: Collecting data for 5 seconds...
[09:35:49.754] INFO: Done with hot pixel readout
[09:36:02.146] INFO: PixTest:: pg_setup set to default.


[09:36:02.147] INFO: 6 hot pixels found in step 9
[09:36:03.146] INFO: Collecting data for 5 seconds...
[09:36:08.163] INFO: Done with hot pixel readout
[09:36:20.569] INFO: PixTest:: pg_setup set to default.


[09:36:20.570] INFO: 11 hot pixels found in step 10
[09:36:21.569] INFO: Collecting data for 5 seconds...
[09:36:26.586] INFO: Done with hot pixel readout
[09:36:39.074] INFO: PixTest:: pg_setup set to default.


[09:36:39.076] INFO: 5 hot pixels found in step 11
[09:36:40.074] INFO: Collecting data for 5 seconds...
[09:36:45.091] INFO: Done with hot pixel readout
[09:36:57.452] INFO: PixTest:: pg_setup set to default.









[09:36:57.453] INFO: 10 hot pixels found in step 12
[09:36:58.451] INFO: Collecting data for 5 seconds...
[09:37:03.468] INFO: Done with hot pixel readout
[09:37:15.560] INFO: PixTest:: pg_setup set to default.


[09:37:15.561] INFO: 3 hot pixels found in step 13
[09:37:16.560] INFO: Collecting data for 5 seconds...
[09:37:21.578] INFO: Done with hot pixel readout
[09:37:33.775] INFO: PixTest:: pg_setup set to default.

[09:37:33.776] INFO: 6 hot pixels found in step 14
[09:37:33.819] INFO: 6 hot pixels could not be trimmed and have been masked.
[09:37:33.822] INFO: PixTest::trimHotPixels() done
[09:37:33.822] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C0.dat
[09:37:33.828] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C1.dat
[09:37:33.833] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C2.dat
[09:37:33.839] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C3.dat
[09:37:33.844] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C4.dat
[09:37:33.849] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C5.dat
[09:37:33.855] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C6.dat
[09:37:33.860] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C7.dat
[09:37:33.866] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C8.dat
[09:37:33.871] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C9.dat
[09:37:33.877] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C10.dat
[09:37:33.882] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C11.dat
[09:37:33.887] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C12.dat
[09:37:33.893] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C13.dat
[09:37:33.898] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C14.dat
[09:37:33.904] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C15.dat
[09:37:33.909] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//defaultMaskFile.dat
[09:37:33.919] INFO: enter test to run
[09:38:24.802] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[09:38:24.802] INFO: running: highrate
[09:38:24.807] INFO: ----------------------------------------------------------------------
[09:38:24.807] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[09:38:24.807] INFO: ----------------------------------------------------------------------
[09:38:24.807] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[09:38:24.807] INFO: edge/corner pixel THR is adjusted
[09:38:24.807] INFO: PixTestHighRate::trimHotPixels: step 0...
[09:38:25.764] INFO: Collecting data for 1 seconds...
[09:38:26.767] INFO: Done with hot pixel readout
[09:38:31.345] INFO: PixTest:: pg_setup set to default.
[09:38:31.346] INFO: 0 hot pixels found in step 0
[09:38:31.351] INFO: 0 hot pixels could not be trimmed and have been masked.
[09:38:31.418] INFO: PixTest::trimHotPixels() done
[09:38:31.418] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C0.dat
[09:38:31.430] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C1.dat
[09:38:31.435] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C2.dat
[09:38:31.440] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C3.dat
[09:38:31.446] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C4.dat
[09:38:31.451] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C5.dat
[09:38:31.456] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C6.dat
[09:38:31.462] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C7.dat
[09:38:31.467] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C8.dat
[09:38:31.472] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C9.dat
[09:38:31.477] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C10.dat
[09:38:31.483] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C11.dat
[09:38:31.488] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C12.dat
[09:38:31.493] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C13.dat
[09:38:31.498] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C14.dat
[09:38:31.504] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//trimParameters35_C15.dat
[09:38:31.509] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NV_FPIXTest-17C-FNAL-160429-1159_2016-04-29_11h59m_1461949190/000_FPIXTest_p17//defaultMaskFile.dat
[09:38:31.519] INFO: enter test to run
[09:38:47.218] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[09:38:47.218] INFO: running: xray
[09:38:47.219] INFO: ----------------------------------------------------------------------
[09:38:47.219] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[09:38:47.219] INFO: ----------------------------------------------------------------------
[09:38:48.182] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[09:38:58.728] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[09:39:28.261] INFO: Resuming triggers.
[09:39:38.807] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[09:40:08.271] INFO: Resuming triggers.
[09:40:18.816] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[09:40:48.413] INFO: Resuming triggers.
[09:40:58.965] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[09:41:28.415] INFO: Resuming triggers.
[09:41:38.965] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[09:42:08.424] INFO: Resuming triggers.
[09:42:18.971] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[09:42:48.532] INFO: Resuming triggers.
[09:42:59.083] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[09:43:28.571] INFO: Resuming triggers.
[09:43:39.119] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[09:44:08.750] INFO: Resuming triggers.
[09:44:19.295] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[09:44:49.421] INFO: Resuming triggers.
[09:44:54.830] INFO: data taking finished, elapsed time: 100 seconds.
[09:45:10.701] INFO: PixTest:: pg_setup set to default.
[09:45:10.704] INFO: PixTestXray::doPhRun() done
[09:45:10.847] INFO: enter test to run
[09:47:00.998] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[09:47:00.998] INFO: running: xray
[09:47:00.999] INFO: ----------------------------------------------------------------------
[09:47:00.999] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[09:47:00.999] INFO: ----------------------------------------------------------------------
[09:47:01.964] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[09:47:07.542] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[09:47:37.472] INFO: Resuming triggers.
[09:47:43.050] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[09:48:13.932] INFO: Resuming triggers.
[09:48:19.511] INFO: run duration 16 seconds, buffer almost full (81%), pausing triggers.
[09:48:49.333] INFO: Resuming triggers.
[09:48:54.912] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[09:49:25.021] INFO: Resuming triggers.
[09:49:30.599] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[09:50:00.657] INFO: Resuming triggers.
[09:50:06.238] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[09:50:36.408] INFO: Resuming triggers.
[09:50:41.988] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[09:51:12.186] INFO: Resuming triggers.
[09:51:17.769] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[09:51:47.942] INFO: Resuming triggers.
[09:51:53.523] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[09:52:23.705] INFO: Resuming triggers.
[09:52:29.286] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[09:52:59.461] INFO: Resuming triggers.
[09:53:05.044] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[09:53:35.236] INFO: Resuming triggers.
[09:53:40.818] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[09:54:11.043] INFO: Resuming triggers.
[09:54:16.625] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[09:54:46.849] INFO: Resuming triggers.
[09:54:52.430] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[09:55:22.774] INFO: Resuming triggers.
[09:55:28.353] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[09:55:59.621] INFO: Resuming triggers.
[09:56:05.201] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[09:56:36.496] INFO: Resuming triggers.
[09:56:42.073] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[09:57:12.635] INFO: Resuming triggers.
[09:57:18.113] INFO: data taking finished, elapsed time: 100 seconds.
[09:57:47.924] INFO: PixTest:: pg_setup set to default.
[09:57:47.927] INFO: PixTestXray::doPhRun() done
[09:57:48.076] INFO: enter test to run
[09:58:02.018] INFO: test: HighRate no parameter change
[09:58:02.018] INFO: running: highrate
[09:58:02.019] INFO: ----------------------------------------------------------------------
[09:58:02.019] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[09:58:02.019] INFO: ----------------------------------------------------------------------
[09:58:02.159] INFO: Expecting 768 events.
[09:58:03.293] INFO: 768 events read in total (418ms).
[09:58:03.294] INFO: Test took 1269ms.
[09:58:04.097] INFO: Expecting 41600 events.
[09:58:07.301] INFO: 41600 events read in total (2677ms).
[09:58:07.302] INFO: Test took 4000ms.
[09:58:07.345] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:08.059] INFO: Expecting 41600 events.
[09:58:11.328] INFO: 41600 events read in total (2743ms).
[09:58:11.330] INFO: Test took 3965ms.
[09:58:11.374] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:12.080] INFO: Expecting 41600 events.
[09:58:15.401] INFO: 41600 events read in total (2794ms).
[09:58:15.402] INFO: Test took 4006ms.
[09:58:15.445] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:16.150] INFO: Expecting 41600 events.
[09:58:19.468] INFO: 41600 events read in total (2791ms).
[09:58:19.469] INFO: Test took 4002ms.
[09:58:19.513] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:20.217] INFO: Expecting 41600 events.
[09:58:23.528] INFO: 41600 events read in total (2784ms).
[09:58:23.529] INFO: Test took 3994ms.
[09:58:23.572] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:24.280] INFO: Expecting 41600 events.
[09:58:27.584] INFO: 41600 events read in total (2777ms).
[09:58:27.585] INFO: Test took 3992ms.
[09:58:27.627] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:28.339] INFO: Expecting 41600 events.
[09:58:31.663] INFO: 41600 events read in total (2798ms).
[09:58:31.664] INFO: Test took 4015ms.
[09:58:31.707] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:32.415] INFO: Expecting 41600 events.
[09:58:35.744] INFO: 41600 events read in total (2802ms).
[09:58:35.745] INFO: Test took 4017ms.
[09:58:35.789] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:36.496] INFO: Expecting 41600 events.
[09:58:39.800] INFO: 41600 events read in total (2778ms).
[09:58:39.801] INFO: Test took 3991ms.
[09:58:39.843] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:40.553] INFO: Expecting 41600 events.
[09:58:43.881] INFO: 41600 events read in total (2801ms).
[09:58:43.882] INFO: Test took 4017ms.
[09:58:43.926] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:44.631] INFO: Expecting 41600 events.
[09:58:47.925] INFO: 41600 events read in total (2767ms).
[09:58:47.926] INFO: Test took 3979ms.
[09:58:47.970] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:48.673] INFO: Expecting 41600 events.
[09:58:51.979] INFO: 41600 events read in total (2779ms).
[09:58:51.980] INFO: Test took 3988ms.
[09:58:52.024] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:52.728] INFO: Expecting 41600 events.
[09:58:56.120] INFO: 41600 events read in total (2865ms).
[09:58:56.121] INFO: Test took 4076ms.
[09:58:56.166] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:56.858] INFO: Expecting 41600 events.
[09:59:00.163] INFO: 41600 events read in total (2779ms).
[09:59:00.164] INFO: Test took 3976ms.
[09:59:00.208] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:00.912] INFO: Expecting 41600 events.
[09:59:04.160] INFO: 41600 events read in total (2721ms).
[09:59:04.161] INFO: Test took 3932ms.
[09:59:04.205] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:04.908] INFO: Expecting 41600 events.
[09:59:08.195] INFO: 41600 events read in total (2760ms).
[09:59:08.196] INFO: Test took 3971ms.
[09:59:08.241] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:08.949] INFO: Expecting 41600 events.
[09:59:12.260] INFO: 41600 events read in total (2784ms).
[09:59:12.261] INFO: Test took 3998ms.
[09:59:12.305] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:13.010] INFO: Expecting 41600 events.
[09:59:16.320] INFO: 41600 events read in total (2783ms).
[09:59:16.321] INFO: Test took 3994ms.
[09:59:16.365] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:17.068] INFO: Expecting 41600 events.
[09:59:20.395] INFO: 41600 events read in total (2801ms).
[09:59:20.396] INFO: Test took 4010ms.
[09:59:20.441] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:21.141] INFO: Expecting 41600 events.
[09:59:24.235] INFO: 41600 events read in total (2567ms).
[09:59:24.236] INFO: Test took 3774ms.
[09:59:24.279] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:24.624] INFO: enter test to run
[09:59:27.785] INFO: test: HighRate no parameter change
[09:59:27.785] INFO: running: highrate
[09:59:27.786] INFO: ----------------------------------------------------------------------
[09:59:27.786] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[09:59:27.786] INFO: ----------------------------------------------------------------------
[09:59:28.404] INFO: Expecting 208000 events.
[09:59:40.700] INFO: 208000 events read in total (11769ms).
[09:59:40.703] INFO: Test took 12910ms.
[09:59:40.897] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:41.165] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[09:59:41.165] INFO: number of red-efficiency pixels: 110 71 123 194 202 191 208 175 157 141 154 140 126 74 20 34
[09:59:41.165] INFO: number of X-ray hits detected: 84672 56786 90895 146607 148036 157919 154435 115042 106028 118276 119597 106356 109599 65726 29336 34132
[09:59:41.165] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[09:59:41.166] INFO: number of Vcal hits detected: 207890 207926 207867 207794 207793 207803 207780 207818 207840 207856 207844 207860 207870 207922 207980 207965
[09:59:41.166] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[09:59:41.166] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[09:59:41.166] INFO: X-ray hit rate [MHz/cm2]: 24.8 16.6 26.6 43.0 43.4 46.3 45.3 33.7 31.1 34.7 35.1 31.2 32.1 19.3 8.6 10.0
[09:59:41.166] INFO: PixTestHighRate::doXPixelAlive() done
[09:59:41.213] INFO: PixTest:: pg_setup set to default.
[09:59:41.225] INFO: enter test to run
[09:59:53.361] INFO: test: HighRate no parameter change
[09:59:53.361] INFO: running: highrate
[09:59:53.362] INFO: ----------------------------------------------------------------------
[09:59:53.362] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[09:59:53.362] INFO: ----------------------------------------------------------------------
[09:59:53.974] INFO: Expecting 208000 events.
[10:00:08.758] INFO: 208000 events read in total (14257ms).
[10:00:08.765] INFO: Test took 15393ms.
[10:00:09.151] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:00:09.481] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:00:09.481] INFO: number of red-efficiency pixels: 330 200 429 772 772 834 814 677 455 463 691 536 406 274 72 89
[10:00:09.481] INFO: number of X-ray hits detected: 179500 118980 192236 308848 312763 330957 326229 242359 223394 249093 252190 224249 229569 140700 61191 72517
[10:00:09.481] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:00:09.481] INFO: number of Vcal hits detected: 207627 207785 207474 207112 207089 207012 207059 207208 207510 207506 207075 207403 207563 207705 207926 207910
[10:00:09.481] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.6 99.6 99.6 99.6 99.6 99.8 99.8 99.6 99.7 99.8 99.9 100.0 100.0
[10:00:09.481] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.6 99.6 99.5 99.5 99.6 99.8 99.8 99.6 99.7 99.8 99.9 100.0 100.0
[10:00:09.481] INFO: X-ray hit rate [MHz/cm2]: 52.6 34.9 56.3 90.5 91.7 97.0 95.6 71.0 65.5 73.0 73.9 65.7 67.3 41.2 17.9 21.3
[10:00:09.482] INFO: PixTestHighRate::doXPixelAlive() done
[10:00:09.532] INFO: PixTest:: pg_setup set to default.
[10:00:09.546] INFO: enter test to run
[10:00:29.200] INFO: test: HighRate no parameter change
[10:00:29.201] INFO: running: highrate
[10:00:29.202] INFO: ----------------------------------------------------------------------
[10:00:29.202] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:00:29.202] INFO: ----------------------------------------------------------------------
[10:00:29.818] INFO: Expecting 208000 events.
[10:00:47.149] INFO: 208000 events read in total (16804ms).
[10:00:47.159] INFO: Test took 17948ms.
[10:00:47.725] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:00:48.115] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:00:48.115] INFO: number of red-efficiency pixels: 813 439 877 1667 1836 1810 1756 1397 1103 1037 1482 1080 891 565 146 165
[10:00:48.115] INFO: number of X-ray hits detected: 261224 174743 281233 451984 459143 484982 476064 355818 328934 365588 370788 328776 337732 204352 90177 106444
[10:00:48.115] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:00:48.115] INFO: number of Vcal hits detected: 206925 207496 206654 205578 205220 205304 205368 205792 206661 206715 205729 206623 206944 207296 207848 207831
[10:00:48.115] INFO: Vcal hit fiducial efficiency (%): 99.5 99.8 99.4 99.0 98.8 98.8 98.9 99.0 99.4 99.4 99.0 99.4 99.5 99.7 99.9 99.9
[10:00:48.115] INFO: Vcal hit overall efficiency (%): 99.5 99.8 99.4 98.8 98.7 98.7 98.7 98.9 99.4 99.4 98.9 99.3 99.5 99.7 99.9 99.9
[10:00:48.115] INFO: X-ray hit rate [MHz/cm2]: 76.6 51.2 82.4 132.5 134.6 142.2 139.5 104.3 96.4 107.2 108.7 96.4 99.0 59.9 26.4 31.2
[10:00:48.116] INFO: PixTestHighRate::doXPixelAlive() done
[10:00:48.163] INFO: PixTest:: pg_setup set to default.
[10:00:48.177] INFO: enter test to run
[10:00:49.585] INFO: test: exit no parameter change
[10:00:49.985] QUIET: Connection to board 32 closed.
[10:00:49.986] INFO: pXar: this is the end, my friend