[16:40:19.616] INFO: *** Welcome to pxar ***
[16:40:19.616] INFO: *** Today: 2016/06/13
[16:40:20.429] INFO: *** Version: v1.9.0-814-g7497
[16:40:20.429] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//dacParameters35_C15.dat
[16:40:20.469] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:40:20.470] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//defaultMaskFile.dat
[16:40:20.470] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C15.dat
[16:40:20.582] INFO: clk: 4
[16:40:20.582] INFO: ctr: 4
[16:40:20.582] INFO: sda: 19
[16:40:20.582] INFO: tin: 9
[16:40:20.582] INFO: level: 15
[16:40:20.582] INFO: triggerdelay: 0
[16:40:20.582] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[16:40:20.582] INFO: Log level: INFO
[16:40:20.599] QUIET: Connection to board DTB_WREKRL opened.
[16:40:20.602] 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:
------------------------------------------------------
[16:40:20.605] INFO: RPC call hashes of host and DTB match: 398089610
[16:40:22.132] INFO: DUT info:
[16:40:22.132] INFO: The DUT currently contains the following objects:
[16:40:22.132] INFO: 2 TBM Cores tbm08c (2 ON)
[16:40:22.132] INFO: TBM Core alpha (0): 7 registers set
[16:40:22.132] INFO: TBM Core beta (1): 7 registers set
[16:40:22.133] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[16:40:22.133] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.133] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[16:40:22.548] INFO: enter 'restricted' command line mode
[16:40:22.548] INFO: enter test to run
[16:40:24.228] INFO: test: timing no parameter change
[16:40:24.228] INFO: running: timing
[16:40:24.255] INFO: ######################################################################
[16:40:24.257] INFO: PixTestTiming::doTest()
[16:40:24.257] INFO: ######################################################################
[16:40:24.258] INFO: ----------------------------------------------------------------------
[16:40:24.258] INFO: PixTestTiming::TBMPhaseScan()
[16:40:24.258] INFO: ----------------------------------------------------------------------
[16:47:51.006] INFO: TBM Phase Settings: 232
[16:47:51.006] INFO: 400MHz Phase: 2
[16:47:51.006] INFO: 160MHz Phase: 7
[16:47:51.006] INFO: Functional Phase Area: 3
[16:47:51.017] INFO: Test took 446759 ms.
[16:47:51.017] INFO: PixTestTiming::TBMPhaseScan() done.
[16:47:51.018] INFO: ----------------------------------------------------------------------
[16:47:51.018] INFO: PixTestTiming::ROCDelayScan()
[16:47:51.018] INFO: ----------------------------------------------------------------------
[16:49:58.539] INFO: ROC Delay Settings: 228
[16:49:58.539] INFO: ROC Header-Trailer/Token Delay: 11
[16:49:58.540] INFO: ROC Port 0 Delay: 4
[16:49:58.540] INFO: ROC Port 1 Delay: 4
[16:49:58.540] INFO: Functional ROC Area: 4
[16:49:58.543] INFO: Test took 127526 ms.
[16:49:58.543] INFO: PixTestTiming::ROCDelayScan() done.
[16:49:58.543] INFO: ----------------------------------------------------------------------
[16:49:58.543] INFO: PixTestTiming::TimingTest()
[16:49:58.543] INFO: ----------------------------------------------------------------------
[16:50:14.906] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:50:30.105] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:50:45.214] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:51:00.212] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:51:15.154] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:51:30.117] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:51:45.053] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:52:00.016] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:52:14.970] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:52:29.907] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:52:30.285] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:52:30.303] INFO: ----------------------------------------------------------------------
[16:52:30.303] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:52:30.303] INFO: ----------------------------------------------------------------------
[16:52:30.303] INFO: ----------------------------------------------------------------------
[16:52:30.303] INFO: Read back bit status: 1
[16:52:30.303] INFO: ----------------------------------------------------------------------
[16:52:30.303] INFO: ----------------------------------------------------------------------
[16:52:30.303] INFO: Timings are good!
[16:52:30.303] INFO: ----------------------------------------------------------------------
[16:52:30.303] INFO: Test took 151760 ms.
[16:52:30.303] INFO: PixTestTiming::TimingTest() done.
[16:52:30.313] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:52:30.314] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:52:30.314] INFO: PixTestTiming::doTest took 726064 ms.
[16:52:30.314] INFO: PixTestTiming::doTest() done
[16:52:30.314] INFO: Write out TBMPhaseScan_0_V0
[16:52:30.401] INFO: Write out TBMPhaseScan_1_V0
[16:52:30.401] INFO: Write out CombinedTBMPhaseScan_V0
[16:52:30.431] INFO: Write out ROCDelayScan3_V0
[16:52:30.431] INFO: enter test to run
[16:52:40.767] INFO: test: PixelAlive no parameter change
[16:52:40.767] INFO: running: pixelalive
[16:52:40.771] INFO: ----------------------------------------------------------------------
[16:52:40.771] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[16:52:40.771] INFO: ----------------------------------------------------------------------
[16:52:41.088] INFO: Expecting 41600 events.
[16:52:45.407] INFO: 41600 events read in total (3603ms).
[16:52:45.408] INFO: Test took 4634ms.
[16:52:45.414] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:52:45.808] INFO: PixTestAlive::aliveTest() done
[16:52:45.808] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:52:45.810] INFO: enter test to run
[16:57:00.893] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:57:00.893] INFO: running: highrate
[16:57:00.894] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:57:01.120] INFO: ----------------------------------------------------------------------
[16:57:01.120] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:57:01.120] INFO: ----------------------------------------------------------------------
[16:57:01.120] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:57:01.120] INFO: edge/corner pixel THR is adjusted
[16:57:01.120] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:57:02.078] INFO: Collecting data for 5 seconds...
[16:57:07.095] INFO: Done with hot pixel readout
[16:57:19.850] INFO: PixTest:: pg_setup set to default.




















[16:57:19.851] INFO: 69 hot pixels found in step 0
[16:57:20.850] INFO: Collecting data for 5 seconds...
[16:57:25.867] INFO: Done with hot pixel readout
[16:57:38.522] INFO: PixTest:: pg_setup set to default.


























[16:57:38.523] INFO: 67 hot pixels found in step 1
[16:57:39.522] INFO: Collecting data for 5 seconds...
[16:57:44.539] INFO: Done with hot pixel readout
[16:57:57.343] INFO: PixTest:: pg_setup set to default.

















[16:57:57.345] INFO: 72 hot pixels found in step 2
[16:57:58.343] INFO: Collecting data for 5 seconds...
[16:58:03.361] INFO: Done with hot pixel readout
[16:58:16.382] INFO: PixTest:: pg_setup set to default.
















[16:58:16.384] INFO: 67 hot pixels found in step 3
[16:58:17.382] INFO: Collecting data for 5 seconds...
[16:58:22.399] INFO: Done with hot pixel readout
[16:58:35.220] INFO: PixTest:: pg_setup set to default.






















[16:58:35.222] INFO: 77 hot pixels found in step 4
[16:58:36.221] INFO: Collecting data for 5 seconds...
[16:58:41.237] INFO: Done with hot pixel readout
[16:58:54.045] INFO: PixTest:: pg_setup set to default.
























[16:58:54.047] INFO: 87 hot pixels found in step 5
[16:58:55.046] INFO: Collecting data for 5 seconds...
[16:59:00.062] INFO: Done with hot pixel readout
[16:59:12.909] INFO: PixTest:: pg_setup set to default.
























[16:59:12.911] INFO: 86 hot pixels found in step 6
[16:59:13.910] INFO: Collecting data for 5 seconds...
[16:59:18.926] INFO: Done with hot pixel readout
[16:59:31.735] INFO: PixTest:: pg_setup set to default.























[16:59:31.736] INFO: 75 hot pixels found in step 7
[16:59:32.735] INFO: Collecting data for 5 seconds...
[16:59:37.751] INFO: Done with hot pixel readout
[16:59:50.594] INFO: PixTest:: pg_setup set to default.
























[16:59:50.595] INFO: 68 hot pixels found in step 8
[16:59:51.594] INFO: Collecting data for 5 seconds...
[16:59:56.610] INFO: Done with hot pixel readout
[17:00:09.401] INFO: PixTest:: pg_setup set to default.




















[17:00:09.402] INFO: 70 hot pixels found in step 9
[17:00:10.402] INFO: Collecting data for 5 seconds...
[17:00:15.417] INFO: Done with hot pixel readout
[17:00:28.138] INFO: PixTest:: pg_setup set to default.






















[17:00:28.139] INFO: 62 hot pixels found in step 10
[17:00:29.138] INFO: Collecting data for 5 seconds...
[17:00:34.154] INFO: Done with hot pixel readout
[17:00:46.938] INFO: PixTest:: pg_setup set to default.

























[17:00:46.940] INFO: 70 hot pixels found in step 11
[17:00:47.940] INFO: Collecting data for 5 seconds...
[17:00:52.955] INFO: Done with hot pixel readout
[17:01:05.959] INFO: PixTest:: pg_setup set to default.




















[17:01:05.961] INFO: 51 hot pixels found in step 12
[17:01:06.960] INFO: Collecting data for 5 seconds...
[17:01:11.977] INFO: Done with hot pixel readout
[17:01:25.272] INFO: PixTest:: pg_setup set to default.






























[17:01:25.274] INFO: 67 hot pixels found in step 13
[17:01:26.272] INFO: Collecting data for 5 seconds...
[17:01:31.290] INFO: Done with hot pixel readout
[17:01:44.340] INFO: PixTest:: pg_setup set to default.





























[17:01:44.341] INFO: 64 hot pixels found in step 14
[17:01:44.385] INFO: 64 hot pixels could not be trimmed and have been masked.
[17:01:44.389] INFO: PixTest::trimHotPixels() done
[17:01:44.389] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C0.dat
[17:01:44.399] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C1.dat
[17:01:44.408] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C2.dat
[17:01:44.417] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C3.dat
[17:01:44.426] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C4.dat
[17:01:44.435] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C5.dat
[17:01:44.444] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C6.dat
[17:01:44.453] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C7.dat
[17:01:44.462] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C8.dat
[17:01:44.471] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C9.dat
[17:01:44.480] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C10.dat
[17:01:44.488] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C11.dat
[17:01:44.497] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C12.dat
[17:01:44.506] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C13.dat
[17:01:44.515] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C14.dat
[17:01:44.524] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C15.dat
[17:01:44.533] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//defaultMaskFile.dat
[17:01:44.546] INFO: enter test to run
[17:02:15.587] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[17:02:15.587] INFO: running: highrate
[17:02:15.592] INFO: ----------------------------------------------------------------------
[17:02:15.592] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[17:02:15.592] INFO: ----------------------------------------------------------------------
[17:02:15.592] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[17:02:15.592] INFO: edge/corner pixel THR is adjusted
[17:02:15.592] INFO: PixTestHighRate::trimHotPixels: step 0...
[17:02:16.549] INFO: Collecting data for 1 seconds...
[17:02:17.553] INFO: Done with hot pixel readout
[17:02:22.136] INFO: PixTest:: pg_setup set to default.
[17:02:22.137] INFO: 0 hot pixels found in step 0
[17:02:22.142] INFO: 0 hot pixels could not be trimmed and have been masked.
[17:02:22.210] INFO: PixTest::trimHotPixels() done
[17:02:22.210] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C0.dat
[17:02:22.222] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C1.dat
[17:02:22.229] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C2.dat
[17:02:22.235] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C3.dat
[17:02:22.240] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C4.dat
[17:02:22.245] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C5.dat
[17:02:22.250] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C6.dat
[17:02:22.255] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C7.dat
[17:02:22.260] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C8.dat
[17:02:22.265] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C9.dat
[17:02:22.271] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C10.dat
[17:02:22.276] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C11.dat
[17:02:22.281] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C12.dat
[17:02:22.286] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C13.dat
[17:02:22.292] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C14.dat
[17:02:22.297] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//trimParameters35_C15.dat
[17:02:22.302] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-H-NS_FPIXTest-17C-FNAL-160603-2151_2016-06-03_21h52m_1465008738/000_FPIXTest_p17//defaultMaskFile.dat
[17:02:22.312] INFO: enter test to run
[17:02:48.771] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[17:02:48.771] INFO: running: xray
[17:02:48.772] INFO: ----------------------------------------------------------------------
[17:02:48.772] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[17:02:48.772] INFO: ----------------------------------------------------------------------
[17:02:49.736] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[17:02:59.972] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[17:03:29.518] INFO: Resuming triggers.
[17:03:39.869] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[17:04:09.702] INFO: Resuming triggers.
[17:04:19.944] INFO: run duration 30 seconds, buffer almost full (81%), pausing triggers.
[17:04:50.628] INFO: Resuming triggers.
[17:05:00.873] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[17:05:30.408] INFO: Resuming triggers.
[17:05:40.653] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[17:06:10.245] INFO: Resuming triggers.
[17:06:20.493] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[17:06:50.142] INFO: Resuming triggers.
[17:07:00.387] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[17:07:30.016] INFO: Resuming triggers.
[17:07:40.263] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[17:08:09.847] INFO: Resuming triggers.
[17:08:20.097] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[17:08:50.177] INFO: Resuming triggers.
[17:08:58.311] INFO: data taking finished, elapsed time: 100 seconds.
[17:09:22.463] INFO: PixTest:: pg_setup set to default.
[17:09:22.466] INFO: PixTestXray::doPhRun() done
[17:09:22.610] INFO: enter test to run
[17:11:19.735] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[17:11:19.735] INFO: running: xray
[17:11:19.736] INFO: ----------------------------------------------------------------------
[17:11:19.736] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[17:11:19.736] INFO: ----------------------------------------------------------------------
[17:11:20.701] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[17:11:26.379] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[17:11:57.016] INFO: Resuming triggers.
[17:12:02.694] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[17:12:33.955] INFO: Resuming triggers.
[17:12:39.634] INFO: run duration 16 seconds, buffer almost full (81%), pausing triggers.
[17:13:09.677] INFO: Resuming triggers.
[17:13:15.362] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[17:13:45.432] INFO: Resuming triggers.
[17:13:51.117] INFO: run duration 28 seconds, buffer almost full (81%), pausing triggers.
[17:14:21.204] INFO: Resuming triggers.
[17:14:26.889] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[17:14:56.952] INFO: Resuming triggers.
[17:15:02.639] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[17:15:33.932] INFO: Resuming triggers.
[17:15:39.620] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[17:16:10.480] INFO: Resuming triggers.
[17:16:16.169] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[17:16:46.236] INFO: Resuming triggers.
[17:16:51.925] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[17:17:22.039] INFO: Resuming triggers.
[17:17:27.728] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[17:17:57.750] INFO: Resuming triggers.
[17:18:03.436] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[17:18:33.552] INFO: Resuming triggers.
[17:18:39.234] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[17:19:09.426] INFO: Resuming triggers.
[17:19:15.109] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[17:19:45.118] INFO: Resuming triggers.
[17:19:50.802] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[17:20:21.759] INFO: Resuming triggers.
[17:20:27.438] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[17:20:58.141] INFO: Resuming triggers.
[17:21:03.819] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[17:21:34.007] INFO: Resuming triggers.
[17:21:37.715] INFO: data taking finished, elapsed time: 100 seconds.
[17:21:57.582] INFO: PixTest:: pg_setup set to default.
[17:21:57.585] INFO: PixTestXray::doPhRun() done
[17:21:57.736] INFO: enter test to run
[17:22:41.771] INFO: test: HighRate no parameter change
[17:22:41.771] INFO: running: highrate
[17:22:41.788] INFO: ----------------------------------------------------------------------
[17:22:41.788] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[17:22:41.788] INFO: ----------------------------------------------------------------------
[17:22:41.943] INFO: Expecting 768 events.
[17:22:43.077] INFO: 768 events read in total (419ms).
[17:22:43.077] INFO: Test took 1268ms.
[17:22:43.880] INFO: Expecting 41600 events.
[17:22:47.220] INFO: 41600 events read in total (2814ms).
[17:22:47.221] INFO: Test took 4137ms.
[17:22:47.278] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:22:47.953] INFO: Expecting 41600 events.
[17:22:51.295] INFO: 41600 events read in total (2816ms).
[17:22:51.296] INFO: Test took 3990ms.
[17:22:51.340] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:22:52.042] INFO: Expecting 41600 events.
[17:22:55.366] INFO: 41600 events read in total (2797ms).
[17:22:55.367] INFO: Test took 4005ms.
[17:22:55.413] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:22:56.118] INFO: Expecting 41600 events.
[17:22:59.590] INFO: 41600 events read in total (2946ms).
[17:22:59.591] INFO: Test took 4158ms.
[17:22:59.636] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:00.336] INFO: Expecting 41600 events.
[17:23:03.695] INFO: 41600 events read in total (2832ms).
[17:23:03.696] INFO: Test took 4039ms.
[17:23:03.741] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:04.445] INFO: Expecting 41600 events.
[17:23:07.846] INFO: 41600 events read in total (2874ms).
[17:23:07.847] INFO: Test took 4086ms.
[17:23:07.892] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:08.597] INFO: Expecting 41600 events.
[17:23:11.971] INFO: 41600 events read in total (2848ms).
[17:23:11.972] INFO: Test took 4059ms.
[17:23:12.016] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:12.716] INFO: Expecting 41600 events.
[17:23:16.199] INFO: 41600 events read in total (2956ms).
[17:23:16.200] INFO: Test took 4163ms.
[17:23:16.245] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:16.950] INFO: Expecting 41600 events.
[17:23:20.373] INFO: 41600 events read in total (2896ms).
[17:23:20.374] INFO: Test took 4109ms.
[17:23:20.419] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:21.122] INFO: Expecting 41600 events.
[17:23:24.449] INFO: 41600 events read in total (2800ms).
[17:23:24.450] INFO: Test took 4009ms.
[17:23:24.493] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:25.196] INFO: Expecting 41600 events.
[17:23:28.533] INFO: 41600 events read in total (2810ms).
[17:23:28.534] INFO: Test took 4020ms.
[17:23:28.576] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:29.285] INFO: Expecting 41600 events.
[17:23:32.622] INFO: 41600 events read in total (2810ms).
[17:23:32.623] INFO: Test took 4025ms.
[17:23:32.670] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:33.369] INFO: Expecting 41600 events.
[17:23:36.702] INFO: 41600 events read in total (2806ms).
[17:23:36.703] INFO: Test took 4011ms.
[17:23:36.746] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:37.451] INFO: Expecting 41600 events.
[17:23:40.794] INFO: 41600 events read in total (2816ms).
[17:23:40.795] INFO: Test took 4027ms.
[17:23:40.838] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:41.543] INFO: Expecting 41600 events.
[17:23:44.878] INFO: 41600 events read in total (2808ms).
[17:23:44.879] INFO: Test took 4020ms.
[17:23:44.923] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:45.630] INFO: Expecting 41600 events.
[17:23:48.966] INFO: 41600 events read in total (2809ms).
[17:23:48.967] INFO: Test took 4022ms.
[17:23:49.010] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:49.715] INFO: Expecting 41600 events.
[17:23:53.049] INFO: 41600 events read in total (2807ms).
[17:23:53.050] INFO: Test took 4018ms.
[17:23:53.093] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:53.802] INFO: Expecting 41600 events.
[17:23:57.149] INFO: 41600 events read in total (2820ms).
[17:23:57.150] INFO: Test took 4036ms.
[17:23:57.194] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:23:57.897] INFO: Expecting 41600 events.
[17:24:01.209] INFO: 41600 events read in total (2785ms).
[17:24:01.211] INFO: Test took 3995ms.
[17:24:01.253] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:24:01.963] INFO: Expecting 41600 events.
[17:24:05.127] INFO: 41600 events read in total (2637ms).
[17:24:05.128] INFO: Test took 3853ms.
[17:24:05.171] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:24:05.517] INFO: enter test to run
[17:24:53.402] INFO: test: HighRate no parameter change
[17:24:53.402] INFO: running: highrate
[17:24:53.403] INFO: ----------------------------------------------------------------------
[17:24:53.403] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:24:53.403] INFO: ----------------------------------------------------------------------
[17:24:54.018] INFO: Expecting 208000 events.
[17:25:06.438] INFO: 208000 events read in total (11893ms).
[17:25:06.442] INFO: Test took 13030ms.
[17:25:06.637] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:25:06.905] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[17:25:06.905] INFO: number of red-efficiency pixels: 141 75 158 235 200 187 213 145 110 164 166 138 133 103 25 40
[17:25:06.905] INFO: number of X-ray hits detected: 85608 61396 92904 153264 160524 153990 148010 104656 94591 127762 130692 119821 117412 70779 26502 29695
[17:25:06.905] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:25:06.905] INFO: number of Vcal hits detected: 207854 207925 207837 207758 207794 207807 207782 207851 207887 207832 207833 207860 207860 207894 207974 207959
[17:25:06.905] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[17:25:06.905] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[17:25:06.906] INFO: X-ray hit rate [MHz/cm2]: 25.1 18.0 27.2 44.9 47.1 45.1 43.4 30.7 27.7 37.4 38.3 35.1 34.4 20.7 7.8 8.7
[17:25:06.906] INFO: PixTestHighRate::doXPixelAlive() done
[17:25:06.957] INFO: PixTest:: pg_setup set to default.
[17:25:06.967] INFO: enter test to run
[17:29:40.968] INFO: test: HighRate no parameter change
[17:29:40.968] INFO: running: highrate
[17:29:40.969] INFO: ----------------------------------------------------------------------
[17:29:40.969] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:29:40.969] INFO: ----------------------------------------------------------------------
[17:29:41.586] INFO: Expecting 208000 events.
[17:29:56.229] INFO: 208000 events read in total (14116ms).
[17:29:56.236] INFO: Test took 15258ms.
[17:29:56.603] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:29:56.931] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[17:29:56.931] INFO: number of red-efficiency pixels: 364 204 492 769 700 664 792 436 373 489 585 463 405 301 68 75
[17:29:56.931] INFO: number of X-ray hits detected: 171282 122252 185607 305737 318450 305399 294882 209071 188442 253837 261038 239702 235037 141046 52909 60089
[17:29:56.931] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:29:56.931] INFO: number of Vcal hits detected: 207596 207782 207399 207092 207174 207244 207094 207516 207596 207468 207355 207495 207570 207667 207925 207924
[17:29:56.931] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.6 99.6 99.7 99.6 99.8 99.8 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[17:29:56.931] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.6 99.6 99.6 99.6 99.8 99.8 99.7 99.7 99.8 99.8 99.8 100.0 100.0
[17:29:56.931] INFO: X-ray hit rate [MHz/cm2]: 50.2 35.8 54.4 89.6 93.3 89.5 86.4 61.3 55.2 74.4 76.5 70.3 68.9 41.3 15.5 17.6
[17:29:56.931] INFO: PixTestHighRate::doXPixelAlive() done
[17:29:56.982] INFO: PixTest:: pg_setup set to default.
[17:29:56.002] INFO: enter test to run
[17:30:52.247] INFO: test: HighRate no parameter change
[17:30:52.247] INFO: running: highrate
[17:30:52.249] INFO: ----------------------------------------------------------------------
[17:30:52.249] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:30:52.249] INFO: ----------------------------------------------------------------------
[17:30:52.866] INFO: Expecting 208000 events.
[17:31:10.142] INFO: 208000 events read in total (16749ms).
[17:31:10.151] INFO: Test took 17893ms.
[17:31:10.715] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:31:11.105] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[17:31:11.105] INFO: number of red-efficiency pixels: 764 349 1131 1730 1798 1606 1812 1076 846 1154 1359 1032 974 766 110 129
[17:31:11.106] INFO: number of X-ray hits detected: 259069 185027 281071 460463 480022 462854 442789 315833 287114 384040 395869 362794 355828 213952 80788 90915
[17:31:11.106] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[17:31:11.106] INFO: number of Vcal hits detected: 206966 207611 206007 205385 205333 205697 205198 206475 206957 206584 206144 206724 206805 207008 207883 207868
[17:31:11.106] INFO: Vcal hit fiducial efficiency (%): 99.6 99.8 99.2 98.9 98.8 99.0 98.8 99.3 99.5 99.4 99.2 99.4 99.5 99.6 99.9 99.9
[17:31:11.106] INFO: Vcal hit overall efficiency (%): 99.5 99.8 99.0 98.7 98.7 98.9 98.7 99.3 99.5 99.3 99.1 99.4 99.4 99.5 99.9 99.9
[17:31:11.106] INFO: X-ray hit rate [MHz/cm2]: 75.9 54.2 82.4 135.0 140.7 135.7 129.8 92.6 84.2 112.6 116.0 106.3 104.3 62.7 23.7 26.6
[17:31:11.106] INFO: PixTestHighRate::doXPixelAlive() done
[17:31:11.156] INFO: PixTest:: pg_setup set to default.
[17:31:11.169] INFO: enter test to run
[17:31:13.375] INFO: test: exit no parameter change
[17:31:13.780] QUIET: Connection to board 33 closed.
[17:31:13.782] INFO: pXar: this is the end, my friend