[12:27:56.506] INFO: *** Welcome to pxar ***
[12:27:56.507] INFO: *** Today: 2016/10/20
[12:27:57.327] INFO: *** Version: v1.9.0-818-g96727
[12:27:57.327] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//dacParameters35_C15.dat
[12:27:57.351] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:27:57.368] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//defaultMaskFile.dat
[12:27:57.384] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C15.dat
[12:27:57.516] INFO: clk: 4
[12:27:57.516] INFO: ctr: 4
[12:27:57.516] INFO: sda: 19
[12:27:57.516] INFO: tin: 9
[12:27:57.516] INFO: level: 15
[12:27:57.516] INFO: triggerdelay: 0
[12:27:57.530] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[12:27:57.530] INFO: Log level: INFO
[12:27:57.555] QUIET: Connection to board DTB_WREKRL opened.
[12:27:57.559] 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:
------------------------------------------------------
[12:27:57.562] INFO: RPC call hashes of host and DTB match: 398089610
[12:27:59.090] INFO: DUT info:
[12:27:59.090] INFO: The DUT currently contains the following objects:
[12:27:59.090] INFO: 2 TBM Cores tbm08c (2 ON)
[12:27:59.090] INFO: TBM Core alpha (0): 7 registers set
[12:27:59.090] INFO: TBM Core beta (1): 7 registers set
[12:27:59.090] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:27:59.090] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.090] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.090] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.090] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.090] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.090] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.090] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.090] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.091] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.091] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.091] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.091] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.091] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.091] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.091] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.091] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:27:59.520] INFO: enter 'restricted' command line mode
[12:27:59.520] INFO: enter test to run
[12:28:07.504] INFO: test: PixelAlive no parameter change
[12:28:07.504] INFO: running: pixelalive
[12:28:07.526] INFO: ----------------------------------------------------------------------
[12:28:07.526] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[12:28:07.526] INFO: ----------------------------------------------------------------------
[12:28:07.850] INFO: Expecting 41600 events.
[12:28:12.182] INFO: 41600 events read in total (3614ms).
[12:28:12.349] INFO: Test took 4820ms.
[12:28:12.363] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:12.682] INFO: PixTestAlive::aliveTest() done
[12:28:12.682] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0
[12:28:12.709] INFO: enter test to run
[12:28:17.864] INFO: test: timing no parameter change
[12:28:17.864] INFO: running: timing
[12:28:17.867] INFO: ######################################################################
[12:28:17.867] INFO: PixTestTiming::doTest()
[12:28:17.867] INFO: ######################################################################
[12:28:17.867] INFO: ----------------------------------------------------------------------
[12:28:17.867] INFO: PixTestTiming::TBMPhaseScan()
[12:28:17.867] INFO: ----------------------------------------------------------------------
[12:33:14.386] INFO: TBM Phase Settings: 240
[12:33:14.386] INFO: 400MHz Phase: 4
[12:33:14.386] INFO: 160MHz Phase: 7
[12:33:14.386] INFO: Functional Phase Area: 4
[12:33:14.396] INFO: Test took 296529 ms.
[12:33:14.396] INFO: PixTestTiming::TBMPhaseScan() done.
[12:33:14.397] INFO: ----------------------------------------------------------------------
[12:33:14.397] INFO: PixTestTiming::ROCDelayScan()
[12:33:14.397] INFO: ----------------------------------------------------------------------
[12:35:17.777] INFO: ROC Delay Settings: 228
[12:35:17.777] INFO: ROC Header-Trailer/Token Delay: 11
[12:35:17.777] INFO: ROC Port 0 Delay: 4
[12:35:17.777] INFO: ROC Port 1 Delay: 4
[12:35:17.777] INFO: Functional ROC Area: 5
[12:35:17.780] INFO: Test took 123383 ms.
[12:35:17.780] INFO: PixTestTiming::ROCDelayScan() done.
[12:35:17.781] INFO: ----------------------------------------------------------------------
[12:35:17.781] INFO: PixTestTiming::TimingTest()
[12:35:17.781] INFO: ----------------------------------------------------------------------
[12:35:33.867] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:35:48.839] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:04.041] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:19.372] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:34.652] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:36:49.831] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:04.000] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:20.409] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:35.706] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:51.055] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:51.436] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:37:51.454] INFO: ----------------------------------------------------------------------
[12:37:51.454] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:37:51.454] INFO: ----------------------------------------------------------------------
[12:37:51.454] INFO: ----------------------------------------------------------------------
[12:37:51.454] INFO: Read back bit status: 1
[12:37:51.454] INFO: ----------------------------------------------------------------------
[12:37:51.454] INFO: ----------------------------------------------------------------------
[12:37:51.454] INFO: Timings are good!
[12:37:51.455] INFO: ----------------------------------------------------------------------
[12:37:51.455] INFO: Test took 153675 ms.
[12:37:51.455] INFO: PixTestTiming::TimingTest() done.
[12:37:51.467] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:37:51.474] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:37:51.474] INFO: PixTestTiming::doTest took 573610 ms.
[12:37:51.474] INFO: PixTestTiming::doTest() done
[12:37:51.474] INFO: Write out TBMPhaseScan_0_V0
[12:37:51.475] INFO: Write out TBMPhaseScan_1_V0
[12:37:51.475] INFO: Write out CombinedTBMPhaseScan_V0
[12:37:51.502] INFO: Write out ROCDelayScan3_V0
[12:37:51.503] INFO: enter test to run
[12:38:16.964] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:38:16.964] INFO: running: highrate
[12:38:16.986] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:38:17.302] INFO: ----------------------------------------------------------------------
[12:38:17.302] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:38:17.302] INFO: ----------------------------------------------------------------------
[12:38:17.302] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:38:17.302] INFO: edge/corner pixel THR is adjusted
[12:38:17.302] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:38:18.274] INFO: Collecting data for 5 seconds...
[12:38:23.292] INFO: Done with hot pixel readout
[12:38:34.893] INFO: PixTest:: pg_setup set to default.
[12:38:34.894] INFO: 13 hot pixels found in step 0
[12:38:35.886] INFO: Collecting data for 5 seconds...
[12:38:40.902] INFO: Done with hot pixel readout
[12:38:52.482] INFO: PixTest:: pg_setup set to default.
[12:38:52.483] INFO: 13 hot pixels found in step 1
[12:38:53.476] INFO: Collecting data for 5 seconds...
[12:38:58.491] INFO: Done with hot pixel readout
[12:39:10.091] INFO: PixTest:: pg_setup set to default.
[12:39:10.091] INFO: 13 hot pixels found in step 2
[12:39:11.083] INFO: Collecting data for 5 seconds...
[12:39:16.099] INFO: Done with hot pixel readout
[12:39:27.703] INFO: PixTest:: pg_setup set to default.
[12:39:27.704] INFO: 14 hot pixels found in step 3
[12:39:28.696] INFO: Collecting data for 5 seconds...
[12:39:33.713] INFO: Done with hot pixel readout
[12:39:45.297] INFO: PixTest:: pg_setup set to default.
[12:39:45.298] INFO: 11 hot pixels found in step 4
[12:39:46.290] INFO: Collecting data for 5 seconds...
[12:39:51.306] INFO: Done with hot pixel readout
[12:40:02.926] INFO: PixTest:: pg_setup set to default.
[12:40:02.927] INFO: 12 hot pixels found in step 5
[12:40:03.918] INFO: Collecting data for 5 seconds...
[12:40:08.935] INFO: Done with hot pixel readout
[12:40:20.517] INFO: PixTest:: pg_setup set to default.
[12:40:20.517] INFO: 12 hot pixels found in step 6
[12:40:21.509] INFO: Collecting data for 5 seconds...
[12:40:26.526] INFO: Done with hot pixel readout
[12:40:38.108] INFO: PixTest:: pg_setup set to default.
[12:40:38.109] INFO: 5 hot pixels found in step 7
[12:40:39.100] INFO: Collecting data for 5 seconds...
[12:40:44.116] INFO: Done with hot pixel readout
[12:40:55.726] INFO: PixTest:: pg_setup set to default.

[12:40:55.727] INFO: 5 hot pixels found in step 8
[12:40:56.720] INFO: Collecting data for 5 seconds...
[12:41:01.736] INFO: Done with hot pixel readout
[12:41:13.364] INFO: PixTest:: pg_setup set to default.
[12:41:13.365] INFO: 1 hot pixels found in step 9
[12:41:14.356] INFO: Collecting data for 5 seconds...
[12:41:19.373] INFO: Done with hot pixel readout
[12:41:30.995] INFO: PixTest:: pg_setup set to default.
[12:41:30.996] INFO: 1 hot pixels found in step 10
[12:41:31.988] INFO: Collecting data for 5 seconds...
[12:41:36.005] INFO: Done with hot pixel readout
[12:41:48.597] INFO: PixTest:: pg_setup set to default.
[12:41:48.598] INFO: 1 hot pixels found in step 11
[12:41:49.589] INFO: Collecting data for 5 seconds...
[12:41:54.605] INFO: Done with hot pixel readout
[12:42:06.235] INFO: PixTest:: pg_setup set to default.
[12:42:06.236] INFO: 0 hot pixels found in step 12
[12:42:06.271] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:42:06.275] INFO: PixTest::trimHotPixels() done
[12:42:06.275] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C0.dat
[12:42:06.280] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C1.dat
[12:42:06.287] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C2.dat
[12:42:06.292] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C3.dat
[12:42:06.297] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C4.dat
[12:42:06.303] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C5.dat
[12:42:06.308] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C6.dat
[12:42:06.313] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C7.dat
[12:42:06.318] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C8.dat
[12:42:06.323] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C9.dat
[12:42:06.328] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C10.dat
[12:42:06.333] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C11.dat
[12:42:06.339] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C12.dat
[12:42:06.344] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C13.dat
[12:42:06.349] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C14.dat
[12:42:06.354] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C15.dat
[12:42:06.359] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//defaultMaskFile.dat
[12:42:06.369] INFO: enter test to run
[12:42:26.618] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:42:26.618] INFO: running: highrate
[12:42:26.623] INFO: ----------------------------------------------------------------------
[12:42:26.623] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:42:26.623] INFO: ----------------------------------------------------------------------
[12:42:26.623] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:42:26.623] INFO: edge/corner pixel THR is adjusted
[12:42:26.623] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:42:27.580] INFO: Collecting data for 1 seconds...
[12:42:28.584] INFO: Done with hot pixel readout
[12:42:32.544] INFO: PixTest:: pg_setup set to default.
[12:42:32.545] INFO: 0 hot pixels found in step 0
[12:42:32.550] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:42:32.645] INFO: PixTest::trimHotPixels() done
[12:42:32.646] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C0.dat
[12:42:32.656] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C1.dat
[12:42:32.661] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C2.dat
[12:42:32.666] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C3.dat
[12:42:32.671] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C4.dat
[12:42:32.676] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C5.dat
[12:42:32.682] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C6.dat
[12:42:32.687] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C7.dat
[12:42:32.692] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C8.dat
[12:42:32.697] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C9.dat
[12:42:32.702] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C10.dat
[12:42:32.707] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C11.dat
[12:42:32.713] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C12.dat
[12:42:32.718] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C13.dat
[12:42:32.723] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C14.dat
[12:42:32.728] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//trimParameters35_C15.dat
[12:42:32.733] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-P-5-47_FPIXTest-17C-FNAL-161018-0928-300V_2016-10-18_09h30m_1476801015/000_FPIXTest_p17//defaultMaskFile.dat
[12:42:32.743] INFO: enter test to run
[12:42:54.618] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:42:54.618] INFO: running: xray
[12:42:54.619] INFO: ----------------------------------------------------------------------
[12:42:54.619] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:42:54.619] INFO: ----------------------------------------------------------------------
[12:42:55.595] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:43:07.142] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:43:36.628] INFO: Resuming triggers.
[12:43:48.177] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[12:44:17.670] INFO: Resuming triggers.
[12:44:29.216] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[12:44:58.590] INFO: Resuming triggers.
[12:45:10.140] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[12:45:39.544] INFO: Resuming triggers.
[12:45:51.093] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[12:46:21.044] INFO: Resuming triggers.
[12:46:32.591] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[12:47:02.259] INFO: Resuming triggers.
[12:47:13.810] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[12:47:43.561] INFO: Resuming triggers.
[12:47:55.108] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[12:48:24.832] INFO: Resuming triggers.
[12:48:32.794] INFO: data taking finished, elapsed time: 100 seconds.
[12:48:53.144] INFO: PixTest:: pg_setup set to default.
[12:48:53.147] INFO: PixTestXray::doPhRun() done
[12:48:53.362] INFO: enter test to run
[12:49:37.327] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:49:37.327] INFO: running: xray
[12:49:37.328] INFO: ----------------------------------------------------------------------
[12:49:37.328] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:49:37.328] INFO: ----------------------------------------------------------------------
[12:49:38.309] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:49:45.228] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:50:16.503] INFO: Resuming triggers.
[12:50:23.430] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[12:50:54.330] INFO: Resuming triggers.
[12:51:01.250] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[12:51:32.415] INFO: Resuming triggers.
[12:51:39.336] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[12:52:11.082] INFO: Resuming triggers.
[12:52:17.005] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[12:52:48.229] INFO: Resuming triggers.
[12:52:55.152] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[12:53:25.361] INFO: Resuming triggers.
[12:53:32.281] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[12:54:02.493] INFO: Resuming triggers.
[12:54:09.421] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[12:54:39.670] INFO: Resuming triggers.
[12:54:46.596] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[12:55:16.488] INFO: Resuming triggers.
[12:55:23.407] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[12:55:53.601] INFO: Resuming triggers.
[12:56:00.527] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[12:56:30.663] INFO: Resuming triggers.
[12:56:37.583] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[12:57:07.765] INFO: Resuming triggers.
[12:57:14.687] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[12:57:44.808] INFO: Resuming triggers.
[12:57:51.731] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[12:58:21.871] INFO: Resuming triggers.
[12:58:25.295] INFO: data taking finished, elapsed time: 100 seconds.
[12:58:40.500] INFO: PixTest:: pg_setup set to default.
[12:58:40.503] INFO: PixTestXray::doPhRun() done
[12:58:40.698] INFO: enter test to run
[12:59:07.643] INFO: test: HighRate no parameter change
[12:59:07.643] INFO: running: highrate
[12:59:07.659] INFO: ----------------------------------------------------------------------
[12:59:07.659] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:59:07.659] INFO: ----------------------------------------------------------------------
[12:59:07.830] INFO: Expecting 768 events.
[12:59:08.979] INFO: 768 events read in total (433ms).
[12:59:08.979] INFO: Test took 1283ms.
[12:59:09.782] INFO: Expecting 41600 events.
[12:59:12.876] INFO: 41600 events read in total (2567ms).
[12:59:12.877] INFO: Test took 3876ms.
[12:59:12.910] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:13.640] INFO: Expecting 41600 events.
[12:59:16.857] INFO: 41600 events read in total (2690ms).
[12:59:16.858] INFO: Test took 3931ms.
[12:59:16.891] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:17.616] INFO: Expecting 41600 events.
[12:59:20.783] INFO: 41600 events read in total (2640ms).
[12:59:20.784] INFO: Test took 3876ms.
[12:59:20.817] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:21.540] INFO: Expecting 41600 events.
[12:59:24.758] INFO: 41600 events read in total (2691ms).
[12:59:24.759] INFO: Test took 3925ms.
[12:59:24.798] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:25.504] INFO: Expecting 41600 events.
[12:59:28.756] INFO: 41600 events read in total (2725ms).
[12:59:28.757] INFO: Test took 3934ms.
[12:59:28.790] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:29.516] INFO: Expecting 41600 events.
[12:59:32.774] INFO: 41600 events read in total (2731ms).
[12:59:32.775] INFO: Test took 3968ms.
[12:59:32.809] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:33.529] INFO: Expecting 41600 events.
[12:59:36.754] INFO: 41600 events read in total (2698ms).
[12:59:36.755] INFO: Test took 3929ms.
[12:59:36.790] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:37.508] INFO: Expecting 41600 events.
[12:59:40.875] INFO: 41600 events read in total (2840ms).
[12:59:40.876] INFO: Test took 4068ms.
[12:59:40.910] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:41.629] INFO: Expecting 41600 events.
[12:59:44.907] INFO: 41600 events read in total (2752ms).
[12:59:44.908] INFO: Test took 3981ms.
[12:59:44.941] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:45.669] INFO: Expecting 41600 events.
[12:59:48.936] INFO: 41600 events read in total (2741ms).
[12:59:48.937] INFO: Test took 3979ms.
[12:59:48.970] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:49.695] INFO: Expecting 41600 events.
[12:59:52.002] INFO: 41600 events read in total (2780ms).
[12:59:52.003] INFO: Test took 4016ms.
[12:59:53.036] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:53.758] INFO: Expecting 41600 events.
[12:59:57.012] INFO: 41600 events read in total (2727ms).
[12:59:57.013] INFO: Test took 3958ms.
[12:59:57.046] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:59:57.771] INFO: Expecting 41600 events.
[13:00:01.051] INFO: 41600 events read in total (2753ms).
[13:00:01.053] INFO: Test took 3990ms.
[13:00:01.092] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:00:01.800] INFO: Expecting 41600 events.
[13:00:05.114] INFO: 41600 events read in total (2787ms).
[13:00:05.115] INFO: Test took 4006ms.
[13:00:05.149] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:00:05.874] INFO: Expecting 41600 events.
[13:00:09.174] INFO: 41600 events read in total (2773ms).
[13:00:09.175] INFO: Test took 4009ms.
[13:00:09.208] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:00:09.927] INFO: Expecting 41600 events.
[13:00:13.183] INFO: 41600 events read in total (2729ms).
[13:00:13.184] INFO: Test took 3959ms.
[13:00:13.218] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:00:13.936] INFO: Expecting 41600 events.
[13:00:17.111] INFO: 41600 events read in total (2648ms).
[13:00:17.112] INFO: Test took 3876ms.
[13:00:17.146] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:00:17.868] INFO: Expecting 41600 events.
[13:00:21.134] INFO: 41600 events read in total (2739ms).
[13:00:21.135] INFO: Test took 3970ms.
[13:00:21.169] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:00:21.894] INFO: Expecting 41600 events.
[13:00:25.117] INFO: 41600 events read in total (2696ms).
[13:00:25.118] INFO: Test took 3932ms.
[13:00:25.152] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:00:25.877] INFO: Expecting 41600 events.
[13:00:28.954] INFO: 41600 events read in total (2550ms).
[13:00:28.955] INFO: Test took 3785ms.
[13:00:28.989] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:00:29.353] INFO: enter test to run
[13:00:49.802] INFO: test: HighRate no parameter change
[13:00:49.803] INFO: running: highrate
[13:00:49.804] INFO: ----------------------------------------------------------------------
[13:00:49.804] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:00:49.804] INFO: ----------------------------------------------------------------------
[13:00:50.425] INFO: Expecting 208000 events.
[13:01:02.474] INFO: 208000 events read in total (11522ms).
[13:01:02.477] INFO: Test took 12665ms.
[13:01:02.647] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:02.928] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 1 0 0 0 0
[13:01:02.928] INFO: number of red-efficiency pixels: 90 51 53 132 161 164 143 97 83 130 98 86 95 66 22 22
[13:01:02.928] INFO: number of X-ray hits detected: 62229 40409 61857 98183 108636 114526 111339 80059 72941 98001 92471 77657 80038 46733 18733 21681
[13:01:02.928] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:01:02.928] INFO: number of Vcal hits detected: 207908 207948 207947 207815 207831 207833 207852 207897 207914 207866 207883 207864 207904 207932 207978 207978
[13:01:02.928] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[13:01:02.928] INFO: Vcal hit overall 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
[13:01:02.928] INFO: X-ray hit rate [MHz/cm2]: 18.2 11.8 18.1 28.8 31.8 33.6 32.6 23.5 21.4 28.7 27.1 22.8 23.5 13.7 5.5 6.4
[13:01:02.928] INFO: PixTestHighRate::doXPixelAlive() done
[13:01:02.974] INFO: PixTest:: pg_setup set to default.
[13:01:02.992] INFO: enter test to run
[13:01:21.154] INFO: test: HighRate no parameter change
[13:01:21.154] INFO: running: highrate
[13:01:21.156] INFO: ----------------------------------------------------------------------
[13:01:21.156] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:01:21.156] INFO: ----------------------------------------------------------------------
[13:01:21.773] INFO: Expecting 208000 events.
[13:01:35.565] INFO: 208000 events read in total (13265ms).
[13:01:35.570] INFO: Test took 14404ms.
[13:01:35.864] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:01:36.166] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 1 0 0 0 0
[13:01:36.166] INFO: number of red-efficiency pixels: 237 145 199 348 558 580 470 350 275 509 392 285 253 192 44 69
[13:01:36.166] INFO: number of X-ray hits detected: 132691 86339 132513 209597 232268 243743 239396 172446 157015 208021 197985 166212 171974 100700 40271 45525
[13:01:36.166] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:01:36.166] INFO: number of Vcal hits detected: 207744 207848 207787 207584 207368 207349 207467 207616 207711 207442 207553 207653 207736 207794 207956 207931
[13:01:36.166] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.8 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[13:01:36.166] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.7 99.8 99.9 99.7 99.8 99.8 99.9 99.9 100.0 100.0
[13:01:36.166] INFO: X-ray hit rate [MHz/cm2]: 38.9 25.3 38.8 61.4 68.1 71.4 70.2 50.5 46.0 61.0 58.0 48.7 50.4 29.5 11.8 13.3
[13:01:36.166] INFO: PixTestHighRate::doXPixelAlive() done
[13:01:36.212] INFO: PixTest:: pg_setup set to default.
[13:01:36.232] INFO: enter test to run
[13:01:50.290] INFO: test: HighRate no parameter change
[13:01:50.290] INFO: running: highrate
[13:01:50.291] INFO: ----------------------------------------------------------------------
[13:01:50.291] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:01:50.291] INFO: ----------------------------------------------------------------------
[13:01:50.908] INFO: Expecting 208000 events.
[13:02:06.344] INFO: 208000 events read in total (14910ms).
[13:02:06.351] INFO: Test took 16049ms.
[13:02:06.808] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:02:07.157] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 1 0 0 0 0
[13:02:07.157] INFO: number of red-efficiency pixels: 536 283 471 766 1349 1378 1115 760 532 1077 933 565 545 382 67 100
[13:02:07.157] INFO: number of X-ray hits detected: 199522 130342 198978 314847 347441 364350 357951 258153 235561 313914 297973 251522 259842 149922 61251 69410
[13:02:07.157] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:02:07.157] INFO: number of Vcal hits detected: 207301 207694 207426 207047 206242 206119 206533 207017 207374 206656 206865 207314 207405 207559 207932 207898
[13:02:07.157] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.8 99.6 99.2 99.2 99.4 99.6 99.7 99.4 99.5 99.7 99.7 99.8 100.0 100.0
[13:02:07.157] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.5 99.2 99.1 99.3 99.5 99.7 99.4 99.5 99.7 99.7 99.8 100.0 100.0
[13:02:07.157] INFO: X-ray hit rate [MHz/cm2]: 58.5 38.2 58.3 92.3 101.8 106.8 104.9 75.7 69.0 92.0 87.3 73.7 76.2 43.9 18.0 20.3
[13:02:07.157] INFO: PixTestHighRate::doXPixelAlive() done
[13:02:07.204] INFO: PixTest:: pg_setup set to default.
[13:02:07.220] INFO: enter test to run
[13:02:26.082] INFO: test: exit no parameter change
[13:02:26.750] QUIET: Connection to board 33 closed.
[13:02:26.938] INFO: pXar: this is the end, my friend