[14:22:16.057] INFO: *** Welcome to pxar ***
[14:22:16.057] INFO: *** Today: 2016/11/16
[14:22:17.119] INFO: *** Version: v1.9.0-818-g96727
[14:22:17.119] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//dacParameters35_C15.dat
[14:22:17.194] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:22:17.215] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//defaultMaskFile.dat
[14:22:17.215] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C15.dat
[14:22:17.395] INFO: clk: 4
[14:22:17.395] INFO: ctr: 4
[14:22:17.395] INFO: sda: 19
[14:22:17.395] INFO: tin: 9
[14:22:17.395] INFO: level: 15
[14:22:17.395] INFO: triggerdelay: 0
[14:22:17.395] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[14:22:17.395] INFO: Log level: INFO
[14:22:17.430] QUIET: Connection to board DTB_WREHUL opened.
[14:22:17.434] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 30
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREHUL
MAC address: 40D85511801E
Hostname: pixelDTB030
Comment:
------------------------------------------------------
[14:22:17.437] INFO: RPC call hashes of host and DTB match: 398089610
[14:22:18.006] INFO: DUT info:
[14:22:18.006] INFO: The DUT currently contains the following objects:
[14:22:18.006] INFO: 2 TBM Cores tbm08c (2 ON)
[14:22:19.038] INFO: TBM Core alpha (0): 7 registers set
[14:22:19.038] INFO: TBM Core beta (1): 7 registers set
[14:22:19.038] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[14:22:19.038] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.038] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[14:22:19.565] INFO: enter 'restricted' command line mode
[14:22:19.565] INFO: enter test to run
[14:22:22.326] INFO: test: PixelAlive no parameter change
[14:22:22.326] INFO: running: pixelalive
[14:22:22.422] INFO: ----------------------------------------------------------------------
[14:22:22.422] 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:22:22.422] INFO: ----------------------------------------------------------------------
[14:22:22.744] INFO: Expecting 41600 events.
[14:22:27.108] INFO: 41600 events read in total (3646ms).
[14:22:27.273] INFO: Test took 4848ms.
[14:22:27.289] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:22:27.693] INFO: PixTestAlive::aliveTest() done
[14:22:27.693] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 3 0 0 0 0 7 0
[14:22:27.813] INFO: enter test to run
[14:22:32.670] INFO: test: timing no parameter change
[14:22:32.670] INFO: running: timing
[14:22:32.674] INFO: ######################################################################
[14:22:32.674] INFO: PixTestTiming::doTest()
[14:22:32.674] INFO: ######################################################################
[14:22:32.674] INFO: ----------------------------------------------------------------------
[14:22:32.674] INFO: PixTestTiming::TBMPhaseScan()
[14:22:32.674] INFO: ----------------------------------------------------------------------
[14:30:46.803] INFO: TBM Phase Settings: 232
[14:30:46.803] INFO: 400MHz Phase: 2
[14:30:46.803] INFO: 160MHz Phase: 7
[14:30:46.803] INFO: Functional Phase Area: 3
[14:30:46.821] INFO: Test took 494147 ms.
[14:30:46.821] INFO: PixTestTiming::TBMPhaseScan() done.
[14:30:46.822] INFO: ----------------------------------------------------------------------
[14:30:46.822] INFO: PixTestTiming::ROCDelayScan()
[14:30:46.822] INFO: ----------------------------------------------------------------------
[14:33:49.057] INFO: ROC Delay Settings: 228
[14:33:49.057] INFO: ROC Header-Trailer/Token Delay: 11
[14:33:49.057] INFO: ROC Port 0 Delay: 4
[14:33:49.057] INFO: ROC Port 1 Delay: 4
[14:33:49.058] INFO: Functional ROC Area: 5
[14:33:49.061] INFO: Test took 182240 ms.
[14:33:49.061] INFO: PixTestTiming::ROCDelayScan() done.
[14:33:49.061] INFO: ----------------------------------------------------------------------
[14:33:49.061] INFO: PixTestTiming::TimingTest()
[14:33:49.061] INFO: ----------------------------------------------------------------------
[14:34:05.444] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:34:20.792] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:34:35.884] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:34:50.933] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:35:05.913] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:35:20.901] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:35:35.886] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:35:50.851] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:36:05.790] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:36:20.768] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:36:21.149] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:36:21.168] INFO: ----------------------------------------------------------------------
[14:36:21.168] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[14:36:21.168] INFO: ----------------------------------------------------------------------
[14:36:21.168] INFO: ----------------------------------------------------------------------
[14:36:21.168] INFO: Read back bit status: 1
[14:36:21.168] INFO: ----------------------------------------------------------------------
[14:36:21.168] INFO: ----------------------------------------------------------------------
[14:36:21.168] INFO: Timings are good!
[14:36:21.168] INFO: ----------------------------------------------------------------------
[14:36:21.168] INFO: Test took 152107 ms.
[14:36:21.168] INFO: PixTestTiming::TimingTest() done.
[14:36:21.168] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//tbmParameters_C0a.dat
[14:36:21.169] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//tbmParameters_C0b.dat
[14:36:21.169] INFO: PixTestTiming::doTest took 828498 ms.
[14:36:21.169] INFO: PixTestTiming::doTest() done
[14:36:21.169] INFO: Write out TBMPhaseScan_0_V0
[14:36:21.169] INFO: Write out TBMPhaseScan_1_V0
[14:36:21.169] INFO: Write out CombinedTBMPhaseScan_V0
[14:36:21.201] INFO: Write out ROCDelayScan3_V0
[14:36:21.202] INFO: enter test to run
[14:37:44.408] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[14:37:44.408] INFO: running: highrate
[14:37:44.425] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[14:37:44.722] INFO: ----------------------------------------------------------------------
[14:37:44.722] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[14:37:44.722] INFO: ----------------------------------------------------------------------
[14:37:44.722] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[14:37:44.722] INFO: edge/corner pixel THR is adjusted
[14:37:44.722] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:37:45.680] INFO: Collecting data for 5 seconds...
[14:37:50.697] INFO: Done with hot pixel readout
[14:38:02.449] INFO: PixTest:: pg_setup set to default.
[14:38:02.449] INFO: 7 hot pixels found in step 0
[14:38:03.443] INFO: Collecting data for 5 seconds...
[14:38:08.459] INFO: Done with hot pixel readout
[14:38:20.171] INFO: PixTest:: pg_setup set to default.
[14:38:20.171] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:38:20.172] INFO: 8 hot pixels found in step 1
[14:38:21.164] INFO: Collecting data for 5 seconds...
[14:38:26.181] INFO: Done with hot pixel readout
[14:38:37.886] INFO: PixTest:: pg_setup set to default.
[14:38:37.886] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:38:37.887] INFO: 6 hot pixels found in step 2
[14:38:38.880] INFO: Collecting data for 5 seconds...
[14:38:43.896] INFO: Done with hot pixel readout
[14:38:55.602] INFO: PixTest:: pg_setup set to default.
[14:38:55.602] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:38:55.602] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:38:55.603] INFO: 5 hot pixels found in step 3
[14:38:56.597] INFO: Collecting data for 5 seconds...
[14:39:01.614] INFO: Done with hot pixel readout
[14:39:13.322] INFO: PixTest:: pg_setup set to default.
[14:39:13.322] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:39:13.322] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:39:13.323] INFO: 8 hot pixels found in step 4
[14:39:14.317] INFO: Collecting data for 5 seconds...
[14:39:19.333] INFO: Done with hot pixel readout
[14:39:31.011] INFO: PixTest:: pg_setup set to default.
[14:39:31.011] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:39:31.011] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:39:31.011] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:39:31.011] INFO: 8 hot pixels found in step 5
[14:39:31.005] INFO: Collecting data for 5 seconds...
[14:39:37.021] INFO: Done with hot pixel readout
[14:39:48.710] INFO: PixTest:: pg_setup set to default.
[14:39:48.710] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:39:48.710] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:39:48.710] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:39:48.711] INFO: 9 hot pixels found in step 6
[14:39:49.705] INFO: Collecting data for 5 seconds...
[14:39:54.721] INFO: Done with hot pixel readout
[14:40:06.378] INFO: PixTest:: pg_setup set to default.
[14:40:06.378] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:40:06.378] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:40:06.378] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:40:06.379] INFO: 3 hot pixels found in step 7
[14:40:06.415] INFO: 3 hot pixels could not be trimmed and have been masked.
[14:40:06.418] INFO: PixTest::trimHotPixels() done
[14:40:06.456] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C0.dat
[14:40:06.470] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C1.dat
[14:40:06.476] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C2.dat
[14:40:06.481] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C3.dat
[14:40:06.486] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C4.dat
[14:40:06.492] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C5.dat
[14:40:06.498] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C6.dat
[14:40:06.503] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C7.dat
[14:40:06.509] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C8.dat
[14:40:06.514] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C9.dat
[14:40:06.520] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C10.dat
[14:40:06.525] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C11.dat
[14:40:06.531] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C12.dat
[14:40:06.537] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C13.dat
[14:40:06.542] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C14.dat
[14:40:06.547] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C15.dat
[14:40:06.553] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//defaultMaskFile.dat
[14:40:06.565] INFO: enter test to run
[14:42:00.998] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:42:00.998] INFO: running: highrate
[14:42:00.003] INFO: ----------------------------------------------------------------------
[14:42:00.003] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:42:00.003] INFO: ----------------------------------------------------------------------
[14:42:00.003] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:42:00.003] INFO: edge/corner pixel THR is adjusted
[14:42:00.003] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:42:01.962] INFO: Collecting data for 1 seconds...
[14:42:02.966] INFO: Done with hot pixel readout
[14:42:06.936] INFO: PixTest:: pg_setup set to default.
[14:42:06.937] INFO: 0 hot pixels found in step 0
[14:42:06.942] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:42:07.035] INFO: PixTest::trimHotPixels() done
[14:42:07.035] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C0.dat
[14:42:07.043] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C1.dat
[14:42:07.050] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C2.dat
[14:42:07.055] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C3.dat
[14:42:07.061] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C4.dat
[14:42:07.066] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C5.dat
[14:42:07.071] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C6.dat
[14:42:07.077] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C7.dat
[14:42:07.082] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C8.dat
[14:42:07.087] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C9.dat
[14:42:07.093] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C10.dat
[14:42:07.098] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C11.dat
[14:42:07.103] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C12.dat
[14:42:07.109] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C13.dat
[14:42:07.114] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C14.dat
[14:42:07.120] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//trimParameters35_C15.dat
[14:42:07.125] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-5-49_FPIXTest-17C-FNAL-161108-1225-150V_2016-11-08_12h25m_1478629520/000_FPIXTest_p17//defaultMaskFile.dat
[14:42:07.135] INFO: enter test to run
[14:42:48.870] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:42:48.870] INFO: running: xray
[14:42:48.871] INFO: ----------------------------------------------------------------------
[14:42:48.871] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:42:48.871] INFO: ----------------------------------------------------------------------
[14:42:49.842] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:43:01.549] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[14:43:31.623] INFO: Resuming triggers.
[14:43:43.327] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[14:44:13.450] INFO: Resuming triggers.
[14:44:25.152] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[14:44:54.970] INFO: Resuming triggers.
[14:45:06.674] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[14:45:36.770] INFO: Resuming triggers.
[14:45:48.473] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[14:46:18.402] INFO: Resuming triggers.
[14:46:30.103] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[14:47:00.292] INFO: Resuming triggers.
[14:47:11.994] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[14:47:42.687] INFO: Resuming triggers.
[14:47:54.393] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[14:48:24.749] INFO: Resuming triggers.
[14:48:31.485] INFO: data taking finished, elapsed time: 100 seconds.
[14:48:49.103] INFO: PixTest:: pg_setup set to default.
[14:48:49.107] INFO: PixTestXray::doPhRun() done
[14:48:49.418] INFO: enter test to run
[14:50:26.083] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:50:26.083] INFO: running: xray
[14:50:26.084] INFO: ----------------------------------------------------------------------
[14:50:26.084] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:50:26.084] INFO: ----------------------------------------------------------------------
[14:50:27.061] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:50:33.936] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[14:51:04.342] INFO: Resuming triggers.
[14:51:11.221] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[14:51:41.429] INFO: Resuming triggers.
[14:51:48.310] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[14:52:18.673] INFO: Resuming triggers.
[14:52:25.578] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[14:52:55.915] INFO: Resuming triggers.
[14:53:02.796] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[14:53:33.188] INFO: Resuming triggers.
[14:53:40.073] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[14:54:10.636] INFO: Resuming triggers.
[14:54:17.514] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[14:54:47.850] INFO: Resuming triggers.
[14:54:54.731] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[14:55:25.137] INFO: Resuming triggers.
[14:55:32.019] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[14:56:02.344] INFO: Resuming triggers.
[14:56:09.226] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[14:56:39.563] INFO: Resuming triggers.
[14:56:46.444] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[14:57:17.716] INFO: Resuming triggers.
[14:57:24.598] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[14:57:55.804] INFO: Resuming triggers.
[14:58:02.684] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[14:58:33.897] INFO: Resuming triggers.
[14:58:40.777] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[14:59:11.835] INFO: Resuming triggers.
[14:59:15.843] INFO: data taking finished, elapsed time: 100 seconds.
[14:59:34.029] INFO: PixTest:: pg_setup set to default.
[14:59:34.032] INFO: PixTestXray::doPhRun() done
[14:59:34.184] INFO: enter test to run
[15:00:50.599] INFO: test: HighRate no parameter change
[15:00:50.599] INFO: running: highrate
[15:00:50.613] INFO: ----------------------------------------------------------------------
[15:00:50.613] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:00:50.613] INFO: ----------------------------------------------------------------------
[15:00:50.846] INFO: Expecting 768 events.
[15:00:51.980] INFO: 768 events read in total (418ms).
[15:00:51.980] INFO: Test took 1288ms.
[15:00:52.783] INFO: Expecting 41600 events.
[15:00:55.846] INFO: 41600 events read in total (2536ms).
[15:00:55.848] INFO: Test took 3778ms.
[15:00:55.880] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:00:56.611] INFO: Expecting 41600 events.
[15:00:59.846] INFO: 41600 events read in total (2708ms).
[15:00:59.847] INFO: Test took 3949ms.
[15:00:59.880] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:00.607] INFO: Expecting 41600 events.
[15:01:03.862] INFO: 41600 events read in total (2728ms).
[15:01:03.863] INFO: Test took 3966ms.
[15:01:03.896] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:04.617] INFO: Expecting 41600 events.
[15:01:07.898] INFO: 41600 events read in total (2754ms).
[15:01:07.899] INFO: Test took 3986ms.
[15:01:07.933] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:08.644] INFO: Expecting 41600 events.
[15:01:11.914] INFO: 41600 events read in total (2743ms).
[15:01:11.915] INFO: Test took 3964ms.
[15:01:11.948] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:12.669] INFO: Expecting 41600 events.
[15:01:15.939] INFO: 41600 events read in total (2743ms).
[15:01:15.940] INFO: Test took 3974ms.
[15:01:15.973] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:16.699] INFO: Expecting 41600 events.
[15:01:20.010] INFO: 41600 events read in total (2784ms).
[15:01:20.011] INFO: Test took 4021ms.
[15:01:20.045] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:20.762] INFO: Expecting 41600 events.
[15:01:24.041] INFO: 41600 events read in total (2753ms).
[15:01:24.042] INFO: Test took 3980ms.
[15:01:24.075] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:24.783] INFO: Expecting 41600 events.
[15:01:28.133] INFO: 41600 events read in total (2824ms).
[15:01:28.134] INFO: Test took 4041ms.
[15:01:28.169] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:28.888] INFO: Expecting 41600 events.
[15:01:32.243] INFO: 41600 events read in total (2828ms).
[15:01:32.243] INFO: Test took 4057ms.
[15:01:32.277] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:32.999] INFO: Expecting 41600 events.
[15:01:36.266] INFO: 41600 events read in total (2740ms).
[15:01:36.267] INFO: Test took 3973ms.
[15:01:36.302] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:37.026] INFO: Expecting 41600 events.
[15:01:40.286] INFO: 41600 events read in total (2734ms).
[15:01:40.286] INFO: Test took 3967ms.
[15:01:40.326] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:41.032] INFO: Expecting 41600 events.
[15:01:44.335] INFO: 41600 events read in total (2777ms).
[15:01:44.336] INFO: Test took 3991ms.
[15:01:44.370] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:45.087] INFO: Expecting 41600 events.
[15:01:48.361] INFO: 41600 events read in total (2747ms).
[15:01:48.362] INFO: Test took 3974ms.
[15:01:48.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:49.119] INFO: Expecting 41600 events.
[15:01:52.404] INFO: 41600 events read in total (2758ms).
[15:01:52.405] INFO: Test took 3992ms.
[15:01:52.439] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:53.159] INFO: Expecting 41600 events.
[15:01:56.482] INFO: 41600 events read in total (2796ms).
[15:01:56.483] INFO: Test took 4027ms.
[15:01:56.517] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:01:57.239] INFO: Expecting 41600 events.
[15:02:00.579] INFO: 41600 events read in total (2813ms).
[15:02:00.580] INFO: Test took 4046ms.
[15:02:00.613] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:02:01.334] INFO: Expecting 41600 events.
[15:02:04.738] INFO: 41600 events read in total (2877ms).
[15:02:04.739] INFO: Test took 4108ms.
[15:02:04.773] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:02:05.494] INFO: Expecting 41600 events.
[15:02:08.784] INFO: 41600 events read in total (2763ms).
[15:02:08.785] INFO: Test took 3995ms.
[15:02:08.819] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:02:09.544] INFO: Expecting 41600 events.
[15:02:12.695] INFO: 41600 events read in total (2625ms).
[15:02:12.696] INFO: Test took 3859ms.
[15:02:12.729] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:02:13.092] INFO: enter test to run
[15:04:24.485] INFO: test: HighRate no parameter change
[15:04:24.485] INFO: running: highrate
[15:04:24.486] INFO: ----------------------------------------------------------------------
[15:04:24.486] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:04:24.486] INFO: ----------------------------------------------------------------------
[15:04:25.107] INFO: Expecting 208000 events.
[15:04:36.955] INFO: 208000 events read in total (11321ms).
[15:04:36.958] INFO: Test took 12462ms.
[15:04:37.097] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:04:37.348] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 3 0 0 0 0 7 0
[15:04:37.362] INFO: number of red-efficiency pixels: 55 58 80 100 110 135 129 95 74 102 157 107 87 68 52 19
[15:04:37.362] INFO: number of X-ray hits detected: 58773 39412 62889 93603 98111 108377 106683 71711 72412 103131 105518 87832 87632 54512 21093 23623
[15:04:37.362] 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:04:37.362] INFO: number of Vcal hits detected: 207943 207941 207918 207899 207889 207862 207867 207902 207925 207750 207841 207890 207878 207929 207548 207981
[15:04:37.362] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0
[15:04:37.362] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 99.8 100.0
[15:04:37.362] INFO: X-ray hit rate [MHz/cm2]: 17.2 11.6 18.4 27.4 28.8 31.8 31.3 21.0 21.2 30.2 30.9 25.7 25.7 16.0 6.2 6.9
[15:04:37.362] INFO: PixTestHighRate::doXPixelAlive() done
[15:04:37.412] INFO: PixTest:: pg_setup set to default.
[15:04:37.423] INFO: enter test to run
[15:04:48.845] INFO: test: HighRate no parameter change
[15:04:48.845] INFO: running: highrate
[15:04:48.846] INFO: ----------------------------------------------------------------------
[15:04:48.846] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:04:48.846] INFO: ----------------------------------------------------------------------
[15:04:49.468] INFO: Expecting 208000 events.
[15:05:02.944] INFO: 208000 events read in total (12949ms).
[15:05:02.949] INFO: Test took 14092ms.
[15:05:03.230] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:03.531] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 3 0 0 0 0 7 0
[15:05:03.531] INFO: number of red-efficiency pixels: 160 137 258 287 309 465 510 305 213 346 457 286 263 202 88 48
[15:05:03.531] INFO: number of X-ray hits detected: 122262 82272 130693 195256 203387 225494 222764 148812 151663 215715 218324 183710 182388 114310 44260 49187
[15:05:03.531] 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:05:03.531] INFO: number of Vcal hits detected: 207834 207857 207721 207695 207666 207473 207440 207678 207775 207481 207491 207702 207680 207788 207519 207952
[15:05:03.531] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.9 99.9 99.8 99.7 99.9 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[15:05:03.531] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.9 99.8 99.7 99.7 99.8 99.9 99.8 99.8 99.9 99.8 99.9 99.8 100.0
[15:05:03.531] INFO: X-ray hit rate [MHz/cm2]: 35.8 24.1 38.3 57.2 59.6 66.1 65.3 43.6 44.5 63.2 64.0 53.8 53.5 33.5 13.0 14.4
[15:05:03.531] INFO: PixTestHighRate::doXPixelAlive() done
[15:05:03.583] INFO: PixTest:: pg_setup set to default.
[15:05:03.602] INFO: enter test to run
[15:05:14.389] INFO: test: HighRate no parameter change
[15:05:14.389] INFO: running: highrate
[15:05:14.390] INFO: ----------------------------------------------------------------------
[15:05:14.390] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:05:14.390] INFO: ----------------------------------------------------------------------
[15:05:15.007] INFO: Expecting 208000 events.
[15:05:30.380] INFO: 208000 events read in total (14846ms).
[15:05:30.387] INFO: Test took 15987ms.
[15:05:30.809] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:05:31.152] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 3 0 0 0 0 7 0
[15:05:31.152] INFO: number of red-efficiency pixels: 331 229 510 619 708 1083 1073 613 421 787 1082 683 562 489 164 86
[15:05:31.152] INFO: number of X-ray hits detected: 185599 124878 198996 296304 307217 340598 336131 225911 230322 326867 330732 277010 277345 174197 67083 74960
[15:05:31.152] 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:05:31.152] INFO: number of Vcal hits detected: 207615 207747 207367 207302 207199 206602 206641 207228 207523 206926 206644 207236 207275 207413 207439 207912
[15:05:31.152] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.7 99.7 99.4 99.4 99.7 99.8 99.6 99.4 99.7 99.7 99.7 99.9 100.0
[15:05:31.152] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.7 99.6 99.3 99.3 99.6 99.8 99.5 99.3 99.6 99.7 99.7 99.7 100.0
[15:05:31.152] INFO: X-ray hit rate [MHz/cm2]: 54.4 36.6 58.3 86.8 90.0 99.8 98.5 66.2 67.5 95.8 96.9 81.2 81.3 51.1 19.7 22.0
[15:05:31.152] INFO: PixTestHighRate::doXPixelAlive() done
[15:05:31.199] INFO: PixTest:: pg_setup set to default.
[15:05:31.217] INFO: enter test to run
[15:05:43.357] INFO: test: exit no parameter change
[15:05:43.977] QUIET: Connection to board 30 closed.
[15:05:44.117] INFO: pXar: this is the end, my friend