[14:28:10.557] INFO: *** Welcome to pxar ***
[14:28:10.557] INFO: *** Today: 2016/09/23
[14:28:11.373] INFO: *** Version: v1.9.0-818-g96727
[14:28:11.373] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//dacParameters35_C15.dat
[14:28:11.392] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:28:11.392] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//defaultMaskFile.dat
[14:28:11.416] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C15.dat
[14:28:11.508] INFO: clk: 4
[14:28:11.509] INFO: ctr: 4
[14:28:11.509] INFO: sda: 19
[14:28:11.509] INFO: tin: 9
[14:28:11.509] INFO: level: 15
[14:28:11.509] INFO: triggerdelay: 0
[14:28:11.509] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[14:28:11.509] INFO: Log level: INFO
[14:28:11.526] QUIET: Connection to board DTB_WREKRL opened.
[14:28:11.530] 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:
------------------------------------------------------
[14:28:11.533] INFO: RPC call hashes of host and DTB match: 398089610
[14:28:13.061] INFO: DUT info:
[14:28:13.061] INFO: The DUT currently contains the following objects:
[14:28:13.061] INFO: 2 TBM Cores tbm08c (2 ON)
[14:28:13.061] INFO: TBM Core alpha (0): 7 registers set
[14:28:13.061] INFO: TBM Core beta (1): 7 registers set
[14:28:13.061] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[14:28:13.061] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.061] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.061] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.061] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.062] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[14:28:13.465] INFO: enter 'restricted' command line mode
[14:28:13.465] INFO: enter test to run
[14:28:30.146] INFO: test: PixelAlive no parameter change
[14:28:30.147] INFO: running: pixelalive
[14:28:30.156] INFO: ----------------------------------------------------------------------
[14:28:30.156] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[14:28:30.156] INFO: ----------------------------------------------------------------------
[14:28:30.474] INFO: Expecting 41600 events.
[14:28:34.804] INFO: 41600 events read in total (3611ms).
[14:28:34.972] INFO: Test took 4814ms.
[14:28:34.984] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:28:35.247] INFO: PixTestAlive::aliveTest() done
[14:28:35.247] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[14:28:35.279] INFO: enter test to run
[14:28:45.306] INFO: test: timing no parameter change
[14:28:45.306] INFO: running: timing
[14:28:45.326] INFO: ######################################################################
[14:28:45.326] INFO: PixTestTiming::doTest()
[14:28:45.326] INFO: ######################################################################
[14:28:45.327] INFO: ----------------------------------------------------------------------
[14:28:45.327] INFO: PixTestTiming::TBMPhaseScan()
[14:28:45.327] INFO: ----------------------------------------------------------------------
[14:35:07.584] INFO: TBM Phase Settings: 232
[14:35:07.584] INFO: 400MHz Phase: 2
[14:35:07.584] INFO: 160MHz Phase: 7
[14:35:07.584] INFO: Functional Phase Area: 3
[14:35:07.587] INFO: Test took 382261 ms.
[14:35:07.587] INFO: PixTestTiming::TBMPhaseScan() done.
[14:35:07.588] INFO: ----------------------------------------------------------------------
[14:35:07.588] INFO: PixTestTiming::ROCDelayScan()
[14:35:07.588] INFO: ----------------------------------------------------------------------
[14:37:16.878] INFO: ROC Delay Settings: 227
[14:37:16.878] INFO: ROC Header-Trailer/Token Delay: 11
[14:37:16.878] INFO: ROC Port 0 Delay: 3
[14:37:16.878] INFO: ROC Port 1 Delay: 4
[14:37:16.878] INFO: Functional ROC Area: 5
[14:37:16.881] INFO: Test took 129294 ms.
[14:37:16.881] INFO: PixTestTiming::ROCDelayScan() done.
[14:37:16.881] INFO: ----------------------------------------------------------------------
[14:37:16.882] INFO: PixTestTiming::TimingTest()
[14:37:16.882] INFO: ----------------------------------------------------------------------
[14:37:33.012] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:37:47.936] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:38:02.911] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:38:17.876] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:38:32.839] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:38:47.814] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:02.779] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:17.747] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:32.716] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:47.682] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:48.060] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:39:48.078] INFO: ----------------------------------------------------------------------
[14:39:48.078] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:39:48.078] INFO: ----------------------------------------------------------------------
[14:39:48.078] INFO: ----------------------------------------------------------------------
[14:39:48.078] INFO: Read back bit status: 1
[14:39:48.078] INFO: ----------------------------------------------------------------------
[14:39:48.078] INFO: ----------------------------------------------------------------------
[14:39:48.078] INFO: Timings are good!
[14:39:48.078] INFO: ----------------------------------------------------------------------
[14:39:48.078] INFO: Test took 151197 ms.
[14:39:48.078] INFO: PixTestTiming::TimingTest() done.
[14:39:48.078] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:39:48.078] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:39:48.079] INFO: PixTestTiming::doTest took 662757 ms.
[14:39:48.079] INFO: PixTestTiming::doTest() done
[14:39:48.079] INFO: Write out TBMPhaseScan_0_V0
[14:39:48.079] INFO: Write out TBMPhaseScan_1_V0
[14:39:48.079] INFO: Write out CombinedTBMPhaseScan_V0
[14:39:48.081] INFO: Write out ROCDelayScan3_V0
[14:39:48.082] INFO: enter test to run
[14:41:22.725] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[14:41:22.725] INFO: running: highrate
[14:41:22.726] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:41:22.946] INFO: ----------------------------------------------------------------------
[14:41:22.946] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[14:41:22.946] INFO: ----------------------------------------------------------------------
[14:41:22.946] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[14:41:22.946] INFO: edge/corner pixel THR is adjusted
[14:41:22.946] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:41:23.904] INFO: Collecting data for 5 seconds...
[14:41:28.920] INFO: Done with hot pixel readout
[14:41:40.788] INFO: PixTest:: pg_setup set to default.
[14:41:40.789] INFO: 2 hot pixels found in step 0
[14:41:41.782] INFO: Collecting data for 5 seconds...
[14:41:46.799] INFO: Done with hot pixel readout
[14:41:58.657] INFO: PixTest:: pg_setup set to default.
[14:41:58.658] INFO: 10 hot pixels found in step 1
[14:41:59.653] INFO: Collecting data for 5 seconds...
[14:42:04.670] INFO: Done with hot pixel readout
[14:42:16.571] INFO: PixTest:: pg_setup set to default.
[14:42:16.572] INFO: 9 hot pixels found in step 2
[14:42:17.565] INFO: Collecting data for 5 seconds...
[14:42:22.582] INFO: Done with hot pixel readout
[14:42:34.432] INFO: PixTest:: pg_setup set to default.
[14:42:34.432] INFO: 6 hot pixels found in step 3
[14:42:35.426] INFO: Collecting data for 5 seconds...
[14:42:40.443] INFO: Done with hot pixel readout
[14:42:52.320] INFO: PixTest:: pg_setup set to default.
[14:42:52.321] INFO: 9 hot pixels found in step 4
[14:42:53.315] INFO: Collecting data for 5 seconds...
[14:42:58.331] INFO: Done with hot pixel readout
[14:43:10.239] INFO: PixTest:: pg_setup set to default.
[14:43:10.239] INFO: 3 hot pixels found in step 5
[14:43:11.234] INFO: Collecting data for 5 seconds...
[14:43:16.251] INFO: Done with hot pixel readout
[14:43:28.193] INFO: PixTest:: pg_setup set to default.
[14:43:28.194] INFO: 3 hot pixels found in step 6
[14:43:29.188] INFO: Collecting data for 5 seconds...
[14:43:34.205] INFO: Done with hot pixel readout
[14:43:46.069] INFO: PixTest:: pg_setup set to default.
[14:43:46.070] INFO: 6 hot pixels found in step 7
[14:43:47.064] INFO: Collecting data for 5 seconds...
[14:43:52.081] INFO: Done with hot pixel readout
[14:44:03.975] INFO: PixTest:: pg_setup set to default.
[14:44:03.976] INFO: 2 hot pixels found in step 8
[14:44:04.971] INFO: Collecting data for 5 seconds...
[14:44:09.987] INFO: Done with hot pixel readout
[14:44:21.882] INFO: PixTest:: pg_setup set to default.
[14:44:21.883] INFO: 5 hot pixels found in step 9
[14:44:22.877] INFO: Collecting data for 5 seconds...
[14:44:27.894] INFO: Done with hot pixel readout
[14:44:39.798] INFO: PixTest:: pg_setup set to default.
[14:44:39.799] INFO: 5 hot pixels found in step 10
[14:44:40.793] INFO: Collecting data for 5 seconds...
[14:44:45.810] INFO: Done with hot pixel readout
[14:44:57.701] INFO: PixTest:: pg_setup set to default.
[14:44:57.701] INFO: 2 hot pixels found in step 11
[14:44:58.695] INFO: Collecting data for 5 seconds...
[14:45:03.711] INFO: Done with hot pixel readout
[14:45:15.707] INFO: PixTest:: pg_setup set to default.
[14:45:15.708] INFO: 8 hot pixels found in step 12
[14:45:16.702] INFO: Collecting data for 5 seconds...
[14:45:21.719] INFO: Done with hot pixel readout
[14:45:33.151] INFO: PixTest:: pg_setup set to default.
[14:45:33.152] INFO: 1 hot pixels found in step 13
[14:45:34.153] INFO: Collecting data for 5 seconds...
[14:45:39.173] INFO: Done with hot pixel readout
[14:45:50.949] INFO: PixTest:: pg_setup set to default.
[14:45:50.950] INFO: 7 hot pixels found in step 14
[14:45:50.989] INFO: 7 hot pixels could not be trimmed and have been masked.
[14:45:50.992] INFO: PixTest::trimHotPixels() done
[14:45:50.992] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C0.dat
[14:45:50.997] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C1.dat
[14:45:50.003] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C2.dat
[14:45:51.008] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C3.dat
[14:45:51.014] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C4.dat
[14:45:51.019] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C5.dat
[14:45:51.024] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C6.dat
[14:45:51.029] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C7.dat
[14:45:51.035] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C8.dat
[14:45:51.040] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C9.dat
[14:45:51.045] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C10.dat
[14:45:51.051] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C11.dat
[14:45:51.056] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C12.dat
[14:45:51.061] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C13.dat
[14:45:51.067] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C14.dat
[14:45:51.072] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C15.dat
[14:45:51.077] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//defaultMaskFile.dat
[14:45:51.089] INFO: enter test to run
[14:46:13.547] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:46:13.548] INFO: running: highrate
[14:46:13.552] INFO: ----------------------------------------------------------------------
[14:46:13.552] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:46:13.552] INFO: ----------------------------------------------------------------------
[14:46:13.552] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:46:13.552] INFO: edge/corner pixel THR is adjusted
[14:46:13.552] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:46:14.510] INFO: Collecting data for 1 seconds...
[14:46:15.513] INFO: Done with hot pixel readout
[14:46:19.681] INFO: PixTest:: pg_setup set to default.
[14:46:19.682] INFO: 0 hot pixels found in step 0
[14:46:19.687] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:46:19.770] INFO: PixTest::trimHotPixels() done
[14:46:19.770] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C0.dat
[14:46:19.780] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C1.dat
[14:46:19.785] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C2.dat
[14:46:19.791] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C3.dat
[14:46:19.796] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C4.dat
[14:46:19.802] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C5.dat
[14:46:19.807] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C6.dat
[14:46:19.813] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C7.dat
[14:46:19.819] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C8.dat
[14:46:19.824] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C9.dat
[14:46:19.829] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C10.dat
[14:46:19.835] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C11.dat
[14:46:19.841] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C12.dat
[14:46:19.846] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C13.dat
[14:46:19.851] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C14.dat
[14:46:19.857] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//trimParameters35_C15.dat
[14:46:19.862] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-7-41_FPIXTest-17C-FNAL-160916-1156-150V_2016-09-16_11h56m_1474044985/000_FPIXTest_p17//defaultMaskFile.dat
[14:46:19.917] INFO: enter test to run
[14:46:37.867] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:46:37.867] INFO: running: xray
[14:46:37.869] INFO: ----------------------------------------------------------------------
[14:46:37.869] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:46:37.869] INFO: ----------------------------------------------------------------------
[14:46:38.833] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:46:49.703] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[14:47:19.550] INFO: Resuming triggers.
[14:47:30.420] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[14:48:00.350] INFO: Resuming triggers.
[14:48:11.217] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[14:48:41.623] INFO: Resuming triggers.
[14:48:52.493] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[14:49:23.136] INFO: Resuming triggers.
[14:49:34.007] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[14:50:03.976] INFO: Resuming triggers.
[14:50:14.842] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[14:50:44.457] INFO: Resuming triggers.
[14:50:55.325] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[14:51:24.919] INFO: Resuming triggers.
[14:51:35.788] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[14:52:05.396] INFO: Resuming triggers.
[14:52:16.264] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[14:52:45.807] INFO: Resuming triggers.
[14:52:48.344] INFO: data taking finished, elapsed time: 100 seconds.
[14:52:55.608] INFO: PixTest:: pg_setup set to default.
[14:52:55.612] INFO: PixTestXray::doPhRun() done
[14:52:55.791] INFO: enter test to run
[14:54:12.408] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:54:12.408] INFO: running: xray
[14:54:12.409] INFO: ----------------------------------------------------------------------
[14:54:12.409] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:54:12.409] INFO: ----------------------------------------------------------------------
[14:54:13.385] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:54:19.772] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[14:54:49.934] INFO: Resuming triggers.
[14:54:56.321] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[14:55:26.470] INFO: Resuming triggers.
[14:55:32.856] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[14:56:03.052] INFO: Resuming triggers.
[14:56:09.437] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[14:56:39.628] INFO: Resuming triggers.
[14:56:46.021] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[14:57:16.237] INFO: Resuming triggers.
[14:57:22.622] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[14:57:53.133] INFO: Resuming triggers.
[14:57:59.519] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[14:58:30.047] INFO: Resuming triggers.
[14:58:36.430] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[14:59:07.504] INFO: Resuming triggers.
[14:59:13.889] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[14:59:44.635] INFO: Resuming triggers.
[14:59:51.018] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[15:00:21.609] INFO: Resuming triggers.
[15:00:27.990] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[15:00:59.531] INFO: Resuming triggers.
[15:01:05.917] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[15:01:37.352] INFO: Resuming triggers.
[15:01:43.738] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[15:02:14.186] INFO: Resuming triggers.
[15:02:20.567] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[15:02:50.738] INFO: Resuming triggers.
[15:02:57.121] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[15:03:27.284] INFO: Resuming triggers.
[15:03:31.852] INFO: data taking finished, elapsed time: 100 seconds.
[15:03:53.657] INFO: PixTest:: pg_setup set to default.
[15:03:53.661] INFO: PixTestXray::doPhRun() done
[15:03:53.812] INFO: enter test to run
[15:04:50.948] INFO: test: HighRate no parameter change
[15:04:50.948] INFO: running: highrate
[15:04:50.994] INFO: ----------------------------------------------------------------------
[15:04:50.994] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:04:50.994] INFO: ----------------------------------------------------------------------
[15:04:51.166] INFO: Expecting 768 events.
[15:04:52.300] INFO: 768 events read in total (419ms).
[15:04:52.300] INFO: Test took 1269ms.
[15:04:53.104] INFO: Expecting 41600 events.
[15:04:56.268] INFO: 41600 events read in total (2637ms).
[15:04:56.269] INFO: Test took 3962ms.
[15:04:56.309] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:04:57.023] INFO: Expecting 41600 events.
[15:05:00.291] INFO: 41600 events read in total (2741ms).
[15:05:00.292] INFO: Test took 3962ms.
[15:05:00.334] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:01.041] INFO: Expecting 41600 events.
[15:05:04.326] INFO: 41600 events read in total (2758ms).
[15:05:04.327] INFO: Test took 3974ms.
[15:05:04.367] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:05.079] INFO: Expecting 41600 events.
[15:05:08.372] INFO: 41600 events read in total (2766ms).
[15:05:08.372] INFO: Test took 3984ms.
[15:05:08.413] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:09.127] INFO: Expecting 41600 events.
[15:05:12.427] INFO: 41600 events read in total (2774ms).
[15:05:12.428] INFO: Test took 3993ms.
[15:05:12.469] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:13.182] INFO: Expecting 41600 events.
[15:05:16.482] INFO: 41600 events read in total (2773ms).
[15:05:16.483] INFO: Test took 3995ms.
[15:05:16.523] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:17.235] INFO: Expecting 41600 events.
[15:05:20.535] INFO: 41600 events read in total (2773ms).
[15:05:20.536] INFO: Test took 3992ms.
[15:05:20.577] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:21.286] INFO: Expecting 41600 events.
[15:05:24.585] INFO: 41600 events read in total (2773ms).
[15:05:24.586] INFO: Test took 3988ms.
[15:05:24.627] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:25.339] INFO: Expecting 41600 events.
[15:05:28.658] INFO: 41600 events read in total (2792ms).
[15:05:28.659] INFO: Test took 4011ms.
[15:05:28.699] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:29.405] INFO: Expecting 41600 events.
[15:05:32.715] INFO: 41600 events read in total (2783ms).
[15:05:32.716] INFO: Test took 3996ms.
[15:05:32.757] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:33.466] INFO: Expecting 41600 events.
[15:05:36.774] INFO: 41600 events read in total (2781ms).
[15:05:36.775] INFO: Test took 3997ms.
[15:05:36.815] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:37.526] INFO: Expecting 41600 events.
[15:05:40.834] INFO: 41600 events read in total (2781ms).
[15:05:40.835] INFO: Test took 3999ms.
[15:05:40.876] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:41.590] INFO: Expecting 41600 events.
[15:05:44.897] INFO: 41600 events read in total (2781ms).
[15:05:44.898] INFO: Test took 4002ms.
[15:05:44.938] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:45.648] INFO: Expecting 41600 events.
[15:05:48.945] INFO: 41600 events read in total (2771ms).
[15:05:48.946] INFO: Test took 3986ms.
[15:05:48.986] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:49.701] INFO: Expecting 41600 events.
[15:05:52.986] INFO: 41600 events read in total (2759ms).
[15:05:52.987] INFO: Test took 3980ms.
[15:05:53.028] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:53.740] INFO: Expecting 41600 events.
[15:05:57.054] INFO: 41600 events read in total (2787ms).
[15:05:57.055] INFO: Test took 4007ms.
[15:05:57.095] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:57.805] INFO: Expecting 41600 events.
[15:06:01.099] INFO: 41600 events read in total (2767ms).
[15:06:01.100] INFO: Test took 3983ms.
[15:06:01.141] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:06:01.853] INFO: Expecting 41600 events.
[15:06:05.154] INFO: 41600 events read in total (2774ms).
[15:06:05.155] INFO: Test took 3993ms.
[15:06:05.197] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:06:05.908] INFO: Expecting 41600 events.
[15:06:09.197] INFO: 41600 events read in total (2762ms).
[15:06:09.198] INFO: Test took 3980ms.
[15:06:09.239] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:06:09.950] INFO: Expecting 41600 events.
[15:06:13.118] INFO: 41600 events read in total (2641ms).
[15:06:13.120] INFO: Test took 3859ms.
[15:06:13.160] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:06:13.512] INFO: enter test to run
[15:06:49.195] INFO: test: HighRate no parameter change
[15:06:49.195] INFO: running: highrate
[15:06:49.196] INFO: ----------------------------------------------------------------------
[15:06:49.196] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:06:49.196] INFO: ----------------------------------------------------------------------
[15:06:49.815] INFO: Expecting 208000 events.
[15:07:02.028] INFO: 208000 events read in total (11686ms).
[15:07:02.032] INFO: Test took 12827ms.
[15:07:02.208] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:07:02.473] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[15:07:02.473] INFO: number of red-efficiency pixels: 92 64 127 138 177 155 174 152 131 161 149 148 173 93 34 30
[15:07:02.473] INFO: number of X-ray hits detected: 83769 53880 80534 123007 130035 135803 134499 106241 97712 127758 120428 107744 113422 68491 27837 31813
[15:07:02.473] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:07:02.473] INFO: number of Vcal hits detected: 207903 207935 207869 207858 207822 207841 207818 207844 207866 207834 207847 207848 207820 207899 207916 207969
[15:07:02.473] INFO: Vcal hit fiducial efficiency (%): 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 100.0
[15:07:02.473] INFO: Vcal hit overall efficiency (%): 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 100.0
[15:07:02.473] INFO: X-ray hit rate [MHz/cm2]: 24.6 15.8 23.6 36.1 38.1 39.8 39.4 31.1 28.6 37.4 35.3 31.6 33.2 20.1 8.2 9.3
[15:07:02.473] INFO: PixTestHighRate::doXPixelAlive() done
[15:07:02.523] INFO: PixTest:: pg_setup set to default.
[15:07:02.537] INFO: enter test to run
[15:07:17.611] INFO: test: HighRate no parameter change
[15:07:17.611] INFO: running: highrate
[15:07:17.612] INFO: ----------------------------------------------------------------------
[15:07:17.612] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:07:17.612] INFO: ----------------------------------------------------------------------
[15:07:18.235] INFO: Expecting 208000 events.
[15:07:32.088] INFO: 208000 events read in total (13326ms).
[15:07:32.093] INFO: Test took 14470ms.
[15:07:32.401] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:07:32.708] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[15:07:32.708] INFO: number of red-efficiency pixels: 223 129 271 415 508 459 469 362 317 400 403 393 449 207 61 87
[15:07:32.708] INFO: number of X-ray hits detected: 149196 96399 143133 217825 232308 240988 239331 188957 175438 226100 215716 192075 200766 121666 49507 57246
[15:07:32.708] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:07:32.708] INFO: number of Vcal hits detected: 207767 207860 207703 207559 207424 207505 207476 207609 207669 207549 207572 207569 207510 207770 207890 207911
[15:07:32.708] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[15:07:32.708] 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.8 99.9 99.9 100.0
[15:07:32.708] INFO: X-ray hit rate [MHz/cm2]: 43.7 28.3 42.0 63.8 68.1 70.6 70.1 55.4 51.4 66.3 63.2 56.3 58.8 35.7 14.5 16.8
[15:07:32.708] INFO: PixTestHighRate::doXPixelAlive() done
[15:07:32.762] INFO: PixTest:: pg_setup set to default.
[15:07:32.778] INFO: enter test to run
[15:07:46.859] INFO: test: HighRate no parameter change
[15:07:46.859] INFO: running: highrate
[15:07:46.860] INFO: ----------------------------------------------------------------------
[15:07:46.860] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:07:46.860] INFO: ----------------------------------------------------------------------
[15:07:47.478] INFO: Expecting 208000 events.
[15:08:03.361] INFO: 208000 events read in total (15356ms).
[15:08:03.369] INFO: Test took 16500ms.
[15:08:03.857] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:08:04.217] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 1 0
[15:08:04.217] INFO: number of red-efficiency pixels: 478 308 698 894 1323 1014 1113 819 744 954 849 941 1049 469 92 98
[15:08:04.217] INFO: number of X-ray hits detected: 224850 145256 217154 328265 350769 365388 363310 286704 264063 343042 325512 289481 304184 184630 74711 86890
[15:08:04.217] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:08:04.217] INFO: number of Vcal hits detected: 207444 207651 207067 206914 206284 206711 206575 206970 207118 206826 206998 206823 206683 207432 207856 207898
[15:08:04.217] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.5 99.3 99.4 99.4 99.5 99.6 99.5 99.6 99.5 99.4 99.8 100.0 100.0
[15:08:04.217] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.6 99.5 99.2 99.4 99.3 99.5 99.6 99.4 99.5 99.4 99.4 99.7 99.9 100.0
[15:08:04.217] INFO: X-ray hit rate [MHz/cm2]: 65.9 42.6 63.6 96.2 102.8 107.1 106.5 84.0 77.4 100.5 95.4 84.8 89.2 54.1 21.9 25.5
[15:08:04.217] INFO: PixTestHighRate::doXPixelAlive() done
[15:08:04.265] INFO: PixTest:: pg_setup set to default.
[15:08:04.279] INFO: enter test to run
[15:08:16.122] INFO: test: exit no parameter change
[15:08:16.587] QUIET: Connection to board 33 closed.
[15:08:16.598] INFO: pXar: this is the end, my friend