[11:18:48.960] INFO: *** Welcome to pxar ***
[11:18:48.960] INFO: *** Today: 2016/04/20
[11:18:48.988] INFO: *** Version: v1.9.0-796-gef167-dirty
[11:18:48.988] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//dacParameters35_C15.dat
[11:18:48.989] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:18:48.989] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//defaultMaskFile.dat
[11:18:48.989] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C15.dat
[11:18:49.057] INFO: clk: 4
[11:18:49.057] INFO: ctr: 4
[11:18:49.057] INFO: sda: 19
[11:18:49.057] INFO: tin: 9
[11:18:49.057] INFO: level: 15
[11:18:49.057] INFO: triggerdelay: 0
[11:18:49.057] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[11:18:49.057] INFO: Log level: INFO
[11:18:49.069] QUIET: Connection to board DTB_WREKRL opened.
[11:18:49.073] 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:18:49.076] INFO: RPC call hashes of host and DTB match: 398089610
[11:18:50.601] INFO: DUT info:
[11:18:50.601] INFO: The DUT currently contains the following objects:
[11:18:50.601] INFO: 2 TBM Cores tbm08c (2 ON)
[11:18:50.601] INFO: TBM Core alpha (0): 7 registers set
[11:18:50.601] INFO: TBM Core beta (1): 7 registers set
[11:18:50.601] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:18:50.601] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.602] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:18:50.005] INFO: enter 'restricted' command line mode
[11:18:50.005] INFO: enter test to run
[11:18:52.368] INFO: test: timing no parameter change
[11:18:52.368] INFO: running: timing
[11:18:52.394] INFO: ######################################################################
[11:18:52.394] INFO: PixTestTiming::doTest()
[11:18:52.400] INFO: ######################################################################
[11:18:52.400] INFO: ----------------------------------------------------------------------
[11:18:52.400] INFO: PixTestTiming::TBMPhaseScan()
[11:18:52.400] INFO: ----------------------------------------------------------------------
[11:23:40.100] INFO: TBM Phase Settings: 248
[11:23:40.100] INFO: 400MHz Phase: 6
[11:23:40.100] INFO: 160MHz Phase: 7
[11:23:40.100] INFO: Functional Phase Area: 4
[11:23:40.103] INFO: Test took 287703 ms.
[11:23:40.103] INFO: PixTestTiming::TBMPhaseScan() done.
[11:23:40.104] INFO: ----------------------------------------------------------------------
[11:23:40.104] INFO: PixTestTiming::ROCDelayScan()
[11:23:40.104] INFO: ----------------------------------------------------------------------
[11:25:47.001] INFO: ROC Delay Settings: 228
[11:25:47.001] INFO: ROC Header-Trailer/Token Delay: 11
[11:25:47.001] INFO: ROC Port 0 Delay: 4
[11:25:47.001] INFO: ROC Port 1 Delay: 4
[11:25:47.001] INFO: Functional ROC Area: 5
[11:25:47.004] INFO: Test took 127900 ms.
[11:25:47.004] INFO: PixTestTiming::ROCDelayScan() done.
[11:25:47.005] INFO: ----------------------------------------------------------------------
[11:25:47.005] INFO: PixTestTiming::TimingTest()
[11:25:47.005] INFO: ----------------------------------------------------------------------
[11:26:04.086] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:26:19.010] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:26:33.962] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:26:48.912] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:27:03.849] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:27:18.764] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:27:33.720] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:27:48.661] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:03.601] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:18.564] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:18.941] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:18.959] INFO: ----------------------------------------------------------------------
[11:28:18.959] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:28:18.959] INFO: ----------------------------------------------------------------------
[11:28:18.959] INFO: ----------------------------------------------------------------------
[11:28:18.959] INFO: Read back bit status: 1
[11:28:18.959] INFO: ----------------------------------------------------------------------
[11:28:18.959] INFO: ----------------------------------------------------------------------
[11:28:18.959] INFO: Timings are good!
[11:28:18.959] INFO: ----------------------------------------------------------------------
[11:28:18.959] INFO: Test took 150954 ms.
[11:28:18.959] INFO: PixTestTiming::TimingTest() done.
[11:28:18.969] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:28:18.969] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:28:18.969] INFO: PixTestTiming::doTest took 566579 ms.
[11:28:18.970] INFO: PixTestTiming::doTest() done
[11:28:18.970] INFO: Write out TBMPhaseScan_0_V0
[11:28:18.999] INFO: Write out TBMPhaseScan_1_V0
[11:28:18.999] INFO: Write out CombinedTBMPhaseScan_V0
[11:28:18.000] INFO: Write out ROCDelayScan3_V0
[11:28:18.000] INFO: enter test to run
[11:28:28.276] INFO: test: timing no parameter change
[11:28:28.276] INFO: running: timing
[11:28:28.281] INFO: ######################################################################
[11:28:28.281] INFO: PixTestTiming::doTest()
[11:28:28.281] INFO: ######################################################################
[11:28:28.281] INFO: ----------------------------------------------------------------------
[11:28:28.281] INFO: PixTestTiming::TBMPhaseScan()
[11:28:28.281] INFO: ----------------------------------------------------------------------
[11:36:14.155] INFO: TBM Phase Settings: 236
[11:36:14.191] INFO: 400MHz Phase: 3
[11:36:14.191] INFO: 160MHz Phase: 7
[11:36:14.191] INFO: Functional Phase Area: 3
[11:36:14.194] INFO: Test took 465913 ms.
[11:36:14.194] INFO: PixTestTiming::TBMPhaseScan() done.
[11:36:14.194] INFO: ----------------------------------------------------------------------
[11:36:14.194] INFO: PixTestTiming::ROCDelayScan()
[11:36:14.194] INFO: ----------------------------------------------------------------------
[11:38:22.100] INFO: ROC Delay Settings: 228
[11:38:22.100] INFO: ROC Header-Trailer/Token Delay: 11
[11:38:22.100] INFO: ROC Port 0 Delay: 4
[11:38:22.100] INFO: ROC Port 1 Delay: 4
[11:38:22.100] INFO: Functional ROC Area: 5
[11:38:22.103] INFO: Test took 127909 ms.
[11:38:22.103] INFO: PixTestTiming::ROCDelayScan() done.
[11:38:22.103] INFO: ----------------------------------------------------------------------
[11:38:22.104] INFO: PixTestTiming::TimingTest()
[11:38:22.104] INFO: ----------------------------------------------------------------------
[11:38:38.253] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:53.272] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:07.316] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:21.518] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:36.356] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:51.249] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:06.168] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:21.143] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:36.049] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:50.998] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:51.380] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:51.393] INFO: ----------------------------------------------------------------------
[11:40:51.393] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:40:51.393] INFO: ----------------------------------------------------------------------
[11:40:51.393] INFO: ----------------------------------------------------------------------
[11:40:51.393] INFO: Read back bit status: 1
[11:40:51.393] INFO: ----------------------------------------------------------------------
[11:40:51.393] INFO: ----------------------------------------------------------------------
[11:40:51.393] INFO: Timings are good!
[11:40:51.393] INFO: ----------------------------------------------------------------------
[11:40:51.393] INFO: Test took 149290 ms.
[11:40:51.393] INFO: PixTestTiming::TimingTest() done.
[11:40:51.393] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:40:51.436] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:40:51.436] INFO: PixTestTiming::doTest took 743160 ms.
[11:40:51.436] INFO: PixTestTiming::doTest() done
[11:40:51.436] INFO: Write out TBMPhaseScan_0_V1
[11:40:51.436] INFO: Write out TBMPhaseScan_1_V1
[11:40:51.436] INFO: Write out CombinedTBMPhaseScan_V1
[11:40:51.436] INFO: Write out ROCDelayScan3_V1
[11:40:51.437] INFO: enter test to run
[11:40:51.437] INFO: test: no parameter change
[11:40:51.437] INFO: running:
[11:40:51.475] INFO: command -><- not known, ignored
[11:40:51.475] INFO: enter test to run
[11:41:00.175] INFO: test: PixelAlive no parameter change
[11:41:00.175] INFO: running: pixelalive
[11:41:00.179] INFO: ----------------------------------------------------------------------
[11:41:00.179] 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:41:00.179] INFO: ----------------------------------------------------------------------
[11:41:00.493] INFO: Expecting 41600 events.
[11:41:04.793] INFO: 41600 events read in total (3584ms).
[11:41:04.793] INFO: Test took 4612ms.
[11:41:04.800] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:05.199] INFO: PixTestAlive::aliveTest() done
[11:41:05.199] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[11:41:05.202] INFO: enter test to run
[11:41:35.511] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:41:35.511] INFO: running: highrate
[11:41:35.511] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:41:36.801] INFO: ----------------------------------------------------------------------
[11:41:36.801] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:41:36.801] INFO: ----------------------------------------------------------------------
[11:41:36.801] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:41:36.801] INFO: edge/corner pixel THR is adjusted
[11:41:36.801] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:41:37.759] INFO: Collecting data for 5 seconds...
[11:41:42.776] INFO: Done with hot pixel readout
[11:41:54.425] INFO: PixTest:: pg_setup set to default.
[11:41:54.426] INFO: 0 hot pixels found in step 0
[11:41:54.462] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:41:54.465] INFO: PixTest::trimHotPixels() done
[11:41:54.465] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C0.dat
[11:41:54.471] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C1.dat
[11:41:54.477] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C2.dat
[11:41:54.483] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C3.dat
[11:41:54.489] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C4.dat
[11:41:54.495] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C5.dat
[11:41:54.500] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C6.dat
[11:41:54.506] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C7.dat
[11:41:54.511] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C8.dat
[11:41:54.517] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C9.dat
[11:41:54.522] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C10.dat
[11:41:54.528] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C11.dat
[11:41:54.533] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C12.dat
[11:41:54.538] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C13.dat
[11:41:54.544] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C14.dat
[11:41:54.549] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C15.dat
[11:41:54.555] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//defaultMaskFile.dat
[11:41:54.565] INFO: enter test to run
[11:42:11.254] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:42:11.254] INFO: running: highrate
[11:42:11.259] INFO: ----------------------------------------------------------------------
[11:42:11.259] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:42:11.259] INFO: ----------------------------------------------------------------------
[11:42:11.259] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:42:11.259] INFO: edge/corner pixel THR is adjusted
[11:42:11.259] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:42:12.216] INFO: Collecting data for 1 seconds...
[11:42:13.219] INFO: Done with hot pixel readout
[11:42:17.078] INFO: PixTest:: pg_setup set to default.
[11:42:17.079] INFO: 0 hot pixels found in step 0
[11:42:17.084] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:42:17.181] INFO: PixTest::trimHotPixels() done
[11:42:17.181] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C0.dat
[11:42:17.191] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C1.dat
[11:42:17.197] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C2.dat
[11:42:17.203] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C3.dat
[11:42:17.208] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C4.dat
[11:42:17.214] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C5.dat
[11:42:17.219] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C6.dat
[11:42:17.225] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C7.dat
[11:42:17.231] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C8.dat
[11:42:17.236] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C9.dat
[11:42:17.242] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C10.dat
[11:42:17.248] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C11.dat
[11:42:17.253] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C12.dat
[11:42:17.259] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C13.dat
[11:42:17.264] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C14.dat
[11:42:17.270] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C15.dat
[11:42:17.275] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-42_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//defaultMaskFile.dat
[11:42:17.284] INFO: enter test to run
[11:42:42.782] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:42:42.782] INFO: running: xray
[11:42:42.847] INFO: ----------------------------------------------------------------------
[11:42:42.847] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:42:42.847] INFO: ----------------------------------------------------------------------
[11:42:43.810] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:42:55.286] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:43:24.139] INFO: Resuming triggers.
[11:43:35.616] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[11:44:04.979] INFO: Resuming triggers.
[11:44:16.454] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:44:45.739] INFO: Resuming triggers.
[11:44:57.219] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[11:45:26.465] INFO: Resuming triggers.
[11:45:37.944] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[11:46:06.641] INFO: Resuming triggers.
[11:46:18.121] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[11:46:47.512] INFO: Resuming triggers.
[11:46:58.988] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:47:28.315] INFO: Resuming triggers.
[11:47:39.794] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[11:48:09.119] INFO: Resuming triggers.
[11:48:17.633] INFO: data taking finished, elapsed time: 100 seconds.
[11:48:39.688] INFO: PixTest:: pg_setup set to default.
[11:48:39.692] INFO: PixTestXray::doPhRun() done
[11:48:39.825] INFO: enter test to run
[11:49:15.643] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:49:15.643] INFO: running: xray
[11:49:15.644] INFO: ----------------------------------------------------------------------
[11:49:15.644] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:49:15.644] INFO: ----------------------------------------------------------------------
[11:49:16.609] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:49:23.419] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:49:51.885] INFO: Resuming triggers.
[11:49:58.703] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[11:50:28.901] INFO: Resuming triggers.
[11:50:35.714] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[11:51:05.707] INFO: Resuming triggers.
[11:51:12.522] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[11:51:42.456] INFO: Resuming triggers.
[11:51:49.275] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[11:52:19.337] INFO: Resuming triggers.
[11:52:26.150] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[11:52:56.210] INFO: Resuming triggers.
[11:53:03.024] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[11:53:33.038] INFO: Resuming triggers.
[11:53:39.849] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[11:54:09.854] INFO: Resuming triggers.
[11:54:16.664] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[11:54:46.755] INFO: Resuming triggers.
[11:54:53.571] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[11:55:23.513] INFO: Resuming triggers.
[11:55:30.326] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[11:55:59.631] INFO: Resuming triggers.
[11:56:06.440] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[11:56:36.306] INFO: Resuming triggers.
[11:56:43.115] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[11:57:12.956] INFO: Resuming triggers.
[11:57:19.769] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[11:57:49.591] INFO: Resuming triggers.
[11:57:54.533] INFO: data taking finished, elapsed time: 100 seconds.
[11:58:16.544] INFO: PixTest:: pg_setup set to default.
[11:58:16.547] INFO: PixTestXray::doPhRun() done
[11:58:16.695] INFO: enter test to run
[11:58:33.351] INFO: test: HighRate no parameter change
[11:58:33.351] INFO: running: highrate
[11:58:33.415] INFO: ----------------------------------------------------------------------
[11:58:33.415] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:58:33.415] INFO: ----------------------------------------------------------------------
[11:58:33.607] INFO: Expecting 768 events.
[11:58:34.741] INFO: 768 events read in total (418ms).
[11:58:34.741] INFO: Test took 1297ms.
[11:58:35.544] INFO: Expecting 41600 events.
[11:58:38.605] INFO: 41600 events read in total (2534ms).
[11:58:38.606] INFO: Test took 3857ms.
[11:58:38.639] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:58:39.369] INFO: Expecting 41600 events.
[11:58:42.484] INFO: 41600 events read in total (2588ms).
[11:58:42.485] INFO: Test took 3829ms.
[11:58:42.517] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:58:43.247] INFO: Expecting 41600 events.
[11:58:46.458] INFO: 41600 events read in total (2684ms).
[11:58:46.458] INFO: Test took 3923ms.
[11:58:46.491] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:58:47.220] INFO: Expecting 41600 events.
[11:58:50.413] INFO: 41600 events read in total (2666ms).
[11:58:50.414] INFO: Test took 3906ms.
[11:58:50.447] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:58:51.172] INFO: Expecting 41600 events.
[11:58:54.324] INFO: 41600 events read in total (2625ms).
[11:58:54.325] INFO: Test took 3860ms.
[11:58:54.359] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:58:55.077] INFO: Expecting 41600 events.
[11:58:58.255] INFO: 41600 events read in total (2651ms).
[11:58:58.256] INFO: Test took 3880ms.
[11:58:58.289] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:58:59.016] INFO: Expecting 41600 events.
[11:59:02.186] INFO: 41600 events read in total (2643ms).
[11:59:02.187] INFO: Test took 3881ms.
[11:59:02.219] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:02.945] INFO: Expecting 41600 events.
[11:59:06.137] INFO: 41600 events read in total (2666ms).
[11:59:06.138] INFO: Test took 3900ms.
[11:59:06.172] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:06.900] INFO: Expecting 41600 events.
[11:59:09.850] INFO: 41600 events read in total (2423ms).
[11:59:09.851] INFO: Test took 3661ms.
[11:59:09.884] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:10.614] INFO: Expecting 41600 events.
[11:59:13.419] INFO: 41600 events read in total (2278ms).
[11:59:13.420] INFO: Test took 3519ms.
[11:59:13.453] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:14.180] INFO: Expecting 41600 events.
[11:59:17.344] INFO: 41600 events read in total (2637ms).
[11:59:17.345] INFO: Test took 3875ms.
[11:59:17.379] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:18.105] INFO: Expecting 41600 events.
[11:59:21.299] INFO: 41600 events read in total (2667ms).
[11:59:21.300] INFO: Test took 3905ms.
[11:59:21.333] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:22.057] INFO: Expecting 41600 events.
[11:59:24.906] INFO: 41600 events read in total (2322ms).
[11:59:24.907] INFO: Test took 3556ms.
[11:59:24.940] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:25.670] INFO: Expecting 41600 events.
[11:59:28.886] INFO: 41600 events read in total (2690ms).
[11:59:28.887] INFO: Test took 3930ms.
[11:59:28.919] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:29.645] INFO: Expecting 41600 events.
[11:59:32.441] INFO: 41600 events read in total (2269ms).
[11:59:32.442] INFO: Test took 3504ms.
[11:59:32.476] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:33.203] INFO: Expecting 41600 events.
[11:59:36.146] INFO: 41600 events read in total (2416ms).
[11:59:36.147] INFO: Test took 3653ms.
[11:59:36.181] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:36.902] INFO: Expecting 41600 events.
[11:59:40.118] INFO: 41600 events read in total (2689ms).
[11:59:40.128] INFO: Test took 3930ms.
[11:59:40.162] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:40.875] INFO: Expecting 41600 events.
[11:59:44.090] INFO: 41600 events read in total (2688ms).
[11:59:44.091] INFO: Test took 3911ms.
[11:59:44.124] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:44.849] INFO: Expecting 41600 events.
[11:59:48.038] INFO: 41600 events read in total (2662ms).
[11:59:48.039] INFO: Test took 3899ms.
[11:59:48.071] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:48.799] INFO: Expecting 41600 events.
[11:59:51.839] INFO: 41600 events read in total (2513ms).
[11:59:51.840] INFO: Test took 3750ms.
[11:59:51.872] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:59:52.238] INFO: enter test to run
[11:59:59.638] INFO: test: HighRate no parameter change
[11:59:59.638] INFO: running: highrate
[11:59:59.640] INFO: ----------------------------------------------------------------------
[11:59:59.640] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:59:59.640] INFO: ----------------------------------------------------------------------
[12:00:00.253] INFO: Expecting 208000 events.
[12:00:11.934] INFO: 208000 events read in total (11154ms).
[12:00:11.937] INFO: Test took 12291ms.
[12:00:12.076] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:12.325] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[12:00:12.325] INFO: number of red-efficiency pixels: 68 46 115 119 125 119 127 77 81 85 102 81 98 61 26 19
[12:00:12.325] INFO: number of X-ray hits detected: 64768 45546 64320 102922 106609 103034 107730 81061 73044 94895 91193 80248 83658 48603 19528 19659
[12:00:12.325] 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:00:12.325] INFO: number of Vcal hits detected: 207932 207954 207883 207880 207873 207879 207870 207922 207916 207915 207895 207919 207900 207938 207974 207981
[12:00:12.325] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[12:00:12.325] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[12:00:12.325] INFO: X-ray hit rate [MHz/cm2]: 19.0 13.3 18.9 30.2 31.2 30.2 31.6 23.8 21.4 27.8 26.7 23.5 24.5 14.2 5.7 5.8
[12:00:12.325] INFO: PixTestHighRate::doXPixelAlive() done
[12:00:12.371] INFO: PixTest:: pg_setup set to default.
[12:00:12.382] INFO: enter test to run
[12:00:23.910] INFO: test: HighRate no parameter change
[12:00:23.910] INFO: running: highrate
[12:00:23.911] INFO: ----------------------------------------------------------------------
[12:00:23.911] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:00:23.911] INFO: ----------------------------------------------------------------------
[12:00:24.527] INFO: Expecting 208000 events.
[12:00:37.663] INFO: 208000 events read in total (12610ms).
[12:00:37.668] INFO: Test took 13748ms.
[12:00:37.946] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:00:38.242] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[12:00:38.242] INFO: number of red-efficiency pixels: 209 114 276 340 470 439 412 256 195 382 374 225 332 183 48 49
[12:00:38.242] INFO: number of X-ray hits detected: 136025 94490 133461 215114 223634 217305 225725 169450 154697 199116 191309 167587 175006 103281 41066 41678
[12:00:38.242] 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:00:38.242] INFO: number of Vcal hits detected: 207780 207881 207691 207623 207478 207528 207569 207732 207793 207594 207597 207768 207648 207808 207952 207950
[12:00:38.242] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[12:00:38.242] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 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:00:38.242] INFO: X-ray hit rate [MHz/cm2]: 39.9 27.7 39.1 63.1 65.5 63.7 66.2 49.7 45.3 58.4 56.1 49.1 51.3 30.3 12.0 12.2
[12:00:38.242] INFO: PixTestHighRate::doXPixelAlive() done
[12:00:38.289] INFO: PixTest:: pg_setup set to default.
[12:00:38.307] INFO: enter test to run
[12:00:50.278] INFO: test: HighRate no parameter change
[12:00:50.278] INFO: running: highrate
[12:00:50.279] INFO: ----------------------------------------------------------------------
[12:00:50.279] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:00:50.279] INFO: ----------------------------------------------------------------------
[12:00:50.892] INFO: Expecting 208000 events.
[12:01:06.119] INFO: 208000 events read in total (14700ms).
[12:01:06.126] INFO: Test took 15839ms.
[12:01:06.542] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:01:06.882] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[12:01:06.882] INFO: number of red-efficiency pixels: 446 196 593 772 1091 1057 977 553 417 931 879 477 698 363 78 68
[12:01:06.882] INFO: number of X-ray hits detected: 201598 141785 201102 322163 333380 323020 336805 251619 230090 296359 286110 251463 261552 154339 61693 61910
[12:01:06.882] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:01:06.882] INFO: number of Vcal hits detected: 207471 207788 207238 207081 206663 206680 206826 207389 207529 206907 207002 207476 207203 207581 207920 207932
[12:01:06.882] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.6 99.4 99.4 99.5 99.7 99.8 99.5 99.6 99.8 99.7 99.8 100.0 100.0
[12:01:06.882] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.6 99.6 99.4 99.4 99.4 99.7 99.8 99.5 99.5 99.7 99.6 99.8 100.0 100.0
[12:01:06.882] INFO: X-ray hit rate [MHz/cm2]: 59.1 41.6 58.9 94.4 97.7 94.7 98.7 73.8 67.4 86.9 83.9 73.7 76.7 45.2 18.1 18.1
[12:01:06.882] INFO: PixTestHighRate::doXPixelAlive() done
[12:01:06.934] INFO: PixTest:: pg_setup set to default.
[12:01:06.947] INFO: enter test to run
[12:01:12.190] INFO: test: exit no parameter change
[12:01:12.611] QUIET: Connection to board 33 closed.
[12:01:12.620] INFO: pXar: this is the end, my friend