[11:14:20.718] INFO: *** Welcome to pxar ***
[11:14:20.718] INFO: *** Today: 2016/10/26
[11:14:22.030] INFO: *** Version: v1.9.0-818-g96727
[11:14:22.030] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//dacParameters35_C15.dat
[11:14:22.118] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:14:22.118] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//defaultMaskFile.dat
[11:14:22.125] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C15.dat
[11:14:22.362] INFO: clk: 4
[11:14:22.362] INFO: ctr: 4
[11:14:22.362] INFO: sda: 19
[11:14:22.362] INFO: tin: 9
[11:14:22.362] INFO: level: 15
[11:14:22.362] INFO: triggerdelay: 0
[11:14:22.362] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:14:22.362] INFO: Log level: INFO
[11:14:22.381] QUIET: Connection to board DTB_WREHUL opened.
[11:14:22.384] 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:
------------------------------------------------------
[11:14:22.387] INFO: RPC call hashes of host and DTB match: 398089610
[11:14:23.940] INFO: DUT info:
[11:14:23.940] INFO: The DUT currently contains the following objects:
[11:14:23.940] INFO: 2 TBM Cores tbm08c (2 ON)
[11:14:23.940] INFO: TBM Core alpha (0): 7 registers set
[11:14:23.940] INFO: TBM Core beta (1): 7 registers set
[11:14:23.940] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:14:23.940] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.940] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.940] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.940] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.940] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.940] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.940] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.940] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.941] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.941] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.941] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.941] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.941] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.941] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.941] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:23.941] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:14:24.397] INFO: enter 'restricted' command line mode
[11:14:24.397] INFO: enter test to run
[11:14:31.380] INFO: test: PixelAlive no parameter change
[11:14:31.380] INFO: running: pixelalive
[11:14:31.433] INFO: ----------------------------------------------------------------------
[11:14:31.433] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:14:31.434] INFO: ----------------------------------------------------------------------
[11:14:31.756] INFO: Expecting 41600 events.
[11:14:36.100] INFO: 41600 events read in total (3625ms).
[11:14:36.269] INFO: Test took 4832ms.
[11:14:36.280] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:36.820] INFO: PixTestAlive::aliveTest() done
[11:14:36.820] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 1 0 0 0 0 0 0 0
[11:14:37.008] INFO: enter test to run
[11:14:41.292] INFO: test: timing no parameter change
[11:14:41.292] INFO: running: timing
[11:14:41.295] INFO: ######################################################################
[11:14:41.295] INFO: PixTestTiming::doTest()
[11:14:41.295] INFO: ######################################################################
[11:14:41.295] INFO: ----------------------------------------------------------------------
[11:14:41.295] INFO: PixTestTiming::TBMPhaseScan()
[11:14:41.295] INFO: ----------------------------------------------------------------------
[11:20:28.827] INFO: TBM Phase Settings: 236
[11:20:28.827] INFO: 400MHz Phase: 3
[11:20:28.827] INFO: 160MHz Phase: 7
[11:20:28.827] INFO: Functional Phase Area: 4
[11:20:28.847] INFO: Test took 347552 ms.
[11:20:28.847] INFO: PixTestTiming::TBMPhaseScan() done.
[11:20:28.847] INFO: ----------------------------------------------------------------------
[11:20:28.847] INFO: PixTestTiming::ROCDelayScan()
[11:20:28.847] INFO: ----------------------------------------------------------------------
[11:22:33.383] INFO: ROC Delay Settings: 228
[11:22:33.383] INFO: ROC Header-Trailer/Token Delay: 11
[11:22:33.384] INFO: ROC Port 0 Delay: 4
[11:22:33.384] INFO: ROC Port 1 Delay: 4
[11:22:33.384] INFO: Functional ROC Area: 5
[11:22:33.387] INFO: Test took 124540 ms.
[11:22:33.387] INFO: PixTestTiming::ROCDelayScan() done.
[11:22:33.387] INFO: ----------------------------------------------------------------------
[11:22:33.388] INFO: PixTestTiming::TimingTest()
[11:22:33.388] INFO: ----------------------------------------------------------------------
[11:22:49.870] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:23:05.019] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:23:20.252] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:23:35.409] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:23:50.373] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:24:05.369] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:24:20.356] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:24:35.326] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:24:50.333] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:25:05.332] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:25:05.710] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:25:05.728] INFO: ----------------------------------------------------------------------
[11:25:05.728] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:25:05.728] INFO: ----------------------------------------------------------------------
[11:25:05.728] INFO: ----------------------------------------------------------------------
[11:25:05.728] INFO: Read back bit status: 1
[11:25:05.728] INFO: ----------------------------------------------------------------------
[11:25:05.728] INFO: ----------------------------------------------------------------------
[11:25:05.728] INFO: Timings are good!
[11:25:05.728] INFO: ----------------------------------------------------------------------
[11:25:05.728] INFO: Test took 152341 ms.
[11:25:05.728] INFO: PixTestTiming::TimingTest() done.
[11:25:05.743] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:25:05.743] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:25:05.743] INFO: PixTestTiming::doTest took 624451 ms.
[11:25:05.744] INFO: PixTestTiming::doTest() done
[11:25:05.744] INFO: Write out TBMPhaseScan_0_V0
[11:25:05.744] INFO: Write out TBMPhaseScan_1_V0
[11:25:05.744] INFO: Write out CombinedTBMPhaseScan_V0
[11:25:05.769] INFO: Write out ROCDelayScan3_V0
[11:25:05.770] INFO: enter test to run
[11:25:46.711] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:25:46.711] INFO: running: highrate
[11:25:46.736] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:25:47.060] INFO: ----------------------------------------------------------------------
[11:25:47.060] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:25:47.060] INFO: ----------------------------------------------------------------------
[11:25:47.060] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:25:47.060] INFO: edge/corner pixel THR is adjusted
[11:25:47.060] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:25:48.039] INFO: Collecting data for 5 seconds...
[11:25:53.058] INFO: Done with hot pixel readout
[11:26:04.789] INFO: PixTest:: pg_setup set to default.
[11:26:04.790] INFO: 6 hot pixels found in step 0
[11:26:05.783] INFO: Collecting data for 5 seconds...
[11:26:10.800] INFO: Done with hot pixel readout
[11:26:22.458] INFO: PixTest:: pg_setup set to default.
[11:26:22.458] INFO: 4 hot pixels found in step 1
[11:26:23.452] INFO: Collecting data for 5 seconds...
[11:26:28.469] INFO: Done with hot pixel readout
[11:26:40.149] INFO: PixTest:: pg_setup set to default.
[11:26:40.149] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:26:40.150] INFO: 9 hot pixels found in step 2
[11:26:41.144] INFO: Collecting data for 5 seconds...
[11:26:46.160] INFO: Done with hot pixel readout
[11:26:57.911] INFO: PixTest:: pg_setup set to default.
[11:26:57.912] INFO: 5 hot pixels found in step 3
[11:26:58.907] INFO: Collecting data for 5 seconds...
[11:27:03.923] INFO: Done with hot pixel readout
[11:27:15.574] INFO: PixTest:: pg_setup set to default.
[11:27:15.575] INFO: 4 hot pixels found in step 4
[11:27:16.568] INFO: Collecting data for 5 seconds...
[11:27:21.585] INFO: Done with hot pixel readout
[11:27:33.296] INFO: PixTest:: pg_setup set to default.
[11:27:33.297] INFO: 7 hot pixels found in step 5
[11:27:34.291] INFO: Collecting data for 5 seconds...
[11:27:39.307] INFO: Done with hot pixel readout
[11:27:50.924] INFO: PixTest:: pg_setup set to default.
[11:27:50.925] INFO: 8 hot pixels found in step 6
[11:27:51.919] INFO: Collecting data for 5 seconds...
[11:27:56.935] INFO: Done with hot pixel readout
[11:28:08.658] INFO: PixTest:: pg_setup set to default.
[11:28:08.658] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:28:08.658] INFO: 12 hot pixels found in step 7
[11:28:09.653] INFO: Collecting data for 5 seconds...
[11:28:14.670] INFO: Done with hot pixel readout
[11:28:26.399] INFO: PixTest:: pg_setup set to default.
[11:28:26.400] INFO: 6 hot pixels found in step 8
[11:28:27.394] INFO: Collecting data for 5 seconds...
[11:28:32.411] INFO: Done with hot pixel readout
[11:28:44.070] INFO: PixTest:: pg_setup set to default.
[11:28:44.071] INFO: 3 hot pixels found in step 9
[11:28:45.065] INFO: Collecting data for 5 seconds...
[11:28:50.081] INFO: Done with hot pixel readout
[11:29:01.808] INFO: PixTest:: pg_setup set to default.
[11:29:01.809] INFO: 6 hot pixels found in step 10
[11:29:02.803] INFO: Collecting data for 5 seconds...
[11:29:07.820] INFO: Done with hot pixel readout
[11:29:19.497] INFO: PixTest:: pg_setup set to default.
[11:29:19.497] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:29:19.498] INFO: 4 hot pixels found in step 11
[11:29:20.492] INFO: Collecting data for 5 seconds...
[11:29:25.508] INFO: Done with hot pixel readout
[11:29:37.210] INFO: PixTest:: pg_setup set to default.
[11:29:37.211] INFO: 4 hot pixels found in step 12
[11:29:38.205] INFO: Collecting data for 5 seconds...
[11:29:43.221] INFO: Done with hot pixel readout
[11:29:54.803] INFO: PixTest:: pg_setup set to default.
[11:29:54.804] INFO: 2 hot pixels found in step 13
[11:29:55.798] INFO: Collecting data for 5 seconds...
[11:30:00.815] INFO: Done with hot pixel readout
[11:30:12.476] INFO: PixTest:: pg_setup set to default.
[11:30:12.476] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:30:12.477] INFO: 5 hot pixels found in step 14
[11:30:12.515] INFO: 5 hot pixels could not be trimmed and have been masked.
[11:30:12.518] INFO: PixTest::trimHotPixels() done
[11:30:12.518] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C0.dat
[11:30:12.531] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C1.dat
[11:30:12.543] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C2.dat
[11:30:12.549] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C3.dat
[11:30:12.554] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C4.dat
[11:30:12.559] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C5.dat
[11:30:12.565] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C6.dat
[11:30:12.570] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C7.dat
[11:30:12.576] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C8.dat
[11:30:12.581] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C9.dat
[11:30:12.587] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C10.dat
[11:30:12.592] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C11.dat
[11:30:12.598] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C12.dat
[11:30:12.603] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C13.dat
[11:30:12.609] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C14.dat
[11:30:12.614] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C15.dat
[11:30:12.620] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//defaultMaskFile.dat
[11:30:12.635] INFO: enter test to run
[11:30:38.437] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:30:38.438] INFO: running: highrate
[11:30:38.442] INFO: ----------------------------------------------------------------------
[11:30:38.442] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:30:38.442] INFO: ----------------------------------------------------------------------
[11:30:38.442] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:30:38.442] INFO: edge/corner pixel THR is adjusted
[11:30:38.442] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:30:39.400] INFO: Collecting data for 1 seconds...
[11:30:40.403] INFO: Done with hot pixel readout
[11:30:44.418] INFO: PixTest:: pg_setup set to default.
[11:30:44.419] INFO: 0 hot pixels found in step 0
[11:30:44.424] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:30:44.513] INFO: PixTest::trimHotPixels() done
[11:30:44.513] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C0.dat
[11:30:44.523] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C1.dat
[11:30:44.529] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C2.dat
[11:30:44.534] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C3.dat
[11:30:44.539] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C4.dat
[11:30:44.545] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C5.dat
[11:30:44.550] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C6.dat
[11:30:44.555] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C7.dat
[11:30:44.560] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C8.dat
[11:30:44.565] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C9.dat
[11:30:44.571] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C10.dat
[11:30:44.576] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C11.dat
[11:30:44.581] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C12.dat
[11:30:44.587] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C13.dat
[11:30:44.592] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C14.dat
[11:30:44.597] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C15.dat
[11:30:44.602] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-10_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//defaultMaskFile.dat
[11:30:44.612] INFO: enter test to run
[11:31:29.941] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:31:29.941] INFO: running: xray
[11:31:29.943] INFO: ----------------------------------------------------------------------
[11:31:29.943] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:31:29.943] INFO: ----------------------------------------------------------------------
[11:31:30.925] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:31:42.257] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:32:12.167] INFO: Resuming triggers.
[11:32:23.500] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[11:32:53.234] INFO: Resuming triggers.
[11:33:04.567] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[11:33:34.271] INFO: Resuming triggers.
[11:33:45.603] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[11:34:15.506] INFO: Resuming triggers.
[11:34:26.841] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[11:34:56.696] INFO: Resuming triggers.
[11:35:08.030] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[11:35:37.307] INFO: Resuming triggers.
[11:35:48.642] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[11:36:18.890] INFO: Resuming triggers.
[11:36:30.224] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[11:37:00.620] INFO: Resuming triggers.
[11:37:10.326] INFO: data taking finished, elapsed time: 100 seconds.
[11:37:36.470] INFO: PixTest:: pg_setup set to default.
[11:37:36.473] INFO: PixTestXray::doPhRun() done
[11:37:36.727] INFO: enter test to run
[11:38:16.098] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:38:16.098] INFO: running: xray
[11:38:16.100] INFO: ----------------------------------------------------------------------
[11:38:16.100] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:38:16.100] INFO: ----------------------------------------------------------------------
[11:38:17.079] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:38:23.689] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:38:55.122] INFO: Resuming triggers.
[11:39:01.735] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[11:39:32.284] INFO: Resuming triggers.
[11:39:38.894] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[11:40:08.821] INFO: Resuming triggers.
[11:40:15.428] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[11:40:45.574] INFO: Resuming triggers.
[11:40:52.187] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[11:41:22.317] INFO: Resuming triggers.
[11:41:28.929] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[11:41:59.178] INFO: Resuming triggers.
[11:42:05.788] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:42:35.892] INFO: Resuming triggers.
[11:42:42.498] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[11:43:12.348] INFO: Resuming triggers.
[11:43:18.953] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[11:43:48.963] INFO: Resuming triggers.
[11:43:55.574] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[11:44:25.816] INFO: Resuming triggers.
[11:44:32.423] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[11:45:02.504] INFO: Resuming triggers.
[11:45:09.107] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[11:45:39.303] INFO: Resuming triggers.
[11:45:45.912] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[11:46:16.795] INFO: Resuming triggers.
[11:46:23.402] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[11:46:53.947] INFO: Resuming triggers.
[11:47:00.559] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[11:47:31.616] INFO: Resuming triggers.
[11:47:32.831] INFO: data taking finished, elapsed time: 100 seconds.
[11:47:38.872] INFO: PixTest:: pg_setup set to default.
[11:47:38.875] INFO: PixTestXray::doPhRun() done
[11:47:39.061] INFO: enter test to run
[11:48:28.430] INFO: test: HighRate no parameter change
[11:48:28.430] INFO: running: highrate
[11:48:28.450] INFO: ----------------------------------------------------------------------
[11:48:28.450] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:48:28.450] INFO: ----------------------------------------------------------------------
[11:48:28.616] INFO: Expecting 768 events.
[11:48:29.750] INFO: 768 events read in total (419ms).
[11:48:29.750] INFO: Test took 1288ms.
[11:48:30.553] INFO: Expecting 41600 events.
[11:48:33.659] INFO: 41600 events read in total (2579ms).
[11:48:33.660] INFO: Test took 3904ms.
[11:48:33.695] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:48:34.420] INFO: Expecting 41600 events.
[11:48:37.559] INFO: 41600 events read in total (2612ms).
[11:48:37.560] INFO: Test took 3846ms.
[11:48:37.595] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:48:38.320] INFO: Expecting 41600 events.
[11:48:41.593] INFO: 41600 events read in total (2746ms).
[11:48:41.594] INFO: Test took 3982ms.
[11:48:41.631] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:48:42.351] INFO: Expecting 41600 events.
[11:48:45.605] INFO: 41600 events read in total (2727ms).
[11:48:45.606] INFO: Test took 3956ms.
[11:48:45.649] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:48:46.347] INFO: Expecting 41600 events.
[11:48:49.528] INFO: 41600 events read in total (2654ms).
[11:48:49.529] INFO: Test took 3863ms.
[11:48:49.564] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:48:50.287] INFO: Expecting 41600 events.
[11:48:53.676] INFO: 41600 events read in total (2862ms).
[11:48:53.677] INFO: Test took 4096ms.
[11:48:53.712] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:48:54.432] INFO: Expecting 41600 events.
[11:48:57.683] INFO: 41600 events read in total (2724ms).
[11:48:57.684] INFO: Test took 3953ms.
[11:48:57.720] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:48:58.437] INFO: Expecting 41600 events.
[11:49:01.682] INFO: 41600 events read in total (2718ms).
[11:49:01.683] INFO: Test took 3945ms.
[11:49:01.719] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:02.440] INFO: Expecting 41600 events.
[11:49:05.689] INFO: 41600 events read in total (2722ms).
[11:49:05.690] INFO: Test took 3953ms.
[11:49:05.730] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:06.447] INFO: Expecting 41600 events.
[11:49:09.729] INFO: 41600 events read in total (2756ms).
[11:49:09.730] INFO: Test took 3979ms.
[11:49:09.766] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:10.482] INFO: Expecting 41600 events.
[11:49:13.728] INFO: 41600 events read in total (2719ms).
[11:49:13.729] INFO: Test took 3944ms.
[11:49:13.764] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:14.477] INFO: Expecting 41600 events.
[11:49:17.744] INFO: 41600 events read in total (2740ms).
[11:49:17.745] INFO: Test took 3962ms.
[11:49:17.781] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:18.496] INFO: Expecting 41600 events.
[11:49:21.776] INFO: 41600 events read in total (2754ms).
[11:49:21.777] INFO: Test took 3978ms.
[11:49:21.812] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:22.537] INFO: Expecting 41600 events.
[11:49:25.838] INFO: 41600 events read in total (2774ms).
[11:49:25.839] INFO: Test took 4009ms.
[11:49:25.875] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:26.597] INFO: Expecting 41600 events.
[11:49:29.783] INFO: 41600 events read in total (2659ms).
[11:49:29.784] INFO: Test took 3891ms.
[11:49:29.820] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:30.540] INFO: Expecting 41600 events.
[11:49:33.780] INFO: 41600 events read in total (2713ms).
[11:49:33.781] INFO: Test took 3942ms.
[11:49:33.819] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:34.527] INFO: Expecting 41600 events.
[11:49:37.768] INFO: 41600 events read in total (2714ms).
[11:49:37.769] INFO: Test took 3924ms.
[11:49:37.804] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:38.528] INFO: Expecting 41600 events.
[11:49:41.760] INFO: 41600 events read in total (2705ms).
[11:49:41.762] INFO: Test took 3940ms.
[11:49:41.800] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:42.502] INFO: Expecting 41600 events.
[11:49:45.792] INFO: 41600 events read in total (2764ms).
[11:49:45.793] INFO: Test took 3966ms.
[11:49:45.828] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:46.549] INFO: Expecting 41600 events.
[11:49:49.508] INFO: 41600 events read in total (2432ms).
[11:49:49.509] INFO: Test took 3663ms.
[11:49:49.543] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:49.907] INFO: enter test to run
[11:49:53.694] INFO: test: HighRate no parameter change
[11:49:53.694] INFO: running: highrate
[11:49:53.695] INFO: ----------------------------------------------------------------------
[11:49:53.695] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:49:53.695] INFO: ----------------------------------------------------------------------
[11:49:54.312] INFO: Expecting 208000 events.
[11:50:06.070] INFO: 208000 events read in total (11232ms).
[11:50:06.073] INFO: Test took 12372ms.
[11:50:06.226] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:06.481] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 1 0 0 0 0 0 0 0
[11:50:06.481] INFO: number of red-efficiency pixels: 76 38 77 99 123 107 123 84 89 159 142 113 104 69 21 29
[11:50:06.481] INFO: number of X-ray hits detected: 62604 38040 65770 94096 106390 112416 114853 80184 80243 112709 108687 91901 96681 57190 22774 24754
[11:50:06.481] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:50:06.481] INFO: number of Vcal hits detected: 207924 207962 207919 207896 207825 207889 207875 207914 207860 207837 207856 207883 207895 207929 207979 207971
[11:50:06.481] 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 99.9 100.0 100.0 100.0 100.0
[11:50:06.481] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[11:50:06.481] INFO: X-ray hit rate [MHz/cm2]: 18.3 11.1 19.3 27.6 31.2 32.9 33.7 23.5 23.5 33.0 31.9 26.9 28.3 16.8 6.7 7.3
[11:50:06.481] INFO: PixTestHighRate::doXPixelAlive() done
[11:50:06.529] INFO: PixTest:: pg_setup set to default.
[11:50:06.544] INFO: enter test to run
[11:50:43.165] INFO: test: HighRate no parameter change
[11:50:43.165] INFO: running: highrate
[11:50:43.166] INFO: ----------------------------------------------------------------------
[11:50:43.167] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:50:43.167] INFO: ----------------------------------------------------------------------
[11:50:43.795] INFO: Expecting 208000 events.
[11:50:58.013] INFO: 208000 events read in total (13691ms).
[11:50:58.018] INFO: Test took 14843ms.
[11:50:58.332] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:58.642] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 1 0 0 0 0 0 0 0
[11:50:58.642] INFO: number of red-efficiency pixels: 205 109 268 329 340 413 429 269 314 570 473 354 325 182 59 56
[11:50:58.642] INFO: number of X-ray hits detected: 129194 78470 136992 194813 219082 232385 239685 166855 167077 234289 226153 191123 201122 119372 47774 51567
[11:50:58.642] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:50:58.642] INFO: number of Vcal hits detected: 207785 207887 207703 207642 207587 207548 207533 207715 207609 207358 207490 207623 207663 207805 207940 207943
[11:50:58.642] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.7 99.8 99.8 99.8 99.9 100.0 100.0
[11:50:58.642] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.8 99.7 99.8 99.8 99.8 99.9 100.0 100.0
[11:50:58.642] INFO: X-ray hit rate [MHz/cm2]: 37.9 23.0 40.2 57.1 64.2 68.1 70.3 48.9 49.0 68.7 66.3 56.0 59.0 35.0 14.0 15.1
[11:50:58.643] INFO: PixTestHighRate::doXPixelAlive() done
[11:50:58.687] INFO: PixTest:: pg_setup set to default.
[11:50:58.710] INFO: enter test to run
[11:51:17.005] INFO: test: HighRate no parameter change
[11:51:17.005] INFO: running: highrate
[11:51:18.006] INFO: ----------------------------------------------------------------------
[11:51:18.006] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:51:18.006] INFO: ----------------------------------------------------------------------
[11:51:18.626] INFO: Expecting 208000 events.
[11:51:34.928] INFO: 208000 events read in total (15775ms).
[11:51:34.935] INFO: Test took 16920ms.
[11:51:35.415] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:35.789] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 0 0 1 0 0 0 0 0 0 0
[11:51:35.789] INFO: number of red-efficiency pixels: 429 237 596 812 775 947 1087 553 651 1301 1150 805 790 412 115 77
[11:51:35.789] INFO: number of X-ray hits detected: 196773 119391 206020 294348 332607 351488 362708 253822 253434 355242 340920 288832 303592 181197 72262 78896
[11:51:35.789] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:51:35.789] INFO: number of Vcal hits detected: 207514 207744 207220 207058 207038 206830 206629 207340 207160 206350 206547 207022 207113 207535 207884 207922
[11:51:35.789] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.6 99.6 99.5 99.4 99.7 99.7 99.3 99.4 99.6 99.6 99.8 99.9 100.0
[11:51:35.789] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.6 99.5 99.5 99.4 99.3 99.7 99.6 99.2 99.3 99.5 99.6 99.8 99.9 100.0
[11:51:35.789] INFO: X-ray hit rate [MHz/cm2]: 57.7 35.0 60.4 86.3 97.5 103.0 106.3 74.4 74.3 104.1 99.9 84.7 89.0 53.1 21.2 23.1
[11:51:35.789] INFO: PixTestHighRate::doXPixelAlive() done
[11:51:35.834] INFO: PixTest:: pg_setup set to default.
[11:51:35.852] INFO: enter test to run
[11:51:56.829] INFO: test: exit no parameter change
[11:51:57.971] QUIET: Connection to board 30 closed.
[11:51:58.062] INFO: pXar: this is the end, my friend