[15:03:02.650] INFO: *** Welcome to pxar ***
[15:03:02.650] INFO: *** Today: 2016/10/13
[15:03:03.906] INFO: *** Version: v1.9.0-818-g96727
[15:03:03.906] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//dacParameters35_C15.dat
[15:03:03.977] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:03:03.977] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//defaultMaskFile.dat
[15:03:03.978] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C15.dat
[15:03:04.106] INFO: clk: 4
[15:03:04.106] INFO: ctr: 4
[15:03:04.106] INFO: sda: 19
[15:03:04.106] INFO: tin: 9
[15:03:04.106] INFO: level: 15
[15:03:04.106] INFO: triggerdelay: 0
[15:03:04.106] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:03:04.106] INFO: Log level: INFO
[15:03:04.124] QUIET: Connection to board DTB_WREKRL opened.
[15:03:04.127] 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:
------------------------------------------------------
[15:03:04.130] INFO: RPC call hashes of host and DTB match: 398089610
[15:03:05.670] INFO: DUT info:
[15:03:05.670] INFO: The DUT currently contains the following objects:
[15:03:05.670] INFO: 2 TBM Cores tbm08c (2 ON)
[15:03:05.670] INFO: TBM Core alpha (0): 7 registers set
[15:03:05.670] INFO: TBM Core beta (1): 7 registers set
[15:03:05.670] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:03:05.670] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:05.670] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:06.102] INFO: enter 'restricted' command line mode
[15:03:06.102] INFO: enter test to run
[15:03:12.607] INFO: test: PixelAlive no parameter change
[15:03:12.607] INFO: running: pixelalive
[15:03:12.672] INFO: ----------------------------------------------------------------------
[15:03:12.672] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[15:03:12.672] INFO: ----------------------------------------------------------------------
[15:03:12.991] INFO: Expecting 41600 events.
[15:03:17.321] INFO: 41600 events read in total (3611ms).
[15:03:17.491] INFO: Test took 4816ms.
[15:03:17.501] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:18.092] INFO: PixTestAlive::aliveTest() done
[15:03:18.092] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0
[15:03:18.270] INFO: enter test to run
[15:03:23.639] INFO: test: timing no parameter change
[15:03:23.639] INFO: running: timing
[15:03:23.643] INFO: ######################################################################
[15:03:23.643] INFO: PixTestTiming::doTest()
[15:03:23.643] INFO: ######################################################################
[15:03:23.643] INFO: ----------------------------------------------------------------------
[15:03:23.643] INFO: PixTestTiming::TBMPhaseScan()
[15:03:23.643] INFO: ----------------------------------------------------------------------
[15:09:43.236] INFO: TBM Phase Settings: 216
[15:09:43.237] INFO: 400MHz Phase: 6
[15:09:43.237] INFO: 160MHz Phase: 6
[15:09:43.237] INFO: Functional Phase Area: 3
[15:09:43.252] INFO: Test took 379609 ms.
[15:09:43.252] INFO: PixTestTiming::TBMPhaseScan() done.
[15:09:43.252] INFO: ----------------------------------------------------------------------
[15:09:43.252] INFO: PixTestTiming::ROCDelayScan()
[15:09:43.252] INFO: ----------------------------------------------------------------------
[15:11:34.245] INFO: ROC Delay Settings: 219
[15:11:34.246] INFO: ROC Header-Trailer/Token Delay: 11
[15:11:34.246] INFO: ROC Port 0 Delay: 3
[15:11:34.246] INFO: ROC Port 1 Delay: 3
[15:11:34.246] INFO: Functional ROC Area: 3
[15:11:34.249] INFO: Test took 110997 ms.
[15:11:34.249] INFO: PixTestTiming::ROCDelayScan() done.
[15:11:34.249] INFO: ----------------------------------------------------------------------
[15:11:34.249] INFO: PixTestTiming::TimingTest()
[15:11:34.249] INFO: ----------------------------------------------------------------------
[15:11:50.645] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:12:05.712] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:12:20.878] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:12:35.972] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:12:51.188] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:06.345] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:21.528] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:36.671] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:13:51.707] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:06.754] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:07.136] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:07.154] INFO: ----------------------------------------------------------------------
[15:14:07.154] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:14:07.154] INFO: ----------------------------------------------------------------------
[15:14:07.154] INFO: ----------------------------------------------------------------------
[15:14:07.154] INFO: Read back bit status: 1
[15:14:07.154] INFO: ----------------------------------------------------------------------
[15:14:07.154] INFO: ----------------------------------------------------------------------
[15:14:07.154] INFO: Timings are good!
[15:14:07.154] INFO: ----------------------------------------------------------------------
[15:14:07.154] INFO: Test took 152905 ms.
[15:14:07.154] INFO: PixTestTiming::TimingTest() done.
[15:14:07.154] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:14:07.155] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:14:07.155] INFO: PixTestTiming::doTest took 643516 ms.
[15:14:07.155] INFO: PixTestTiming::doTest() done
[15:14:07.155] INFO: Write out TBMPhaseScan_0_V0
[15:14:07.155] INFO: Write out TBMPhaseScan_1_V0
[15:14:07.155] INFO: Write out CombinedTBMPhaseScan_V0
[15:14:07.183] INFO: Write out ROCDelayScan3_V0
[15:14:07.184] INFO: enter test to run
[15:15:05.026] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:15:05.027] INFO: running: highrate
[15:15:05.042] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:15:05.307] INFO: ----------------------------------------------------------------------
[15:15:05.307] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:15:05.307] INFO: ----------------------------------------------------------------------
[15:15:05.307] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:15:05.307] INFO: edge/corner pixel THR is adjusted
[15:15:05.307] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:15:06.286] INFO: Collecting data for 5 seconds...
[15:15:11.302] INFO: Done with hot pixel readout
[15:15:23.107] INFO: PixTest:: pg_setup set to default.
[15:15:23.108] INFO: 41 hot pixels found in step 0
[15:15:24.101] INFO: Collecting data for 5 seconds...
[15:15:29.118] INFO: Done with hot pixel readout
[15:15:40.714] INFO: PixTest:: pg_setup set to default.
[15:15:40.715] INFO: 32 hot pixels found in step 1
[15:15:41.708] INFO: Collecting data for 5 seconds...
[15:15:46.725] INFO: Done with hot pixel readout
[15:15:58.508] INFO: PixTest:: pg_setup set to default.
[15:15:58.509] INFO: 34 hot pixels found in step 2
[15:15:59.502] INFO: Collecting data for 5 seconds...
[15:16:04.519] INFO: Done with hot pixel readout
[15:16:16.259] INFO: PixTest:: pg_setup set to default.
[15:16:16.260] INFO: 37 hot pixels found in step 3
[15:16:17.251] INFO: Collecting data for 5 seconds...
[15:16:22.268] INFO: Done with hot pixel readout
[15:16:33.931] INFO: PixTest:: pg_setup set to default.
[15:16:33.932] INFO: 39 hot pixels found in step 4
[15:16:34.925] INFO: Collecting data for 5 seconds...
[15:16:39.941] INFO: Done with hot pixel readout
[15:16:51.662] INFO: PixTest:: pg_setup set to default.
[15:16:51.663] INFO: 35 hot pixels found in step 5
[15:16:52.655] INFO: Collecting data for 5 seconds...
[15:16:57.672] INFO: Done with hot pixel readout
[15:17:09.262] INFO: PixTest:: pg_setup set to default.

[15:17:09.263] INFO: 32 hot pixels found in step 6
[15:17:10.255] INFO: Collecting data for 5 seconds...
[15:17:15.271] INFO: Done with hot pixel readout
[15:17:27.007] INFO: PixTest:: pg_setup set to default.

[15:17:27.008] INFO: 30 hot pixels found in step 7
[15:17:27.000] INFO: Collecting data for 5 seconds...
[15:17:33.017] INFO: Done with hot pixel readout
[15:17:44.794] INFO: PixTest:: pg_setup set to default.


[15:17:44.795] INFO: 26 hot pixels found in step 8
[15:17:45.787] INFO: Collecting data for 5 seconds...
[15:17:50.803] INFO: Done with hot pixel readout
[15:18:02.581] INFO: PixTest:: pg_setup set to default.


[15:18:02.582] INFO: 24 hot pixels found in step 9
[15:18:03.575] INFO: Collecting data for 5 seconds...
[15:18:08.592] INFO: Done with hot pixel readout
[15:18:20.278] INFO: PixTest:: pg_setup set to default.


[15:18:20.279] INFO: 18 hot pixels found in step 10
[15:18:21.272] INFO: Collecting data for 5 seconds...
[15:18:26.289] INFO: Done with hot pixel readout
[15:18:38.040] INFO: PixTest:: pg_setup set to default.



[15:18:38.041] INFO: 12 hot pixels found in step 11
[15:18:39.035] INFO: Collecting data for 5 seconds...
[15:18:44.051] INFO: Done with hot pixel readout
[15:18:55.798] INFO: PixTest:: pg_setup set to default.


[15:18:55.799] INFO: 11 hot pixels found in step 12
[15:18:56.792] INFO: Collecting data for 5 seconds...
[15:19:01.808] INFO: Done with hot pixel readout
[15:19:13.619] INFO: PixTest:: pg_setup set to default.


[15:19:13.619] INFO: 10 hot pixels found in step 13
[15:19:14.612] INFO: Collecting data for 5 seconds...
[15:19:19.629] INFO: Done with hot pixel readout
[15:19:31.413] INFO: PixTest:: pg_setup set to default.


[15:19:31.414] INFO: 12 hot pixels found in step 14
[15:19:31.451] INFO: 12 hot pixels could not be trimmed and have been masked.
[15:19:31.454] INFO: PixTest::trimHotPixels() done
[15:19:31.454] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C0.dat
[15:19:31.461] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C1.dat
[15:19:31.467] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C2.dat
[15:19:31.472] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C3.dat
[15:19:31.477] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C4.dat
[15:19:31.483] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C5.dat
[15:19:31.488] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C6.dat
[15:19:31.493] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C7.dat
[15:19:31.499] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C8.dat
[15:19:31.504] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C9.dat
[15:19:31.509] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C10.dat
[15:19:31.515] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C11.dat
[15:19:31.520] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C12.dat
[15:19:31.525] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C13.dat
[15:19:31.530] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C14.dat
[15:19:31.536] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C15.dat
[15:19:31.541] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//defaultMaskFile.dat
[15:19:31.551] INFO: enter test to run
[15:20:43.264] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:20:43.264] INFO: running: highrate
[15:20:43.269] INFO: ----------------------------------------------------------------------
[15:20:43.269] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:20:43.269] INFO: ----------------------------------------------------------------------
[15:20:43.269] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:20:43.269] INFO: edge/corner pixel THR is adjusted
[15:20:43.269] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:20:44.227] INFO: Collecting data for 1 seconds...
[15:20:45.231] INFO: Done with hot pixel readout
[15:20:49.287] INFO: PixTest:: pg_setup set to default.
[15:20:49.288] INFO: 0 hot pixels found in step 0
[15:20:49.294] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:20:49.380] INFO: PixTest::trimHotPixels() done
[15:20:49.380] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C0.dat
[15:20:49.393] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C1.dat
[15:20:49.399] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C2.dat
[15:20:49.404] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C3.dat
[15:20:49.410] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C4.dat
[15:20:49.416] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C5.dat
[15:20:49.421] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C6.dat
[15:20:49.427] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C7.dat
[15:20:49.432] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C8.dat
[15:20:49.437] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C9.dat
[15:20:49.443] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C10.dat
[15:20:49.449] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C11.dat
[15:20:49.454] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C12.dat
[15:20:49.459] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C13.dat
[15:20:49.465] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C14.dat
[15:20:49.471] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//trimParameters35_C15.dat
[15:20:49.476] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-03_FPIXTest-17C-FNAL-161010-1202-150V_2016-10-10_12h10m_1476119430/000_FPIXTest_p17//defaultMaskFile.dat
[15:20:49.486] INFO: enter test to run
[15:21:16.528] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:21:16.528] INFO: running: xray
[15:21:16.529] INFO: ----------------------------------------------------------------------
[15:21:16.529] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:21:16.529] INFO: ----------------------------------------------------------------------
[15:21:17.505] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:21:28.885] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:21:58.103] INFO: Resuming triggers.
[15:22:09.488] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:22:38.933] INFO: Resuming triggers.
[15:22:50.508] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[15:23:20.243] INFO: Resuming triggers.
[15:23:31.630] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:24:01.487] INFO: Resuming triggers.
[15:24:12.874] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[15:24:42.812] INFO: Resuming triggers.
[15:24:54.199] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[15:25:24.721] INFO: Resuming triggers.
[15:25:36.107] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[15:26:06.215] INFO: Resuming triggers.
[15:26:17.601] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[15:26:47.914] INFO: Resuming triggers.
[15:26:57.205] INFO: data taking finished, elapsed time: 100 seconds.
[15:27:22.089] INFO: PixTest:: pg_setup set to default.
[15:27:22.093] INFO: PixTestXray::doPhRun() done
[15:27:22.301] INFO: enter test to run
[15:28:07.333] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:28:07.333] INFO: running: xray
[15:28:07.334] INFO: ----------------------------------------------------------------------
[15:28:07.334] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:28:07.334] INFO: ----------------------------------------------------------------------
[15:28:08.315] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:28:15.010] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:28:45.079] INFO: Resuming triggers.
[15:28:51.775] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[15:29:21.839] INFO: Resuming triggers.
[15:29:28.536] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[15:29:58.600] INFO: Resuming triggers.
[15:30:05.292] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[15:30:35.474] INFO: Resuming triggers.
[15:30:42.164] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[15:31:12.252] INFO: Resuming triggers.
[15:31:18.945] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[15:31:48.935] INFO: Resuming triggers.
[15:31:55.630] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[15:32:25.557] INFO: Resuming triggers.
[15:32:32.253] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[15:33:02.247] INFO: Resuming triggers.
[15:33:08.944] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[15:33:39.085] INFO: Resuming triggers.
[15:33:45.778] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[15:34:15.817] INFO: Resuming triggers.
[15:34:22.514] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[15:34:53.103] INFO: Resuming triggers.
[15:34:59.797] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[15:35:30.703] INFO: Resuming triggers.
[15:35:37.398] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[15:36:08.639] INFO: Resuming triggers.
[15:36:15.336] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[15:36:46.156] INFO: Resuming triggers.
[15:36:52.772] INFO: data taking finished, elapsed time: 100 seconds.
[15:37:23.569] INFO: PixTest:: pg_setup set to default.
[15:37:23.572] INFO: PixTestXray::doPhRun() done
[15:37:23.729] INFO: enter test to run
[15:38:00.209] INFO: test: HighRate no parameter change
[15:38:00.209] INFO: running: highrate
[15:38:00.230] INFO: ----------------------------------------------------------------------
[15:38:00.230] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:38:00.230] INFO: ----------------------------------------------------------------------
[15:38:00.428] INFO: Expecting 768 events.
[15:38:01.582] INFO: 768 events read in total (431ms).
[15:38:01.582] INFO: Test took 1324ms.
[15:38:02.385] INFO: Expecting 41600 events.
[15:38:05.375] INFO: 41600 events read in total (2463ms).
[15:38:05.376] INFO: Test took 3723ms.
[15:38:05.424] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:06.139] INFO: Expecting 41600 events.
[15:38:09.281] INFO: 41600 events read in total (2615ms).
[15:38:09.282] INFO: Test took 3839ms.
[15:38:09.316] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:10.029] INFO: Expecting 41600 events.
[15:38:13.258] INFO: 41600 events read in total (2702ms).
[15:38:13.259] INFO: Test took 3926ms.
[15:38:13.294] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:14.012] INFO: Expecting 41600 events.
[15:38:17.279] INFO: 41600 events read in total (2740ms).
[15:38:17.280] INFO: Test took 3968ms.
[15:38:17.315] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:18.035] INFO: Expecting 41600 events.
[15:38:21.242] INFO: 41600 events read in total (2680ms).
[15:38:21.243] INFO: Test took 3911ms.
[15:38:21.278] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:21.001] INFO: Expecting 41600 events.
[15:38:25.346] INFO: 41600 events read in total (2818ms).
[15:38:25.461] INFO: Test took 4165ms.
[15:38:25.499] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:26.129] INFO: Expecting 41600 events.
[15:38:29.403] INFO: 41600 events read in total (2747ms).
[15:38:29.404] INFO: Test took 3886ms.
[15:38:29.440] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:30.162] INFO: Expecting 41600 events.
[15:38:33.448] INFO: 41600 events read in total (2759ms).
[15:38:33.449] INFO: Test took 3990ms.
[15:38:33.495] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:34.199] INFO: Expecting 41600 events.
[15:38:37.501] INFO: 41600 events read in total (2775ms).
[15:38:37.502] INFO: Test took 3981ms.
[15:38:37.537] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:38.260] INFO: Expecting 41600 events.
[15:38:41.483] INFO: 41600 events read in total (2696ms).
[15:38:41.484] INFO: Test took 3929ms.
[15:38:41.520] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:42.238] INFO: Expecting 41600 events.
[15:38:45.479] INFO: 41600 events read in total (2714ms).
[15:38:45.480] INFO: Test took 3941ms.
[15:38:45.517] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:46.233] INFO: Expecting 41600 events.
[15:38:49.528] INFO: 41600 events read in total (2768ms).
[15:38:49.529] INFO: Test took 3995ms.
[15:38:49.565] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:50.281] INFO: Expecting 41600 events.
[15:38:53.520] INFO: 41600 events read in total (2712ms).
[15:38:53.521] INFO: Test took 3939ms.
[15:38:53.556] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:54.276] INFO: Expecting 41600 events.
[15:38:57.572] INFO: 41600 events read in total (2769ms).
[15:38:57.573] INFO: Test took 3999ms.
[15:38:57.608] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:38:58.324] INFO: Expecting 41600 events.
[15:39:01.604] INFO: 41600 events read in total (2753ms).
[15:39:01.605] INFO: Test took 3981ms.
[15:39:01.643] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:39:02.349] INFO: Expecting 41600 events.
[15:39:05.687] INFO: 41600 events read in total (2811ms).
[15:39:05.687] INFO: Test took 4026ms.
[15:39:05.723] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:39:06.441] INFO: Expecting 41600 events.
[15:39:09.821] INFO: 41600 events read in total (2853ms).
[15:39:09.822] INFO: Test took 4081ms.
[15:39:09.857] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:39:10.564] INFO: Expecting 41600 events.
[15:39:13.918] INFO: 41600 events read in total (2827ms).
[15:39:13.919] INFO: Test took 4044ms.
[15:39:13.964] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:39:14.658] INFO: Expecting 41600 events.
[15:39:17.871] INFO: 41600 events read in total (2686ms).
[15:39:17.871] INFO: Test took 3889ms.
[15:39:17.906] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:39:18.629] INFO: Expecting 41600 events.
[15:39:21.830] INFO: 41600 events read in total (2674ms).
[15:39:21.831] INFO: Test took 3906ms.
[15:39:21.865] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:39:22.234] INFO: enter test to run
[15:39:26.241] INFO: test: HighRate no parameter change
[15:39:26.241] INFO: running: highrate
[15:39:26.242] INFO: ----------------------------------------------------------------------
[15:39:26.242] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:39:26.242] INFO: ----------------------------------------------------------------------
[15:39:26.866] INFO: Expecting 208000 events.
[15:39:39.138] INFO: 208000 events read in total (11745ms).
[15:39:39.141] INFO: Test took 12893ms.
[15:39:39.290] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:39:39.546] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0
[15:39:39.546] INFO: number of red-efficiency pixels: 95 48 83 138 154 187 190 104 62 101 153 105 112 66 26 27
[15:39:39.546] INFO: number of X-ray hits detected: 71280 44227 67742 111601 115694 122715 120541 82542 72021 95778 95430 81258 82548 48671 23173 25122
[15:39:39.546] 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:39:39.546] INFO: number of Vcal hits detected: 207905 207952 207913 207859 207842 207808 207803 207885 207936 207898 207844 207846 207887 207934 207974 207973
[15:39:39.546] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 99.9 100.0 99.9 100.0 100.0 100.0
[15:39:39.546] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0
[15:39:39.546] INFO: X-ray hit rate [MHz/cm2]: 20.9 13.0 19.9 32.7 33.9 36.0 35.3 24.2 21.1 28.1 28.0 23.8 24.2 14.3 6.8 7.4
[15:39:39.546] INFO: PixTestHighRate::doXPixelAlive() done
[15:39:39.593] INFO: PixTest:: pg_setup set to default.
[15:39:39.615] INFO: enter test to run
[15:40:00.720] INFO: test: HighRate no parameter change
[15:40:00.720] INFO: running: highrate
[15:40:00.722] INFO: ----------------------------------------------------------------------
[15:40:00.722] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:40:00.722] INFO: ----------------------------------------------------------------------
[15:40:01.342] INFO: Expecting 208000 events.
[15:40:15.350] INFO: 208000 events read in total (13481ms).
[15:40:15.356] INFO: Test took 14625ms.
[15:40:15.662] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:15.972] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0
[15:40:15.972] INFO: number of red-efficiency pixels: 306 118 296 500 552 629 618 284 268 406 403 337 317 179 63 59
[15:40:15.972] INFO: number of X-ray hits detected: 146949 91201 138060 228805 236302 251994 245103 170459 149895 194861 196416 167789 170389 99461 47852 51911
[15:40:15.972] 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:40:15.972] INFO: number of Vcal hits detected: 207672 207878 207675 207444 207393 207280 207297 207683 207709 207570 207571 207599 207663 207808 207936 207940
[15:40:15.972] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.7 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[15:40:15.972] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.7 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:40:15.972] INFO: X-ray hit rate [MHz/cm2]: 43.1 26.7 40.5 67.1 69.3 73.9 71.8 50.0 43.9 57.1 57.6 49.2 49.9 29.2 14.0 15.2
[15:40:15.972] INFO: PixTestHighRate::doXPixelAlive() done
[15:40:16.017] INFO: PixTest:: pg_setup set to default.
[15:40:16.028] INFO: enter test to run
[15:40:38.352] INFO: test: HighRate no parameter change
[15:40:38.352] INFO: running: highrate
[15:40:38.353] INFO: ----------------------------------------------------------------------
[15:40:38.353] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:40:38.353] INFO: ----------------------------------------------------------------------
[15:40:38.978] INFO: Expecting 208000 events.
[15:40:55.065] INFO: 208000 events read in total (15560ms).
[15:40:55.072] INFO: Test took 16710ms.
[15:40:55.532] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:40:55.882] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0
[15:40:55.882] INFO: number of red-efficiency pixels: 598 241 658 1222 1421 1561 1421 592 531 945 931 698 686 409 98 107
[15:40:55.882] INFO: number of X-ray hits detected: 220431 138333 209328 344978 356374 380032 370024 257562 225955 295206 297079 253308 256811 150006 73136 78993
[15:40:55.882] 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:40:55.882] INFO: number of Vcal hits detected: 207224 207746 207098 206402 206147 205805 206056 207226 207375 206875 206903 207135 207233 207530 207900 207888
[15:40:55.882] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.3 99.2 99.0 99.2 99.7 99.7 99.5 99.5 99.7 99.7 99.8 100.0 99.9
[15:40:55.882] INFO: Vcal hit overall efficiency (%): 99.6 99.9 99.6 99.2 99.1 98.9 99.1 99.6 99.7 99.5 99.5 99.6 99.6 99.8 100.0 99.9
[15:40:55.882] INFO: X-ray hit rate [MHz/cm2]: 64.6 40.5 61.4 101.1 104.5 111.4 108.5 75.5 66.2 86.5 87.1 74.2 75.3 44.0 21.4 23.2
[15:40:55.882] INFO: PixTestHighRate::doXPixelAlive() done
[15:40:55.928] INFO: PixTest:: pg_setup set to default.
[15:40:55.940] INFO: enter test to run
[15:41:31.063] INFO: test: exit no parameter change
[15:41:31.774] QUIET: Connection to board 33 closed.
[15:41:31.800] INFO: pXar: this is the end, my friend