[14:17:04.750] INFO: *** Welcome to pxar ***
[14:17:04.750] INFO: *** Today: 2016/10/19
[14:17:05.782] INFO: *** Version: v1.9.0-818-g96727
[14:17:05.782] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//dacParameters35_C15.dat
[14:17:05.814] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:17:05.814] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//defaultMaskFile.dat
[14:17:05.834] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C15.dat
[14:17:05.990] INFO: clk: 4
[14:17:05.990] INFO: ctr: 4
[14:17:05.990] INFO: sda: 19
[14:17:05.990] INFO: tin: 9
[14:17:05.990] INFO: level: 15
[14:17:05.990] INFO: triggerdelay: 0
[14:17:05.990] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[14:17:05.990] INFO: Log level: INFO
[14:17:06.008] QUIET: Connection to board DTB_WREKRL opened.
[14:17:06.011] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[14:17:06.014] INFO: RPC call hashes of host and DTB match: 398089610
[14:17:07.540] INFO: DUT info:
[14:17:07.540] INFO: The DUT currently contains the following objects:
[14:17:07.540] INFO: 2 TBM Cores tbm08c (2 ON)
[14:17:07.540] INFO: TBM Core alpha (0): 7 registers set
[14:17:07.540] INFO: TBM Core beta (1): 7 registers set
[14:17:07.540] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[14:17:07.540] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.540] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.541] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[14:17:07.971] INFO: enter 'restricted' command line mode
[14:17:07.971] INFO: enter test to run
[14:17:15.392] INFO: test: PixelAlive no parameter change
[14:17:15.392] INFO: running: pixelalive
[14:17:15.457] INFO: ----------------------------------------------------------------------
[14:17:15.457] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[14:17:15.457] INFO: ----------------------------------------------------------------------
[14:17:15.776] INFO: Expecting 41600 events.
[14:17:20.116] INFO: 41600 events read in total (3621ms).
[14:17:20.285] INFO: Test took 4824ms.
[14:17:20.296] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:17:20.965] INFO: PixTestAlive::aliveTest() done
[14:17:20.965] INFO: number of dead pixels (per ROC): 0 0 0 2 12 0 0 1 0 0 1 0 0 0 0 0
[14:17:21.146] INFO: enter test to run
[14:17:29.976] INFO: test: timing no parameter change
[14:17:29.976] INFO: running: timing
[14:17:29.979] INFO: ######################################################################
[14:17:29.979] INFO: PixTestTiming::doTest()
[14:17:29.979] INFO: ######################################################################
[14:17:29.979] INFO: ----------------------------------------------------------------------
[14:17:29.979] INFO: PixTestTiming::TBMPhaseScan()
[14:17:29.979] INFO: ----------------------------------------------------------------------
[14:23:54.382] INFO: TBM Phase Settings: 240
[14:23:54.382] INFO: 400MHz Phase: 4
[14:23:54.382] INFO: 160MHz Phase: 7
[14:23:54.382] INFO: Functional Phase Area: 5
[14:23:54.395] INFO: Test took 384416 ms.
[14:23:54.395] INFO: PixTestTiming::TBMPhaseScan() done.
[14:23:54.396] INFO: ----------------------------------------------------------------------
[14:23:54.396] INFO: PixTestTiming::ROCDelayScan()
[14:23:54.396] INFO: ----------------------------------------------------------------------
[14:25:58.526] INFO: ROC Delay Settings: 228
[14:25:58.526] INFO: ROC Header-Trailer/Token Delay: 11
[14:25:58.526] INFO: ROC Port 0 Delay: 4
[14:25:58.526] INFO: ROC Port 1 Delay: 4
[14:25:58.526] INFO: Functional ROC Area: 5
[14:25:58.529] INFO: Test took 124133 ms.
[14:25:58.529] INFO: PixTestTiming::ROCDelayScan() done.
[14:25:58.529] INFO: ----------------------------------------------------------------------
[14:25:58.529] INFO: PixTestTiming::TimingTest()
[14:25:58.529] INFO: ----------------------------------------------------------------------
[14:26:14.908] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:26:30.152] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:26:45.332] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:27:00.508] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:27:15.729] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:27:30.925] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:27:46.184] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:28:01.377] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:28:16.544] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:28:31.675] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:28:32.054] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:28:32.072] INFO: ----------------------------------------------------------------------
[14:28:32.072] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:28:32.072] INFO: ----------------------------------------------------------------------
[14:28:32.072] INFO: ----------------------------------------------------------------------
[14:28:32.072] INFO: Read back bit status: 1
[14:28:32.072] INFO: ----------------------------------------------------------------------
[14:28:32.072] INFO: ----------------------------------------------------------------------
[14:28:32.072] INFO: Timings are good!
[14:28:32.072] INFO: ----------------------------------------------------------------------
[14:28:32.072] INFO: Test took 153543 ms.
[14:28:32.072] INFO: PixTestTiming::TimingTest() done.
[14:28:32.072] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:28:32.098] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:28:32.098] INFO: PixTestTiming::doTest took 662122 ms.
[14:28:32.098] INFO: PixTestTiming::doTest() done
[14:28:32.099] INFO: Write out TBMPhaseScan_0_V0
[14:28:32.099] INFO: Write out TBMPhaseScan_1_V0
[14:28:32.099] INFO: Write out CombinedTBMPhaseScan_V0
[14:28:32.100] INFO: Write out ROCDelayScan3_V0
[14:28:32.100] INFO: enter test to run
[14:31:11.187] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[14:31:11.187] INFO: running: highrate
[14:31:11.208] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:31:11.486] INFO: ----------------------------------------------------------------------
[14:31:11.486] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[14:31:11.486] INFO: ----------------------------------------------------------------------
[14:31:11.486] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[14:31:11.486] INFO: edge/corner pixel THR is adjusted
[14:31:11.486] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:31:12.444] INFO: Collecting data for 5 seconds...
[14:31:17.462] INFO: Done with hot pixel readout
[14:31:28.783] INFO: PixTest:: pg_setup set to default.
[14:31:28.783] INFO: 9 hot pixels found in step 0
[14:31:29.771] INFO: Collecting data for 5 seconds...
[14:31:34.788] INFO: Done with hot pixel readout
[14:31:46.114] INFO: PixTest:: pg_setup set to default.
[14:31:46.115] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:31:46.115] INFO: 10 hot pixels found in step 1
[14:31:47.104] INFO: Collecting data for 5 seconds...
[14:31:52.121] INFO: Done with hot pixel readout
[14:32:03.472] INFO: PixTest:: pg_setup set to default.
[14:32:03.473] INFO: 7 hot pixels found in step 2
[14:32:04.459] INFO: Collecting data for 5 seconds...
[14:32:09.477] INFO: Done with hot pixel readout
[14:32:20.765] INFO: PixTest:: pg_setup set to default.
[14:32:20.766] INFO: 5 hot pixels found in step 3
[14:32:21.755] INFO: Collecting data for 5 seconds...
[14:32:26.772] INFO: Done with hot pixel readout
[14:32:38.117] INFO: PixTest:: pg_setup set to default.
[14:32:38.118] INFO: 5 hot pixels found in step 4
[14:32:39.106] INFO: Collecting data for 5 seconds...
[14:32:44.123] INFO: Done with hot pixel readout
[14:32:55.399] INFO: PixTest:: pg_setup set to default.
[14:32:55.399] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:32:55.402] INFO: 2 hot pixels found in step 5
[14:32:56.392] INFO: Collecting data for 5 seconds...
[14:33:01.410] INFO: Done with hot pixel readout
[14:33:12.725] INFO: PixTest:: pg_setup set to default.
[14:33:12.726] INFO: 2 hot pixels found in step 6
[14:33:13.713] INFO: Collecting data for 5 seconds...
[14:33:18.731] INFO: Done with hot pixel readout
[14:33:30.100] INFO: PixTest:: pg_setup set to default.
[14:33:30.100] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:33:30.101] INFO: 1 hot pixels found in step 7
[14:33:30.132] INFO: 1 hot pixels could not be trimmed and have been masked.
[14:33:30.135] INFO: PixTest::trimHotPixels() done
[14:33:30.135] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C0.dat
[14:33:30.141] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C1.dat
[14:33:30.147] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C2.dat
[14:33:30.152] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C3.dat
[14:33:30.157] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C4.dat
[14:33:30.162] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C5.dat
[14:33:30.168] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C6.dat
[14:33:30.173] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C7.dat
[14:33:30.178] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C8.dat
[14:33:30.183] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C9.dat
[14:33:30.189] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C10.dat
[14:33:30.194] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C11.dat
[14:33:30.199] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C12.dat
[14:33:30.204] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C13.dat
[14:33:30.210] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C14.dat
[14:33:30.215] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C15.dat
[14:33:30.220] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//defaultMaskFile.dat
[14:33:30.230] INFO: enter test to run
[14:36:46.712] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:36:46.712] INFO: running: highrate
[14:36:46.717] INFO: ----------------------------------------------------------------------
[14:36:46.717] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:36:46.717] INFO: ----------------------------------------------------------------------
[14:36:46.717] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:36:46.717] INFO: edge/corner pixel THR is adjusted
[14:36:46.717] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:36:47.674] INFO: Collecting data for 1 seconds...
[14:36:48.679] INFO: Done with hot pixel readout
[14:36:52.328] INFO: PixTest:: pg_setup set to default.
[14:36:52.328] INFO: 0 hot pixels found in step 0
[14:36:52.334] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:36:52.433] INFO: PixTest::trimHotPixels() done
[14:36:52.433] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C0.dat
[14:36:52.443] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C1.dat
[14:36:52.449] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C2.dat
[14:36:52.454] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C3.dat
[14:36:52.460] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C4.dat
[14:36:52.465] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C5.dat
[14:36:52.470] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C6.dat
[14:36:52.476] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C7.dat
[14:36:52.481] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C8.dat
[14:36:52.486] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C9.dat
[14:36:52.492] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C10.dat
[14:36:52.497] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C11.dat
[14:36:52.502] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C12.dat
[14:36:52.508] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C13.dat
[14:36:52.513] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C14.dat
[14:36:52.518] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//trimParameters35_C15.dat
[14:36:52.524] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-05_FPIXTest-17C-FNAL-161007-1342-150V_2016-10-07_13h42m_1475865776/000_FPIXTest_p17//defaultMaskFile.dat
[14:36:52.534] INFO: enter test to run
[14:37:08.752] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:37:08.752] INFO: running: xray
[14:37:08.753] INFO: ----------------------------------------------------------------------
[14:37:08.753] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:37:08.753] INFO: ----------------------------------------------------------------------
[14:37:09.730] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:37:21.860] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[14:37:50.960] INFO: Resuming triggers.
[14:38:03.095] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[14:38:32.373] INFO: Resuming triggers.
[14:38:44.505] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[14:39:13.691] INFO: Resuming triggers.
[14:39:25.820] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[14:39:56.015] INFO: Resuming triggers.
[14:40:08.144] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[14:40:37.843] INFO: Resuming triggers.
[14:40:49.968] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[14:41:19.437] INFO: Resuming triggers.
[14:41:31.562] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[14:42:00.816] INFO: Resuming triggers.
[14:42:12.943] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[14:42:42.284] INFO: Resuming triggers.
[14:42:45.626] INFO: data taking finished, elapsed time: 100 seconds.
[14:42:54.014] INFO: PixTest:: pg_setup set to default.
[14:42:54.017] INFO: PixTestXray::doPhRun() done
[14:42:54.167] INFO: enter test to run
[14:43:55.117] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:43:55.117] INFO: running: xray
[14:43:55.118] INFO: ----------------------------------------------------------------------
[14:43:55.118] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:43:55.118] INFO: ----------------------------------------------------------------------
[14:43:56.082] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:44:03.420] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[14:44:33.924] INFO: Resuming triggers.
[14:44:41.266] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[14:45:11.698] INFO: Resuming triggers.
[14:45:19.041] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[14:45:49.443] INFO: Resuming triggers.
[14:45:56.786] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[14:46:27.175] INFO: Resuming triggers.
[14:46:34.520] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[14:47:04.943] INFO: Resuming triggers.
[14:47:12.290] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[14:47:42.776] INFO: Resuming triggers.
[14:47:50.119] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[14:48:20.546] INFO: Resuming triggers.
[14:48:27.887] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[14:48:58.266] INFO: Resuming triggers.
[14:49:05.608] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[14:49:36.949] INFO: Resuming triggers.
[14:49:44.286] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[14:50:15.261] INFO: Resuming triggers.
[14:50:22.596] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[14:50:53.488] INFO: Resuming triggers.
[14:51:00.826] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[14:51:31.787] INFO: Resuming triggers.
[14:51:39.120] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[14:52:10.062] INFO: Resuming triggers.
[14:52:14.988] INFO: data taking finished, elapsed time: 100 seconds.
[14:52:36.554] INFO: PixTest:: pg_setup set to default.
[14:52:36.558] INFO: PixTestXray::doPhRun() done
[14:52:36.708] INFO: enter test to run
[14:58:51.447] INFO: test: HighRate no parameter change
[14:58:51.447] INFO: running: highrate
[14:58:51.458] INFO: ----------------------------------------------------------------------
[14:58:51.458] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[14:58:51.458] INFO: ----------------------------------------------------------------------
[14:58:51.613] INFO: Expecting 768 events.
[14:58:52.747] INFO: 768 events read in total (418ms).
[14:58:52.748] INFO: Test took 1270ms.
[14:58:53.551] INFO: Expecting 41600 events.
[14:58:56.565] INFO: 41600 events read in total (2487ms).
[14:58:56.566] INFO: Test took 3812ms.
[14:58:56.595] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:58:57.332] INFO: Expecting 41600 events.
[14:59:00.493] INFO: 41600 events read in total (2634ms).
[14:59:00.494] INFO: Test took 3882ms.
[14:59:00.525] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:01.256] INFO: Expecting 41600 events.
[14:59:04.449] INFO: 41600 events read in total (2666ms).
[14:59:04.450] INFO: Test took 3908ms.
[14:59:04.480] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:05.211] INFO: Expecting 41600 events.
[14:59:08.407] INFO: 41600 events read in total (2669ms).
[14:59:08.408] INFO: Test took 3911ms.
[14:59:08.438] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:09.167] INFO: Expecting 41600 events.
[14:59:12.370] INFO: 41600 events read in total (2676ms).
[14:59:12.371] INFO: Test took 3916ms.
[14:59:12.401] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:13.134] INFO: Expecting 41600 events.
[14:59:16.339] INFO: 41600 events read in total (2678ms).
[14:59:16.340] INFO: Test took 3923ms.
[14:59:16.370] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:17.098] INFO: Expecting 41600 events.
[14:59:20.292] INFO: 41600 events read in total (2667ms).
[14:59:20.293] INFO: Test took 3906ms.
[14:59:20.323] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:21.057] INFO: Expecting 41600 events.
[14:59:24.250] INFO: 41600 events read in total (2666ms).
[14:59:24.251] INFO: Test took 3912ms.
[14:59:24.281] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:25.014] INFO: Expecting 41600 events.
[14:59:28.220] INFO: 41600 events read in total (2679ms).
[14:59:28.221] INFO: Test took 3923ms.
[14:59:28.251] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:28.981] INFO: Expecting 41600 events.
[14:59:32.180] INFO: 41600 events read in total (2672ms).
[14:59:32.181] INFO: Test took 3913ms.
[14:59:32.211] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:32.941] INFO: Expecting 41600 events.
[14:59:36.151] INFO: 41600 events read in total (2683ms).
[14:59:36.152] INFO: Test took 3924ms.
[14:59:36.182] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:36.911] INFO: Expecting 41600 events.
[14:59:40.124] INFO: 41600 events read in total (2686ms).
[14:59:40.125] INFO: Test took 3926ms.
[14:59:40.155] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:40.885] INFO: Expecting 41600 events.
[14:59:44.095] INFO: 41600 events read in total (2683ms).
[14:59:44.095] INFO: Test took 3924ms.
[14:59:44.125] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:44.854] INFO: Expecting 41600 events.
[14:59:48.055] INFO: 41600 events read in total (2674ms).
[14:59:48.056] INFO: Test took 3915ms.
[14:59:48.086] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:48.817] INFO: Expecting 41600 events.
[14:59:52.027] INFO: 41600 events read in total (2683ms).
[14:59:52.027] INFO: Test took 3925ms.
[14:59:52.057] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:52.787] INFO: Expecting 41600 events.
[14:59:55.989] INFO: 41600 events read in total (2675ms).
[14:59:55.989] INFO: Test took 3914ms.
[14:59:56.020] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:59:56.749] INFO: Expecting 41600 events.
[14:59:59.948] INFO: 41600 events read in total (2672ms).
[14:59:59.949] INFO: Test took 3913ms.
[14:59:59.979] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:00.709] INFO: Expecting 41600 events.
[15:00:03.864] INFO: 41600 events read in total (2628ms).
[15:00:03.865] INFO: Test took 3870ms.
[15:00:03.895] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:04.628] INFO: Expecting 41600 events.
[15:00:07.798] INFO: 41600 events read in total (2643ms).
[15:00:07.799] INFO: Test took 3887ms.
[15:00:07.829] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:08.561] INFO: Expecting 41600 events.
[15:00:11.620] INFO: 41600 events read in total (2532ms).
[15:00:11.621] INFO: Test took 3774ms.
[15:00:11.650] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:12.023] INFO: enter test to run
[15:00:45.111] INFO: test: HighRate no parameter change
[15:00:45.111] INFO: running: highrate
[15:00:45.112] INFO: ----------------------------------------------------------------------
[15:00:45.112] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:00:45.112] INFO: ----------------------------------------------------------------------
[15:00:45.730] INFO: Expecting 208000 events.
[15:00:57.400] INFO: 208000 events read in total (11143ms).
[15:00:57.403] INFO: Test took 12282ms.
[15:00:57.525] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:57.773] INFO: number of dead pixels (per ROC): 0 0 0 2 12 0 0 1 0 0 1 1 0 0 0 0
[15:00:57.773] INFO: number of red-efficiency pixels: 56 56 92 91 130 96 136 80 73 104 109 108 93 42 19 24
[15:00:57.773] INFO: number of X-ray hits detected: 56912 36573 54191 75650 93370 98847 100803 74253 67963 86708 83839 73849 74898 45860 19223 23904
[15:00:57.773] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:00:57.773] INFO: number of Vcal hits detected: 207944 207942 207907 207811 207280 207900 207860 207865 207926 207892 207836 207841 207905 207958 207981 207976
[15:00:57.773] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 100.0 99.9 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[15:00:57.773] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.7 100.0 99.9 99.9 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0
[15:00:57.773] INFO: X-ray hit rate [MHz/cm2]: 16.7 10.7 15.9 22.2 27.4 29.0 29.5 21.8 19.9 25.4 24.6 21.6 22.0 13.4 5.6 7.0
[15:00:57.773] INFO: PixTestHighRate::doXPixelAlive() done
[15:00:57.829] INFO: PixTest:: pg_setup set to default.
[15:00:57.844] INFO: enter test to run
[15:02:02.454] INFO: test: HighRate no parameter change
[15:02:02.454] INFO: running: highrate
[15:02:02.455] INFO: ----------------------------------------------------------------------
[15:02:02.455] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:02:02.455] INFO: ----------------------------------------------------------------------
[15:02:03.074] INFO: Expecting 208000 events.
[15:02:16.361] INFO: 208000 events read in total (12760ms).
[15:02:16.366] INFO: Test took 13901ms.
[15:02:16.627] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:02:16.919] INFO: number of dead pixels (per ROC): 0 0 0 2 11 0 0 1 0 0 1 1 0 0 0 0
[15:02:16.919] INFO: number of red-efficiency pixels: 164 113 220 213 353 355 467 281 236 340 275 292 303 142 61 48
[15:02:16.919] INFO: number of X-ray hits detected: 118423 76507 113247 158295 195488 206598 210918 156586 142080 181544 175289 156353 157059 96152 40088 50294
[15:02:16.919] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:02:16.919] INFO: number of Vcal hits detected: 207831 207885 207760 207682 207042 207627 207496 207652 207757 207636 207656 207646 207683 207852 207937 207952
[15:02:16.919] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.9 99.8 99.8 99.8 99.9 99.9 99.8 99.9 99.9 99.9 99.9 100.0 100.0
[15:02:16.919] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.5 99.8 99.8 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[15:02:16.919] INFO: X-ray hit rate [MHz/cm2]: 34.7 22.4 33.2 46.4 57.3 60.6 61.8 45.9 41.6 53.2 51.4 45.8 46.0 28.2 11.8 14.7
[15:02:16.919] INFO: PixTestHighRate::doXPixelAlive() done
[15:02:16.966] INFO: PixTest:: pg_setup set to default.
[15:02:16.987] INFO: enter test to run
[15:02:58.062] INFO: test: HighRate no parameter change
[15:02:58.062] INFO: running: highrate
[15:02:58.063] INFO: ----------------------------------------------------------------------
[15:02:58.063] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:02:58.063] INFO: ----------------------------------------------------------------------
[15:02:58.681] INFO: Expecting 208000 events.
[15:03:13.535] INFO: 208000 events read in total (14327ms).
[15:03:13.541] INFO: Test took 15469ms.
[15:03:13.942] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:03:14.275] INFO: number of dead pixels (per ROC): 0 0 0 2 12 0 0 1 0 0 1 1 0 0 0 0
[15:03:14.275] INFO: number of red-efficiency pixels: 351 237 445 427 854 763 1025 668 463 780 625 609 615 274 92 85
[15:03:14.275] INFO: number of X-ray hits detected: 177797 114143 169657 239104 292214 308739 314886 234709 214435 271718 261703 234512 235654 144218 60066 75845
[15:03:14.275] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:03:14.275] INFO: number of Vcal hits detected: 207601 207749 207468 207431 206410 207112 206686 207142 207480 207089 207252 207262 207299 207689 207904 207914
[15:03:14.275] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.8 99.6 99.6 99.4 99.6 99.8 99.6 99.7 99.7 99.7 99.9 100.0 100.0
[15:03:14.275] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.7 99.2 99.6 99.4 99.6 99.8 99.6 99.6 99.6 99.7 99.9 100.0 100.0
[15:03:14.275] INFO: X-ray hit rate [MHz/cm2]: 52.1 33.5 49.7 70.1 85.7 90.5 92.3 68.8 62.9 79.6 76.7 68.7 69.1 42.3 17.6 22.2
[15:03:14.275] INFO: PixTestHighRate::doXPixelAlive() done
[15:03:14.322] INFO: PixTest:: pg_setup set to default.
[15:03:14.336] INFO: enter test to run
[15:03:18.397] INFO: test: exit no parameter change
[15:03:18.879] QUIET: Connection to board 33 closed.
[15:03:18.880] INFO: pXar: this is the end, my friend