[14:13:59.305] INFO: *** Welcome to pxar ***
[14:13:59.305] INFO: *** Today: 2016/09/21
[14:14:00.042] INFO: *** Version: v1.9.0-818-g96727
[14:14:00.042] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//dacParameters35_C15.dat
[14:14:00.064] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:14:00.064] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//defaultMaskFile.dat
[14:14:00.073] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C15.dat
[14:14:00.157] INFO: clk: 4
[14:14:00.157] INFO: ctr: 4
[14:14:00.157] INFO: sda: 19
[14:14:00.157] INFO: tin: 9
[14:14:00.157] INFO: level: 15
[14:14:00.157] INFO: triggerdelay: 0
[14:14:00.157] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[14:14:00.157] INFO: Log level: INFO
[14:14:00.176] QUIET: Connection to board DTB_WREKRL opened.
[14:14:00.179] 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:
------------------------------------------------------
[14:14:00.182] INFO: RPC call hashes of host and DTB match: 398089610
[14:14:01.718] INFO: DUT info:
[14:14:01.718] INFO: The DUT currently contains the following objects:
[14:14:01.718] INFO: 2 TBM Cores tbm08c (2 ON)
[14:14:01.718] INFO: TBM Core alpha (0): 7 registers set
[14:14:01.718] INFO: TBM Core beta (1): 7 registers set
[14:14:01.718] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[14:14:01.718] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.718] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.718] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:01.719] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[14:14:02.122] INFO: enter 'restricted' command line mode
[14:14:02.122] INFO: enter test to run
[14:14:06.609] INFO: test: PixelAlive no parameter change
[14:14:06.609] INFO: running: pixelalive
[14:14:06.618] INFO: ----------------------------------------------------------------------
[14:14:06.618] 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:14:06.618] INFO: ----------------------------------------------------------------------
[14:14:06.939] INFO: Expecting 41600 events.
[14:14:11.285] INFO: 41600 events read in total (3627ms).
[14:14:11.455] INFO: Test took 4833ms.
[14:14:11.465] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:14:11.790] INFO: PixTestAlive::aliveTest() done
[14:14:11.790] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 1 0 0 0
[14:14:11.826] INFO: enter test to run
[14:14:17.329] INFO: test: timing no parameter change
[14:14:17.329] INFO: running: timing
[14:14:17.332] INFO: ######################################################################
[14:14:17.332] INFO: PixTestTiming::doTest()
[14:14:17.332] INFO: ######################################################################
[14:14:17.332] INFO: ----------------------------------------------------------------------
[14:14:17.332] INFO: PixTestTiming::TBMPhaseScan()
[14:14:17.332] INFO: ----------------------------------------------------------------------
[14:27:09.261] INFO: TBM Phase Settings: 236
[14:27:09.261] INFO: 400MHz Phase: 3
[14:27:09.261] INFO: 160MHz Phase: 7
[14:27:09.261] INFO: Functional Phase Area: 5
[14:27:09.264] INFO: Test took 771932 ms.
[14:27:09.264] INFO: PixTestTiming::TBMPhaseScan() done.
[14:27:09.264] INFO: ----------------------------------------------------------------------
[14:27:09.264] INFO: PixTestTiming::ROCDelayScan()
[14:27:09.264] INFO: ----------------------------------------------------------------------
[14:31:49.896] INFO: ROC Delay Settings: 220
[14:31:49.896] INFO: ROC Header-Trailer/Token Delay: 11
[14:31:49.896] INFO: ROC Port 0 Delay: 4
[14:31:49.896] INFO: ROC Port 1 Delay: 3
[14:31:49.897] INFO: Functional ROC Area: 4
[14:31:49.900] INFO: Test took 280636 ms.
[14:31:49.900] INFO: PixTestTiming::ROCDelayScan() done.
[14:31:49.900] INFO: ----------------------------------------------------------------------
[14:31:49.900] INFO: PixTestTiming::TimingTest()
[14:31:49.900] INFO: ----------------------------------------------------------------------
[14:32:06.013] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:32:20.944] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:32:35.877] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:32:50.815] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:05.758] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:20.730] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:35.669] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:33:50.673] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:34:05.687] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:34:20.780] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:34:21.161] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:34:21.177] INFO: ----------------------------------------------------------------------
[14:34:21.177] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:34:21.177] INFO: ----------------------------------------------------------------------
[14:34:21.177] INFO: ----------------------------------------------------------------------
[14:34:21.177] INFO: Read back bit status: 1
[14:34:21.177] INFO: ----------------------------------------------------------------------
[14:34:21.177] INFO: ----------------------------------------------------------------------
[14:34:21.177] INFO: Timings are good!
[14:34:21.177] INFO: ----------------------------------------------------------------------
[14:34:21.177] INFO: Test took 151277 ms.
[14:34:21.177] INFO: PixTestTiming::TimingTest() done.
[14:34:21.178] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:34:21.178] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:34:21.178] INFO: PixTestTiming::doTest took 1203849 ms.
[14:34:21.178] INFO: PixTestTiming::doTest() done
[14:34:21.178] INFO: Write out TBMPhaseScan_0_V0
[14:34:21.178] INFO: Write out TBMPhaseScan_1_V0
[14:34:21.179] INFO: Write out CombinedTBMPhaseScan_V0
[14:34:21.180] INFO: Write out ROCDelayScan3_V0
[14:34:21.180] INFO: enter test to run
[14:34:58.960] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[14:34:58.960] INFO: running: highrate
[14:34:58.961] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:34:59.304] INFO: ----------------------------------------------------------------------
[14:34:59.304] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[14:34:59.304] INFO: ----------------------------------------------------------------------
[14:34:59.304] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[14:34:59.304] INFO: edge/corner pixel THR is adjusted
[14:34:59.304] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:35:00.261] INFO: Collecting data for 5 seconds...
[14:35:05.278] INFO: Done with hot pixel readout
[14:35:17.375] INFO: PixTest:: pg_setup set to default.


[14:35:17.376] INFO: 85 hot pixels found in step 0
[14:35:18.369] INFO: Collecting data for 5 seconds...
[14:35:23.387] INFO: Done with hot pixel readout
[14:35:35.568] INFO: PixTest:: pg_setup set to default.


[14:35:35.569] INFO: 85 hot pixels found in step 1
[14:35:36.564] INFO: Collecting data for 5 seconds...
[14:35:41.583] INFO: Done with hot pixel readout
[14:35:52.983] INFO: PixTest:: pg_setup set to default.

[14:35:52.984] INFO: 60 hot pixels found in step 2
[14:35:53.980] INFO: Collecting data for 5 seconds...
[14:35:58.998] INFO: Done with hot pixel readout
[14:36:10.682] INFO: PixTest:: pg_setup set to default.


[14:36:10.683] INFO: 82 hot pixels found in step 3
[14:36:11.678] INFO: Collecting data for 5 seconds...
[14:36:16.696] INFO: Done with hot pixel readout
[14:36:28.770] INFO: PixTest:: pg_setup set to default.
[14:36:28.771] INFO: 71 hot pixels found in step 4
[14:36:29.765] INFO: Collecting data for 5 seconds...
[14:36:34.783] INFO: Done with hot pixel readout
[14:36:47.137] INFO: PixTest:: pg_setup set to default.
[14:36:47.138] INFO: 60 hot pixels found in step 5
[14:36:48.132] INFO: Collecting data for 5 seconds...
[14:36:53.151] INFO: Done with hot pixel readout
[14:37:05.444] INFO: PixTest:: pg_setup set to default.
[14:37:05.445] INFO: 50 hot pixels found in step 6
[14:37:06.440] INFO: Collecting data for 5 seconds...
[14:37:11.458] INFO: Done with hot pixel readout
[14:37:23.782] INFO: PixTest:: pg_setup set to default.




[14:37:23.784] INFO: 43 hot pixels found in step 7
[14:37:24.778] INFO: Collecting data for 5 seconds...
[14:37:29.796] INFO: Done with hot pixel readout
[14:37:41.998] INFO: PixTest:: pg_setup set to default.





[14:37:41.999] INFO: 54 hot pixels found in step 8
[14:37:42.993] INFO: Collecting data for 5 seconds...
[14:37:48.013] INFO: Done with hot pixel readout
[14:38:00.241] INFO: PixTest:: pg_setup set to default.





[14:38:00.242] INFO: 39 hot pixels found in step 9
[14:38:01.236] INFO: Collecting data for 5 seconds...
[14:38:06.254] INFO: Done with hot pixel readout
[14:38:18.423] INFO: PixTest:: pg_setup set to default.




[14:38:18.424] INFO: 40 hot pixels found in step 10
[14:38:19.418] INFO: Collecting data for 5 seconds...
[14:38:24.439] INFO: Done with hot pixel readout
[14:38:36.706] INFO: PixTest:: pg_setup set to default.





[14:38:36.707] INFO: 40 hot pixels found in step 11
[14:38:37.702] INFO: Collecting data for 5 seconds...
[14:38:42.721] INFO: Done with hot pixel readout
[14:38:54.726] INFO: PixTest:: pg_setup set to default.






[14:38:54.727] INFO: 35 hot pixels found in step 12
[14:38:55.721] INFO: Collecting data for 5 seconds...
[14:39:00.738] INFO: Done with hot pixel readout
[14:39:12.747] INFO: PixTest:: pg_setup set to default.









[14:39:12.749] INFO: 41 hot pixels found in step 13
[14:39:13.742] INFO: Collecting data for 5 seconds...
[14:39:18.759] INFO: Done with hot pixel readout
[14:39:30.774] INFO: PixTest:: pg_setup set to default.





[14:39:30.775] INFO: 34 hot pixels found in step 14
[14:39:30.813] INFO: 34 hot pixels could not be trimmed and have been masked.
[14:39:30.816] INFO: PixTest::trimHotPixels() done
[14:39:30.816] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C0.dat
[14:39:30.823] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C1.dat
[14:39:30.829] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C2.dat
[14:39:30.834] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C3.dat
[14:39:30.840] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C4.dat
[14:39:30.845] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C5.dat
[14:39:30.850] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C6.dat
[14:39:30.856] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C7.dat
[14:39:30.861] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C8.dat
[14:39:30.866] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C9.dat
[14:39:30.871] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C10.dat
[14:39:30.877] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C11.dat
[14:39:30.882] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C12.dat
[14:39:30.887] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C13.dat
[14:39:30.892] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C14.dat
[14:39:30.898] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C15.dat
[14:39:30.903] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//defaultMaskFile.dat
[14:39:30.913] INFO: enter test to run
[14:40:40.454] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:40:40.454] INFO: running: highrate
[14:40:40.459] INFO: ----------------------------------------------------------------------
[14:40:40.459] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:40:40.459] INFO: ----------------------------------------------------------------------
[14:40:40.459] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:40:40.459] INFO: edge/corner pixel THR is adjusted
[14:40:40.459] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:40:41.417] INFO: Collecting data for 1 seconds...
[14:40:42.420] INFO: Done with hot pixel readout
[14:40:46.601] INFO: PixTest:: pg_setup set to default.
[14:40:46.601] INFO: 0 hot pixels found in step 0
[14:40:46.606] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:40:46.690] INFO: PixTest::trimHotPixels() done
[14:40:46.690] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C0.dat
[14:40:46.698] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C1.dat
[14:40:46.703] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C2.dat
[14:40:46.708] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C3.dat
[14:40:46.714] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C4.dat
[14:40:46.719] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C5.dat
[14:40:46.724] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C6.dat
[14:40:46.730] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C7.dat
[14:40:46.735] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C8.dat
[14:40:46.740] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C9.dat
[14:40:46.745] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C10.dat
[14:40:46.751] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C11.dat
[14:40:46.756] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C12.dat
[14:40:46.761] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C13.dat
[14:40:46.767] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C14.dat
[14:40:46.772] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//trimParameters35_C15.dat
[14:40:46.777] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-6-01_FPIXTest-17C-FNAL-160916-1208-150V_2016-09-16_12h08m_1474045711/000_FPIXTest_p17//defaultMaskFile.dat
[14:40:46.793] INFO: enter test to run
[14:41:09.966] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:41:09.966] INFO: running: xray
[14:41:09.981] INFO: ----------------------------------------------------------------------
[14:41:09.981] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:41:09.981] INFO: ----------------------------------------------------------------------
[14:41:10.969] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:41:22.184] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[14:41:51.720] INFO: Resuming triggers.
[14:42:03.041] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[14:42:32.479] INFO: Resuming triggers.
[14:42:43.696] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[14:43:13.283] INFO: Resuming triggers.
[14:43:24.507] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[14:43:53.988] INFO: Resuming triggers.
[14:44:05.209] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[14:44:34.773] INFO: Resuming triggers.
[14:44:45.991] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[14:45:15.436] INFO: Resuming triggers.
[14:45:26.658] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[14:45:56.239] INFO: Resuming triggers.
[14:46:07.464] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[14:46:36.797] INFO: Resuming triggers.
[14:46:47.365] INFO: data taking finished, elapsed time: 100 seconds.
[14:47:15.485] INFO: PixTest:: pg_setup set to default.
[14:47:15.488] INFO: PixTestXray::doPhRun() done
[14:47:15.706] INFO: enter test to run
[14:48:12.987] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:48:12.987] INFO: running: xray
[14:48:12.988] INFO: ----------------------------------------------------------------------
[14:48:12.988] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:48:12.988] INFO: ----------------------------------------------------------------------
[14:48:13.960] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:48:20.378] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[14:48:50.257] INFO: Resuming triggers.
[14:48:56.679] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[14:49:27.658] INFO: Resuming triggers.
[14:49:34.077] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[14:50:05.364] INFO: Resuming triggers.
[14:50:11.789] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[14:50:43.335] INFO: Resuming triggers.
[14:50:49.756] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[14:51:20.528] INFO: Resuming triggers.
[14:51:26.947] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[14:51:56.912] INFO: Resuming triggers.
[14:52:03.339] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[14:52:33.399] INFO: Resuming triggers.
[14:52:39.821] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[14:53:09.864] INFO: Resuming triggers.
[14:53:16.285] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[14:53:46.246] INFO: Resuming triggers.
[14:53:52.671] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[14:54:22.776] INFO: Resuming triggers.
[14:54:29.196] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[14:54:59.199] INFO: Resuming triggers.
[14:55:05.621] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[14:55:35.611] INFO: Resuming triggers.
[14:55:42.036] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[14:56:12.081] INFO: Resuming triggers.
[14:56:18.505] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[14:56:48.694] INFO: Resuming triggers.
[14:56:55.118] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[14:57:25.176] INFO: Resuming triggers.
[14:57:29.184] INFO: data taking finished, elapsed time: 100 seconds.
[14:57:48.152] INFO: PixTest:: pg_setup set to default.
[14:57:48.155] INFO: PixTestXray::doPhRun() done
[14:57:48.304] INFO: enter test to run
[14:59:10.239] INFO: test: HighRate no parameter change
[14:59:10.239] INFO: running: highrate
[14:59:10.256] INFO: ----------------------------------------------------------------------
[14:59:10.256] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[14:59:10.256] INFO: ----------------------------------------------------------------------
[14:59:10.410] INFO: Expecting 768 events.
[14:59:11.544] INFO: 768 events read in total (419ms).
[14:59:11.544] INFO: Test took 1268ms.
[14:59:12.348] INFO: Expecting 41600 events.
[14:59:15.481] INFO: 41600 events read in total (2606ms).
[14:59:15.482] INFO: Test took 3931ms.
[14:59:15.517] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:16.242] INFO: Expecting 41600 events.
[14:59:19.589] INFO: 41600 events read in total (2820ms).
[14:59:19.590] INFO: Test took 4055ms.
[14:59:19.627] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:20.337] INFO: Expecting 41600 events.
[14:59:23.716] INFO: 41600 events read in total (2852ms).
[14:59:23.718] INFO: Test took 4073ms.
[14:59:23.758] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:24.470] INFO: Expecting 41600 events.
[14:59:27.757] INFO: 41600 events read in total (2760ms).
[14:59:27.758] INFO: Test took 3982ms.
[14:59:27.795] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:28.512] INFO: Expecting 41600 events.
[14:59:31.824] INFO: 41600 events read in total (2785ms).
[14:59:31.825] INFO: Test took 4011ms.
[14:59:31.862] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:32.576] INFO: Expecting 41600 events.
[14:59:35.906] INFO: 41600 events read in total (2803ms).
[14:59:35.907] INFO: Test took 4026ms.
[14:59:35.943] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:36.659] INFO: Expecting 41600 events.
[14:59:39.973] INFO: 41600 events read in total (2787ms).
[14:59:39.974] INFO: Test took 4013ms.
[14:59:40.012] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:40.726] INFO: Expecting 41600 events.
[14:59:44.020] INFO: 41600 events read in total (2767ms).
[14:59:44.021] INFO: Test took 3990ms.
[14:59:44.059] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:44.775] INFO: Expecting 41600 events.
[14:59:48.019] INFO: 41600 events read in total (2717ms).
[14:59:48.020] INFO: Test took 3942ms.
[14:59:48.058] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:48.776] INFO: Expecting 41600 events.
[14:59:52.057] INFO: 41600 events read in total (2754ms).
[14:59:52.058] INFO: Test took 3982ms.
[14:59:52.096] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:52.810] INFO: Expecting 41600 events.
[14:59:56.091] INFO: 41600 events read in total (2754ms).
[14:59:56.092] INFO: Test took 3976ms.
[14:59:56.129] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:56.844] INFO: Expecting 41600 events.
[15:00:00.121] INFO: 41600 events read in total (2750ms).
[15:00:00.122] INFO: Test took 3975ms.
[15:00:00.160] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:00.875] INFO: Expecting 41600 events.
[15:00:04.310] INFO: 41600 events read in total (2908ms).
[15:00:04.311] INFO: Test took 4133ms.
[15:00:04.348] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:05.064] INFO: Expecting 41600 events.
[15:00:08.379] INFO: 41600 events read in total (2788ms).
[15:00:08.380] INFO: Test took 4011ms.
[15:00:08.416] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:09.135] INFO: Expecting 41600 events.
[15:00:12.430] INFO: 41600 events read in total (2768ms).
[15:00:12.431] INFO: Test took 3996ms.
[15:00:12.470] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:13.183] INFO: Expecting 41600 events.
[15:00:16.476] INFO: 41600 events read in total (2767ms).
[15:00:16.477] INFO: Test took 3985ms.
[15:00:16.515] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:17.228] INFO: Expecting 41600 events.
[15:00:20.461] INFO: 41600 events read in total (2706ms).
[15:00:20.462] INFO: Test took 3928ms.
[15:00:20.499] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:21.214] INFO: Expecting 41600 events.
[15:00:24.589] INFO: 41600 events read in total (2848ms).
[15:00:24.590] INFO: Test took 4072ms.
[15:00:24.627] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:25.341] INFO: Expecting 41600 events.
[15:00:28.602] INFO: 41600 events read in total (2734ms).
[15:00:28.603] INFO: Test took 3958ms.
[15:00:28.640] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:29.360] INFO: Expecting 41600 events.
[15:00:32.483] INFO: 41600 events read in total (2596ms).
[15:00:32.484] INFO: Test took 3824ms.
[15:00:32.521] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:32.872] INFO: enter test to run
[15:01:43.317] INFO: test: HighRate no parameter change
[15:01:43.317] INFO: running: highrate
[15:01:43.319] INFO: ----------------------------------------------------------------------
[15:01:43.319] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:01:43.319] INFO: ----------------------------------------------------------------------
[15:01:43.935] INFO: Expecting 208000 events.
[15:01:55.983] INFO: 208000 events read in total (11522ms).
[15:01:55.986] INFO: Test took 12659ms.
[15:01:56.148] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:56.406] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[15:01:56.406] INFO: number of red-efficiency pixels: 110 58 97 134 188 186 145 130 81 121 157 95 112 87 25 31
[15:01:56.406] INFO: number of X-ray hits detected: 79079 51758 70611 109335 122767 128268 130742 92735 81533 102829 105688 86241 92892 53863 22162 24793
[15:01:56.406] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:01:56.406] INFO: number of Vcal hits detected: 207889 207942 207903 207861 207809 207807 207849 207868 207919 207876 207790 207904 207888 207913 207975 207969
[15:01:56.406] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[15:01:56.406] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[15:01:56.406] INFO: X-ray hit rate [MHz/cm2]: 23.2 15.2 20.7 32.0 36.0 37.6 38.3 27.2 23.9 30.1 31.0 25.3 27.2 15.8 6.5 7.3
[15:01:56.406] INFO: PixTestHighRate::doXPixelAlive() done
[15:01:56.451] INFO: PixTest:: pg_setup set to default.
[15:01:56.465] INFO: enter test to run
[15:02:18.501] INFO: test: HighRate no parameter change
[15:02:18.502] INFO: running: highrate
[15:02:18.503] INFO: ----------------------------------------------------------------------
[15:02:18.503] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:02:18.503] INFO: ----------------------------------------------------------------------
[15:02:19.118] INFO: Expecting 208000 events.
[15:02:33.490] INFO: 208000 events read in total (13845ms).
[15:02:33.495] INFO: Test took 14983ms.
[15:02:33.818] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:02:34.168] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[15:02:34.168] INFO: number of red-efficiency pixels: 273 196 364 482 630 682 532 333 236 456 497 343 371 199 49 64
[15:02:34.168] INFO: number of X-ray hits detected: 161671 105992 144789 224036 250776 262280 266436 191026 166602 209471 215533 178319 190490 111169 45374 51349
[15:02:34.168] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:02:34.168] INFO: number of Vcal hits detected: 207711 207792 207585 207475 207307 207214 207414 207629 207751 207505 207409 207630 207612 207783 207949 207936
[15:02:34.168] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.7 99.7 99.7 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[15:02:34.169] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.6 99.7 99.8 99.9 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[15:02:34.169] INFO: X-ray hit rate [MHz/cm2]: 47.4 31.1 42.4 65.7 73.5 76.9 78.1 56.0 48.8 61.4 63.2 52.3 55.8 32.6 13.3 15.1
[15:02:34.169] INFO: PixTestHighRate::doXPixelAlive() done
[15:02:34.215] INFO: PixTest:: pg_setup set to default.
[15:02:34.230] INFO: enter test to run
[15:02:49.981] INFO: test: HighRate no parameter change
[15:02:49.981] INFO: running: highrate
[15:02:49.983] INFO: ----------------------------------------------------------------------
[15:02:49.983] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:02:49.983] INFO: ----------------------------------------------------------------------
[15:02:50.605] INFO: Expecting 208000 events.
[15:03:06.986] INFO: 208000 events read in total (15854ms).
[15:03:06.994] INFO: Test took 17001ms.
[15:03:07.497] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:07.862] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[15:03:07.863] INFO: number of red-efficiency pixels: 557 408 766 1080 1505 1582 1287 751 584 1066 1134 752 858 502 84 102
[15:03:07.863] INFO: number of X-ray hits detected: 241707 158990 217593 335573 375521 392178 401781 285757 251311 316222 323676 267915 286107 167781 68419 77428
[15:03:07.863] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:03:07.863] INFO: number of Vcal hits detected: 207276 207528 206937 206657 205927 205714 206268 207027 207326 206709 206529 207128 206957 207374 207913 207896
[15:03:07.863] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.5 99.4 99.1 99.0 99.3 99.6 99.7 99.4 99.4 99.6 99.5 99.7 100.0 100.0
[15:03:07.863] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.5 99.4 99.0 98.9 99.2 99.5 99.7 99.4 99.3 99.6 99.5 99.7 100.0 100.0
[15:03:07.863] INFO: X-ray hit rate [MHz/cm2]: 70.8 46.6 63.8 98.4 110.1 115.0 117.8 83.8 73.7 92.7 94.9 78.5 83.9 49.2 20.1 22.7
[15:03:07.863] INFO: PixTestHighRate::doXPixelAlive() done
[15:03:07.909] INFO: PixTest:: pg_setup set to default.
[15:03:07.919] INFO: enter test to run
[15:03:14.509] INFO: test: exit no parameter change
[15:03:14.944] QUIET: Connection to board 33 closed.
[15:03:14.959] INFO: pXar: this is the end, my friend