[15:23:10.708] INFO: *** Welcome to pxar ***
[15:23:10.708] INFO: *** Today: 2016/09/28
[15:23:11.570] INFO: *** Version: v1.9.0-818-g96727
[15:23:11.570] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//dacParameters35_C15.dat
[15:23:11.627] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:23:11.627] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//defaultMaskFile.dat
[15:23:11.637] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C15.dat
[15:23:11.731] INFO: clk: 4
[15:23:11.731] INFO: ctr: 4
[15:23:11.731] INFO: sda: 19
[15:23:11.731] INFO: tin: 9
[15:23:11.731] INFO: level: 15
[15:23:11.731] INFO: triggerdelay: 0
[15:23:11.732] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:23:11.732] INFO: Log level: INFO
[15:23:11.761] QUIET: Connection to board DTB_WREKRL opened.
[15:23:11.764] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[15:23:11.767] INFO: RPC call hashes of host and DTB match: 398089610
[15:23:13.301] INFO: DUT info:
[15:23:13.301] INFO: The DUT currently contains the following objects:
[15:23:13.301] INFO: 2 TBM Cores tbm08c (2 ON)
[15:23:13.301] INFO: TBM Core alpha (0): 7 registers set
[15:23:13.301] INFO: TBM Core beta (1): 7 registers set
[15:23:13.301] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:23:13.301] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.301] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.301] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.302] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:23:13.719] INFO: enter 'restricted' command line mode
[15:23:13.719] INFO: enter test to run
[15:23:25.535] INFO: test: PixelAlive no parameter change
[15:23:25.535] INFO: running: pixelalive
[15:23:25.554] INFO: ----------------------------------------------------------------------
[15:23:25.554] 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:23:25.555] INFO: ----------------------------------------------------------------------
[15:23:25.888] INFO: Expecting 41600 events.
[15:23:30.207] INFO: 41600 events read in total (3601ms).
[15:23:30.375] INFO: Test took 4818ms.
[15:23:30.389] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:23:30.677] INFO: PixTestAlive::aliveTest() done
[15:23:30.677] INFO: number of dead pixels (per ROC): 0 2 0 0 0 0 0 1 1 1 0 0 0 1 0 0
[15:23:30.714] INFO: enter test to run
[15:23:36.295] INFO: test: timing no parameter change
[15:23:36.295] INFO: running: timing
[15:23:36.298] INFO: ######################################################################
[15:23:36.298] INFO: PixTestTiming::doTest()
[15:23:36.298] INFO: ######################################################################
[15:23:36.298] INFO: ----------------------------------------------------------------------
[15:23:36.298] INFO: PixTestTiming::TBMPhaseScan()
[15:23:36.298] INFO: ----------------------------------------------------------------------
[15:32:16.945] INFO: TBM Phase Settings: 248
[15:32:16.945] INFO: 400MHz Phase: 6
[15:32:16.945] INFO: 160MHz Phase: 7
[15:32:16.945] INFO: Functional Phase Area: 5
[15:32:16.948] INFO: Test took 520650 ms.
[15:32:16.948] INFO: PixTestTiming::TBMPhaseScan() done.
[15:32:16.948] INFO: ----------------------------------------------------------------------
[15:32:16.948] INFO: PixTestTiming::ROCDelayScan()
[15:32:16.949] INFO: ----------------------------------------------------------------------
[15:35:24.128] INFO: ROC Delay Settings: 228
[15:35:24.128] INFO: ROC Header-Trailer/Token Delay: 11
[15:35:24.128] INFO: ROC Port 0 Delay: 4
[15:35:24.128] INFO: ROC Port 1 Delay: 4
[15:35:24.128] INFO: Functional ROC Area: 5
[15:35:24.132] INFO: Test took 187184 ms.
[15:35:24.132] INFO: PixTestTiming::ROCDelayScan() done.
[15:35:24.132] INFO: ----------------------------------------------------------------------
[15:35:24.132] INFO: PixTestTiming::TimingTest()
[15:35:24.132] INFO: ----------------------------------------------------------------------
[15:35:40.618] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:35:55.762] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:10.950] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:26.083] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:41.228] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:36:56.397] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:37:11.695] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:37:26.732] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:37:41.707] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:37:56.696] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:37:57.078] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:37:57.096] INFO: ----------------------------------------------------------------------
[15:37:57.096] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:37:57.096] INFO: ----------------------------------------------------------------------
[15:37:57.096] INFO: ----------------------------------------------------------------------
[15:37:57.096] INFO: Read back bit status: 1
[15:37:57.096] INFO: ----------------------------------------------------------------------
[15:37:57.096] INFO: ----------------------------------------------------------------------
[15:37:57.096] INFO: Timings are good!
[15:37:57.096] INFO: ----------------------------------------------------------------------
[15:37:57.096] INFO: Test took 152964 ms.
[15:37:57.096] INFO: PixTestTiming::TimingTest() done.
[15:37:57.096] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:37:57.096] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:37:57.096] INFO: PixTestTiming::doTest took 860801 ms.
[15:37:57.096] INFO: PixTestTiming::doTest() done
[15:37:57.096] INFO: Write out TBMPhaseScan_0_V0
[15:37:57.096] INFO: Write out TBMPhaseScan_1_V0
[15:37:57.096] INFO: Write out CombinedTBMPhaseScan_V0
[15:37:57.097] INFO: Write out ROCDelayScan3_V0
[15:37:57.098] INFO: enter test to run
[15:38:35.961] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:38:35.961] INFO: running: highrate
[15:38:35.961] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:38:36.203] INFO: ----------------------------------------------------------------------
[15:38:36.203] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:38:36.203] INFO: ----------------------------------------------------------------------
[15:38:36.203] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:38:36.203] INFO: edge/corner pixel THR is adjusted
[15:38:36.203] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:38:37.162] INFO: Collecting data for 5 seconds...
[15:38:42.178] INFO: Done with hot pixel readout
[15:38:53.920] INFO: PixTest:: pg_setup set to default.
[15:38:53.921] INFO: 21 hot pixels found in step 0
[15:38:54.913] INFO: Collecting data for 5 seconds...
[15:38:59.930] INFO: Done with hot pixel readout
[15:39:11.667] INFO: PixTest:: pg_setup set to default.
[15:39:11.667] INFO: 22 hot pixels found in step 1
[15:39:12.661] INFO: Collecting data for 5 seconds...
[15:39:17.678] INFO: Done with hot pixel readout
[15:39:29.408] INFO: PixTest:: pg_setup set to default.
[15:39:29.409] INFO: 21 hot pixels found in step 2
[15:39:30.402] INFO: Collecting data for 5 seconds...
[15:39:35.419] INFO: Done with hot pixel readout
[15:39:47.182] INFO: PixTest:: pg_setup set to default.
[15:39:47.183] INFO: 22 hot pixels found in step 3
[15:39:48.176] INFO: Collecting data for 5 seconds...
[15:39:53.194] INFO: Done with hot pixel readout
[15:40:04.870] INFO: PixTest:: pg_setup set to default.
[15:40:04.871] INFO: 20 hot pixels found in step 4
[15:40:05.863] INFO: Collecting data for 5 seconds...
[15:40:10.880] INFO: Done with hot pixel readout
[15:40:22.582] INFO: PixTest:: pg_setup set to default.
[15:40:22.582] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:40:22.583] INFO: 15 hot pixels found in step 5
[15:40:23.577] INFO: Collecting data for 5 seconds...
[15:40:28.595] INFO: Done with hot pixel readout
[15:40:40.338] INFO: PixTest:: pg_setup set to default.
[15:40:40.338] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:40:40.338] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:40:40.339] INFO: 8 hot pixels found in step 6
[15:40:41.331] INFO: Collecting data for 5 seconds...
[15:40:46.348] INFO: Done with hot pixel readout
[15:40:58.110] INFO: PixTest:: pg_setup set to default.
[15:40:58.111] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:40:58.111] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:40:58.111] INFO: 5 hot pixels found in step 7
[15:40:59.104] INFO: Collecting data for 5 seconds...
[15:41:04.120] INFO: Done with hot pixel readout
[15:41:15.887] INFO: PixTest:: pg_setup set to default.
[15:41:15.888] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:41:15.888] INFO: 4 hot pixels found in step 8
[15:41:16.881] INFO: Collecting data for 5 seconds...
[15:41:21.898] INFO: Done with hot pixel readout
[15:41:33.595] INFO: PixTest:: pg_setup set to default.
[15:41:33.595] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:41:33.595] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:41:33.596] INFO: 6 hot pixels found in step 9
[15:41:34.589] INFO: Collecting data for 5 seconds...
[15:41:39.606] INFO: Done with hot pixel readout
[15:41:51.320] INFO: PixTest:: pg_setup set to default.
[15:41:51.320] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:41:51.320] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:41:51.321] INFO: 5 hot pixels found in step 10
[15:41:52.314] INFO: Collecting data for 5 seconds...
[15:41:57.332] INFO: Done with hot pixel readout
[15:42:09.046] INFO: PixTest:: pg_setup set to default.
[15:42:09.046] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:42:09.046] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:42:09.046] INFO: 6 hot pixels found in step 11
[15:42:10.039] INFO: Collecting data for 5 seconds...
[15:42:15.056] INFO: Done with hot pixel readout
[15:42:26.805] INFO: PixTest:: pg_setup set to default.
[15:42:26.805] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:42:26.806] INFO: 3 hot pixels found in step 12
[15:42:27.799] INFO: Collecting data for 5 seconds...
[15:42:32.816] INFO: Done with hot pixel readout
[15:42:44.565] INFO: PixTest:: pg_setup set to default.
[15:42:44.565] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:42:44.565] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:42:44.565] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:42:44.566] INFO: 5 hot pixels found in step 13
[15:42:45.559] INFO: Collecting data for 5 seconds...
[15:42:50.575] INFO: Done with hot pixel readout
[15:43:02.291] INFO: PixTest:: pg_setup set to default.
[15:43:02.291] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:43:02.292] INFO: 6 hot pixels found in step 14
[15:43:02.329] INFO: 6 hot pixels could not be trimmed and have been masked.
[15:43:02.332] INFO: PixTest::trimHotPixels() done
[15:43:02.333] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C0.dat
[15:43:02.338] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C1.dat
[15:43:02.344] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C2.dat
[15:43:02.349] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C3.dat
[15:43:02.368] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C4.dat
[15:43:02.380] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C5.dat
[15:43:02.392] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C6.dat
[15:43:02.397] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C7.dat
[15:43:02.402] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C8.dat
[15:43:02.408] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C9.dat
[15:43:02.414] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C10.dat
[15:43:02.419] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C11.dat
[15:43:02.424] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C12.dat
[15:43:02.430] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C13.dat
[15:43:02.435] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C14.dat
[15:43:02.441] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C15.dat
[15:43:02.447] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//defaultMaskFile.dat
[15:43:02.463] INFO: enter test to run
[15:45:08.486] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:45:08.486] INFO: running: highrate
[15:45:08.491] INFO: ----------------------------------------------------------------------
[15:45:08.491] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:45:08.491] INFO: ----------------------------------------------------------------------
[15:45:08.491] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:45:08.491] INFO: edge/corner pixel THR is adjusted
[15:45:08.491] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:45:09.449] INFO: Collecting data for 1 seconds...
[15:45:10.453] INFO: Done with hot pixel readout
[15:45:14.711] INFO: PixTest:: pg_setup set to default.
[15:45:14.712] INFO: 0 hot pixels found in step 0
[15:45:14.717] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:45:14.799] INFO: PixTest::trimHotPixels() done
[15:45:14.800] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C0.dat
[15:45:14.811] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C1.dat
[15:45:14.816] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C2.dat
[15:45:14.822] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C3.dat
[15:45:14.827] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C4.dat
[15:45:14.832] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C5.dat
[15:45:14.838] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C6.dat
[15:45:14.843] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C7.dat
[15:45:14.848] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C8.dat
[15:45:14.854] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C9.dat
[15:45:14.859] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C10.dat
[15:45:14.864] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C11.dat
[15:45:14.870] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C12.dat
[15:45:14.875] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C13.dat
[15:45:14.880] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C14.dat
[15:45:14.886] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//trimParameters35_C15.dat
[15:45:14.891] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-8-19_FPIXTest-17C-FNAL-160920-1327-300V_2016-09-20_13h27m_1474396054/000_FPIXTest_p17//defaultMaskFile.dat
[15:45:14.902] INFO: enter test to run
[15:45:38.454] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:45:38.454] INFO: running: xray
[15:45:38.455] INFO: ----------------------------------------------------------------------
[15:45:38.456] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:45:38.456] INFO: ----------------------------------------------------------------------
[15:45:39.419] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:45:50.728] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:46:20.483] INFO: Resuming triggers.
[15:46:31.790] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:47:01.740] INFO: Resuming triggers.
[15:47:13.052] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[15:47:42.870] INFO: Resuming triggers.
[15:47:54.176] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:48:24.149] INFO: Resuming triggers.
[15:48:35.457] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[15:49:05.735] INFO: Resuming triggers.
[15:49:17.042] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[15:49:47.265] INFO: Resuming triggers.
[15:49:58.570] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[15:50:27.960] INFO: Resuming triggers.
[15:50:39.267] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[15:51:08.693] INFO: Resuming triggers.
[15:51:18.603] INFO: data taking finished, elapsed time: 100 seconds.
[15:51:44.499] INFO: PixTest:: pg_setup set to default.
[15:51:44.502] INFO: PixTestXray::doPhRun() done
[15:51:44.640] INFO: enter test to run
[15:53:39.259] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:53:39.259] INFO: running: xray
[15:53:39.260] INFO: ----------------------------------------------------------------------
[15:53:39.260] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:53:39.260] INFO: ----------------------------------------------------------------------
[15:53:40.239] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:53:46.628] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:54:16.718] INFO: Resuming triggers.
[15:54:23.111] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[15:54:53.180] INFO: Resuming triggers.
[15:54:59.575] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[15:55:29.660] INFO: Resuming triggers.
[15:55:36.054] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[15:56:06.117] INFO: Resuming triggers.
[15:56:12.511] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[15:56:42.690] INFO: Resuming triggers.
[15:56:49.085] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[15:57:19.234] INFO: Resuming triggers.
[15:57:25.628] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[15:57:55.779] INFO: Resuming triggers.
[15:58:02.174] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[15:58:33.318] INFO: Resuming triggers.
[15:58:39.712] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[15:59:10.243] INFO: Resuming triggers.
[15:59:16.636] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[15:59:47.573] INFO: Resuming triggers.
[15:59:53.964] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[16:00:25.066] INFO: Resuming triggers.
[16:00:31.461] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[16:01:03.075] INFO: Resuming triggers.
[16:01:09.467] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[16:01:40.831] INFO: Resuming triggers.
[16:01:47.223] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[16:02:18.556] INFO: Resuming triggers.
[16:02:24.943] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[16:02:55.040] INFO: Resuming triggers.
[16:02:59.501] INFO: data taking finished, elapsed time: 100 seconds.
[16:03:20.775] INFO: PixTest:: pg_setup set to default.
[16:03:20.779] INFO: PixTestXray::doPhRun() done
[16:03:20.927] INFO: enter test to run
[16:03:45.583] INFO: test: HighRate no parameter change
[16:03:45.583] INFO: running: highrate
[16:03:45.595] INFO: ----------------------------------------------------------------------
[16:03:45.595] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:03:45.595] INFO: ----------------------------------------------------------------------
[16:03:45.750] INFO: Expecting 768 events.
[16:03:46.883] INFO: 768 events read in total (418ms).
[16:03:46.883] INFO: Test took 1268ms.
[16:03:47.687] INFO: Expecting 41600 events.
[16:03:50.796] INFO: 41600 events read in total (2583ms).
[16:03:50.797] INFO: Test took 3906ms.
[16:03:50.831] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:03:51.560] INFO: Expecting 41600 events.
[16:03:54.780] INFO: 41600 events read in total (2693ms).
[16:03:54.781] INFO: Test took 3932ms.
[16:03:54.816] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:03:55.540] INFO: Expecting 41600 events.
[16:03:58.764] INFO: 41600 events read in total (2698ms).
[16:03:58.765] INFO: Test took 3931ms.
[16:03:58.800] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:03:59.522] INFO: Expecting 41600 events.
[16:04:02.760] INFO: 41600 events read in total (2711ms).
[16:04:02.761] INFO: Test took 3944ms.
[16:04:02.795] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:03.517] INFO: Expecting 41600 events.
[16:04:06.755] INFO: 41600 events read in total (2711ms).
[16:04:06.757] INFO: Test took 3944ms.
[16:04:06.800] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:07.512] INFO: Expecting 41600 events.
[16:04:10.774] INFO: 41600 events read in total (2735ms).
[16:04:10.775] INFO: Test took 3956ms.
[16:04:10.811] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:11.530] INFO: Expecting 41600 events.
[16:04:14.774] INFO: 41600 events read in total (2717ms).
[16:04:14.775] INFO: Test took 3947ms.
[16:04:14.810] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:15.535] INFO: Expecting 41600 events.
[16:04:18.779] INFO: 41600 events read in total (2717ms).
[16:04:18.780] INFO: Test took 3952ms.
[16:04:18.814] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:19.535] INFO: Expecting 41600 events.
[16:04:22.788] INFO: 41600 events read in total (2726ms).
[16:04:22.789] INFO: Test took 3956ms.
[16:04:22.831] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:23.545] INFO: Expecting 41600 events.
[16:04:26.593] INFO: 41600 events read in total (2521ms).
[16:04:26.594] INFO: Test took 3743ms.
[16:04:26.629] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:27.353] INFO: Expecting 41600 events.
[16:04:30.598] INFO: 41600 events read in total (2718ms).
[16:04:30.599] INFO: Test took 3951ms.
[16:04:30.634] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:31.354] INFO: Expecting 41600 events.
[16:04:34.596] INFO: 41600 events read in total (2715ms).
[16:04:34.597] INFO: Test took 3946ms.
[16:04:34.633] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:35.354] INFO: Expecting 41600 events.
[16:04:38.607] INFO: 41600 events read in total (2726ms).
[16:04:38.608] INFO: Test took 3957ms.
[16:04:38.643] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:39.368] INFO: Expecting 41600 events.
[16:04:42.612] INFO: 41600 events read in total (2717ms).
[16:04:42.613] INFO: Test took 3951ms.
[16:04:42.648] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:43.369] INFO: Expecting 41600 events.
[16:04:46.621] INFO: 41600 events read in total (2725ms).
[16:04:46.622] INFO: Test took 3955ms.
[16:04:46.656] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:47.380] INFO: Expecting 41600 events.
[16:04:50.631] INFO: 41600 events read in total (2724ms).
[16:04:50.632] INFO: Test took 3958ms.
[16:04:50.667] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:51.391] INFO: Expecting 41600 events.
[16:04:54.637] INFO: 41600 events read in total (2719ms).
[16:04:54.638] INFO: Test took 3952ms.
[16:04:54.673] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:55.397] INFO: Expecting 41600 events.
[16:04:58.631] INFO: 41600 events read in total (2707ms).
[16:04:58.632] INFO: Test took 3940ms.
[16:04:58.667] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:59.389] INFO: Expecting 41600 events.
[16:05:02.618] INFO: 41600 events read in total (2702ms).
[16:05:02.619] INFO: Test took 3933ms.
[16:05:02.653] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:05:03.378] INFO: Expecting 41600 events.
[16:05:06.475] INFO: 41600 events read in total (2570ms).
[16:05:06.476] INFO: Test took 3804ms.
[16:05:06.511] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:05:06.874] INFO: enter test to run
[16:06:33.622] INFO: test: HighRate no parameter change
[16:06:33.622] INFO: running: highrate
[16:06:33.623] INFO: ----------------------------------------------------------------------
[16:06:33.623] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:06:33.623] INFO: ----------------------------------------------------------------------
[16:06:34.242] INFO: Expecting 208000 events.
[16:06:46.106] INFO: 208000 events read in total (11337ms).
[16:06:46.110] INFO: Test took 12478ms.
[16:06:46.257] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:06:46.511] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 1 1 0 0 0 1 0 0
[16:06:46.512] INFO: number of red-efficiency pixels: 89 55 72 132 126 157 159 81 97 130 116 102 124 62 20 27
[16:06:46.512] INFO: number of X-ray hits detected: 64713 42681 67775 104691 115583 118079 111196 77641 79909 105248 102529 87572 93596 55342 21197 27724
[16:06:46.512] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:06:46.512] INFO: number of Vcal hits detected: 207909 207940 207927 207863 207866 207842 207836 207864 207852 207818 207880 207894 207874 207888 207980 207973
[16:06:46.512] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[16:06:46.512] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[16:06:46.512] INFO: X-ray hit rate [MHz/cm2]: 19.0 12.5 19.9 30.7 33.9 34.6 32.6 22.8 23.4 30.8 30.1 25.7 27.4 16.2 6.2 8.1
[16:06:46.512] INFO: PixTestHighRate::doXPixelAlive() done
[16:06:46.559] INFO: PixTest:: pg_setup set to default.
[16:06:46.576] INFO: enter test to run
[16:07:01.885] INFO: test: HighRate no parameter change
[16:07:01.886] INFO: running: highrate
[16:07:01.887] INFO: ----------------------------------------------------------------------
[16:07:01.887] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:07:01.887] INFO: ----------------------------------------------------------------------
[16:07:02.504] INFO: Expecting 208000 events.
[16:07:16.321] INFO: 208000 events read in total (13290ms).
[16:07:16.326] INFO: Test took 14430ms.
[16:07:16.638] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:07:16.948] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 1 1 0 0 0 1 0 0
[16:07:16.948] INFO: number of red-efficiency pixels: 283 178 276 540 533 527 573 250 326 432 534 384 448 264 59 64
[16:07:16.948] INFO: number of X-ray hits detected: 139092 92954 146482 226929 249718 255289 239344 167350 173182 227637 222219 189164 202740 119958 45729 59162
[16:07:16.948] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:07:16.948] INFO: number of Vcal hits detected: 207687 207798 207708 207410 207395 207430 207356 207687 207607 207478 207406 207589 207518 207659 207941 207936
[16:07:16.948] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.7 99.7 99.7 99.7 99.9 99.8 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[16:07:16.948] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.9 99.7 99.7 99.7 99.7 99.8 99.8 99.7 99.7 99.8 99.8 99.8 100.0 100.0
[16:07:16.948] INFO: X-ray hit rate [MHz/cm2]: 40.8 27.2 42.9 66.5 73.2 74.8 70.2 49.1 50.8 66.7 65.1 55.4 59.4 35.2 13.4 17.3
[16:07:16.948] INFO: PixTestHighRate::doXPixelAlive() done
[16:07:16.997] INFO: PixTest:: pg_setup set to default.
[16:07:17.011] INFO: enter test to run
[16:07:38.957] INFO: test: HighRate no parameter change
[16:07:38.957] INFO: running: highrate
[16:07:38.958] INFO: ----------------------------------------------------------------------
[16:07:38.958] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:07:38.958] INFO: ----------------------------------------------------------------------
[16:07:39.573] INFO: Expecting 208000 events.
[16:07:55.443] INFO: 208000 events read in total (15343ms).
[16:07:55.451] INFO: Test took 16483ms.
[16:07:55.944] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:07:56.303] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 1 1 1 0 0 0 1 0 0
[16:07:56.303] INFO: number of red-efficiency pixels: 570 289 581 1208 1282 1158 1328 562 759 968 1236 927 1035 547 91 116
[16:07:56.303] INFO: number of X-ray hits detected: 208848 139654 219995 340433 375757 382395 359345 250976 260291 342877 334285 283184 303844 179315 69779 89821
[16:07:56.303] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:07:56.303] INFO: number of Vcal hits detected: 207295 207652 207234 206447 206307 206439 206201 207299 207038 206794 206413 206844 206730 207262 207902 207881
[16:07:56.303] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.7 99.3 99.3 99.3 99.2 99.7 99.6 99.5 99.3 99.5 99.4 99.7 100.0 99.9
[16:07:56.303] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.6 99.3 99.2 99.2 99.1 99.7 99.5 99.4 99.2 99.4 99.4 99.6 100.0 99.9
[16:07:56.303] INFO: X-ray hit rate [MHz/cm2]: 61.2 40.9 64.5 99.8 110.1 112.1 105.3 73.6 76.3 100.5 98.0 83.0 89.1 52.6 20.5 26.3
[16:07:56.303] INFO: PixTestHighRate::doXPixelAlive() done
[16:07:56.353] INFO: PixTest:: pg_setup set to default.
[16:07:56.370] INFO: enter test to run
[16:08:01.573] INFO: test: exit no parameter change
[16:08:01.002] QUIET: Connection to board 33 closed.
[16:08:02.040] INFO: pXar: this is the end, my friend