[16:08:42.008] INFO: *** Welcome to pxar ***
[16:08:42.008] INFO: *** Today: 2016/09/08
[16:08:42.357] INFO: *** Version: v1.9.0-818-g96727
[16:08:42.357] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//dacParameters35_C15.dat
[16:08:42.387] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:08:42.387] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//defaultMaskFile.dat
[16:08:42.392] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C15.dat
[16:08:42.470] INFO: clk: 4
[16:08:42.470] INFO: ctr: 4
[16:08:42.470] INFO: sda: 19
[16:08:42.470] INFO: tin: 9
[16:08:42.470] INFO: level: 15
[16:08:42.470] INFO: triggerdelay: 0
[16:08:42.471] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[16:08:42.471] INFO: Log level: INFO
[16:08:42.486] QUIET: Connection to board DTB_WREKRL opened.
[16:08:42.489] 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:08:42.492] INFO: RPC call hashes of host and DTB match: 398089610
[16:08:44.032] INFO: DUT info:
[16:08:44.032] INFO: The DUT currently contains the following objects:
[16:08:44.032] INFO: 2 TBM Cores tbm08c (2 ON)
[16:08:44.032] INFO: TBM Core alpha (0): 7 registers set
[16:08:44.032] INFO: TBM Core beta (1): 7 registers set
[16:08:44.032] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[16:08:44.032] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.032] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[16:08:44.435] INFO: enter 'restricted' command line mode
[16:08:44.435] INFO: enter test to run
[16:08:54.674] INFO: test: PixelAlive no parameter change
[16:08:54.674] INFO: running: pixelalive
[16:08:54.697] INFO: ----------------------------------------------------------------------
[16:08:54.697] 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:08:54.697] INFO: ----------------------------------------------------------------------
[16:08:55.021] INFO: Expecting 41600 events.
[16:08:59.404] INFO: 41600 events read in total (3665ms).
[16:08:59.572] INFO: Test took 4872ms.
[16:08:59.600] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:09:00.176] INFO: PixTestAlive::aliveTest() done
[16:09:00.176] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 26 0 0 0 0 1 0 0
[16:09:00.205] INFO: enter test to run
[16:09:30.745] INFO: test: timing no parameter change
[16:09:30.745] INFO: running: timing
[16:09:30.749] INFO: ######################################################################
[16:09:30.749] INFO: PixTestTiming::doTest()
[16:09:30.749] INFO: ######################################################################
[16:09:30.749] INFO: ----------------------------------------------------------------------
[16:09:30.749] INFO: PixTestTiming::TBMPhaseScan()
[16:09:30.749] INFO: ----------------------------------------------------------------------
[16:14:16.078] INFO: TBM Phase Settings: 16
[16:14:16.078] INFO: 400MHz Phase: 4
[16:14:16.078] INFO: 160MHz Phase: 0
[16:14:16.078] INFO: Functional Phase Area: 3
[16:14:16.081] INFO: Test took 285332 ms.
[16:14:16.081] INFO: PixTestTiming::TBMPhaseScan() done.
[16:14:16.082] INFO: ----------------------------------------------------------------------
[16:14:16.082] INFO: PixTestTiming::ROCDelayScan()
[16:14:16.082] INFO: ----------------------------------------------------------------------
[16:16:19.705] INFO: ROC Delay Settings: 219
[16:16:19.705] INFO: ROC Header-Trailer/Token Delay: 11
[16:16:19.705] INFO: ROC Port 0 Delay: 3
[16:16:19.705] INFO: ROC Port 1 Delay: 3
[16:16:19.705] INFO: Functional ROC Area: 4
[16:16:19.708] INFO: Test took 123626 ms.
[16:16:19.708] INFO: PixTestTiming::ROCDelayScan() done.
[16:16:19.708] INFO: ----------------------------------------------------------------------
[16:16:19.708] INFO: PixTestTiming::TimingTest()
[16:16:19.708] INFO: ----------------------------------------------------------------------
[16:16:35.858] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:50.813] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:17:05.728] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:17:20.673] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:17:35.621] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:17:50.560] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:05.501] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:20.453] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:35.407] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:50.356] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:50.734] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:18:50.752] INFO: ----------------------------------------------------------------------
[16:18:50.752] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:18:50.752] INFO: ----------------------------------------------------------------------
[16:18:50.752] INFO: ----------------------------------------------------------------------
[16:18:50.752] INFO: Read back bit status: 1
[16:18:50.752] INFO: ----------------------------------------------------------------------
[16:18:50.752] INFO: ----------------------------------------------------------------------
[16:18:50.752] INFO: Timings are good!
[16:18:50.752] INFO: ----------------------------------------------------------------------
[16:18:50.752] INFO: Test took 151044 ms.
[16:18:50.752] INFO: PixTestTiming::TimingTest() done.
[16:18:50.760] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:18:50.760] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:18:50.761] INFO: PixTestTiming::doTest took 560015 ms.
[16:18:50.761] INFO: PixTestTiming::doTest() done
[16:18:50.761] INFO: Write out TBMPhaseScan_0_V0
[16:18:50.761] INFO: Write out TBMPhaseScan_1_V0
[16:18:50.761] INFO: Write out CombinedTBMPhaseScan_V0
[16:18:50.762] INFO: Write out ROCDelayScan3_V0
[16:18:50.763] INFO: enter test to run
[16:19:35.422] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:19:35.422] INFO: running: highrate
[16:19:35.423] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:19:35.711] INFO: ----------------------------------------------------------------------
[16:19:35.711] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:19:35.711] INFO: ----------------------------------------------------------------------
[16:19:35.711] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:19:35.726] INFO: edge/corner pixel THR is adjusted
[16:19:35.726] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:19:36.698] INFO: Collecting data for 5 seconds...
[16:19:41.715] INFO: Done with hot pixel readout
[16:19:52.975] INFO: PixTest:: pg_setup set to default.
[16:19:52.976] INFO: 24 hot pixels found in step 0
[16:19:53.965] INFO: Collecting data for 5 seconds...
[16:19:58.982] INFO: Done with hot pixel readout
[16:20:10.242] INFO: PixTest:: pg_setup set to default.
[16:20:10.243] INFO: 22 hot pixels found in step 1
[16:20:11.231] INFO: Collecting data for 5 seconds...
[16:20:16.248] INFO: Done with hot pixel readout
[16:20:27.540] INFO: PixTest:: pg_setup set to default.


[16:20:27.541] INFO: 22 hot pixels found in step 2
[16:20:28.530] INFO: Collecting data for 5 seconds...
[16:20:33.548] INFO: Done with hot pixel readout
[16:20:44.796] INFO: PixTest:: pg_setup set to default.




[16:20:44.797] INFO: 21 hot pixels found in step 3
[16:20:45.785] INFO: Collecting data for 5 seconds...
[16:20:50.803] INFO: Done with hot pixel readout
[16:21:02.007] INFO: PixTest:: pg_setup set to default.






[16:21:02.008] INFO: 21 hot pixels found in step 4
[16:21:02.996] INFO: Collecting data for 5 seconds...
[16:21:08.014] INFO: Done with hot pixel readout
[16:21:19.323] INFO: PixTest:: pg_setup set to default.







[16:21:19.324] INFO: 19 hot pixels found in step 5
[16:21:20.313] INFO: Collecting data for 5 seconds...
[16:21:25.331] INFO: Done with hot pixel readout
[16:21:36.215] INFO: PixTest:: pg_setup set to default.











[16:21:36.216] INFO: 21 hot pixels found in step 6
[16:21:37.204] INFO: Collecting data for 5 seconds...
[16:21:42.222] INFO: Done with hot pixel readout
[16:21:53.435] INFO: PixTest:: pg_setup set to default.













[16:21:53.436] INFO: 23 hot pixels found in step 7
[16:21:54.424] INFO: Collecting data for 5 seconds...
[16:21:59.442] INFO: Done with hot pixel readout
[16:22:10.513] INFO: PixTest:: pg_setup set to default.














[16:22:10.514] INFO: 20 hot pixels found in step 8
[16:22:11.502] INFO: Collecting data for 5 seconds...
[16:22:16.520] INFO: Done with hot pixel readout
[16:22:27.728] INFO: PixTest:: pg_setup set to default.


















[16:22:27.729] INFO: 21 hot pixels found in step 9
[16:22:28.718] INFO: Collecting data for 5 seconds...
[16:22:33.737] INFO: Done with hot pixel readout
[16:22:44.895] INFO: PixTest:: pg_setup set to default.

















[16:22:44.896] INFO: 17 hot pixels found in step 10
[16:22:44.929] INFO: 17 hot pixels could not be trimmed and have been masked.
[16:22:44.932] INFO: PixTest::trimHotPixels() done
[16:22:44.933] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C0.dat
[16:22:44.938] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C1.dat
[16:22:44.949] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C2.dat
[16:22:44.958] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C3.dat
[16:22:44.965] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C4.dat
[16:22:44.971] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C5.dat
[16:22:44.977] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C6.dat
[16:22:44.984] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C7.dat
[16:22:44.990] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C8.dat
[16:22:44.996] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C9.dat
[16:22:44.003] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C10.dat
[16:22:45.009] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C11.dat
[16:22:45.015] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C12.dat
[16:22:45.022] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C13.dat
[16:22:45.028] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C14.dat
[16:22:45.034] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C15.dat
[16:22:45.040] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//defaultMaskFile.dat
[16:22:45.050] INFO: enter test to run
[16:23:47.916] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:23:47.916] INFO: running: highrate
[16:23:47.921] INFO: ----------------------------------------------------------------------
[16:23:47.921] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:23:47.921] INFO: ----------------------------------------------------------------------
[16:23:47.921] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:23:47.921] INFO: edge/corner pixel THR is adjusted
[16:23:47.921] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:23:48.879] INFO: Collecting data for 1 seconds...
[16:23:49.883] INFO: Done with hot pixel readout
[16:23:53.671] INFO: PixTest:: pg_setup set to default.
[16:23:53.671] INFO: 0 hot pixels found in step 0
[16:23:53.677] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:23:53.780] INFO: PixTest::trimHotPixels() done
[16:23:53.780] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C0.dat
[16:23:53.792] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C1.dat
[16:23:53.801] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C2.dat
[16:23:53.806] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C3.dat
[16:23:53.812] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C4.dat
[16:23:53.817] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C5.dat
[16:23:53.822] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C6.dat
[16:23:53.828] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C7.dat
[16:23:53.833] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C8.dat
[16:23:53.839] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C9.dat
[16:23:53.844] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C10.dat
[16:23:53.849] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C11.dat
[16:23:53.855] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C12.dat
[16:23:53.860] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C13.dat
[16:23:53.866] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C14.dat
[16:23:53.871] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//trimParameters35_C15.dat
[16:23:53.876] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-4-42_FPIXTest-17C-FNAL-160906-1541-300V_2016-09-06_15h41m_1473194476/000_FPIXTest_p17//defaultMaskFile.dat
[16:23:53.886] INFO: enter test to run
[16:24:22.084] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:24:22.084] INFO: running: xray
[16:24:22.085] INFO: ----------------------------------------------------------------------
[16:24:22.085] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:24:22.085] INFO: ----------------------------------------------------------------------
[16:24:23.049] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:24:35.176] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[16:25:04.975] INFO: Resuming triggers.
[16:25:17.098] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[16:25:46.635] INFO: Resuming triggers.
[16:25:58.761] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[16:26:28.147] INFO: Resuming triggers.
[16:26:40.274] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[16:27:09.780] INFO: Resuming triggers.
[16:27:21.907] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[16:27:51.336] INFO: Resuming triggers.
[16:28:03.470] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[16:28:32.953] INFO: Resuming triggers.
[16:28:45.078] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[16:29:14.474] INFO: Resuming triggers.
[16:29:26.598] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[16:29:55.999] INFO: Resuming triggers.
[16:29:59.320] INFO: data taking finished, elapsed time: 100 seconds.
[16:30:07.628] INFO: PixTest:: pg_setup set to default.
[16:30:07.631] INFO: PixTestXray::doPhRun() done
[16:30:07.828] INFO: enter test to run
[16:30:45.761] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:30:45.762] INFO: running: xray
[16:30:45.763] INFO: ----------------------------------------------------------------------
[16:30:45.763] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:30:45.763] INFO: ----------------------------------------------------------------------
[16:30:46.736] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:30:54.231] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[16:31:24.503] INFO: Resuming triggers.
[16:31:31.998] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[16:32:02.132] INFO: Resuming triggers.
[16:32:09.624] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[16:32:39.803] INFO: Resuming triggers.
[16:32:47.295] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[16:33:18.243] INFO: Resuming triggers.
[16:33:25.734] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[16:33:56.515] INFO: Resuming triggers.
[16:34:04.008] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[16:34:34.169] INFO: Resuming triggers.
[16:34:41.662] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[16:35:12.812] INFO: Resuming triggers.
[16:35:20.304] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[16:35:51.659] INFO: Resuming triggers.
[16:35:59.151] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[16:36:30.726] INFO: Resuming triggers.
[16:36:38.219] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[16:37:09.051] INFO: Resuming triggers.
[16:37:16.547] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[16:37:46.764] INFO: Resuming triggers.
[16:37:54.260] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[16:38:24.552] INFO: Resuming triggers.
[16:38:32.048] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[16:39:02.159] INFO: Resuming triggers.
[16:39:05.096] INFO: data taking finished, elapsed time: 100 seconds.
[16:39:17.213] INFO: PixTest:: pg_setup set to default.
[16:39:17.216] INFO: PixTestXray::doPhRun() done
[16:39:17.365] INFO: enter test to run
[16:39:51.190] INFO: test: HighRate no parameter change
[16:39:51.190] INFO: running: highrate
[16:39:51.210] INFO: ----------------------------------------------------------------------
[16:39:51.210] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:39:51.210] INFO: ----------------------------------------------------------------------
[16:39:51.365] INFO: Expecting 768 events.
[16:39:52.499] INFO: 768 events read in total (419ms).
[16:39:52.499] INFO: Test took 1269ms.
[16:39:53.302] INFO: Expecting 41600 events.
[16:39:56.373] INFO: 41600 events read in total (2544ms).
[16:39:56.374] INFO: Test took 3868ms.
[16:39:56.403] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:57.141] INFO: Expecting 41600 events.
[16:40:00.294] INFO: 41600 events read in total (2626ms).
[16:40:00.295] INFO: Test took 3876ms.
[16:40:00.325] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:01.055] INFO: Expecting 41600 events.
[16:40:04.245] INFO: 41600 events read in total (2663ms).
[16:40:04.246] INFO: Test took 3906ms.
[16:40:04.275] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:05.008] INFO: Expecting 41600 events.
[16:40:08.203] INFO: 41600 events read in total (2668ms).
[16:40:08.204] INFO: Test took 3911ms.
[16:40:08.233] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:08.964] INFO: Expecting 41600 events.
[16:40:12.155] INFO: 41600 events read in total (2664ms).
[16:40:12.156] INFO: Test took 3907ms.
[16:40:12.186] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:12.920] INFO: Expecting 41600 events.
[16:40:16.124] INFO: 41600 events read in total (2677ms).
[16:40:16.124] INFO: Test took 3922ms.
[16:40:16.154] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:16.885] INFO: Expecting 41600 events.
[16:40:20.085] INFO: 41600 events read in total (2673ms).
[16:40:20.086] INFO: Test took 3915ms.
[16:40:20.115] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:20.850] INFO: Expecting 41600 events.
[16:40:24.055] INFO: 41600 events read in total (2678ms).
[16:40:24.056] INFO: Test took 3925ms.
[16:40:24.084] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:24.815] INFO: Expecting 41600 events.
[16:40:28.015] INFO: 41600 events read in total (2673ms).
[16:40:28.016] INFO: Test took 3916ms.
[16:40:28.046] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:28.777] INFO: Expecting 41600 events.
[16:40:31.977] INFO: 41600 events read in total (2673ms).
[16:40:31.978] INFO: Test took 3915ms.
[16:40:32.007] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:32.740] INFO: Expecting 41600 events.
[16:40:35.933] INFO: 41600 events read in total (2666ms).
[16:40:35.934] INFO: Test took 3910ms.
[16:40:35.963] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:36.699] INFO: Expecting 41600 events.
[16:40:39.896] INFO: 41600 events read in total (2670ms).
[16:40:39.897] INFO: Test took 3917ms.
[16:40:39.927] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:40.659] INFO: Expecting 41600 events.
[16:40:43.860] INFO: 41600 events read in total (2674ms).
[16:40:43.861] INFO: Test took 3917ms.
[16:40:43.891] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:44.624] INFO: Expecting 41600 events.
[16:40:47.818] INFO: 41600 events read in total (2668ms).
[16:40:47.819] INFO: Test took 3911ms.
[16:40:47.849] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:48.582] INFO: Expecting 41600 events.
[16:40:51.810] INFO: 41600 events read in total (2701ms).
[16:40:51.811] INFO: Test took 3946ms.
[16:40:51.840] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:52.570] INFO: Expecting 41600 events.
[16:40:55.775] INFO: 41600 events read in total (2678ms).
[16:40:55.776] INFO: Test took 3920ms.
[16:40:55.806] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:56.539] INFO: Expecting 41600 events.
[16:40:59.735] INFO: 41600 events read in total (2669ms).
[16:40:59.736] INFO: Test took 3913ms.
[16:40:59.766] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:41:00.499] INFO: Expecting 41600 events.
[16:41:03.695] INFO: 41600 events read in total (2669ms).
[16:41:03.696] INFO: Test took 3913ms.
[16:41:03.725] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:41:04.461] INFO: Expecting 41600 events.
[16:41:07.631] INFO: 41600 events read in total (2643ms).
[16:41:07.631] INFO: Test took 3888ms.
[16:41:07.660] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:41:08.396] INFO: Expecting 41600 events.
[16:41:11.443] INFO: 41600 events read in total (2520ms).
[16:41:11.444] INFO: Test took 3766ms.
[16:41:11.473] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:41:11.845] INFO: enter test to run
[16:41:18.901] INFO: test: HighRate no parameter change
[16:41:18.901] INFO: running: highrate
[16:41:18.902] INFO: ----------------------------------------------------------------------
[16:41:18.902] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:41:18.902] INFO: ----------------------------------------------------------------------
[16:41:19.517] INFO: Expecting 208000 events.
[16:41:31.172] INFO: 208000 events read in total (11128ms).
[16:41:31.175] INFO: Test took 12266ms.
[16:41:31.296] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:41:31.541] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 25 0 0 0 0 1 0 0
[16:41:31.541] INFO: number of red-efficiency pixels: 100 43 70 97 131 128 90 76 98 86 92 71 63 36 17 29
[16:41:31.541] INFO: number of X-ray hits detected: 62418 38479 58837 90403 97468 97925 93800 65006 57008 73852 75740 66779 73168 42436 18647 22155
[16:41:31.541] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:41:31.541] INFO: number of Vcal hits detected: 207898 207957 207927 207901 207867 207865 207906 207921 206623 207909 207906 207929 207937 207914 207983 207970
[16:41:31.541] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[16:41:31.541] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 100.0 100.0 99.3 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[16:41:31.541] INFO: X-ray hit rate [MHz/cm2]: 18.3 11.3 17.2 26.5 28.6 28.7 27.5 19.1 16.7 21.6 22.2 19.6 21.4 12.4 5.5 6.5
[16:41:31.541] INFO: PixTestHighRate::doXPixelAlive() done
[16:41:31.586] INFO: PixTest:: pg_setup set to default.
[16:41:31.600] INFO: enter test to run
[16:41:51.989] INFO: test: HighRate no parameter change
[16:41:51.989] INFO: running: highrate
[16:41:51.990] INFO: ----------------------------------------------------------------------
[16:41:51.990] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:41:51.990] INFO: ----------------------------------------------------------------------
[16:41:52.607] INFO: Expecting 208000 events.
[16:42:05.632] INFO: 208000 events read in total (12498ms).
[16:42:05.636] INFO: Test took 13637ms.
[16:42:05.880] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:42:06.170] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 26 0 0 0 0 1 0 0
[16:42:06.170] INFO: number of red-efficiency pixels: 275 98 219 348 398 439 302 206 211 250 224 251 242 135 37 58
[16:42:06.170] INFO: number of X-ray hits detected: 128448 78707 122640 187431 200887 201390 192741 133587 117787 153087 156218 138334 150460 88008 38712 46015
[16:42:06.170] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:42:06.170] INFO: number of Vcal hits detected: 207695 207897 207760 207632 207576 207517 207686 207785 206510 207726 207771 207741 207747 207813 207963 207940
[16:42:06.170] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[16:42:06.170] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.8 99.8 99.9 99.3 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[16:42:06.170] INFO: X-ray hit rate [MHz/cm2]: 37.6 23.1 35.9 54.9 58.9 59.0 56.5 39.2 34.5 44.9 45.8 40.5 44.1 25.8 11.3 13.5
[16:42:06.170] INFO: PixTestHighRate::doXPixelAlive() done
[16:42:06.224] INFO: PixTest:: pg_setup set to default.
[16:42:06.243] INFO: enter test to run
[16:42:25.557] INFO: test: HighRate no parameter change
[16:42:25.557] INFO: running: highrate
[16:42:25.558] INFO: ----------------------------------------------------------------------
[16:42:25.558] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:42:25.558] INFO: ----------------------------------------------------------------------
[16:42:26.171] INFO: Expecting 208000 events.
[16:42:40.733] INFO: 208000 events read in total (14036ms).
[16:42:40.739] INFO: Test took 15171ms.
[16:42:41.100] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:42:41.424] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 26 0 0 0 0 1 0 0
[16:42:41.425] INFO: number of red-efficiency pixels: 532 206 530 835 983 1018 676 442 409 585 495 474 558 244 76 82
[16:42:41.425] INFO: number of X-ray hits detected: 192805 119575 185323 282860 304504 304379 292021 203310 179062 231721 236217 209343 227778 133736 58507 70132
[16:42:41.425] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:42:41.425] INFO: number of Vcal hits detected: 207303 207782 207349 207012 206809 206734 207213 207498 206287 207354 207461 207476 207379 207690 207919 207912
[16:42:41.425] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.7 99.6 99.5 99.5 99.7 99.8 99.8 99.7 99.8 99.8 99.7 99.9 100.0 100.0
[16:42:41.425] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.7 99.5 99.4 99.4 99.6 99.8 99.2 99.7 99.7 99.7 99.7 99.9 100.0 100.0
[16:42:41.425] INFO: X-ray hit rate [MHz/cm2]: 56.5 35.0 54.3 82.9 89.3 89.2 85.6 59.6 52.5 67.9 69.2 61.4 66.8 39.2 17.1 20.6
[16:42:41.425] INFO: PixTestHighRate::doXPixelAlive() done
[16:42:41.475] INFO: PixTest:: pg_setup set to default.
[16:42:41.495] INFO: enter test to run
[16:43:21.556] INFO: test: exit no parameter change
[16:43:21.949] QUIET: Connection to board 33 closed.
[16:43:21.964] INFO: pXar: this is the end, my friend