[15:03:26.628] INFO: *** Welcome to pxar ***
[15:03:26.628] INFO: *** Today: 2016/10/26
[15:03:27.414] INFO: *** Version: v1.9.0-818-g96727
[15:03:27.414] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//dacParameters35_C15.dat
[15:03:27.447] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:03:27.447] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//defaultMaskFile.dat
[15:03:27.447] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C15.dat
[15:03:27.586] INFO: clk: 4
[15:03:27.586] INFO: ctr: 4
[15:03:27.586] INFO: sda: 19
[15:03:27.586] INFO: tin: 9
[15:03:27.586] INFO: level: 15
[15:03:27.586] INFO: triggerdelay: 0
[15:03:27.586] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:03:27.586] INFO: Log level: INFO
[15:03:27.602] QUIET: Connection to board DTB_WREHUL opened.
[15:03:27.605] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 30
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREHUL
MAC address: 40D85511801E
Hostname: pixelDTB030
Comment:
------------------------------------------------------
[15:03:27.608] INFO: RPC call hashes of host and DTB match: 398089610
[15:03:29.141] INFO: DUT info:
[15:03:29.141] INFO: The DUT currently contains the following objects:
[15:03:29.141] INFO: 2 TBM Cores tbm08c (2 ON)
[15:03:29.141] INFO: TBM Core alpha (0): 7 registers set
[15:03:29.141] INFO: TBM Core beta (1): 7 registers set
[15:03:29.141] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:03:29.141] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.141] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.142] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:03:29.556] INFO: enter 'restricted' command line mode
[15:03:29.556] INFO: enter test to run
[15:03:39.063] INFO: test: PixelAlive no parameter change
[15:03:39.063] INFO: running: pixelalive
[15:03:39.073] INFO: ----------------------------------------------------------------------
[15:03:39.073] 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:39.073] INFO: ----------------------------------------------------------------------
[15:03:39.391] INFO: Expecting 41600 events.
[15:03:43.732] INFO: 41600 events read in total (3623ms).
[15:03:43.901] INFO: Test took 4826ms.
[15:03:43.913] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:44.174] INFO: PixTestAlive::aliveTest() done
[15:03:44.175] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 1 1 0 0 0 13 0
[15:03:44.206] INFO: enter test to run
[15:04:31.895] INFO: test: timing no parameter change
[15:04:31.895] INFO: running: timing
[15:04:31.899] INFO: ######################################################################
[15:04:31.899] INFO: PixTestTiming::doTest()
[15:04:31.899] INFO: ######################################################################
[15:04:31.899] INFO: ----------------------------------------------------------------------
[15:04:31.899] INFO: PixTestTiming::TBMPhaseScan()
[15:04:31.899] INFO: ----------------------------------------------------------------------
[15:12:09.248] INFO: TBM Phase Settings: 240
[15:12:09.248] INFO: 400MHz Phase: 4
[15:12:09.248] INFO: 160MHz Phase: 7
[15:12:09.248] INFO: Functional Phase Area: 5
[15:12:09.251] INFO: Test took 457352 ms.
[15:12:09.251] INFO: PixTestTiming::TBMPhaseScan() done.
[15:12:09.251] INFO: ----------------------------------------------------------------------
[15:12:09.251] INFO: PixTestTiming::ROCDelayScan()
[15:12:09.251] INFO: ----------------------------------------------------------------------
[15:14:21.250] INFO: ROC Delay Settings: 228
[15:14:21.250] INFO: ROC Header-Trailer/Token Delay: 11
[15:14:21.251] INFO: ROC Port 0 Delay: 4
[15:14:21.251] INFO: ROC Port 1 Delay: 4
[15:14:21.251] INFO: Functional ROC Area: 4
[15:14:21.254] INFO: Test took 132003 ms.
[15:14:21.254] INFO: PixTestTiming::ROCDelayScan() done.
[15:14:21.254] INFO: ----------------------------------------------------------------------
[15:14:21.254] INFO: PixTestTiming::TimingTest()
[15:14:21.254] INFO: ----------------------------------------------------------------------
[15:14:37.372] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:14:52.657] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:15:07.786] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:15:22.983] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:15:38.134] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:15:53.250] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:08.551] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:23.931] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:39.092] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:54.224] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:54.605] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:16:54.623] INFO: ----------------------------------------------------------------------
[15:16:54.623] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:16:54.623] INFO: ----------------------------------------------------------------------
[15:16:54.623] INFO: ----------------------------------------------------------------------
[15:16:54.623] INFO: Read back bit status: 1
[15:16:54.623] INFO: ----------------------------------------------------------------------
[15:16:54.623] INFO: ----------------------------------------------------------------------
[15:16:54.623] INFO: Timings are good!
[15:16:54.623] INFO: ----------------------------------------------------------------------
[15:16:54.623] INFO: Test took 153369 ms.
[15:16:54.623] INFO: PixTestTiming::TimingTest() done.
[15:16:54.623] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:16:54.633] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:16:54.633] INFO: PixTestTiming::doTest took 742738 ms.
[15:16:54.633] INFO: PixTestTiming::doTest() done
[15:16:54.633] INFO: Write out TBMPhaseScan_0_V0
[15:16:54.633] INFO: Write out TBMPhaseScan_1_V0
[15:16:54.634] INFO: Write out CombinedTBMPhaseScan_V0
[15:16:54.635] INFO: Write out ROCDelayScan3_V0
[15:16:54.636] INFO: enter test to run
[15:18:41.793] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:18:41.794] INFO: running: highrate
[15:18:41.802] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:18:42.110] INFO: ----------------------------------------------------------------------
[15:18:42.110] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:18:42.110] INFO: ----------------------------------------------------------------------
[15:18:42.110] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:18:42.110] INFO: edge/corner pixel THR is adjusted
[15:18:42.110] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:18:43.070] INFO: Collecting data for 5 seconds...
[15:18:48.086] INFO: Done with hot pixel readout
[15:19:00.044] INFO: PixTest:: pg_setup set to default.
[15:19:00.045] INFO: 16 hot pixels found in step 0
[15:19:01.041] INFO: Collecting data for 5 seconds...
[15:19:06.057] INFO: Done with hot pixel readout
[15:19:18.055] INFO: PixTest:: pg_setup set to default.
[15:19:18.056] INFO: 24 hot pixels found in step 1
[15:19:19.052] INFO: Collecting data for 5 seconds...
[15:19:24.069] INFO: Done with hot pixel readout
[15:19:35.974] INFO: PixTest:: pg_setup set to default.
[15:19:35.975] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:19:35.975] INFO: 24 hot pixels found in step 2
[15:19:36.971] INFO: Collecting data for 5 seconds...
[15:19:41.988] INFO: Done with hot pixel readout
[15:19:53.902] INFO: PixTest:: pg_setup set to default.
[15:19:53.902] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:19:53.903] INFO: 26 hot pixels found in step 3
[15:19:54.898] INFO: Collecting data for 5 seconds...
[15:19:59.915] INFO: Done with hot pixel readout
[15:20:11.854] INFO: PixTest:: pg_setup set to default.
[15:20:11.854] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:20:11.854] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:20:11.855] INFO: 27 hot pixels found in step 4
[15:20:12.851] INFO: Collecting data for 5 seconds...
[15:20:17.868] INFO: Done with hot pixel readout
[15:20:29.885] INFO: PixTest:: pg_setup set to default.
[15:20:29.886] INFO: 14 hot pixels found in step 5
[15:20:30.882] INFO: Collecting data for 5 seconds...
[15:20:35.899] INFO: Done with hot pixel readout
[15:20:47.853] INFO: PixTest:: pg_setup set to default.
[15:20:47.854] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:20:47.854] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:20:47.854] INFO: 19 hot pixels found in step 6
[15:20:48.849] INFO: Collecting data for 5 seconds...
[15:20:53.865] INFO: Done with hot pixel readout
[15:21:05.864] INFO: PixTest:: pg_setup set to default.
[15:21:05.865] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:21:05.865] INFO: 19 hot pixels found in step 7
[15:21:06.863] INFO: Collecting data for 5 seconds...
[15:21:11.879] INFO: Done with hot pixel readout
[15:21:23.672] INFO: PixTest:: pg_setup set to default.
[15:21:23.673] INFO: 20 hot pixels found in step 8
[15:21:24.669] INFO: Collecting data for 5 seconds...
[15:21:29.686] INFO: Done with hot pixel readout
[15:21:41.686] INFO: PixTest:: pg_setup set to default.
[15:21:41.686] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:21:41.687] INFO: 14 hot pixels found in step 9
[15:21:42.683] INFO: Collecting data for 5 seconds...
[15:21:47.700] INFO: Done with hot pixel readout
[15:21:59.648] INFO: PixTest:: pg_setup set to default.
[15:21:59.649] INFO: 14 hot pixels found in step 10
[15:22:00.644] INFO: Collecting data for 5 seconds...
[15:22:05.661] INFO: Done with hot pixel readout
[15:22:17.636] INFO: PixTest:: pg_setup set to default.
[15:22:17.636] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:22:17.637] INFO: 19 hot pixels found in step 11
[15:22:18.632] INFO: Collecting data for 5 seconds...
[15:22:23.649] INFO: Done with hot pixel readout
[15:22:35.628] INFO: PixTest:: pg_setup set to default.
[15:22:35.628] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:22:35.629] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:22:35.629] INFO: 22 hot pixels found in step 12
[15:22:36.626] INFO: Collecting data for 5 seconds...
[15:22:41.643] INFO: Done with hot pixel readout
[15:22:53.652] INFO: PixTest:: pg_setup set to default.
[15:22:53.652] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:22:53.653] INFO: 16 hot pixels found in step 13
[15:22:54.649] INFO: Collecting data for 5 seconds...
[15:22:59.665] INFO: Done with hot pixel readout
[15:23:11.579] INFO: PixTest:: pg_setup set to default.
[15:23:11.579] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:23:11.580] INFO: 17 hot pixels found in step 14
[15:23:11.619] INFO: 17 hot pixels could not be trimmed and have been masked.
[15:23:11.622] INFO: PixTest::trimHotPixels() done
[15:23:11.623] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C0.dat
[15:23:11.644] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C1.dat
[15:23:11.656] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C2.dat
[15:23:11.667] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C3.dat
[15:23:11.673] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C4.dat
[15:23:11.678] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C5.dat
[15:23:11.683] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C6.dat
[15:23:11.688] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C7.dat
[15:23:11.694] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C8.dat
[15:23:11.699] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C9.dat
[15:23:11.705] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C10.dat
[15:23:11.710] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C11.dat
[15:23:11.715] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C12.dat
[15:23:11.720] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C13.dat
[15:23:11.726] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C14.dat
[15:23:11.731] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C15.dat
[15:23:11.737] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//defaultMaskFile.dat
[15:23:11.747] INFO: enter test to run
[15:24:07.111] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:24:07.111] INFO: running: highrate
[15:24:07.116] INFO: ----------------------------------------------------------------------
[15:24:07.116] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:24:07.116] INFO: ----------------------------------------------------------------------
[15:24:07.116] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:24:07.116] INFO: edge/corner pixel THR is adjusted
[15:24:07.116] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:24:08.074] INFO: Collecting data for 1 seconds...
[15:24:09.077] INFO: Done with hot pixel readout
[15:24:13.056] INFO: PixTest:: pg_setup set to default.
[15:24:13.057] INFO: 0 hot pixels found in step 0
[15:24:13.062] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:24:13.155] INFO: PixTest::trimHotPixels() done
[15:24:13.155] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C0.dat
[15:24:13.166] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C1.dat
[15:24:13.172] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C2.dat
[15:24:13.177] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C3.dat
[15:24:13.182] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C4.dat
[15:24:13.188] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C5.dat
[15:24:13.193] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C6.dat
[15:24:13.198] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C7.dat
[15:24:13.203] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C8.dat
[15:24:13.209] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C9.dat
[15:24:13.214] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C10.dat
[15:24:13.219] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C11.dat
[15:24:13.225] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C12.dat
[15:24:13.230] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C13.dat
[15:24:13.235] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C14.dat
[15:24:13.240] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C15.dat
[15:24:13.246] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-15_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//defaultMaskFile.dat
[15:24:13.262] INFO: enter test to run
[15:24:36.895] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:24:36.895] INFO: running: xray
[15:24:36.896] INFO: ----------------------------------------------------------------------
[15:24:36.896] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:24:36.896] INFO: ----------------------------------------------------------------------
[15:24:37.860] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:24:49.278] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:25:19.205] INFO: Resuming triggers.
[15:25:30.627] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:25:59.865] INFO: Resuming triggers.
[15:26:11.285] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[15:26:40.926] INFO: Resuming triggers.
[15:26:52.346] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:27:21.971] INFO: Resuming triggers.
[15:27:33.390] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[15:28:03.047] INFO: Resuming triggers.
[15:28:14.464] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[15:28:44.891] INFO: Resuming triggers.
[15:28:56.311] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[15:29:26.188] INFO: Resuming triggers.
[15:29:37.604] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[15:30:07.420] INFO: Resuming triggers.
[15:30:16.440] INFO: data taking finished, elapsed time: 100 seconds.
[15:30:39.727] INFO: PixTest:: pg_setup set to default.
[15:30:39.731] INFO: PixTestXray::doPhRun() done
[15:30:39.939] INFO: enter test to run
[15:32:10.900] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:32:10.900] INFO: running: xray
[15:32:10.901] INFO: ----------------------------------------------------------------------
[15:32:10.901] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:32:10.901] INFO: ----------------------------------------------------------------------
[15:32:11.865] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:32:18.748] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:32:48.818] INFO: Resuming triggers.
[15:32:55.703] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[15:33:25.725] INFO: Resuming triggers.
[15:33:32.607] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[15:34:02.800] INFO: Resuming triggers.
[15:34:09.680] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[15:34:39.597] INFO: Resuming triggers.
[15:34:46.480] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[15:35:16.500] INFO: Resuming triggers.
[15:35:23.384] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[15:35:53.537] INFO: Resuming triggers.
[15:36:00.422] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[15:36:30.676] INFO: Resuming triggers.
[15:36:37.563] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[15:37:07.748] INFO: Resuming triggers.
[15:37:14.636] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[15:37:44.875] INFO: Resuming triggers.
[15:37:51.761] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[15:38:22.834] INFO: Resuming triggers.
[15:38:29.720] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[15:39:00.364] INFO: Resuming triggers.
[15:39:07.253] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[15:39:37.760] INFO: Resuming triggers.
[15:39:44.649] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[15:40:14.720] INFO: Resuming triggers.
[15:40:21.608] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[15:40:52.037] INFO: Resuming triggers.
[15:40:55.982] INFO: data taking finished, elapsed time: 100 seconds.
[15:41:13.827] INFO: PixTest:: pg_setup set to default.
[15:41:13.830] INFO: PixTestXray::doPhRun() done
[15:41:13.978] INFO: enter test to run
[15:42:06.560] INFO: test: HighRate no parameter change
[15:42:06.560] INFO: running: highrate
[15:42:06.617] INFO: ----------------------------------------------------------------------
[15:42:06.617] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:42:06.617] INFO: ----------------------------------------------------------------------
[15:42:06.782] INFO: Expecting 768 events.
[15:42:07.916] INFO: 768 events read in total (419ms).
[15:42:07.916] INFO: Test took 1268ms.
[15:42:08.719] INFO: Expecting 41600 events.
[15:42:11.794] INFO: 41600 events read in total (2548ms).
[15:42:11.795] INFO: Test took 3822ms.
[15:42:11.829] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:12.556] INFO: Expecting 41600 events.
[15:42:15.808] INFO: 41600 events read in total (2725ms).
[15:42:15.809] INFO: Test took 3963ms.
[15:42:15.847] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:16.568] INFO: Expecting 41600 events.
[15:42:19.835] INFO: 41600 events read in total (2741ms).
[15:42:19.836] INFO: Test took 3971ms.
[15:42:19.872] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:20.586] INFO: Expecting 41600 events.
[15:42:23.831] INFO: 41600 events read in total (2719ms).
[15:42:23.832] INFO: Test took 3942ms.
[15:42:23.869] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:24.588] INFO: Expecting 41600 events.
[15:42:27.904] INFO: 41600 events read in total (2790ms).
[15:42:27.905] INFO: Test took 4018ms.
[15:42:27.942] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:28.653] INFO: Expecting 41600 events.
[15:42:31.968] INFO: 41600 events read in total (2788ms).
[15:42:31.969] INFO: Test took 4009ms.
[15:42:32.006] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:32.721] INFO: Expecting 41600 events.
[15:42:35.992] INFO: 41600 events read in total (2745ms).
[15:42:35.993] INFO: Test took 3968ms.
[15:42:36.030] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:36.748] INFO: Expecting 41600 events.
[15:42:40.069] INFO: 41600 events read in total (2794ms).
[15:42:40.070] INFO: Test took 4021ms.
[15:42:40.107] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:40.822] INFO: Expecting 41600 events.
[15:42:44.118] INFO: 41600 events read in total (2769ms).
[15:42:44.119] INFO: Test took 3993ms.
[15:42:44.156] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:44.875] INFO: Expecting 41600 events.
[15:42:48.157] INFO: 41600 events read in total (2755ms).
[15:42:48.158] INFO: Test took 3983ms.
[15:42:48.195] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:48.910] INFO: Expecting 41600 events.
[15:42:52.262] INFO: 41600 events read in total (2825ms).
[15:42:52.263] INFO: Test took 4050ms.
[15:42:52.311] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:52.999] INFO: Expecting 41600 events.
[15:42:56.307] INFO: 41600 events read in total (2781ms).
[15:42:56.308] INFO: Test took 3970ms.
[15:42:56.344] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:42:57.063] INFO: Expecting 41600 events.
[15:43:00.368] INFO: 41600 events read in total (2778ms).
[15:43:00.369] INFO: Test took 4007ms.
[15:43:00.406] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:01.116] INFO: Expecting 41600 events.
[15:43:04.490] INFO: 41600 events read in total (2847ms).
[15:43:04.492] INFO: Test took 4067ms.
[15:43:04.528] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:05.246] INFO: Expecting 41600 events.
[15:43:08.493] INFO: 41600 events read in total (2720ms).
[15:43:08.494] INFO: Test took 3948ms.
[15:43:08.535] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:09.238] INFO: Expecting 41600 events.
[15:43:12.606] INFO: 41600 events read in total (2842ms).
[15:43:12.607] INFO: Test took 4051ms.
[15:43:12.644] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:13.365] INFO: Expecting 41600 events.
[15:43:16.671] INFO: 41600 events read in total (2779ms).
[15:43:16.671] INFO: Test took 4006ms.
[15:43:16.709] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:17.427] INFO: Expecting 41600 events.
[15:43:20.722] INFO: 41600 events read in total (2768ms).
[15:43:20.723] INFO: Test took 3996ms.
[15:43:20.765] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:21.469] INFO: Expecting 41600 events.
[15:43:24.730] INFO: 41600 events read in total (2735ms).
[15:43:24.731] INFO: Test took 3941ms.
[15:43:24.772] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:25.484] INFO: Expecting 41600 events.
[15:43:28.653] INFO: 41600 events read in total (2642ms).
[15:43:28.654] INFO: Test took 3864ms.
[15:43:28.693] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:43:29.050] INFO: enter test to run
[15:43:49.791] INFO: test: HighRate no parameter change
[15:43:49.791] INFO: running: highrate
[15:43:49.792] INFO: ----------------------------------------------------------------------
[15:43:49.792] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:43:49.792] INFO: ----------------------------------------------------------------------
[15:43:50.410] INFO: Expecting 208000 events.
[15:44:02.370] INFO: 208000 events read in total (11433ms).
[15:44:02.373] INFO: Test took 12572ms.
[15:44:02.527] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:02.783] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 160 1 1 0 0 0 13 0
[15:44:02.783] INFO: number of red-efficiency pixels: 88 51 85 94 119 133 163 96 260 126 137 109 114 75 39 33
[15:44:02.783] INFO: number of X-ray hits detected: 67374 46586 67784 105953 111782 118214 117714 77274 79030 115656 114887 98683 99026 61028 24043 27113
[15:44:02.783] 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:44:02.783] INFO: number of Vcal hits detected: 207911 207949 207914 207904 207837 207862 207833 207903 199898 207823 207811 207887 207885 207900 207312 207967
[15:44:02.783] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[15:44:02.783] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 96.1 99.9 99.9 99.9 99.9 100.0 99.7 100.0
[15:44:02.783] INFO: X-ray hit rate [MHz/cm2]: 19.7 13.7 19.9 31.1 32.8 34.6 34.5 22.6 23.2 33.9 33.7 28.9 29.0 17.9 7.0 7.9
[15:44:02.783] INFO: PixTestHighRate::doXPixelAlive() done
[15:44:02.834] INFO: PixTest:: pg_setup set to default.
[15:44:02.849] INFO: enter test to run
[15:44:22.455] INFO: test: HighRate no parameter change
[15:44:22.455] INFO: running: highrate
[15:44:22.456] INFO: ----------------------------------------------------------------------
[15:44:22.456] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:44:22.456] INFO: ----------------------------------------------------------------------
[15:44:23.072] INFO: Expecting 208000 events.
[15:44:36.661] INFO: 208000 events read in total (13062ms).
[15:44:36.667] INFO: Test took 14202ms.
[15:44:36.969] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:44:37.270] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 160 1 1 0 0 0 13 0
[15:44:37.270] INFO: number of red-efficiency pixels: 208 125 269 306 344 348 485 278 427 335 351 355 264 183 66 53
[15:44:37.270] INFO: number of X-ray hits detected: 130700 90301 132051 205485 217785 228903 227480 148480 153910 224153 223366 191289 193239 118197 47704 52942
[15:44:37.270] 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:44:37.270] INFO: number of Vcal hits detected: 207774 207866 207708 207673 207583 207620 207467 207704 199720 207603 207574 207610 207723 207777 207284 207947
[15:44:37.270] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.9 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.8 99.9 99.9 100.0 100.0
[15:44:37.270] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.7 99.9 96.0 99.8 99.8 99.8 99.9 99.9 99.7 100.0
[15:44:37.270] INFO: X-ray hit rate [MHz/cm2]: 38.3 26.5 38.7 60.2 63.8 67.1 66.7 43.5 45.1 65.7 65.5 56.1 56.6 34.6 14.0 15.5
[15:44:37.270] INFO: PixTestHighRate::doXPixelAlive() done
[15:44:37.323] INFO: PixTest:: pg_setup set to default.
[15:44:37.338] INFO: enter test to run
[15:44:56.135] INFO: test: HighRate no parameter change
[15:44:56.135] INFO: running: highrate
[15:44:56.136] INFO: ----------------------------------------------------------------------
[15:44:56.136] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:44:56.136] INFO: ----------------------------------------------------------------------
[15:44:56.754] INFO: Expecting 208000 events.
[15:45:11.935] INFO: 208000 events read in total (14654ms).
[15:45:11.942] INFO: Test took 15796ms.
[15:45:12.367] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:45:12.708] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 160 1 1 0 0 0 13 0
[15:45:12.708] INFO: number of red-efficiency pixels: 375 269 524 606 672 763 1016 550 652 693 783 751 543 311 101 87
[15:45:12.708] INFO: number of X-ray hits detected: 187860 129661 190117 294568 313084 326839 328099 212923 221643 321717 319518 274522 275879 169503 68002 75968
[15:45:12.708] 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:45:12.708] INFO: number of Vcal hits detected: 207575 207712 207346 207306 207146 207104 206773 207328 199410 207163 207011 207092 207408 207595 207246 207912
[15:45:12.708] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.7 99.6 99.6 99.5 99.7 99.7 99.7 99.6 99.6 99.7 99.8 100.0 100.0
[15:45:12.708] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.7 99.6 99.6 99.4 99.7 95.9 99.6 99.5 99.6 99.7 99.8 99.6 100.0
[15:45:12.708] INFO: X-ray hit rate [MHz/cm2]: 55.1 38.0 55.7 86.3 91.8 95.8 96.2 62.4 65.0 94.3 93.7 80.5 80.9 49.7 19.9 22.3
[15:45:12.708] INFO: PixTestHighRate::doXPixelAlive() done
[15:45:12.754] INFO: PixTest:: pg_setup set to default.
[15:45:12.765] INFO: enter test to run
[15:45:40.174] INFO: test: exit no parameter change
[15:45:40.814] QUIET: Connection to board 30 closed.
[15:45:40.846] INFO: pXar: this is the end, my friend