[11:30:54.564] INFO: *** Welcome to pxar ***
[11:30:54.564] INFO: *** Today: 2016/04/27
[11:30:54.586] INFO: *** Version: v1.9.0-796-gef167-dirty
[11:30:54.586] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//dacParameters35_C15.dat
[11:30:54.587] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:30:54.587] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//defaultMaskFile.dat
[11:30:54.587] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C15.dat
[11:30:54.657] INFO: clk: 4
[11:30:54.657] INFO: ctr: 4
[11:30:54.657] INFO: sda: 19
[11:30:54.657] INFO: tin: 9
[11:30:54.657] INFO: level: 15
[11:30:54.657] INFO: triggerdelay: 0
[11:30:54.657] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[11:30:54.657] INFO: Log level: INFO
[11:30:54.674] QUIET: Connection to board DTB_WREKRL opened.
[11:30:54.677] 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:30:54.680] INFO: RPC call hashes of host and DTB match: 398089610
[11:30:56.211] INFO: DUT info:
[11:30:56.211] INFO: The DUT currently contains the following objects:
[11:30:56.211] INFO: 2 TBM Cores tbm08c (2 ON)
[11:30:56.211] INFO: TBM Core alpha (0): 7 registers set
[11:30:56.211] INFO: TBM Core beta (1): 7 registers set
[11:30:56.211] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:30:56.212] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.212] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:30:56.615] INFO: enter 'restricted' command line mode
[11:30:56.616] INFO: enter test to run
[11:30:57.710] INFO: test: timing no parameter change
[11:30:57.710] INFO: running: timing
[11:30:57.719] INFO: ######################################################################
[11:30:57.719] INFO: PixTestTiming::doTest()
[11:30:57.719] INFO: ######################################################################
[11:30:57.719] INFO: ----------------------------------------------------------------------
[11:30:57.719] INFO: PixTestTiming::TBMPhaseScan()
[11:30:57.719] INFO: ----------------------------------------------------------------------
[11:38:17.303] INFO: TBM Phase Settings: 224
[11:38:17.303] INFO: 400MHz Phase: 0
[11:38:17.303] INFO: 160MHz Phase: 7
[11:38:17.303] INFO: Functional Phase Area: 4
[11:38:17.306] INFO: Test took 439587 ms.
[11:38:17.306] INFO: PixTestTiming::TBMPhaseScan() done.
[11:38:17.307] INFO: ----------------------------------------------------------------------
[11:38:17.307] INFO: PixTestTiming::ROCDelayScan()
[11:38:17.307] INFO: ----------------------------------------------------------------------
[11:42:16.921] INFO: ROC Delay Settings: 228
[11:42:16.921] INFO: ROC Header-Trailer/Token Delay: 11
[11:42:16.921] INFO: ROC Port 0 Delay: 4
[11:42:16.921] INFO: ROC Port 1 Delay: 4
[11:42:16.921] INFO: Functional ROC Area: 5
[11:42:16.924] INFO: Test took 239618 ms.
[11:42:16.924] INFO: PixTestTiming::ROCDelayScan() done.
[11:42:16.924] INFO: ----------------------------------------------------------------------
[11:42:16.924] INFO: PixTestTiming::TimingTest()
[11:42:16.924] INFO: ----------------------------------------------------------------------
[11:42:33.064] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:48.057] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:03.020] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:18.002] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:32.952] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:47.915] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:02.882] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:17.845] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:32.809] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:47.772] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:48.154] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:48.171] INFO: ----------------------------------------------------------------------
[11:44:48.171] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:44:48.171] INFO: ----------------------------------------------------------------------
[11:44:48.171] INFO: ----------------------------------------------------------------------
[11:44:48.171] INFO: Read back bit status: 1
[11:44:48.171] INFO: ----------------------------------------------------------------------
[11:44:48.171] INFO: ----------------------------------------------------------------------
[11:44:48.171] INFO: Timings are good!
[11:44:48.171] INFO: ----------------------------------------------------------------------
[11:44:48.171] INFO: Test took 151247 ms.
[11:44:48.171] INFO: PixTestTiming::TimingTest() done.
[11:44:48.171] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:44:48.172] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:44:48.172] INFO: PixTestTiming::doTest took 830458 ms.
[11:44:48.172] INFO: PixTestTiming::doTest() done
[11:44:48.172] INFO: Write out TBMPhaseScan_0_V0
[11:44:48.198] INFO: Write out TBMPhaseScan_1_V0
[11:44:48.198] INFO: Write out CombinedTBMPhaseScan_V0
[11:44:48.199] INFO: Write out ROCDelayScan3_V0
[11:44:48.199] INFO: enter test to run
[11:44:57.585] INFO: test: PixelAlive no parameter change
[11:44:57.585] INFO: running: pixelalive
[11:44:57.589] INFO: ----------------------------------------------------------------------
[11:44:57.589] 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:44:57.589] INFO: ----------------------------------------------------------------------
[11:44:57.910] INFO: Expecting 41600 events.
[11:45:02.225] INFO: 41600 events read in total (3599ms).
[11:45:02.225] INFO: Test took 4632ms.
[11:45:02.232] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:45:02.627] INFO: PixTestAlive::aliveTest() done
[11:45:02.627] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 7 0 0 0 0 0 0 0 0 0
[11:45:02.631] INFO: enter test to run
[11:48:52.247] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:48:52.247] INFO: running: highrate
[11:48:52.247] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:48:52.406] INFO: ----------------------------------------------------------------------
[11:48:52.406] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:48:52.406] INFO: ----------------------------------------------------------------------
[11:48:52.406] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:48:52.406] INFO: edge/corner pixel THR is adjusted
[11:48:52.406] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:48:53.364] INFO: Collecting data for 5 seconds...
[11:48:58.382] INFO: Done with hot pixel readout
[11:49:10.271] INFO: PixTest:: pg_setup set to default.
[11:49:10.272] INFO: 2 hot pixels found in step 0
[11:49:11.266] INFO: Collecting data for 5 seconds...
[11:49:16.283] INFO: Done with hot pixel readout
[11:49:28.181] INFO: PixTest:: pg_setup set to default.

[11:49:28.182] INFO: 2 hot pixels found in step 1
[11:49:29.176] INFO: Collecting data for 5 seconds...
[11:49:34.194] INFO: Done with hot pixel readout
[11:49:46.080] INFO: PixTest:: pg_setup set to default.
[11:49:46.081] INFO: 2 hot pixels found in step 2
[11:49:47.074] INFO: Collecting data for 5 seconds...
[11:49:52.091] INFO: Done with hot pixel readout
[11:50:03.993] INFO: PixTest:: pg_setup set to default.
[11:50:03.994] INFO: 5 hot pixels found in step 3
[11:50:04.988] INFO: Collecting data for 5 seconds...
[11:50:10.004] INFO: Done with hot pixel readout
[11:50:21.913] INFO: PixTest:: pg_setup set to default.
[11:50:21.914] INFO: 4 hot pixels found in step 4
[11:50:22.909] INFO: Collecting data for 5 seconds...
[11:50:27.927] INFO: Done with hot pixel readout
[11:50:39.864] INFO: PixTest:: pg_setup set to default.
[11:50:39.865] INFO: 3 hot pixels found in step 5
[11:50:40.859] INFO: Collecting data for 5 seconds...
[11:50:45.876] INFO: Done with hot pixel readout
[11:50:57.799] INFO: PixTest:: pg_setup set to default.
[11:50:57.800] INFO: 3 hot pixels found in step 6
[11:50:58.793] INFO: Collecting data for 5 seconds...
[11:51:03.811] INFO: Done with hot pixel readout
[11:51:15.721] INFO: PixTest:: pg_setup set to default.
[11:51:15.722] INFO: 4 hot pixels found in step 7
[11:51:16.717] INFO: Collecting data for 5 seconds...
[11:51:21.734] INFO: Done with hot pixel readout
[11:51:33.647] INFO: PixTest:: pg_setup set to default.
[11:51:33.648] INFO: 3 hot pixels found in step 8
[11:51:34.644] INFO: Collecting data for 5 seconds...
[11:51:39.661] INFO: Done with hot pixel readout
[11:51:51.576] INFO: PixTest:: pg_setup set to default.
[11:51:51.576] INFO: 3 hot pixels found in step 9
[11:51:52.571] INFO: Collecting data for 5 seconds...
[11:51:57.588] INFO: Done with hot pixel readout
[11:52:09.482] INFO: PixTest:: pg_setup set to default.
[11:52:09.483] INFO: 2 hot pixels found in step 10
[11:52:10.478] INFO: Collecting data for 5 seconds...
[11:52:15.495] INFO: Done with hot pixel readout
[11:52:27.408] INFO: PixTest:: pg_setup set to default.
[11:52:27.408] INFO: 3 hot pixels found in step 11
[11:52:28.403] INFO: Collecting data for 5 seconds...
[11:52:33.420] INFO: Done with hot pixel readout
[11:52:45.334] INFO: PixTest:: pg_setup set to default.
[11:52:45.335] INFO: 0 hot pixels found in step 12
[11:52:45.373] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:52:45.377] INFO: PixTest::trimHotPixels() done
[11:52:45.377] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C0.dat
[11:52:45.383] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C1.dat
[11:52:45.390] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C2.dat
[11:52:45.395] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C3.dat
[11:52:45.400] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C4.dat
[11:52:45.406] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C5.dat
[11:52:45.411] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C6.dat
[11:52:45.416] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C7.dat
[11:52:45.421] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C8.dat
[11:52:45.426] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C9.dat
[11:52:45.432] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C10.dat
[11:52:45.437] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C11.dat
[11:52:45.442] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C12.dat
[11:52:45.447] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C13.dat
[11:52:45.452] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C14.dat
[11:52:45.458] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C15.dat
[11:52:45.463] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//defaultMaskFile.dat
[11:52:45.473] INFO: enter test to run
[11:53:12.533] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:53:12.533] INFO: running: highrate
[11:53:12.537] INFO: ----------------------------------------------------------------------
[11:53:12.537] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:53:12.537] INFO: ----------------------------------------------------------------------
[11:53:12.537] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:53:12.537] INFO: edge/corner pixel THR is adjusted
[11:53:12.537] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:53:13.495] INFO: Collecting data for 1 seconds...
[11:53:14.499] INFO: Done with hot pixel readout
[11:53:18.597] INFO: PixTest:: pg_setup set to default.
[11:53:18.598] INFO: 0 hot pixels found in step 0
[11:53:18.603] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:53:18.690] INFO: PixTest::trimHotPixels() done
[11:53:18.690] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C0.dat
[11:53:18.698] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C1.dat
[11:53:18.705] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C2.dat
[11:53:18.711] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C3.dat
[11:53:18.716] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C4.dat
[11:53:18.721] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C5.dat
[11:53:18.727] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C6.dat
[11:53:18.732] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C7.dat
[11:53:18.737] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C8.dat
[11:53:18.742] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C9.dat
[11:53:18.747] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C10.dat
[11:53:18.753] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C11.dat
[11:53:18.758] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C12.dat
[11:53:18.763] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C13.dat
[11:53:18.768] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C14.dat
[11:53:18.773] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//trimParameters35_C15.dat
[11:53:18.779] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-2-48_FPIXTest-17C-FNAL-160422-0956_2016-04-22_09h56m_1461337018/000_FPIXTest_p17//defaultMaskFile.dat
[11:53:18.788] INFO: enter test to run
[11:53:43.484] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:53:43.484] INFO: running: xray
[11:53:43.486] INFO: ----------------------------------------------------------------------
[11:53:43.486] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:53:43.486] INFO: ----------------------------------------------------------------------
[11:53:44.450] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:53:55.759] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:54:25.238] INFO: Resuming triggers.
[11:54:36.553] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[11:55:05.919] INFO: Resuming triggers.
[11:55:17.231] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[11:55:46.724] INFO: Resuming triggers.
[11:55:58.035] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[11:56:27.420] INFO: Resuming triggers.
[11:56:38.729] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[11:57:07.856] INFO: Resuming triggers.
[11:57:19.171] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[11:57:48.337] INFO: Resuming triggers.
[11:57:59.651] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[11:58:29.110] INFO: Resuming triggers.
[11:58:40.424] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[11:59:09.844] INFO: Resuming triggers.
[11:59:19.673] INFO: data taking finished, elapsed time: 100 seconds.
[11:59:45.433] INFO: PixTest:: pg_setup set to default.
[11:59:45.436] INFO: PixTestXray::doPhRun() done
[11:59:45.572] INFO: enter test to run
[12:00:07.946] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:00:07.946] INFO: running: xray
[12:00:07.947] INFO: ----------------------------------------------------------------------
[12:00:07.947] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:00:07.947] INFO: ----------------------------------------------------------------------
[12:00:08.922] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:00:15.517] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:00:45.578] INFO: Resuming triggers.
[12:00:52.167] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[12:01:22.198] INFO: Resuming triggers.
[12:01:28.789] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[12:01:58.850] INFO: Resuming triggers.
[12:02:05.442] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[12:02:35.548] INFO: Resuming triggers.
[12:02:42.138] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[12:03:12.179] INFO: Resuming triggers.
[12:03:18.771] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[12:03:48.911] INFO: Resuming triggers.
[12:03:55.500] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[12:04:25.584] INFO: Resuming triggers.
[12:04:32.170] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[12:05:02.182] INFO: Resuming triggers.
[12:05:08.774] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[12:05:38.872] INFO: Resuming triggers.
[12:05:45.459] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[12:06:15.516] INFO: Resuming triggers.
[12:06:22.103] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[12:06:52.241] INFO: Resuming triggers.
[12:06:58.832] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[12:07:25.884] INFO: Resuming triggers.
[12:07:32.473] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[12:08:02.542] INFO: Resuming triggers.
[12:08:09.130] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[12:08:39.255] INFO: Resuming triggers.
[12:08:45.845] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[12:09:15.900] INFO: Resuming triggers.
[12:09:17.392] INFO: data taking finished, elapsed time: 100 seconds.
[12:09:24.517] INFO: PixTest:: pg_setup set to default.
[12:09:24.520] INFO: PixTestXray::doPhRun() done
[12:09:24.670] INFO: enter test to run
[12:13:18.060] INFO: test: HighRate no parameter change
[12:13:18.060] INFO: running: highrate
[12:13:18.061] INFO: ----------------------------------------------------------------------
[12:13:18.061] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:13:18.061] INFO: ----------------------------------------------------------------------
[12:13:18.201] INFO: Expecting 768 events.
[12:13:19.335] INFO: 768 events read in total (418ms).
[12:13:19.335] INFO: Test took 1268ms.
[12:13:20.138] INFO: Expecting 41600 events.
[12:13:23.261] INFO: 41600 events read in total (2596ms).
[12:13:23.262] INFO: Test took 3919ms.
[12:13:23.297] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:24.023] INFO: Expecting 41600 events.
[12:13:27.241] INFO: 41600 events read in total (2691ms).
[12:13:27.242] INFO: Test took 3928ms.
[12:13:27.278] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:27.996] INFO: Expecting 41600 events.
[12:13:31.264] INFO: 41600 events read in total (2741ms).
[12:13:31.265] INFO: Test took 3968ms.
[12:13:31.301] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:32.018] INFO: Expecting 41600 events.
[12:13:35.306] INFO: 41600 events read in total (2761ms).
[12:13:35.307] INFO: Test took 3986ms.
[12:13:35.344] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:36.059] INFO: Expecting 41600 events.
[12:13:39.321] INFO: 41600 events read in total (2735ms).
[12:13:39.322] INFO: Test took 3958ms.
[12:13:39.357] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:40.081] INFO: Expecting 41600 events.
[12:13:43.351] INFO: 41600 events read in total (2743ms).
[12:13:43.352] INFO: Test took 3976ms.
[12:13:43.389] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:44.109] INFO: Expecting 41600 events.
[12:13:47.371] INFO: 41600 events read in total (2735ms).
[12:13:47.372] INFO: Test took 3964ms.
[12:13:47.408] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:48.130] INFO: Expecting 41600 events.
[12:13:51.389] INFO: 41600 events read in total (2732ms).
[12:13:51.391] INFO: Test took 3965ms.
[12:13:51.426] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:52.148] INFO: Expecting 41600 events.
[12:13:55.384] INFO: 41600 events read in total (2709ms).
[12:13:55.385] INFO: Test took 3940ms.
[12:13:55.421] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:56.141] INFO: Expecting 41600 events.
[12:13:59.178] INFO: 41600 events read in total (2510ms).
[12:13:59.179] INFO: Test took 3739ms.
[12:13:59.215] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:13:59.937] INFO: Expecting 41600 events.
[12:14:03.124] INFO: 41600 events read in total (2661ms).
[12:14:03.125] INFO: Test took 3892ms.
[12:14:03.165] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:03.872] INFO: Expecting 41600 events.
[12:14:06.867] INFO: 41600 events read in total (2468ms).
[12:14:06.869] INFO: Test took 3685ms.
[12:14:06.907] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:07.624] INFO: Expecting 41600 events.
[12:14:10.675] INFO: 41600 events read in total (2525ms).
[12:14:10.676] INFO: Test took 3749ms.
[12:14:10.712] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:11.431] INFO: Expecting 41600 events.
[12:14:14.586] INFO: 41600 events read in total (2628ms).
[12:14:14.588] INFO: Test took 3857ms.
[12:14:14.625] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:15.345] INFO: Expecting 41600 events.
[12:14:18.329] INFO: 41600 events read in total (2458ms).
[12:14:18.330] INFO: Test took 3685ms.
[12:14:18.367] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:19.085] INFO: Expecting 41600 events.
[12:14:22.359] INFO: 41600 events read in total (2747ms).
[12:14:22.360] INFO: Test took 3974ms.
[12:14:22.395] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:23.113] INFO: Expecting 41600 events.
[12:14:26.382] INFO: 41600 events read in total (2742ms).
[12:14:26.383] INFO: Test took 3969ms.
[12:14:26.419] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:27.140] INFO: Expecting 41600 events.
[12:14:30.399] INFO: 41600 events read in total (2732ms).
[12:14:30.400] INFO: Test took 3962ms.
[12:14:30.436] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:31.153] INFO: Expecting 41600 events.
[12:14:34.398] INFO: 41600 events read in total (2718ms).
[12:14:34.399] INFO: Test took 3944ms.
[12:14:34.435] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:35.157] INFO: Expecting 41600 events.
[12:14:38.296] INFO: 41600 events read in total (2612ms).
[12:14:38.297] INFO: Test took 3843ms.
[12:14:38.331] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:38.692] INFO: enter test to run
[12:15:39.371] INFO: test: HighRate no parameter change
[12:15:39.371] INFO: running: highrate
[12:15:39.372] INFO: ----------------------------------------------------------------------
[12:15:39.372] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:15:39.372] INFO: ----------------------------------------------------------------------
[12:15:39.987] INFO: Expecting 208000 events.
[12:15:51.977] INFO: 208000 events read in total (11463ms).
[12:15:51.980] INFO: Test took 12598ms.
[12:15:52.132] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:52.387] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 7 0 0 0 0 0 0 0 0 0
[12:15:52.387] INFO: number of red-efficiency pixels: 77 49 99 160 159 127 145 95 95 126 142 114 110 56 37 29
[12:15:52.387] INFO: number of X-ray hits detected: 58913 42909 75312 117369 123528 126107 123094 95287 85671 97058 102657 86693 89316 51477 22166 27733
[12:15:52.387] 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:15:52.387] INFO: number of Vcal hits detected: 207919 207950 207897 207835 207838 207870 207510 207904 207903 207871 207856 207884 207885 207942 207963 207971
[12:15:52.387] 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 99.9 100.0 100.0 100.0 100.0
[12:15:52.387] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.8 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[12:15:52.387] INFO: X-ray hit rate [MHz/cm2]: 17.3 12.6 22.1 34.4 36.2 37.0 36.1 27.9 25.1 28.4 30.1 25.4 26.2 15.1 6.5 8.1
[12:15:52.387] INFO: PixTestHighRate::doXPixelAlive() done
[12:15:52.438] INFO: PixTest:: pg_setup set to default.
[12:15:52.450] INFO: enter test to run
[12:16:35.619] INFO: test: HighRate no parameter change
[12:16:35.619] INFO: running: highrate
[12:16:35.620] INFO: ----------------------------------------------------------------------
[12:16:35.620] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:16:35.620] INFO: ----------------------------------------------------------------------
[12:16:36.236] INFO: Expecting 208000 events.
[12:16:50.006] INFO: 208000 events read in total (13243ms).
[12:16:50.011] INFO: Test took 14383ms.
[12:16:50.316] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:16:50.619] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 7 0 0 0 0 0 0 0 0 0
[12:16:50.619] INFO: number of red-efficiency pixels: 158 111 271 513 542 478 449 295 285 376 397 310 337 189 58 66
[12:16:50.619] INFO: number of X-ray hits detected: 119438 87237 152695 237215 249341 255747 249527 195132 173654 196560 208620 178162 182456 105265 45036 56939
[12:16:50.619] 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:16:50.619] INFO: number of Vcal hits detected: 207831 207886 207702 207431 207389 207478 207182 207682 207699 207605 207573 207671 207649 207798 207942 207932
[12:16:50.620] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.7 99.7 99.8 99.8 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[12:16:50.620] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.7 99.7 99.7 99.6 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[12:16:50.620] INFO: X-ray hit rate [MHz/cm2]: 35.0 25.6 44.8 69.5 73.1 75.0 73.1 57.2 50.9 57.6 61.1 52.2 53.5 30.9 13.2 16.7
[12:16:50.620] INFO: PixTestHighRate::doXPixelAlive() done
[12:16:50.667] INFO: PixTest:: pg_setup set to default.
[12:16:50.683] INFO: enter test to run
[12:17:02.826] INFO: test: HighRate no parameter change
[12:17:02.826] INFO: running: highrate
[12:17:02.827] INFO: ----------------------------------------------------------------------
[12:17:02.827] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:17:02.827] INFO: ----------------------------------------------------------------------
[12:17:03.443] INFO: Expecting 208000 events.
[12:17:18.218] INFO: 208000 events read in total (14248ms).
[12:17:18.225] INFO: Test took 15387ms.
[12:17:18.692] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:19.049] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 7 0 0 0 0 0 0 0 0 0
[12:17:19.049] INFO: number of red-efficiency pixels: 358 269 651 1330 1301 1104 1081 730 697 964 1052 782 727 437 102 89
[12:17:19.049] INFO: number of X-ray hits detected: 180626 133170 234158 360413 379796 389377 377922 296257 265618 299121 316060 269814 278401 160307 69839 86270
[12:17:19.049] 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:17:19.049] INFO: number of Vcal hits detected: 207605 207706 207119 206210 206258 206598 206326 207104 207201 206837 206709 207056 207151 207500 207892 207911
[12:17:19.049] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.2 99.3 99.4 99.4 99.6 99.6 99.5 99.4 99.6 99.6 99.8 99.9 100.0
[12:17:19.049] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.6 99.1 99.2 99.3 99.2 99.6 99.6 99.4 99.4 99.5 99.6 99.8 99.9 100.0
[12:17:19.049] INFO: X-ray hit rate [MHz/cm2]: 52.9 39.0 68.6 105.6 111.3 114.1 110.8 86.8 77.9 87.7 92.6 79.1 81.6 47.0 20.5 25.3
[12:17:19.049] INFO: PixTestHighRate::doXPixelAlive() done
[12:17:19.097] INFO: PixTest:: pg_setup set to default.
[12:17:19.113] INFO: enter test to run
[12:17:21.570] INFO: test: exit no parameter change
[12:17:22.096] QUIET: Connection to board 33 closed.
[12:17:22.098] INFO: pXar: this is the end, my friend