[11:24:04.749] INFO: *** Welcome to pxar ***
[11:24:04.749] INFO: *** Today: 2016/10/05
[11:24:04.770] INFO: *** Version: v1.9.0-818-g96727
[11:24:04.770] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//dacParameters35_C15.dat
[11:24:04.771] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:24:04.771] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//defaultMaskFile.dat
[11:24:04.771] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C15.dat
[11:24:04.842] INFO: clk: 4
[11:24:04.842] INFO: ctr: 4
[11:24:04.842] INFO: sda: 19
[11:24:04.842] INFO: tin: 9
[11:24:04.842] INFO: level: 15
[11:24:04.842] INFO: triggerdelay: 0
[11:24:04.842] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:24:04.842] INFO: Log level: INFO
[11:24:04.858] QUIET: Connection to board DTB_WREKRL opened.
[11:24:04.861] 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:
------------------------------------------------------
[11:24:04.863] INFO: RPC call hashes of host and DTB match: 398089610
[11:24:06.400] INFO: DUT info:
[11:24:06.401] INFO: The DUT currently contains the following objects:
[11:24:06.401] INFO: 2 TBM Cores tbm08c (2 ON)
[11:24:06.401] INFO: TBM Core alpha (0): 7 registers set
[11:24:06.401] INFO: TBM Core beta (1): 7 registers set
[11:24:06.401] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:24:06.401] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.401] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:24:06.804] INFO: enter 'restricted' command line mode
[11:24:06.804] INFO: enter test to run
[11:24:10.370] INFO: test: PixelAlive no parameter change
[11:24:10.370] INFO: running: pixelalive
[11:24:10.379] INFO: ----------------------------------------------------------------------
[11:24:10.379] 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:24:10.379] INFO: ----------------------------------------------------------------------
[11:24:10.703] INFO: Expecting 41600 events.
[11:24:15.075] INFO: 41600 events read in total (3654ms).
[11:24:15.236] INFO: Test took 4854ms.
[11:24:15.246] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:24:15.510] INFO: PixTestAlive::aliveTest() done
[11:24:15.510] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0
[11:24:15.543] INFO: enter test to run
[11:24:22.561] INFO: test: timing no parameter change
[11:24:22.562] INFO: running: timing
[11:24:22.565] INFO: ######################################################################
[11:24:22.565] INFO: PixTestTiming::doTest()
[11:24:22.565] INFO: ######################################################################
[11:24:22.565] INFO: ----------------------------------------------------------------------
[11:24:22.565] INFO: PixTestTiming::TBMPhaseScan()
[11:24:22.565] INFO: ----------------------------------------------------------------------
[11:32:14.286] INFO: TBM Phase Settings: 232
[11:32:14.286] INFO: 400MHz Phase: 2
[11:32:14.286] INFO: 160MHz Phase: 7
[11:32:14.286] INFO: Functional Phase Area: 3
[11:32:14.303] INFO: Test took 471738 ms.
[11:32:14.303] INFO: PixTestTiming::TBMPhaseScan() done.
[11:32:14.303] INFO: ----------------------------------------------------------------------
[11:32:14.303] INFO: PixTestTiming::ROCDelayScan()
[11:32:14.303] INFO: ----------------------------------------------------------------------
[11:34:05.700] INFO: ROC Delay Settings: 228
[11:34:05.700] INFO: ROC Header-Trailer/Token Delay: 11
[11:34:05.701] INFO: ROC Port 0 Delay: 4
[11:34:05.701] INFO: ROC Port 1 Delay: 4
[11:34:05.701] INFO: Functional ROC Area: 3
[11:34:05.704] INFO: Test took 111401 ms.
[11:34:05.704] INFO: PixTestTiming::ROCDelayScan() done.
[11:34:05.704] INFO: ----------------------------------------------------------------------
[11:34:05.704] INFO: PixTestTiming::TimingTest()
[11:34:05.704] INFO: ----------------------------------------------------------------------
[11:34:21.898] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:34:36.800] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:34:51.815] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:35:06.910] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:35:22.030] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:35:37.055] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:35:52.077] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:36:07.143] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:36:22.182] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:36:37.280] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:36:37.656] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:36:37.674] INFO: ----------------------------------------------------------------------
[11:36:37.674] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:36:37.674] INFO: ----------------------------------------------------------------------
[11:36:37.674] INFO: ----------------------------------------------------------------------
[11:36:37.674] INFO: Read back bit status: 1
[11:36:37.674] INFO: ----------------------------------------------------------------------
[11:36:37.674] INFO: ----------------------------------------------------------------------
[11:36:37.674] INFO: Timings are good!
[11:36:37.674] INFO: ----------------------------------------------------------------------
[11:36:37.674] INFO: Test took 151970 ms.
[11:36:37.674] INFO: PixTestTiming::TimingTest() done.
[11:36:37.691] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:36:37.691] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:36:37.691] INFO: PixTestTiming::doTest took 735129 ms.
[11:36:37.691] INFO: PixTestTiming::doTest() done
[11:36:37.692] INFO: Write out TBMPhaseScan_0_V0
[11:36:37.692] INFO: Write out TBMPhaseScan_1_V0
[11:36:37.692] INFO: Write out CombinedTBMPhaseScan_V0
[11:36:37.717] INFO: Write out ROCDelayScan3_V0
[11:36:37.718] INFO: enter test to run
[11:37:14.588] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:37:14.588] INFO: running: highrate
[11:37:14.659] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:37:14.950] INFO: ----------------------------------------------------------------------
[11:37:14.950] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:37:14.950] INFO: ----------------------------------------------------------------------
[11:37:14.950] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:37:14.950] INFO: edge/corner pixel THR is adjusted
[11:37:14.950] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:37:15.928] INFO: Collecting data for 5 seconds...
[11:37:20.949] INFO: Done with hot pixel readout
[11:37:32.995] INFO: PixTest:: pg_setup set to default.
[11:37:32.996] INFO: 5 hot pixels found in step 0
[11:37:33.991] INFO: Collecting data for 5 seconds...
[11:37:39.010] INFO: Done with hot pixel readout
[11:37:51.040] INFO: PixTest:: pg_setup set to default.
[11:37:51.040] INFO: 7 hot pixels found in step 1
[11:37:52.034] INFO: Collecting data for 5 seconds...
[11:37:57.053] INFO: Done with hot pixel readout
[11:38:08.919] INFO: PixTest:: pg_setup set to default.
[11:38:08.920] INFO: 1 hot pixels found in step 2
[11:38:09.914] INFO: Collecting data for 5 seconds...
[11:38:14.934] INFO: Done with hot pixel readout
[11:38:26.828] INFO: PixTest:: pg_setup set to default.
[11:38:26.829] INFO: 5 hot pixels found in step 3
[11:38:27.822] INFO: Collecting data for 5 seconds...
[11:38:32.842] INFO: Done with hot pixel readout
[11:38:44.587] INFO: PixTest:: pg_setup set to default.
[11:38:44.587] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:38:44.588] INFO: 3 hot pixels found in step 4
[11:38:45.581] INFO: Collecting data for 5 seconds...
[11:38:50.604] INFO: Done with hot pixel readout
[11:39:02.469] INFO: PixTest:: pg_setup set to default.
[11:39:02.470] INFO: 4 hot pixels found in step 5
[11:39:03.463] INFO: Collecting data for 5 seconds...
[11:39:08.480] INFO: Done with hot pixel readout
[11:39:20.205] INFO: PixTest:: pg_setup set to default.
[11:39:20.206] INFO: 1 hot pixels found in step 6
[11:39:21.199] INFO: Collecting data for 5 seconds...
[11:39:26.216] INFO: Done with hot pixel readout
[11:39:37.942] INFO: PixTest:: pg_setup set to default.
[11:39:37.943] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:39:37.943] INFO: 4 hot pixels found in step 7
[11:39:38.937] INFO: Collecting data for 5 seconds...
[11:39:43.955] INFO: Done with hot pixel readout
[11:39:55.701] INFO: PixTest:: pg_setup set to default.
[11:39:55.701] INFO: 2 hot pixels found in step 8
[11:39:56.695] INFO: Collecting data for 5 seconds...
[11:40:01.712] INFO: Done with hot pixel readout
[11:40:13.162] INFO: PixTest:: pg_setup set to default.
[11:40:13.163] INFO: 3 hot pixels found in step 9
[11:40:14.156] INFO: Collecting data for 5 seconds...
[11:40:19.172] INFO: Done with hot pixel readout
[11:40:30.902] INFO: PixTest:: pg_setup set to default.
[11:40:30.903] INFO: 2 hot pixels found in step 10
[11:40:31.896] INFO: Collecting data for 5 seconds...
[11:40:36.912] INFO: Done with hot pixel readout
[11:40:48.627] INFO: PixTest:: pg_setup set to default.
[11:40:48.628] INFO: 5 hot pixels found in step 11
[11:40:49.621] INFO: Collecting data for 5 seconds...
[11:40:54.637] INFO: Done with hot pixel readout
[11:41:06.421] INFO: PixTest:: pg_setup set to default.
[11:41:06.422] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:41:06.422] INFO: 2 hot pixels found in step 12
[11:41:07.416] INFO: Collecting data for 5 seconds...
[11:41:12.432] INFO: Done with hot pixel readout
[11:41:24.108] INFO: PixTest:: pg_setup set to default.
[11:41:24.109] INFO: 4 hot pixels found in step 13
[11:41:25.102] INFO: Collecting data for 5 seconds...
[11:41:30.118] INFO: Done with hot pixel readout
[11:41:41.879] INFO: PixTest:: pg_setup set to default.
[11:41:41.880] INFO: 2 hot pixels found in step 14
[11:41:41.917] INFO: 2 hot pixels could not be trimmed and have been masked.
[11:41:41.920] INFO: PixTest::trimHotPixels() done
[11:41:41.920] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C0.dat
[11:41:41.926] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C1.dat
[11:41:41.932] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C2.dat
[11:41:41.937] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C3.dat
[11:41:41.943] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C4.dat
[11:41:41.948] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C5.dat
[11:41:41.953] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C6.dat
[11:41:41.958] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C7.dat
[11:41:41.964] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C8.dat
[11:41:41.969] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C9.dat
[11:41:41.974] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C10.dat
[11:41:41.980] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C11.dat
[11:41:41.985] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C12.dat
[11:41:41.990] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C13.dat
[11:41:41.996] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C14.dat
[11:41:41.001] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C15.dat
[11:41:42.006] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//defaultMaskFile.dat
[11:41:42.017] INFO: enter test to run
[11:42:22.586] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:42:22.587] INFO: running: highrate
[11:42:22.591] INFO: ----------------------------------------------------------------------
[11:42:22.591] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:42:22.591] INFO: ----------------------------------------------------------------------
[11:42:22.591] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:42:22.591] INFO: edge/corner pixel THR is adjusted
[11:42:22.591] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:42:23.549] INFO: Collecting data for 1 seconds...
[11:42:24.553] INFO: Done with hot pixel readout
[11:42:28.583] INFO: PixTest:: pg_setup set to default.
[11:42:28.584] INFO: 0 hot pixels found in step 0
[11:42:28.589] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:42:28.680] INFO: PixTest::trimHotPixels() done
[11:42:28.680] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C0.dat
[11:42:28.693] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C1.dat
[11:42:28.699] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C2.dat
[11:42:28.704] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C3.dat
[11:42:28.711] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C4.dat
[11:42:28.716] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C5.dat
[11:42:28.721] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C6.dat
[11:42:28.727] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C7.dat
[11:42:28.732] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C8.dat
[11:42:28.737] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C9.dat
[11:42:28.743] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C10.dat
[11:42:28.749] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C11.dat
[11:42:28.754] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C12.dat
[11:42:28.759] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C13.dat
[11:42:28.765] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C14.dat
[11:42:28.771] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//trimParameters35_C15.dat
[11:42:28.776] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-04_FPIXTest-17C-FNAL-160928-1217-300V_2016-09-28_12h21m_1475083302/000_FPIXTest_p17//defaultMaskFile.dat
[11:42:28.800] INFO: enter test to run
[11:43:04.402] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:43:04.402] INFO: running: xray
[11:43:04.404] INFO: ----------------------------------------------------------------------
[11:43:04.404] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:43:04.404] INFO: ----------------------------------------------------------------------
[11:43:05.381] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:43:16.870] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:43:46.294] INFO: Resuming triggers.
[11:43:57.778] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[11:44:27.244] INFO: Resuming triggers.
[11:44:38.736] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:45:07.809] INFO: Resuming triggers.
[11:45:19.301] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[11:45:48.625] INFO: Resuming triggers.
[11:46:00.113] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[11:46:29.419] INFO: Resuming triggers.
[11:46:40.902] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[11:47:10.829] INFO: Resuming triggers.
[11:47:22.312] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:47:51.844] INFO: Resuming triggers.
[11:48:03.334] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[11:48:33.061] INFO: Resuming triggers.
[11:48:41.505] INFO: data taking finished, elapsed time: 100 seconds.
[11:49:03.220] INFO: PixTest:: pg_setup set to default.
[11:49:03.223] INFO: PixTestXray::doPhRun() done
[11:49:03.439] INFO: enter test to run
[11:49:39.815] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:49:39.816] INFO: running: xray
[11:49:39.816] INFO: ----------------------------------------------------------------------
[11:49:39.816] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:49:39.816] INFO: ----------------------------------------------------------------------
[11:49:40.779] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:49:47.499] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:50:17.947] INFO: Resuming triggers.
[11:50:24.666] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[11:50:56.305] INFO: Resuming triggers.
[11:51:03.025] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[11:51:34.227] INFO: Resuming triggers.
[11:51:40.945] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[11:52:12.410] INFO: Resuming triggers.
[11:52:19.131] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[11:52:50.104] INFO: Resuming triggers.
[11:52:56.824] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[11:53:27.276] INFO: Resuming triggers.
[11:53:33.000] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:54:04.241] INFO: Resuming triggers.
[11:54:10.964] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[11:54:41.106] INFO: Resuming triggers.
[11:54:47.828] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[11:55:17.859] INFO: Resuming triggers.
[11:55:24.581] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[11:55:54.535] INFO: Resuming triggers.
[11:56:01.259] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[11:56:31.337] INFO: Resuming triggers.
[11:56:38.061] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:57:08.331] INFO: Resuming triggers.
[11:57:15.056] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[11:57:45.072] INFO: Resuming triggers.
[11:57:51.795] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[11:58:21.827] INFO: Resuming triggers.
[11:58:28.072] INFO: data taking finished, elapsed time: 100 seconds.
[11:58:56.426] INFO: PixTest:: pg_setup set to default.
[11:58:56.430] INFO: PixTestXray::doPhRun() done
[11:58:56.603] INFO: enter test to run
[11:59:56.459] INFO: test: HighRate no parameter change
[11:59:56.459] INFO: running: highrate
[11:59:56.481] INFO: ----------------------------------------------------------------------
[11:59:56.481] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:59:56.481] INFO: ----------------------------------------------------------------------
[11:59:56.638] INFO: Expecting 768 events.
[11:59:57.777] INFO: 768 events read in total (423ms).
[11:59:57.778] INFO: Test took 1281ms.
[11:59:58.580] INFO: Expecting 41600 events.
[12:00:01.603] INFO: 41600 events read in total (2496ms).
[12:00:01.604] INFO: Test took 3775ms.
[12:00:01.645] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:02.367] INFO: Expecting 41600 events.
[12:00:05.505] INFO: 41600 events read in total (2611ms).
[12:00:05.506] INFO: Test took 3843ms.
[12:00:05.539] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:06.266] INFO: Expecting 41600 events.
[12:00:09.492] INFO: 41600 events read in total (2699ms).
[12:00:09.493] INFO: Test took 3935ms.
[12:00:09.527] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:10.254] INFO: Expecting 41600 events.
[12:00:13.500] INFO: 41600 events read in total (2719ms).
[12:00:13.501] INFO: Test took 3953ms.
[12:00:13.535] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:14.260] INFO: Expecting 41600 events.
[12:00:17.606] INFO: 41600 events read in total (2819ms).
[12:00:17.607] INFO: Test took 4053ms.
[12:00:17.642] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:18.367] INFO: Expecting 41600 events.
[12:00:21.755] INFO: 41600 events read in total (2862ms).
[12:00:21.756] INFO: Test took 4096ms.
[12:00:21.791] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:22.509] INFO: Expecting 41600 events.
[12:00:25.826] INFO: 41600 events read in total (2790ms).
[12:00:25.827] INFO: Test took 4018ms.
[12:00:25.862] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:26.586] INFO: Expecting 41600 events.
[12:00:29.806] INFO: 41600 events read in total (2693ms).
[12:00:29.807] INFO: Test took 3927ms.
[12:00:29.843] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:30.564] INFO: Expecting 41600 events.
[12:00:33.805] INFO: 41600 events read in total (2714ms).
[12:00:33.806] INFO: Test took 3946ms.
[12:00:33.841] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:34.564] INFO: Expecting 41600 events.
[12:00:37.825] INFO: 41600 events read in total (2734ms).
[12:00:37.826] INFO: Test took 3967ms.
[12:00:37.861] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:38.585] INFO: Expecting 41600 events.
[12:00:41.843] INFO: 41600 events read in total (2731ms).
[12:00:41.844] INFO: Test took 3966ms.
[12:00:41.880] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:42.594] INFO: Expecting 41600 events.
[12:00:45.852] INFO: 41600 events read in total (2731ms).
[12:00:45.852] INFO: Test took 3955ms.
[12:00:45.887] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:46.608] INFO: Expecting 41600 events.
[12:00:49.870] INFO: 41600 events read in total (2735ms).
[12:00:49.871] INFO: Test took 3966ms.
[12:00:49.906] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:50.625] INFO: Expecting 41600 events.
[12:00:53.868] INFO: 41600 events read in total (2716ms).
[12:00:53.869] INFO: Test took 3945ms.
[12:00:53.903] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:54.625] INFO: Expecting 41600 events.
[12:00:57.913] INFO: 41600 events read in total (2761ms).
[12:00:57.913] INFO: Test took 3992ms.
[12:00:57.948] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:58.671] INFO: Expecting 41600 events.
[12:01:01.919] INFO: 41600 events read in total (2721ms).
[12:01:01.920] INFO: Test took 3955ms.
[12:01:01.955] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:02.673] INFO: Expecting 41600 events.
[12:01:05.966] INFO: 41600 events read in total (2766ms).
[12:01:05.967] INFO: Test took 3992ms.
[12:01:05.002] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:06.726] INFO: Expecting 41600 events.
[12:01:10.007] INFO: 41600 events read in total (2754ms).
[12:01:10.008] INFO: Test took 3987ms.
[12:01:10.043] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:10.762] INFO: Expecting 41600 events.
[12:01:13.937] INFO: 41600 events read in total (2648ms).
[12:01:13.938] INFO: Test took 3875ms.
[12:01:13.973] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:14.690] INFO: Expecting 41600 events.
[12:01:17.808] INFO: 41600 events read in total (2591ms).
[12:01:17.809] INFO: Test took 3818ms.
[12:01:17.843] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:18.204] INFO: enter test to run
[12:01:29.435] INFO: test: HighRate no parameter change
[12:01:29.435] INFO: running: highrate
[12:01:29.436] INFO: ----------------------------------------------------------------------
[12:01:29.436] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:01:29.436] INFO: ----------------------------------------------------------------------
[12:01:30.053] INFO: Expecting 208000 events.
[12:01:41.902] INFO: 208000 events read in total (11323ms).
[12:01:41.905] INFO: Test took 12460ms.
[12:01:42.051] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:42.305] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0
[12:01:42.305] INFO: number of red-efficiency pixels: 75 34 79 145 142 133 145 144 92 139 133 93 103 51 24 28
[12:01:42.305] INFO: number of X-ray hits detected: 61382 39990 65031 102193 108554 114319 116489 84848 79711 99035 96915 83184 84752 49949 22144 25062
[12:01:42.305] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:01:42.305] INFO: number of Vcal hits detected: 207925 207965 207918 207852 207855 207865 207801 207855 207906 207859 207863 207905 207896 207949 207975 207972
[12:01:42.305] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[12:01:42.305] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[12:01:42.305] INFO: X-ray hit rate [MHz/cm2]: 18.0 11.7 19.1 30.0 31.8 33.5 34.1 24.9 23.4 29.0 28.4 24.4 24.8 14.6 6.5 7.3
[12:01:42.305] INFO: PixTestHighRate::doXPixelAlive() done
[12:01:42.355] INFO: PixTest:: pg_setup set to default.
[12:01:42.364] INFO: enter test to run
[12:02:01.866] INFO: test: HighRate no parameter change
[12:02:01.866] INFO: running: highrate
[12:02:01.867] INFO: ----------------------------------------------------------------------
[12:02:01.867] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:02:01.868] INFO: ----------------------------------------------------------------------
[12:02:02.494] INFO: Expecting 208000 events.
[12:02:16.116] INFO: 208000 events read in total (13095ms).
[12:02:16.121] INFO: Test took 14244ms.
[12:02:16.414] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:16.717] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0
[12:02:16.717] INFO: number of red-efficiency pixels: 215 119 263 452 523 455 553 386 306 445 426 318 283 179 63 56
[12:02:16.717] INFO: number of X-ray hits detected: 127722 82893 135118 213564 226879 238026 240213 176791 165889 207555 202068 172786 177191 104966 46428 52605
[12:02:16.717] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:02:16.717] INFO: number of Vcal hits detected: 207772 207878 207705 207508 207423 207494 207328 207566 207679 207512 207540 207661 207706 207806 207935 207944
[12:02:16.717] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.7 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[12:02:16.717] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.7 99.8 99.8 99.8 99.8 99.8 99.9 99.9 100.0 100.0
[12:02:16.717] INFO: X-ray hit rate [MHz/cm2]: 37.4 24.3 39.6 62.6 66.5 69.8 70.4 51.8 48.6 60.8 59.2 50.6 51.9 30.8 13.6 15.4
[12:02:16.717] INFO: PixTestHighRate::doXPixelAlive() done
[12:02:16.764] INFO: PixTest:: pg_setup set to default.
[12:02:16.780] INFO: enter test to run
[12:02:36.650] INFO: test: HighRate no parameter change
[12:02:36.650] INFO: running: highrate
[12:02:36.651] INFO: ----------------------------------------------------------------------
[12:02:36.651] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:02:36.651] INFO: ----------------------------------------------------------------------
[12:02:37.271] INFO: Expecting 208000 events.
[12:02:52.840] INFO: 208000 events read in total (15042ms).
[12:02:52.848] INFO: Test took 16188ms.
[12:02:53.292] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:02:53.645] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 1 0 0 0 0 0 0 0 0 0
[12:02:53.645] INFO: number of red-efficiency pixels: 477 250 612 1150 1248 1012 1307 917 679 1122 1005 684 599 443 108 115
[12:02:53.645] INFO: number of X-ray hits detected: 192786 126860 204748 322549 343757 358740 362420 266358 251881 313108 306292 261515 267795 157748 70626 80380
[12:02:53.645] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:02:53.645] INFO: number of Vcal hits detected: 207437 207732 207174 206547 206366 206745 206193 206763 207201 206632 206764 207187 207332 207469 207890 207880
[12:02:53.645] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.4 99.3 99.5 99.2 99.5 99.7 99.4 99.5 99.7 99.7 99.8 99.9 99.9
[12:02:53.645] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.6 99.3 99.2 99.4 99.1 99.4 99.6 99.3 99.4 99.6 99.7 99.7 99.9 99.9
[12:02:53.645] INFO: X-ray hit rate [MHz/cm2]: 56.5 37.2 60.0 94.5 100.8 105.1 106.2 78.1 73.8 91.8 89.8 76.7 78.5 46.2 20.7 23.6
[12:02:53.645] INFO: PixTestHighRate::doXPixelAlive() done
[12:02:53.692] INFO: PixTest:: pg_setup set to default.
[12:02:53.707] INFO: enter test to run
[12:03:13.546] INFO: test: exit no parameter change
[12:03:14.453] QUIET: Connection to board 33 closed.
[12:03:14.710] INFO: pXar: this is the end, my friend