[14:12:24.038] INFO: *** Welcome to pxar ***
[14:12:24.038] INFO: *** Today: 2016/05/04
[14:12:24.058] INFO: *** Version: v1.9.0-796-gef167-dirty
[14:12:24.058] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//dacParameters35_C15.dat
[14:12:24.059] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:12:24.060] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//defaultMaskFile.dat
[14:12:24.060] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C15.dat
[14:12:24.133] INFO: clk: 4
[14:12:24.133] INFO: ctr: 4
[14:12:24.133] INFO: sda: 19
[14:12:24.133] INFO: tin: 9
[14:12:24.133] INFO: level: 15
[14:12:24.133] INFO: triggerdelay: 0
[14:12:24.133] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[14:12:24.133] INFO: Log level: INFO
[14:12:24.149] QUIET: Connection to board DTB_WREK4U opened.
[14:12:24.152] 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:
------------------------------------------------------
[14:12:24.155] INFO: RPC call hashes of host and DTB match: 398089610
[14:12:25.695] INFO: DUT info:
[14:12:25.695] INFO: The DUT currently contains the following objects:
[14:12:25.695] INFO: 2 TBM Cores tbm08c (2 ON)
[14:12:25.695] INFO: TBM Core alpha (0): 7 registers set
[14:12:25.695] INFO: TBM Core beta (1): 7 registers set
[14:12:25.695] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[14:12:25.695] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.695] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.695] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:25.696] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[14:12:26.099] INFO: enter 'restricted' command line mode
[14:12:26.100] INFO: enter test to run
[14:12:32.874] INFO: test: timing no parameter change
[14:12:32.875] INFO: running: timing
[14:12:32.903] INFO: ######################################################################
[14:12:32.903] INFO: PixTestTiming::doTest()
[14:12:32.903] INFO: ######################################################################
[14:12:32.904] INFO: ----------------------------------------------------------------------
[14:12:32.904] INFO: PixTestTiming::TBMPhaseScan()
[14:12:32.904] INFO: ----------------------------------------------------------------------
[14:17:17.182] INFO: TBM Phase Settings: 248
[14:17:17.182] INFO: 400MHz Phase: 6
[14:17:17.182] INFO: 160MHz Phase: 7
[14:17:17.182] INFO: Functional Phase Area: 4
[14:17:17.185] INFO: Test took 284282 ms.
[14:17:17.185] INFO: PixTestTiming::TBMPhaseScan() done.
[14:17:17.185] INFO: ----------------------------------------------------------------------
[14:17:17.185] INFO: PixTestTiming::ROCDelayScan()
[14:17:17.185] INFO: ----------------------------------------------------------------------
[14:19:39.140] INFO: ROC Delay Settings: 228
[14:19:39.140] INFO: ROC Header-Trailer/Token Delay: 11
[14:19:39.140] INFO: ROC Port 0 Delay: 4
[14:19:39.140] INFO: ROC Port 1 Delay: 4
[14:19:39.140] INFO: Functional ROC Area: 6
[14:19:39.144] INFO: Test took 141959 ms.
[14:19:39.144] INFO: PixTestTiming::ROCDelayScan() done.
[14:19:39.144] INFO: ----------------------------------------------------------------------
[14:19:39.144] INFO: PixTestTiming::TimingTest()
[14:19:39.144] INFO: ----------------------------------------------------------------------
[14:19:55.297] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:10.264] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:25.227] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:40.195] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:20:55.159] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:10.095] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:25.048] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:39.003] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:21:54.966] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:09.931] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:10.312] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:10.328] INFO: ----------------------------------------------------------------------
[14:22:10.328] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:22:10.328] INFO: ----------------------------------------------------------------------
[14:22:10.328] INFO: ----------------------------------------------------------------------
[14:22:10.328] INFO: Read back bit status: 1
[14:22:10.328] INFO: ----------------------------------------------------------------------
[14:22:10.328] INFO: ----------------------------------------------------------------------
[14:22:10.328] INFO: Timings are good!
[14:22:10.328] INFO: ----------------------------------------------------------------------
[14:22:10.328] INFO: Test took 151184 ms.
[14:22:10.328] INFO: PixTestTiming::TimingTest() done.
[14:22:10.339] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:22:10.339] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:22:10.339] INFO: PixTestTiming::doTest took 577441 ms.
[14:22:10.339] INFO: PixTestTiming::doTest() done
[14:22:10.339] INFO: Write out TBMPhaseScan_0_V0
[14:22:10.365] INFO: Write out TBMPhaseScan_1_V0
[14:22:10.365] INFO: Write out CombinedTBMPhaseScan_V0
[14:22:10.492] INFO: Write out ROCDelayScan3_V0
[14:22:10.493] INFO: enter test to run
[14:22:35.782] INFO: test: PixelAlive no parameter change
[14:22:35.782] INFO: running: pixelalive
[14:22:35.786] INFO: ----------------------------------------------------------------------
[14:22:35.786] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[14:22:35.786] INFO: ----------------------------------------------------------------------
[14:22:36.107] INFO: Expecting 41600 events.
[14:22:40.500] INFO: 41600 events read in total (3677ms).
[14:22:40.501] INFO: Test took 4712ms.
[14:22:40.508] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:40.901] INFO: PixTestAlive::aliveTest() done
[14:22:40.902] INFO: number of dead pixels (per ROC): 0 1 0 1 0 0 0 0 0 0 0 0 0 0 1 0
[14:22:40.905] INFO: enter test to run
[14:23:13.238] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[14:23:13.238] INFO: running: highrate
[14:23:13.238] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:23:13.412] INFO: ----------------------------------------------------------------------
[14:23:13.412] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[14:23:13.412] INFO: ----------------------------------------------------------------------
[14:23:13.412] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[14:23:13.412] INFO: edge/corner pixel THR is adjusted
[14:23:13.412] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:23:14.369] INFO: Collecting data for 5 seconds...
[14:23:19.387] INFO: Done with hot pixel readout
[14:23:32.318] INFO: PixTest:: pg_setup set to default.




[14:23:32.319] INFO: 144 hot pixels found in step 0
[14:23:33.318] INFO: Collecting data for 5 seconds...
[14:23:38.336] INFO: Done with hot pixel readout
[14:23:51.273] INFO: PixTest:: pg_setup set to default.






[14:23:51.274] INFO: 139 hot pixels found in step 1
[14:23:52.274] INFO: Collecting data for 5 seconds...
[14:23:57.294] INFO: Done with hot pixel readout
[14:24:10.245] INFO: PixTest:: pg_setup set to default.


[14:24:10.246] INFO: 113 hot pixels found in step 2
[14:24:11.247] INFO: Collecting data for 5 seconds...
[14:24:16.265] INFO: Done with hot pixel readout
[14:24:29.291] INFO: PixTest:: pg_setup set to default.







[14:24:29.292] INFO: 123 hot pixels found in step 3
[14:24:30.291] INFO: Collecting data for 5 seconds...
[14:24:35.307] INFO: Done with hot pixel readout
[14:24:48.135] INFO: PixTest:: pg_setup set to default.








[14:24:48.137] INFO: 113 hot pixels found in step 4
[14:24:49.135] INFO: Collecting data for 5 seconds...
[14:24:54.151] INFO: Done with hot pixel readout
[14:25:06.926] INFO: PixTest:: pg_setup set to default.




[14:25:06.927] INFO: 109 hot pixels found in step 5
[14:25:07.924] INFO: Collecting data for 5 seconds...
[14:25:12.941] INFO: Done with hot pixel readout
[14:25:25.776] INFO: PixTest:: pg_setup set to default.








[14:25:25.777] INFO: 102 hot pixels found in step 6
[14:25:26.776] INFO: Collecting data for 5 seconds...
[14:25:31.793] INFO: Done with hot pixel readout
[14:25:44.759] INFO: PixTest:: pg_setup set to default.










[14:25:44.760] INFO: 117 hot pixels found in step 7
[14:25:45.760] INFO: Collecting data for 5 seconds...
[14:25:50.779] INFO: Done with hot pixel readout
[14:26:03.543] INFO: PixTest:: pg_setup set to default.









[14:26:03.544] INFO: 93 hot pixels found in step 8
[14:26:04.544] INFO: Collecting data for 5 seconds...
[14:26:09.563] INFO: Done with hot pixel readout
[14:26:21.947] INFO: PixTest:: pg_setup set to default.











[14:26:21.948] INFO: 80 hot pixels found in step 9
[14:26:22.947] INFO: Collecting data for 5 seconds...
[14:26:27.965] INFO: Done with hot pixel readout
[14:26:40.666] INFO: PixTest:: pg_setup set to default.











[14:26:40.667] INFO: 85 hot pixels found in step 10
[14:26:41.665] INFO: Collecting data for 5 seconds...
[14:26:46.682] INFO: Done with hot pixel readout
[14:26:59.458] INFO: PixTest:: pg_setup set to default.











[14:26:59.459] INFO: 83 hot pixels found in step 11
[14:27:00.457] INFO: Collecting data for 5 seconds...
[14:27:05.474] INFO: Done with hot pixel readout
[14:27:18.292] INFO: PixTest:: pg_setup set to default.










[14:27:18.293] INFO: 82 hot pixels found in step 12
[14:27:19.292] INFO: Collecting data for 5 seconds...
[14:27:24.308] INFO: Done with hot pixel readout
[14:27:37.114] INFO: PixTest:: pg_setup set to default.












[14:27:37.116] INFO: 76 hot pixels found in step 13
[14:27:38.115] INFO: Collecting data for 5 seconds...
[14:27:43.131] INFO: Done with hot pixel readout
[14:27:55.936] INFO: PixTest:: pg_setup set to default.













[14:27:55.937] INFO: 68 hot pixels found in step 14
[14:27:55.979] INFO: 68 hot pixels could not be trimmed and have been masked.
[14:27:55.983] INFO: PixTest::trimHotPixels() done
[14:27:55.983] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C0.dat
[14:27:55.989] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C1.dat
[14:27:55.995] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C2.dat
[14:27:55.000] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C3.dat
[14:27:56.005] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C4.dat
[14:27:56.011] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C5.dat
[14:27:56.016] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C6.dat
[14:27:56.022] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C7.dat
[14:27:56.027] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C8.dat
[14:27:56.033] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C9.dat
[14:27:56.038] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C10.dat
[14:27:56.043] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C11.dat
[14:27:56.048] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C12.dat
[14:27:56.054] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C13.dat
[14:27:56.059] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C14.dat
[14:27:56.065] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C15.dat
[14:27:56.070] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//defaultMaskFile.dat
[14:27:56.081] INFO: enter test to run
[14:28:36.323] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:28:36.324] INFO: running: highrate
[14:28:36.328] INFO: ----------------------------------------------------------------------
[14:28:36.328] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:28:36.328] INFO: ----------------------------------------------------------------------
[14:28:36.328] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:28:36.328] INFO: edge/corner pixel THR is adjusted
[14:28:36.328] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:28:37.286] INFO: Collecting data for 1 seconds...
[14:28:38.289] INFO: Done with hot pixel readout
[14:28:42.947] INFO: PixTest:: pg_setup set to default.
[14:28:42.948] INFO: 0 hot pixels found in step 0
[14:28:42.953] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:28:43.019] INFO: PixTest::trimHotPixels() done
[14:28:43.019] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C0.dat
[14:28:43.031] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C1.dat
[14:28:43.038] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C2.dat
[14:28:43.043] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C3.dat
[14:28:43.049] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C4.dat
[14:28:43.054] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C5.dat
[14:28:43.060] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C6.dat
[14:28:43.065] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C7.dat
[14:28:43.071] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C8.dat
[14:28:43.076] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C9.dat
[14:28:43.082] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C10.dat
[14:28:43.087] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C11.dat
[14:28:43.093] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C12.dat
[14:28:43.098] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C13.dat
[14:28:43.103] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C14.dat
[14:28:43.109] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C15.dat
[14:28:43.114] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-K-NJ_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//defaultMaskFile.dat
[14:28:43.125] INFO: enter test to run
[14:29:04.379] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:29:04.379] INFO: running: xray
[14:29:04.380] INFO: ----------------------------------------------------------------------
[14:29:04.380] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:29:04.381] INFO: ----------------------------------------------------------------------
[14:29:05.345] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:29:15.915] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[14:29:45.363] INFO: Resuming triggers.
[14:29:55.938] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[14:30:25.496] INFO: Resuming triggers.
[14:30:36.072] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[14:31:05.671] INFO: Resuming triggers.
[14:31:16.245] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[14:31:45.733] INFO: Resuming triggers.
[14:31:56.307] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[14:32:25.950] INFO: Resuming triggers.
[14:32:36.524] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[14:33:06.217] INFO: Resuming triggers.
[14:33:16.790] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[14:33:46.801] INFO: Resuming triggers.
[14:33:57.375] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[14:34:27.667] INFO: Resuming triggers.
[14:34:38.242] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[14:35:08.705] INFO: Resuming triggers.
[14:35:13.875] INFO: data taking finished, elapsed time: 100 seconds.
[14:35:28.704] INFO: PixTest:: pg_setup set to default.
[14:35:28.707] INFO: PixTestXray::doPhRun() done
[14:35:28.845] INFO: enter test to run
[14:35:51.856] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:35:51.856] INFO: running: xray
[14:35:51.857] INFO: ----------------------------------------------------------------------
[14:35:51.857] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:35:51.857] INFO: ----------------------------------------------------------------------
[14:35:52.821] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:35:58.319] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[14:36:28.626] INFO: Resuming triggers.
[14:36:34.121] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[14:37:05.339] INFO: Resuming triggers.
[14:37:10.834] INFO: run duration 16 seconds, buffer almost full (81%), pausing triggers.
[14:37:40.989] INFO: Resuming triggers.
[14:37:46.488] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[14:38:16.768] INFO: Resuming triggers.
[14:38:22.266] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[14:38:52.573] INFO: Resuming triggers.
[14:38:58.066] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[14:39:28.392] INFO: Resuming triggers.
[14:39:33.890] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[14:40:04.125] INFO: Resuming triggers.
[14:40:09.623] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[14:40:39.798] INFO: Resuming triggers.
[14:40:45.293] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[14:41:15.627] INFO: Resuming triggers.
[14:41:21.123] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[14:41:51.451] INFO: Resuming triggers.
[14:41:56.947] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[14:42:27.254] INFO: Resuming triggers.
[14:42:32.750] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[14:43:03.111] INFO: Resuming triggers.
[14:43:08.611] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[14:43:38.878] INFO: Resuming triggers.
[14:43:44.377] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[14:44:14.709] INFO: Resuming triggers.
[14:44:20.207] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[14:44:51.301] INFO: Resuming triggers.
[14:44:56.799] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[14:45:28.210] INFO: Resuming triggers.
[14:45:33.707] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[14:46:05.472] INFO: Resuming triggers.
[14:46:10.968] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[14:46:41.396] INFO: Resuming triggers.
[14:46:42.780] INFO: data taking finished, elapsed time: 100 seconds.
[14:46:50.733] INFO: PixTest:: pg_setup set to default.
[14:46:50.736] INFO: PixTestXray::doPhRun() done
[14:46:50.913] INFO: enter test to run
[14:47:15.323] INFO: test: HighRate no parameter change
[14:47:15.323] INFO: running: highrate
[14:47:15.324] INFO: ----------------------------------------------------------------------
[14:47:15.324] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[14:47:15.324] INFO: ----------------------------------------------------------------------
[14:47:15.466] INFO: Expecting 768 events.
[14:47:16.599] INFO: 768 events read in total (418ms).
[14:47:16.599] INFO: Test took 1267ms.
[14:47:17.402] INFO: Expecting 41600 events.
[14:47:20.557] INFO: 41600 events read in total (2628ms).
[14:47:20.558] INFO: Test took 3951ms.
[14:47:20.597] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:21.314] INFO: Expecting 41600 events.
[14:47:24.572] INFO: 41600 events read in total (2731ms).
[14:47:24.573] INFO: Test took 3956ms.
[14:47:24.615] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:25.327] INFO: Expecting 41600 events.
[14:47:28.626] INFO: 41600 events read in total (2772ms).
[14:47:28.627] INFO: Test took 3991ms.
[14:47:28.669] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:29.379] INFO: Expecting 41600 events.
[14:47:32.683] INFO: 41600 events read in total (2777ms).
[14:47:32.710] INFO: Test took 4020ms.
[14:47:32.753] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:33.436] INFO: Expecting 41600 events.
[14:47:36.738] INFO: 41600 events read in total (2775ms).
[14:47:36.739] INFO: Test took 3965ms.
[14:47:36.780] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:37.491] INFO: Expecting 41600 events.
[14:47:40.865] INFO: 41600 events read in total (2847ms).
[14:47:40.866] INFO: Test took 4066ms.
[14:47:40.908] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:41.612] INFO: Expecting 41600 events.
[14:47:44.946] INFO: 41600 events read in total (2807ms).
[14:47:44.947] INFO: Test took 4018ms.
[14:47:44.989] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:45.696] INFO: Expecting 41600 events.
[14:47:48.964] INFO: 41600 events read in total (2741ms).
[14:47:48.965] INFO: Test took 3956ms.
[14:47:49.011] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:49.707] INFO: Expecting 41600 events.
[14:47:53.046] INFO: 41600 events read in total (2813ms).
[14:47:53.047] INFO: Test took 4016ms.
[14:47:53.089] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:53.796] INFO: Expecting 41600 events.
[14:47:57.118] INFO: 41600 events read in total (2796ms).
[14:47:57.119] INFO: Test took 4010ms.
[14:47:57.163] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:47:57.870] INFO: Expecting 41600 events.
[14:48:01.159] INFO: 41600 events read in total (2762ms).
[14:48:01.160] INFO: Test took 3977ms.
[14:48:01.203] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:01.907] INFO: Expecting 41600 events.
[14:48:05.217] INFO: 41600 events read in total (2783ms).
[14:48:05.218] INFO: Test took 3994ms.
[14:48:05.260] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:05.970] INFO: Expecting 41600 events.
[14:48:09.279] INFO: 41600 events read in total (2782ms).
[14:48:09.280] INFO: Test took 3999ms.
[14:48:09.330] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:10.024] INFO: Expecting 41600 events.
[14:48:13.303] INFO: 41600 events read in total (2752ms).
[14:48:13.304] INFO: Test took 3954ms.
[14:48:13.346] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:14.052] INFO: Expecting 41600 events.
[14:48:17.294] INFO: 41600 events read in total (2715ms).
[14:48:17.295] INFO: Test took 3927ms.
[14:48:17.336] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:18.039] INFO: Expecting 41600 events.
[14:48:21.366] INFO: 41600 events read in total (2800ms).
[14:48:21.367] INFO: Test took 4010ms.
[14:48:21.410] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:22.111] INFO: Expecting 41600 events.
[14:48:25.439] INFO: 41600 events read in total (2801ms).
[14:48:25.440] INFO: Test took 4009ms.
[14:48:25.483] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:26.192] INFO: Expecting 41600 events.
[14:48:29.536] INFO: 41600 events read in total (2817ms).
[14:48:29.537] INFO: Test took 4033ms.
[14:48:29.579] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:30.273] INFO: Expecting 41600 events.
[14:48:33.574] INFO: 41600 events read in total (2774ms).
[14:48:33.575] INFO: Test took 3974ms.
[14:48:33.617] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:34.327] INFO: Expecting 41600 events.
[14:48:37.410] INFO: 41600 events read in total (2557ms).
[14:48:37.411] INFO: Test took 3773ms.
[14:48:37.454] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:48:37.804] INFO: enter test to run
[14:48:57.123] INFO: test: HighRate no parameter change
[14:48:57.123] INFO: running: highrate
[14:48:57.124] INFO: ----------------------------------------------------------------------
[14:48:57.124] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:48:57.124] INFO: ----------------------------------------------------------------------
[14:48:57.742] INFO: Expecting 208000 events.
[14:49:10.076] INFO: 208000 events read in total (11807ms).
[14:49:10.080] INFO: Test took 12946ms.
[14:49:10.263] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:49:10.527] INFO: number of dead pixels (per ROC): 0 1 0 1 0 0 0 0 0 0 0 0 0 0 1 0
[14:49:10.527] INFO: number of red-efficiency pixels: 97 67 97 200 186 196 199 106 102 137 132 127 102 72 27 61
[14:49:10.529] INFO: number of X-ray hits detected: 85389 58798 84840 139703 144386 152648 150520 103289 95062 117692 119247 105738 108590 62242 29972 30601
[14:49:10.529] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:49:10.529] INFO: number of Vcal hits detected: 207901 207883 207902 207743 207808 207796 207793 207892 207896 207861 207866 207867 207896 207928 207923 207939
[14:49:10.529] 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 99.9 100.0 100.0 100.0 100.0
[14:49:10.529] INFO: Vcal hit overall efficiency (%): 100.0 99.9 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0
[14:49:10.529] INFO: X-ray hit rate [MHz/cm2]: 25.0 17.2 24.9 40.9 42.3 44.7 44.1 30.3 27.9 34.5 35.0 31.0 31.8 18.2 8.8 9.0
[14:49:10.529] INFO: PixTestHighRate::doXPixelAlive() done
[14:49:10.582] INFO: PixTest:: pg_setup set to default.
[14:49:10.597] INFO: enter test to run
[14:49:53.146] INFO: test: HighRate no parameter change
[14:49:53.146] INFO: running: highrate
[14:49:53.147] INFO: ----------------------------------------------------------------------
[14:49:53.147] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:49:53.147] INFO: ----------------------------------------------------------------------
[14:49:53.759] INFO: Expecting 208000 events.
[14:50:08.617] INFO: 208000 events read in total (14331ms).
[14:50:08.623] INFO: Test took 15466ms.
[14:50:08.003] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:50:09.336] INFO: number of dead pixels (per ROC): 0 1 0 1 0 0 0 0 0 0 0 0 0 0 1 0
[14:50:09.336] INFO: number of red-efficiency pixels: 312 238 370 872 697 795 812 464 330 473 477 555 392 298 81 109
[14:50:09.337] INFO: number of X-ray hits detected: 185134 127944 183265 302852 315179 330298 326437 225256 207265 254375 256928 231102 237823 134450 65447 66002
[14:50:09.337] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:50:09.337] INFO: number of Vcal hits detected: 207656 207706 207576 206921 207190 207086 207051 207487 207648 207471 207482 207385 207571 207677 207867 207887
[14:50:09.337] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.6 99.6 99.6 99.6 99.8 99.8 99.8 99.8 99.7 99.8 99.9 100.0 100.0
[14:50:09.337] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.5 99.6 99.6 99.5 99.8 99.8 99.7 99.8 99.7 99.8 99.8 99.9 99.9
[14:50:09.337] INFO: X-ray hit rate [MHz/cm2]: 54.3 37.5 53.7 88.8 92.4 96.8 95.7 66.0 60.8 74.6 75.3 67.7 69.7 39.4 19.2 19.3
[14:50:09.337] INFO: PixTestHighRate::doXPixelAlive() done
[14:50:09.386] INFO: PixTest:: pg_setup set to default.
[14:50:09.401] INFO: enter test to run
[14:50:16.146] INFO: test: HighRate no parameter change
[14:50:16.146] INFO: running: highrate
[14:50:16.147] INFO: ----------------------------------------------------------------------
[14:50:16.147] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:50:16.147] INFO: ----------------------------------------------------------------------
[14:50:16.760] INFO: Expecting 208000 events.
[14:50:31.678] INFO: 208000 events read in total (14391ms).
[14:50:31.686] INFO: Test took 15533ms.
[14:50:32.080] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:50:32.414] INFO: number of dead pixels (per ROC): 0 1 0 1 0 0 0 0 0 0 0 0 0 0 1 0
[14:50:32.414] INFO: number of red-efficiency pixels: 329 231 383 850 705 765 806 444 301 469 456 512 384 264 75 123
[14:50:32.414] INFO: number of X-ray hits detected: 185993 127737 182828 303857 313317 330966 327142 224728 206056 255414 258494 230930 237230 134434 65271 66113
[14:50:32.414] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:50:32.414] INFO: number of Vcal hits detected: 207636 207706 207558 206946 207198 207120 207062 207503 207679 207491 207508 207428 207589 207708 207874 207869
[14:50:32.414] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.6 99.6 99.6 99.6 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 99.9
[14:50:32.414] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.5 99.6 99.6 99.5 99.8 99.8 99.8 99.8 99.7 99.8 99.9 99.9 99.9
[14:50:32.414] INFO: X-ray hit rate [MHz/cm2]: 54.5 37.4 53.6 89.1 91.8 97.0 95.9 65.9 60.4 74.9 75.8 67.7 69.5 39.4 19.1 19.4
[14:50:32.414] INFO: PixTestHighRate::doXPixelAlive() done
[14:50:32.465] INFO: PixTest:: pg_setup set to default.
[14:50:32.479] INFO: enter test to run
[14:50:57.290] INFO: test: HighRate no parameter change
[14:50:57.290] INFO: running: highrate
[14:50:57.291] INFO: ----------------------------------------------------------------------
[14:50:57.291] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:50:57.291] INFO: ----------------------------------------------------------------------
[14:50:57.906] INFO: Expecting 208000 events.
[14:51:15.605] INFO: 208000 events read in total (17172ms).
[14:51:15.614] INFO: Test took 18315ms.
[14:51:16.222] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:51:16.617] INFO: number of dead pixels (per ROC): 0 1 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[14:51:16.617] INFO: number of red-efficiency pixels: 631 530 828 2065 1701 1860 1850 1073 730 1201 1105 1195 877 618 128 179
[14:51:16.617] INFO: number of X-ray hits detected: 279004 193401 276337 457257 474007 498575 493511 338758 313637 385440 389635 347826 358805 203867 98527 100280
[14:51:16.617] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:51:16.617] INFO: number of Vcal hits detected: 207200 207320 206756 204628 205464 205097 205207 206480 207128 206498 206613 206405 206951 207204 207811 207816
[14:51:16.617] INFO: Vcal hit fiducial efficiency (%): 99.7 99.7 99.5 98.5 98.9 98.8 98.8 99.3 99.6 99.3 99.4 99.3 99.6 99.7 99.9 99.9
[14:51:16.617] INFO: Vcal hit overall efficiency (%): 99.6 99.7 99.4 98.4 98.8 98.6 98.7 99.3 99.6 99.3 99.3 99.2 99.5 99.6 99.9 99.9
[14:51:16.617] INFO: X-ray hit rate [MHz/cm2]: 81.8 56.7 81.0 134.0 138.9 146.1 144.7 99.3 91.9 113.0 114.2 102.0 105.2 59.8 28.9 29.4
[14:51:16.617] INFO: PixTestHighRate::doXPixelAlive() done
[14:51:16.664] INFO: PixTest:: pg_setup set to default.
[14:51:16.677] INFO: enter test to run
[14:51:19.729] INFO: test: exit no parameter change
[14:51:20.126] QUIET: Connection to board 32 closed.
[14:51:20.127] INFO: pXar: this is the end, my friend