[11:54:26.154] INFO: *** Welcome to pxar ***
[11:54:26.154] INFO: *** Today: 2016/04/29
[11:54:26.173] INFO: *** Version: v1.9.0-796-gef167-dirty
[11:54:26.173] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//dacParameters35_C15.dat
[11:54:26.174] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:54:26.174] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//defaultMaskFile.dat
[11:54:26.174] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C15.dat
[11:54:26.249] INFO: clk: 4
[11:54:26.249] INFO: ctr: 4
[11:54:26.249] INFO: sda: 19
[11:54:26.249] INFO: tin: 9
[11:54:26.249] INFO: level: 15
[11:54:26.249] INFO: triggerdelay: 0
[11:54:26.249] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[11:54:26.249] INFO: Log level: INFO
[11:54:26.267] QUIET: Connection to board DTB_WREKRL opened.
[11:54:26.270] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[11:54:26.273] INFO: RPC call hashes of host and DTB match: 398089610
[11:54:27.799] INFO: DUT info:
[11:54:27.799] INFO: The DUT currently contains the following objects:
[11:54:27.799] INFO: 2 TBM Cores tbm08c (2 ON)
[11:54:27.799] INFO: TBM Core alpha (0): 7 registers set
[11:54:27.799] INFO: TBM Core beta (1): 7 registers set
[11:54:27.799] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:54:27.799] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:27.799] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:54:28.202] INFO: enter 'restricted' command line mode
[11:54:28.202] INFO: enter test to run
[11:54:31.011] INFO: test: timing no parameter change
[11:54:31.011] INFO: running: timing
[11:54:31.020] INFO: ######################################################################
[11:54:31.020] INFO: PixTestTiming::doTest()
[11:54:31.020] INFO: ######################################################################
[11:54:31.020] INFO: ----------------------------------------------------------------------
[11:54:31.020] INFO: PixTestTiming::TBMPhaseScan()
[11:54:31.020] INFO: ----------------------------------------------------------------------
[11:58:48.604] INFO: TBM Phase Settings: 196
[11:58:48.604] INFO: 400MHz Phase: 1
[11:58:48.604] INFO: 160MHz Phase: 6
[11:58:48.604] INFO: Functional Phase Area: 4
[11:58:48.608] INFO: Test took 257588 ms.
[11:58:48.608] INFO: PixTestTiming::TBMPhaseScan() done.
[11:58:48.608] INFO: ----------------------------------------------------------------------
[11:58:48.608] INFO: PixTestTiming::ROCDelayScan()
[11:58:48.608] INFO: ----------------------------------------------------------------------
[12:00:53.144] INFO: ROC Delay Settings: 220
[12:00:53.144] INFO: ROC Header-Trailer/Token Delay: 11
[12:00:53.144] INFO: ROC Port 0 Delay: 4
[12:00:53.144] INFO: ROC Port 1 Delay: 3
[12:00:53.144] INFO: Functional ROC Area: 5
[12:00:53.147] INFO: Test took 124539 ms.
[12:00:53.147] INFO: PixTestTiming::ROCDelayScan() done.
[12:00:53.147] INFO: ----------------------------------------------------------------------
[12:00:53.147] INFO: PixTestTiming::TimingTest()
[12:00:53.147] INFO: ----------------------------------------------------------------------
[12:01:09.302] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:24.265] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:39.218] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:54.178] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:09.133] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:24.096] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:39.068] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:54.022] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:08.999] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:23.965] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:24.348] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:24.364] INFO: ----------------------------------------------------------------------
[12:03:24.364] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:03:24.364] INFO: ----------------------------------------------------------------------
[12:03:24.364] INFO: ----------------------------------------------------------------------
[12:03:24.364] INFO: Read back bit status: 1
[12:03:24.364] INFO: ----------------------------------------------------------------------
[12:03:24.364] INFO: ----------------------------------------------------------------------
[12:03:24.364] INFO: Timings are good!
[12:03:24.365] INFO: ----------------------------------------------------------------------
[12:03:24.365] INFO: Test took 151218 ms.
[12:03:24.365] INFO: PixTestTiming::TimingTest() done.
[12:03:24.365] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:03:24.365] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:03:24.365] INFO: PixTestTiming::doTest took 533350 ms.
[12:03:24.365] INFO: PixTestTiming::doTest() done
[12:03:24.365] INFO: Write out TBMPhaseScan_0_V0
[12:03:24.392] INFO: Write out TBMPhaseScan_1_V0
[12:03:24.392] INFO: Write out CombinedTBMPhaseScan_V0
[12:03:24.393] INFO: Write out ROCDelayScan3_V0
[12:03:24.393] INFO: enter test to run
[12:03:49.135] INFO: test: PixelAlive no parameter change
[12:03:49.135] INFO: running: pixelalive
[12:03:49.139] INFO: ----------------------------------------------------------------------
[12:03:49.139] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[12:03:49.139] INFO: ----------------------------------------------------------------------
[12:03:49.454] INFO: Expecting 41600 events.
[12:03:53.776] INFO: 41600 events read in total (3607ms).
[12:03:53.777] INFO: Test took 4636ms.
[12:03:53.784] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:03:54.178] INFO: PixTestAlive::aliveTest() done
[12:03:54.178] INFO: number of dead pixels (per ROC): 0 0 1 0 0 0 0 0 0 0 0 0 1 0 0 0
[12:03:54.182] INFO: enter test to run
[12:04:13.175] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:04:13.175] INFO: running: highrate
[12:04:13.175] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:04:13.325] INFO: ----------------------------------------------------------------------
[12:04:13.325] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:04:13.325] INFO: ----------------------------------------------------------------------
[12:04:13.325] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:04:13.325] INFO: edge/corner pixel THR is adjusted
[12:04:13.325] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:04:14.283] INFO: Collecting data for 5 seconds...
[12:04:19.298] INFO: Done with hot pixel readout
[12:04:31.294] INFO: PixTest:: pg_setup set to default.
[12:04:31.295] INFO: 14 hot pixels found in step 0
[12:04:32.288] INFO: Collecting data for 5 seconds...
[12:04:37.305] INFO: Done with hot pixel readout
[12:04:49.262] INFO: PixTest:: pg_setup set to default.
[12:04:49.263] INFO: 15 hot pixels found in step 1
[12:04:50.257] INFO: Collecting data for 5 seconds...
[12:04:55.273] INFO: Done with hot pixel readout
[12:05:07.250] INFO: PixTest:: pg_setup set to default.
[12:05:07.250] INFO: 15 hot pixels found in step 2
[12:05:08.245] INFO: Collecting data for 5 seconds...
[12:05:13.260] INFO: Done with hot pixel readout
[12:05:25.248] INFO: PixTest:: pg_setup set to default.
[12:05:25.249] INFO: 14 hot pixels found in step 3
[12:05:26.245] INFO: Collecting data for 5 seconds...
[12:05:31.261] INFO: Done with hot pixel readout
[12:05:43.285] INFO: PixTest:: pg_setup set to default.
[12:05:43.286] INFO: 13 hot pixels found in step 4
[12:05:44.280] INFO: Collecting data for 5 seconds...
[12:05:49.296] INFO: Done with hot pixel readout
[12:06:01.297] INFO: PixTest:: pg_setup set to default.
[12:06:01.298] INFO: 11 hot pixels found in step 5
[12:06:02.292] INFO: Collecting data for 5 seconds...
[12:06:07.308] INFO: Done with hot pixel readout
[12:06:19.310] INFO: PixTest:: pg_setup set to default.
[12:06:19.311] INFO: 7 hot pixels found in step 6
[12:06:20.306] INFO: Collecting data for 5 seconds...
[12:06:25.323] INFO: Done with hot pixel readout
[12:06:35.148] INFO: PixTest:: pg_setup set to default.


[12:06:35.149] INFO: 11 hot pixels found in step 7
[12:06:36.144] INFO: Collecting data for 5 seconds...
[12:06:41.159] INFO: Done with hot pixel readout
[12:06:51.496] INFO: PixTest:: pg_setup set to default.


[12:06:51.497] INFO: 9 hot pixels found in step 8
[12:06:52.492] INFO: Collecting data for 5 seconds...
[12:06:57.508] INFO: Done with hot pixel readout
[12:07:07.745] INFO: PixTest:: pg_setup set to default.



[12:07:07.746] INFO: 7 hot pixels found in step 9
[12:07:08.741] INFO: Collecting data for 5 seconds...
[12:07:13.756] INFO: Done with hot pixel readout
[12:07:25.702] INFO: PixTest:: pg_setup set to default.




[12:07:25.703] INFO: 10 hot pixels found in step 10
[12:07:26.697] INFO: Collecting data for 5 seconds...
[12:07:31.713] INFO: Done with hot pixel readout
[12:07:43.596] INFO: PixTest:: pg_setup set to default.


[12:07:43.597] INFO: 4 hot pixels found in step 11
[12:07:44.590] INFO: Collecting data for 5 seconds...
[12:07:49.606] INFO: Done with hot pixel readout
[12:08:01.538] INFO: PixTest:: pg_setup set to default.




[12:08:01.539] INFO: 7 hot pixels found in step 12
[12:08:02.533] INFO: Collecting data for 5 seconds...
[12:08:07.552] INFO: Done with hot pixel readout
[12:08:18.433] INFO: PixTest:: pg_setup set to default.




[12:08:18.434] INFO: 6 hot pixels found in step 13
[12:08:19.433] INFO: Collecting data for 5 seconds...
[12:08:24.449] INFO: Done with hot pixel readout
[12:08:35.819] INFO: PixTest:: pg_setup set to default.





[12:08:35.820] INFO: 6 hot pixels found in step 14
[12:08:35.857] INFO: 6 hot pixels could not be trimmed and have been masked.
[12:08:35.860] INFO: PixTest::trimHotPixels() done
[12:08:35.860] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C0.dat
[12:08:35.867] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C1.dat
[12:08:35.873] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C2.dat
[12:08:35.879] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C3.dat
[12:08:35.884] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C4.dat
[12:08:35.890] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C5.dat
[12:08:35.895] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C6.dat
[12:08:35.900] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C7.dat
[12:08:35.905] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C8.dat
[12:08:35.911] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C9.dat
[12:08:35.917] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C10.dat
[12:08:35.922] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C11.dat
[12:08:35.927] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C12.dat
[12:08:35.932] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C13.dat
[12:08:35.938] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C14.dat
[12:08:35.995] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C15.dat
[12:08:35.001] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//defaultMaskFile.dat
[12:08:36.012] INFO: enter test to run
[12:09:03.757] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:09:03.757] INFO: running: highrate
[12:09:03.761] INFO: ----------------------------------------------------------------------
[12:09:03.761] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:09:03.761] INFO: ----------------------------------------------------------------------
[12:09:03.761] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:09:03.761] INFO: edge/corner pixel THR is adjusted
[12:09:03.761] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:09:04.719] INFO: Collecting data for 1 seconds...
[12:09:05.723] INFO: Done with hot pixel readout
[12:09:09.668] INFO: PixTest:: pg_setup set to default.
[12:09:09.669] INFO: 0 hot pixels found in step 0
[12:09:09.674] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:09:09.759] INFO: PixTest::trimHotPixels() done
[12:09:09.759] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C0.dat
[12:09:09.771] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C1.dat
[12:09:09.778] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C2.dat
[12:09:09.783] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C3.dat
[12:09:09.788] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C4.dat
[12:09:09.794] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C5.dat
[12:09:09.799] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C6.dat
[12:09:09.804] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C7.dat
[12:09:09.809] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C8.dat
[12:09:09.814] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C9.dat
[12:09:09.820] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C10.dat
[12:09:09.825] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C11.dat
[12:09:09.830] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C12.dat
[12:09:09.851] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C13.dat
[12:09:09.857] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C14.dat
[12:09:09.862] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//trimParameters35_C15.dat
[12:09:09.867] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-1-14_FPIXTest-17C-FNAL-160425-1233_2016-04-25_12h33m_1461605635/000_FPIXTest_p17//defaultMaskFile.dat
[12:09:09.883] INFO: enter test to run
[12:09:29.844] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:09:29.844] INFO: running: xray
[12:09:29.846] INFO: ----------------------------------------------------------------------
[12:09:29.846] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:09:29.846] INFO: ----------------------------------------------------------------------
[12:09:30.809] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:09:41.990] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:10:11.316] INFO: Resuming triggers.
[12:10:22.504] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[12:10:51.940] INFO: Resuming triggers.
[12:11:03.124] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[12:11:32.437] INFO: Resuming triggers.
[12:11:43.619] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[12:12:13.047] INFO: Resuming triggers.
[12:12:24.231] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[12:12:53.728] INFO: Resuming triggers.
[12:13:04.909] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[12:13:34.237] INFO: Resuming triggers.
[12:13:45.417] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[12:14:14.807] INFO: Resuming triggers.
[12:14:25.988] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[12:14:55.346] INFO: Resuming triggers.
[12:15:06.197] INFO: data taking finished, elapsed time: 100 seconds.
[12:15:34.864] INFO: PixTest:: pg_setup set to default.
[12:15:34.867] INFO: PixTestXray::doPhRun() done
[12:15:35.004] INFO: enter test to run
[12:16:09.721] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:16:09.721] INFO: running: xray
[12:16:09.722] INFO: ----------------------------------------------------------------------
[12:16:09.722] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:16:09.722] INFO: ----------------------------------------------------------------------
[12:16:10.694] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:16:17.079] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:16:45.265] INFO: Resuming triggers.
[12:16:51.648] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[12:17:18.668] INFO: Resuming triggers.
[12:17:25.054] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[12:17:55.181] INFO: Resuming triggers.
[12:18:01.567] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[12:18:31.720] INFO: Resuming triggers.
[12:18:38.106] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[12:19:08.194] INFO: Resuming triggers.
[12:19:14.582] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[12:19:44.588] INFO: Resuming triggers.
[12:19:50.977] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[12:20:21.077] INFO: Resuming triggers.
[12:20:27.466] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[12:20:57.434] INFO: Resuming triggers.
[12:21:03.821] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[12:21:33.941] INFO: Resuming triggers.
[12:21:40.327] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[12:22:10.447] INFO: Resuming triggers.
[12:22:16.832] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[12:22:46.949] INFO: Resuming triggers.
[12:22:53.337] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[12:23:23.318] INFO: Resuming triggers.
[12:23:29.702] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[12:23:59.799] INFO: Resuming triggers.
[12:24:06.180] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[12:24:36.274] INFO: Resuming triggers.
[12:24:42.659] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[12:25:12.777] INFO: Resuming triggers.
[12:25:17.300] INFO: data taking finished, elapsed time: 100 seconds.
[12:25:38.856] INFO: PixTest:: pg_setup set to default.
[12:25:38.859] INFO: PixTestXray::doPhRun() done
[12:25:39.007] INFO: enter test to run
[12:26:12.493] INFO: test: HighRate no parameter change
[12:26:12.493] INFO: running: highrate
[12:26:12.494] INFO: ----------------------------------------------------------------------
[12:26:12.494] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:26:12.494] INFO: ----------------------------------------------------------------------
[12:26:12.636] INFO: Expecting 768 events.
[12:26:13.769] INFO: 768 events read in total (418ms).
[12:26:13.769] INFO: Test took 1268ms.
[12:26:14.573] INFO: Expecting 41600 events.
[12:26:17.704] INFO: 41600 events read in total (2604ms).
[12:26:17.705] INFO: Test took 3930ms.
[12:26:17.741] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:18.467] INFO: Expecting 41600 events.
[12:26:21.698] INFO: 41600 events read in total (2704ms).
[12:26:21.699] INFO: Test took 3941ms.
[12:26:21.735] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:22.453] INFO: Expecting 41600 events.
[12:26:25.696] INFO: 41600 events read in total (2716ms).
[12:26:25.697] INFO: Test took 3943ms.
[12:26:25.733] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:26.452] INFO: Expecting 41600 events.
[12:26:29.718] INFO: 41600 events read in total (2739ms).
[12:26:29.719] INFO: Test took 3967ms.
[12:26:29.756] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:30.477] INFO: Expecting 41600 events.
[12:26:33.736] INFO: 41600 events read in total (2732ms).
[12:26:33.737] INFO: Test took 3962ms.
[12:26:33.772] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:34.492] INFO: Expecting 41600 events.
[12:26:37.733] INFO: 41600 events read in total (2714ms).
[12:26:37.734] INFO: Test took 3943ms.
[12:26:37.770] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:38.491] INFO: Expecting 41600 events.
[12:26:41.327] INFO: 41600 events read in total (2309ms).
[12:26:41.328] INFO: Test took 3539ms.
[12:26:41.364] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:42.087] INFO: Expecting 41600 events.
[12:26:44.928] INFO: 41600 events read in total (2314ms).
[12:26:44.929] INFO: Test took 3547ms.
[12:26:44.966] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:45.690] INFO: Expecting 41600 events.
[12:26:48.929] INFO: 41600 events read in total (2712ms).
[12:26:48.930] INFO: Test took 3945ms.
[12:26:48.966] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:49.688] INFO: Expecting 41600 events.
[12:26:52.937] INFO: 41600 events read in total (2722ms).
[12:26:52.938] INFO: Test took 3952ms.
[12:26:52.974] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:53.694] INFO: Expecting 41600 events.
[12:26:56.819] INFO: 41600 events read in total (2598ms).
[12:26:56.820] INFO: Test took 3827ms.
[12:26:56.857] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:57.579] INFO: Expecting 41600 events.
[12:27:00.426] INFO: 41600 events read in total (2320ms).
[12:27:00.427] INFO: Test took 3552ms.
[12:27:00.464] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:01.188] INFO: Expecting 41600 events.
[12:27:04.459] INFO: 41600 events read in total (2745ms).
[12:27:04.460] INFO: Test took 3978ms.
[12:27:04.495] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:05.217] INFO: Expecting 41600 events.
[12:27:08.352] INFO: 41600 events read in total (2609ms).
[12:27:08.353] INFO: Test took 3840ms.
[12:27:08.390] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:09.113] INFO: Expecting 41600 events.
[12:27:11.938] INFO: 41600 events read in total (2298ms).
[12:27:11.939] INFO: Test took 3531ms.
[12:27:11.976] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:12.699] INFO: Expecting 41600 events.
[12:27:15.943] INFO: 41600 events read in total (2717ms).
[12:27:15.943] INFO: Test took 3948ms.
[12:27:15.979] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:16.701] INFO: Expecting 41600 events.
[12:27:19.963] INFO: 41600 events read in total (2735ms).
[12:27:19.964] INFO: Test took 3965ms.
[12:27:19.999] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:20.721] INFO: Expecting 41600 events.
[12:27:23.992] INFO: 41600 events read in total (2744ms).
[12:27:23.993] INFO: Test took 3976ms.
[12:27:24.029] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:24.748] INFO: Expecting 41600 events.
[12:27:27.953] INFO: 41600 events read in total (2678ms).
[12:27:27.954] INFO: Test took 3906ms.
[12:27:27.989] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:28.711] INFO: Expecting 41600 events.
[12:27:31.753] INFO: 41600 events read in total (2515ms).
[12:27:31.754] INFO: Test took 3747ms.
[12:27:31.788] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:32.150] INFO: enter test to run
[12:27:43.292] INFO: test: HighRate no parameter change
[12:27:43.292] INFO: running: highrate
[12:27:43.294] INFO: ----------------------------------------------------------------------
[12:27:43.294] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:27:43.294] INFO: ----------------------------------------------------------------------
[12:27:43.909] INFO: Expecting 208000 events.
[12:27:55.840] INFO: 208000 events read in total (11404ms).
[12:27:55.844] INFO: Test took 12540ms.
[12:27:55.998] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:56.252] INFO: number of dead pixels (per ROC): 0 0 1 0 0 0 0 0 0 0 0 0 1 0 0 0
[12:27:56.253] INFO: number of red-efficiency pixels: 70 64 72 110 112 149 159 106 106 159 121 154 128 83 28 27
[12:27:56.253] INFO: number of X-ray hits detected: 70090 44621 66079 104740 109383 111573 115935 84994 87443 118442 113930 98915 99520 59129 22842 26765
[12:27:56.253] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:27:56.253] INFO: number of Vcal hits detected: 207926 207935 207879 207890 207887 207849 207839 207891 207891 207836 207878 207839 207820 207912 207972 207973
[12:27:56.253] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[12:27:56.253] INFO: Vcal hit overall 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
[12:27:56.253] INFO: X-ray hit rate [MHz/cm2]: 20.5 13.1 19.4 30.7 32.1 32.7 34.0 24.9 25.6 34.7 33.4 29.0 29.2 17.3 6.7 7.8
[12:27:56.253] INFO: PixTestHighRate::doXPixelAlive() done
[12:27:56.304] INFO: PixTest:: pg_setup set to default.
[12:27:56.321] INFO: enter test to run
[12:28:15.148] INFO: test: HighRate no parameter change
[12:28:15.148] INFO: running: highrate
[12:28:15.149] INFO: ----------------------------------------------------------------------
[12:28:15.149] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:28:15.149] INFO: ----------------------------------------------------------------------
[12:28:15.767] INFO: Expecting 208000 events.
[12:28:29.566] INFO: 208000 events read in total (13272ms).
[12:28:29.571] INFO: Test took 14413ms.
[12:28:29.877] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:30.181] INFO: number of dead pixels (per ROC): 0 0 1 0 0 0 0 0 0 0 0 0 1 0 0 0
[12:28:30.181] INFO: number of red-efficiency pixels: 224 139 281 322 391 393 574 379 258 459 425 443 458 271 60 77
[12:28:30.181] INFO: number of X-ray hits detected: 143536 92435 136249 215676 224025 227594 236597 175146 179645 241903 233517 202962 204804 121876 47241 55100
[12:28:30.181] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:28:30.181] INFO: number of Vcal hits detected: 207758 207850 207640 207659 207584 207584 207368 207584 207725 207497 207545 207507 207458 207708 207940 207921
[12:28:30.181] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.7 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[12:28:30.181] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.8 99.7 99.8 99.9 99.8 99.8 99.8 99.7 99.9 100.0 100.0
[12:28:30.181] INFO: X-ray hit rate [MHz/cm2]: 42.1 27.1 39.9 63.2 65.7 66.7 69.3 51.3 52.7 70.9 68.4 59.5 60.0 35.7 13.8 16.2
[12:28:30.181] INFO: PixTestHighRate::doXPixelAlive() done
[12:28:30.226] INFO: PixTest:: pg_setup set to default.
[12:28:30.245] INFO: enter test to run
[12:28:45.812] INFO: test: HighRate no parameter change
[12:28:45.812] INFO: running: highrate
[12:28:45.813] INFO: ----------------------------------------------------------------------
[12:28:45.813] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:28:45.813] INFO: ----------------------------------------------------------------------
[12:28:46.429] INFO: Expecting 208000 events.
[12:29:02.334] INFO: 208000 events read in total (15378ms).
[12:29:02.342] INFO: Test took 16520ms.
[12:29:02.841] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:03.201] INFO: number of dead pixels (per ROC): 0 0 1 0 0 0 0 0 0 0 0 0 1 0 0 0
[12:29:03.201] INFO: number of red-efficiency pixels: 449 266 611 791 924 930 1265 818 536 1024 890 1033 978 549 116 114
[12:29:03.201] INFO: number of X-ray hits detected: 218510 140117 207116 326188 338538 345957 360771 265755 272773 368014 355753 307921 311891 185726 72123 83095
[12:29:03.201] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:29:03.201] INFO: number of Vcal hits detected: 207489 207714 207184 207094 206917 206879 206376 207010 207380 206747 206950 206720 206782 207311 207877 207882
[12:29:03.201] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.6 99.5 99.5 99.3 99.6 99.7 99.5 99.5 99.4 99.5 99.7 99.9 99.9
[12:29:03.201] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.6 99.6 99.5 99.5 99.2 99.5 99.7 99.4 99.5 99.4 99.4 99.7 99.9 99.9
[12:29:03.201] INFO: X-ray hit rate [MHz/cm2]: 64.0 41.1 60.7 95.6 99.2 101.4 105.7 77.9 80.0 107.9 104.3 90.3 91.4 54.4 21.1 24.4
[12:29:03.201] INFO: PixTestHighRate::doXPixelAlive() done
[12:29:03.251] INFO: PixTest:: pg_setup set to default.
[12:29:03.264] INFO: enter test to run
[12:29:07.003] INFO: test: exit no parameter change
[12:29:07.417] QUIET: Connection to board 33 closed.
[12:29:07.418] INFO: pXar: this is the end, my friend