[12:00:59.898] INFO: *** Welcome to pxar ***
[12:00:59.898] INFO: *** Today: 2016/10/10
[12:01:00.914] INFO: *** Version: v1.9.0-818-g96727
[12:01:00.914] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//dacParameters35_C15.dat
[12:01:00.005] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:01:00.005] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//defaultMaskFile.dat
[12:01:01.013] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C15.dat
[12:01:01.141] INFO: clk: 4
[12:01:01.141] INFO: ctr: 4
[12:01:01.141] INFO: sda: 19
[12:01:01.141] INFO: tin: 9
[12:01:01.141] INFO: level: 15
[12:01:01.141] INFO: triggerdelay: 0
[12:01:01.141] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[12:01:01.141] INFO: Log level: INFO
[12:01:01.162] QUIET: Connection to board DTB_WREKRL opened.
[12:01:01.166] 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:
------------------------------------------------------
[12:01:01.168] INFO: RPC call hashes of host and DTB match: 398089610
[12:01:02.704] INFO: DUT info:
[12:01:02.704] INFO: The DUT currently contains the following objects:
[12:01:02.705] INFO: 2 TBM Cores tbm08c (2 ON)
[12:01:02.725] INFO: TBM Core alpha (0): 7 registers set
[12:01:02.725] INFO: TBM Core beta (1): 7 registers set
[12:01:02.725] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:01:02.725] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.725] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.725] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.725] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.725] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.726] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.726] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.726] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.726] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.726] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.726] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.726] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.726] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.726] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.726] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:02.726] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:01:03.178] INFO: enter 'restricted' command line mode
[12:01:03.178] INFO: enter test to run
[12:01:08.053] INFO: test: PixelAlive no parameter change
[12:01:08.053] INFO: running: pixelalive
[12:01:08.114] INFO: ----------------------------------------------------------------------
[12:01:08.114] 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:01:08.114] INFO: ----------------------------------------------------------------------
[12:01:08.442] INFO: Expecting 41600 events.
[12:01:12.736] INFO: 41600 events read in total (3575ms).
[12:01:12.899] INFO: Test took 4782ms.
[12:01:12.915] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:13.248] INFO: PixTestAlive::aliveTest() done
[12:01:13.248] INFO: number of dead pixels (per ROC): 4 0 0 0 0 0 0 0 0 0 0 0 0 0 0 5
[12:01:13.355] INFO: enter test to run
[12:01:15.573] INFO: test: timing no parameter change
[12:01:15.573] INFO: running: timing
[12:01:15.577] INFO: ######################################################################
[12:01:15.577] INFO: PixTestTiming::doTest()
[12:01:15.577] INFO: ######################################################################
[12:01:15.577] INFO: ----------------------------------------------------------------------
[12:01:15.577] INFO: PixTestTiming::TBMPhaseScan()
[12:01:15.577] INFO: ----------------------------------------------------------------------
[12:07:10.010] INFO: TBM Phase Settings: 232
[12:07:10.010] INFO: 400MHz Phase: 2
[12:07:10.010] INFO: 160MHz Phase: 7
[12:07:10.010] INFO: Functional Phase Area: 2
[12:07:10.028] INFO: Test took 354451 ms.
[12:07:10.028] INFO: PixTestTiming::TBMPhaseScan() done.
[12:07:10.028] INFO: ----------------------------------------------------------------------
[12:07:10.028] INFO: PixTestTiming::ROCDelayScan()
[12:07:10.028] INFO: ----------------------------------------------------------------------
[12:11:08.111] INFO: ROC Delay Settings: 228
[12:11:08.111] INFO: ROC Header-Trailer/Token Delay: 11
[12:11:08.111] INFO: ROC Port 0 Delay: 4
[12:11:08.111] INFO: ROC Port 1 Delay: 4
[12:11:08.111] INFO: Functional ROC Area: 3
[12:11:08.115] INFO: Test took 238087 ms.
[12:11:08.115] INFO: PixTestTiming::ROCDelayScan() done.
[12:11:08.115] INFO: ----------------------------------------------------------------------
[12:11:08.115] INFO: PixTestTiming::TimingTest()
[12:11:08.115] INFO: ----------------------------------------------------------------------
[12:11:24.277] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:11:39.369] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:11:54.613] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:09.670] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:24.754] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:39.849] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:12:54.994] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:10.097] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:25.079] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:40.134] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:40.516] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:40.533] INFO: ----------------------------------------------------------------------
[12:13:40.533] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:13:40.533] INFO: ----------------------------------------------------------------------
[12:13:40.533] INFO: ----------------------------------------------------------------------
[12:13:40.533] INFO: Read back bit status: 1
[12:13:40.533] INFO: ----------------------------------------------------------------------
[12:13:40.533] INFO: ----------------------------------------------------------------------
[12:13:40.533] INFO: Timings are good!
[12:13:40.533] INFO: ----------------------------------------------------------------------
[12:13:40.533] INFO: Test took 152418 ms.
[12:13:40.534] INFO: PixTestTiming::TimingTest() done.
[12:13:40.547] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:13:40.547] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:13:40.547] INFO: PixTestTiming::doTest took 744973 ms.
[12:13:40.548] INFO: PixTestTiming::doTest() done
[12:13:40.548] INFO: Write out TBMPhaseScan_0_V0
[12:13:40.548] INFO: Write out TBMPhaseScan_1_V0
[12:13:40.548] INFO: Write out CombinedTBMPhaseScan_V0
[12:13:40.574] INFO: Write out ROCDelayScan3_V0
[12:13:40.574] INFO: enter test to run
[12:14:14.552] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:14:14.552] INFO: running: highrate
[12:14:14.574] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:14:14.906] INFO: ----------------------------------------------------------------------
[12:14:14.906] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:14:14.906] INFO: ----------------------------------------------------------------------
[12:14:14.906] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:14:14.906] INFO: edge/corner pixel THR is adjusted
[12:14:14.906] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:14:15.884] INFO: Collecting data for 5 seconds...
[12:14:20.903] INFO: Done with hot pixel readout
[12:14:32.524] INFO: PixTest:: pg_setup set to default.
[12:14:32.525] INFO: 8 hot pixels found in step 0
[12:14:33.518] INFO: Collecting data for 5 seconds...
[12:14:38.536] INFO: Done with hot pixel readout
[12:14:50.247] INFO: PixTest:: pg_setup set to default.
[12:14:50.248] INFO: 10 hot pixels found in step 1
[12:14:51.241] INFO: Collecting data for 5 seconds...
[12:14:56.258] INFO: Done with hot pixel readout
[12:15:08.205] INFO: PixTest:: pg_setup set to default.
[12:15:08.206] INFO: 7 hot pixels found in step 2
[12:15:09.199] INFO: Collecting data for 5 seconds...
[12:15:14.217] INFO: Done with hot pixel readout
[12:15:26.150] INFO: PixTest:: pg_setup set to default.
[12:15:26.151] INFO: 2 hot pixels found in step 3
[12:15:27.144] INFO: Collecting data for 5 seconds...
[12:15:32.165] INFO: Done with hot pixel readout
[12:15:44.059] INFO: PixTest:: pg_setup set to default.
[12:15:44.060] INFO: 7 hot pixels found in step 4
[12:15:45.052] INFO: Collecting data for 5 seconds...
[12:15:50.070] INFO: Done with hot pixel readout
[12:16:02.121] INFO: PixTest:: pg_setup set to default.

[12:16:02.122] INFO: 4 hot pixels found in step 5
[12:16:03.115] INFO: Collecting data for 5 seconds...
[12:16:08.137] INFO: Done with hot pixel readout
[12:16:20.033] INFO: PixTest:: pg_setup set to default.
[12:16:20.034] INFO: 2 hot pixels found in step 6
[12:16:21.027] INFO: Collecting data for 5 seconds...
[12:16:26.045] INFO: Done with hot pixel readout
[12:16:37.912] INFO: PixTest:: pg_setup set to default.
[12:16:37.913] INFO: 6 hot pixels found in step 7
[12:16:38.907] INFO: Collecting data for 5 seconds...
[12:16:43.927] INFO: Done with hot pixel readout
[12:16:55.381] INFO: PixTest:: pg_setup set to default.
[12:16:55.382] INFO: 2 hot pixels found in step 8
[12:16:56.375] INFO: Collecting data for 5 seconds...
[12:17:01.394] INFO: Done with hot pixel readout
[12:17:12.403] INFO: PixTest:: pg_setup set to default.
[12:17:12.404] INFO: 4 hot pixels found in step 9
[12:17:13.396] INFO: Collecting data for 5 seconds...
[12:17:18.412] INFO: Done with hot pixel readout
[12:17:29.979] INFO: PixTest:: pg_setup set to default.
[12:17:29.980] INFO: 1 hot pixels found in step 10
[12:17:30.971] INFO: Collecting data for 5 seconds...
[12:17:35.988] INFO: Done with hot pixel readout
[12:17:47.641] INFO: PixTest:: pg_setup set to default.
[12:17:47.642] INFO: 1 hot pixels found in step 11
[12:17:48.633] INFO: Collecting data for 5 seconds...
[12:17:53.650] INFO: Done with hot pixel readout
[12:18:05.365] INFO: PixTest:: pg_setup set to default.
[12:18:05.366] INFO: 2 hot pixels found in step 12
[12:18:06.357] INFO: Collecting data for 5 seconds...
[12:18:11.374] INFO: Done with hot pixel readout
[12:18:23.177] INFO: PixTest:: pg_setup set to default.
[12:18:23.178] INFO: 5 hot pixels found in step 13
[12:18:24.170] INFO: Collecting data for 5 seconds...
[12:18:29.186] INFO: Done with hot pixel readout
[12:18:40.921] INFO: PixTest:: pg_setup set to default.
[12:18:40.922] INFO: 2 hot pixels found in step 14
[12:18:40.957] INFO: 2 hot pixels could not be trimmed and have been masked.
[12:18:40.961] INFO: PixTest::trimHotPixels() done
[12:18:40.969] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C0.dat
[12:18:40.980] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C1.dat
[12:18:40.986] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C2.dat
[12:18:40.991] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C3.dat
[12:18:40.997] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C4.dat
[12:18:40.002] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C5.dat
[12:18:41.007] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C6.dat
[12:18:41.012] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C7.dat
[12:18:41.018] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C8.dat
[12:18:41.023] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C9.dat
[12:18:41.028] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C10.dat
[12:18:41.033] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C11.dat
[12:18:41.039] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C12.dat
[12:18:41.044] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C13.dat
[12:18:41.049] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C14.dat
[12:18:41.055] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C15.dat
[12:18:41.060] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//defaultMaskFile.dat
[12:18:41.078] INFO: enter test to run
[12:19:03.390] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:19:03.390] INFO: running: highrate
[12:19:03.395] INFO: ----------------------------------------------------------------------
[12:19:03.395] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:19:03.395] INFO: ----------------------------------------------------------------------
[12:19:03.395] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:19:03.395] INFO: edge/corner pixel THR is adjusted
[12:19:03.395] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:19:04.353] INFO: Collecting data for 1 seconds...
[12:19:05.356] INFO: Done with hot pixel readout
[12:19:09.397] INFO: PixTest:: pg_setup set to default.
[12:19:09.398] INFO: 0 hot pixels found in step 0
[12:19:09.403] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:19:09.496] INFO: PixTest::trimHotPixels() done
[12:19:09.496] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C0.dat
[12:19:09.532] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C1.dat
[12:19:09.538] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C2.dat
[12:19:09.543] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C3.dat
[12:19:09.548] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C4.dat
[12:19:09.554] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C5.dat
[12:19:09.559] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C6.dat
[12:19:09.564] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C7.dat
[12:19:09.569] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C8.dat
[12:19:09.575] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C9.dat
[12:19:09.580] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C10.dat
[12:19:09.585] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C11.dat
[12:19:09.590] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C12.dat
[12:19:09.596] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C13.dat
[12:19:09.601] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C14.dat
[12:19:09.606] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//trimParameters35_C15.dat
[12:19:09.611] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-05_FPIXTest-17C-FNAL-161004-1227-150V_2016-10-04_12h27m_1475602047/000_FPIXTest_p17//defaultMaskFile.dat
[12:19:09.627] INFO: enter test to run
[12:19:30.110] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:19:30.110] INFO: running: xray
[12:19:30.111] INFO: ----------------------------------------------------------------------
[12:19:30.111] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:19:30.111] INFO: ----------------------------------------------------------------------
[12:19:31.097] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:19:42.597] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:20:12.297] INFO: Resuming triggers.
[12:20:23.802] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[12:20:53.589] INFO: Resuming triggers.
[12:21:05.089] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[12:21:34.673] INFO: Resuming triggers.
[12:21:46.180] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[12:22:15.331] INFO: Resuming triggers.
[12:22:26.839] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[12:22:56.307] INFO: Resuming triggers.
[12:23:07.811] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[12:23:36.323] INFO: Resuming triggers.
[12:23:47.824] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[12:24:16.723] INFO: Resuming triggers.
[12:24:28.228] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[12:24:57.654] INFO: Resuming triggers.
[12:25:05.959] INFO: data taking finished, elapsed time: 100 seconds.
[12:25:27.796] INFO: PixTest:: pg_setup set to default.
[12:25:27.799] INFO: PixTestXray::doPhRun() done
[12:25:28.503] INFO: enter test to run
[12:25:57.931] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:25:57.931] INFO: running: xray
[12:25:57.932] INFO: ----------------------------------------------------------------------
[12:25:57.932] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:25:57.932] INFO: ----------------------------------------------------------------------
[12:25:58.896] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:26:05.512] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:26:36.666] INFO: Resuming triggers.
[12:26:43.285] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[12:27:14.393] INFO: Resuming triggers.
[12:27:21.014] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[12:27:52.102] INFO: Resuming triggers.
[12:27:58.721] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[12:28:29.072] INFO: Resuming triggers.
[12:28:35.689] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[12:29:06.726] INFO: Resuming triggers.
[12:29:13.345] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[12:29:44.940] INFO: Resuming triggers.
[12:29:51.555] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[12:30:23.337] INFO: Resuming triggers.
[12:30:29.952] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[12:31:02.054] INFO: Resuming triggers.
[12:31:08.672] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[12:31:40.259] INFO: Resuming triggers.
[12:31:46.874] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[12:32:17.559] INFO: Resuming triggers.
[12:32:24.175] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[12:32:54.774] INFO: Resuming triggers.
[12:33:01.392] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[12:33:32.102] INFO: Resuming triggers.
[12:33:38.720] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[12:34:09.568] INFO: Resuming triggers.
[12:34:16.182] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[12:34:47.119] INFO: Resuming triggers.
[12:34:53.735] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[12:35:24.383] INFO: Resuming triggers.
[12:35:25.476] INFO: data taking finished, elapsed time: 100 seconds.
[12:35:30.863] INFO: PixTest:: pg_setup set to default.
[12:35:30.866] INFO: PixTestXray::doPhRun() done
[12:35:31.021] INFO: enter test to run
[12:35:52.935] INFO: test: HighRate no parameter change
[12:35:52.935] INFO: running: highrate
[12:35:52.946] INFO: ----------------------------------------------------------------------
[12:35:52.946] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:35:52.946] INFO: ----------------------------------------------------------------------
[12:35:53.100] INFO: Expecting 768 events.
[12:35:54.251] INFO: 768 events read in total (436ms).
[12:35:54.252] INFO: Test took 1286ms.
[12:35:55.055] INFO: Expecting 41600 events.
[12:35:58.098] INFO: 41600 events read in total (2516ms).
[12:35:58.099] INFO: Test took 3788ms.
[12:35:58.133] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:35:58.857] INFO: Expecting 41600 events.
[12:36:02.040] INFO: 41600 events read in total (2656ms).
[12:36:02.041] INFO: Test took 3891ms.
[12:36:02.076] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:02.800] INFO: Expecting 41600 events.
[12:36:06.047] INFO: 41600 events read in total (2721ms).
[12:36:06.048] INFO: Test took 3954ms.
[12:36:06.084] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:06.803] INFO: Expecting 41600 events.
[12:36:10.010] INFO: 41600 events read in total (2680ms).
[12:36:10.011] INFO: Test took 3907ms.
[12:36:10.047] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:10.768] INFO: Expecting 41600 events.
[12:36:14.030] INFO: 41600 events read in total (2735ms).
[12:36:14.031] INFO: Test took 3965ms.
[12:36:14.067] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:14.788] INFO: Expecting 41600 events.
[12:36:18.049] INFO: 41600 events read in total (2734ms).
[12:36:18.050] INFO: Test took 3965ms.
[12:36:18.086] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:18.805] INFO: Expecting 41600 events.
[12:36:22.081] INFO: 41600 events read in total (2749ms).
[12:36:22.082] INFO: Test took 3977ms.
[12:36:22.118] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:22.839] INFO: Expecting 41600 events.
[12:36:26.112] INFO: 41600 events read in total (2746ms).
[12:36:26.113] INFO: Test took 3975ms.
[12:36:26.148] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:26.867] INFO: Expecting 41600 events.
[12:36:30.136] INFO: 41600 events read in total (2742ms).
[12:36:30.137] INFO: Test took 3971ms.
[12:36:30.173] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:30.894] INFO: Expecting 41600 events.
[12:36:34.167] INFO: 41600 events read in total (2746ms).
[12:36:34.168] INFO: Test took 3976ms.
[12:36:34.204] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:34.925] INFO: Expecting 41600 events.
[12:36:38.197] INFO: 41600 events read in total (2745ms).
[12:36:38.197] INFO: Test took 3973ms.
[12:36:38.233] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:38.953] INFO: Expecting 41600 events.
[12:36:42.229] INFO: 41600 events read in total (2749ms).
[12:36:42.230] INFO: Test took 3979ms.
[12:36:42.265] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:42.986] INFO: Expecting 41600 events.
[12:36:46.228] INFO: 41600 events read in total (2715ms).
[12:36:46.228] INFO: Test took 3943ms.
[12:36:46.264] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:46.987] INFO: Expecting 41600 events.
[12:36:50.209] INFO: 41600 events read in total (2695ms).
[12:36:50.210] INFO: Test took 3928ms.
[12:36:50.245] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:50.966] INFO: Expecting 41600 events.
[12:36:54.253] INFO: 41600 events read in total (2760ms).
[12:36:54.254] INFO: Test took 3990ms.
[12:36:54.290] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:55.008] INFO: Expecting 41600 events.
[12:36:58.262] INFO: 41600 events read in total (2727ms).
[12:36:58.263] INFO: Test took 3954ms.
[12:36:58.299] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:59.021] INFO: Expecting 41600 events.
[12:37:02.272] INFO: 41600 events read in total (2724ms).
[12:37:02.273] INFO: Test took 3955ms.
[12:37:02.309] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:03.031] INFO: Expecting 41600 events.
[12:37:06.290] INFO: 41600 events read in total (2732ms).
[12:37:06.291] INFO: Test took 3964ms.
[12:37:06.326] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:07.049] INFO: Expecting 41600 events.
[12:37:10.300] INFO: 41600 events read in total (2724ms).
[12:37:10.301] INFO: Test took 3956ms.
[12:37:10.337] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:11.060] INFO: Expecting 41600 events.
[12:37:14.169] INFO: 41600 events read in total (2582ms).
[12:37:14.170] INFO: Test took 3814ms.
[12:37:14.204] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:14.569] INFO: enter test to run
[12:37:37.231] INFO: test: HighRate no parameter change
[12:37:37.231] INFO: running: highrate
[12:37:37.232] INFO: ----------------------------------------------------------------------
[12:37:37.232] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:37:37.232] INFO: ----------------------------------------------------------------------
[12:37:37.845] INFO: Expecting 208000 events.
[12:37:49.871] INFO: 208000 events read in total (11499ms).
[12:37:49.874] INFO: Test took 12632ms.
[12:37:50.025] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:50.281] INFO: number of dead pixels (per ROC): 3 0 0 0 0 0 0 0 0 0 0 0 0 0 0 5
[12:37:50.296] INFO: number of red-efficiency pixels: 85 44 84 352 162 158 139 117 91 152 138 95 91 72 23 39
[12:37:50.296] INFO: number of X-ray hits detected: 70156 45999 74248 110621 120071 125528 124052 88900 81647 105330 99770 81178 82280 54890 23492 28611
[12:37:50.296] 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:37:50.296] INFO: number of Vcal hits detected: 207719 207953 207914 207634 207836 207835 207850 207880 207909 207844 207859 207900 207900 207927 207976 207715
[12:37:50.296] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 100.0 99.8 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[12:37:50.297] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.8 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 99.9
[12:37:50.297] INFO: X-ray hit rate [MHz/cm2]: 20.6 13.5 21.8 32.4 35.2 36.8 36.4 26.1 23.9 30.9 29.2 23.8 24.1 16.1 6.9 8.4
[12:37:50.297] INFO: PixTestHighRate::doXPixelAlive() done
[12:37:50.346] INFO: PixTest:: pg_setup set to default.
[12:37:50.358] INFO: enter test to run
[12:38:14.022] INFO: test: HighRate no parameter change
[12:38:14.022] INFO: running: highrate
[12:38:14.024] INFO: ----------------------------------------------------------------------
[12:38:14.024] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:38:14.024] INFO: ----------------------------------------------------------------------
[12:38:14.638] INFO: Expecting 208000 events.
[12:38:28.261] INFO: 208000 events read in total (13097ms).
[12:38:28.266] INFO: Test took 14232ms.
[12:38:28.549] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:38:28.848] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 0 0 0 0 0 0 0 0 0 5
[12:38:28.848] INFO: number of red-efficiency pixels: 198 123 238 581 477 546 413 344 230 362 337 257 193 178 48 67
[12:38:28.848] INFO: number of X-ray hits detected: 134133 87973 141349 210607 227667 240574 237989 168487 155892 201397 189678 154537 157708 104396 44611 54491
[12:38:28.848] 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:38:28.848] INFO: number of Vcal hits detected: 207592 207868 207741 207307 207480 207401 207556 207629 207761 207612 207650 207727 207785 207808 207952 207688
[12:38:28.848] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.7 99.8 99.7 99.8 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[12:38:28.848] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.9 99.7 99.8 99.7 99.8 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 99.9
[12:38:28.848] INFO: X-ray hit rate [MHz/cm2]: 39.3 25.8 41.4 61.7 66.7 70.5 69.8 49.4 45.7 59.0 55.6 45.3 46.2 30.6 13.1 16.0
[12:38:28.848] INFO: PixTestHighRate::doXPixelAlive() done
[12:38:28.902] INFO: PixTest:: pg_setup set to default.
[12:38:28.915] INFO: enter test to run
[12:38:43.742] INFO: test: HighRate no parameter change
[12:38:43.742] INFO: running: highrate
[12:38:43.743] INFO: ----------------------------------------------------------------------
[12:38:43.743] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:38:43.743] INFO: ----------------------------------------------------------------------
[12:38:44.360] INFO: Expecting 208000 events.
[12:38:59.975] INFO: 208000 events read in total (15089ms).
[12:38:59.982] INFO: Test took 16228ms.
[12:39:00.417] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:39:00.765] INFO: number of dead pixels (per ROC): 4 0 0 0 0 0 0 0 0 0 0 0 0 0 0 5
[12:39:00.765] INFO: number of red-efficiency pixels: 383 257 499 1242 1192 1155 964 749 475 911 772 568 457 402 84 130
[12:39:00.765] INFO: number of X-ray hits detected: 205293 135465 216674 323043 350249 367687 362964 259409 240126 308628 290918 237764 241161 161060 68663 85021
[12:39:00.765] 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:39:00.765] INFO: number of Vcal hits detected: 207363 207720 207388 205317 206521 206492 206813 207099 207468 206915 207111 207348 207480 207527 207912 207622
[12:39:00.765] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 98.7 99.4 99.4 99.5 99.6 99.8 99.5 99.6 99.7 99.8 99.8 100.0 99.9
[12:39:00.765] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 98.7 99.3 99.3 99.4 99.6 99.7 99.5 99.6 99.7 99.8 99.8 100.0 99.8
[12:39:00.765] INFO: X-ray hit rate [MHz/cm2]: 60.2 39.7 63.5 94.7 102.7 107.8 106.4 76.0 70.4 90.5 85.3 69.7 70.7 47.2 20.1 24.9
[12:39:00.765] INFO: PixTestHighRate::doXPixelAlive() done
[12:39:00.815] INFO: PixTest:: pg_setup set to default.
[12:39:00.833] INFO: enter test to run
[12:39:22.126] INFO: test: exit no parameter change
[12:39:22.703] QUIET: Connection to board 33 closed.
[12:39:22.883] INFO: pXar: this is the end, my friend