[17:20:35.185] INFO: *** Welcome to pxar ***
[17:20:35.185] INFO: *** Today: 2016/05/23
[17:20:35.198] INFO: *** Version: v1.9.0-796-gef167-dirty
[17:20:35.198] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//dacParameters35_C15.dat
[17:20:35.198] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//tbmParameters_C0b.dat
[17:20:35.199] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//defaultMaskFile.dat
[17:20:35.199] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C15.dat
[17:20:35.267] INFO: clk: 4
[17:20:35.267] INFO: ctr: 4
[17:20:35.267] INFO: sda: 19
[17:20:35.267] INFO: tin: 9
[17:20:35.267] INFO: level: 15
[17:20:35.267] INFO: triggerdelay: 0
[17:20:35.267] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[17:20:35.267] INFO: Log level: INFO
[17:20:35.283] QUIET: Connection to board DTB_WREKRL opened.
[17:20:35.286] 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:
------------------------------------------------------
[17:20:35.289] INFO: RPC call hashes of host and DTB match: 398089610
[17:20:36.820] INFO: DUT info:
[17:20:36.820] INFO: The DUT currently contains the following objects:
[17:20:36.820] INFO: 2 TBM Cores tbm08c (2 ON)
[17:20:36.820] INFO: TBM Core alpha (0): 7 registers set
[17:20:36.820] INFO: TBM Core beta (1): 7 registers set
[17:20:36.820] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[17:20:36.820] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.820] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.820] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.820] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.820] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.820] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.820] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.820] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.820] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.820] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.820] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.821] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.821] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.821] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.821] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:36.821] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[17:20:37.224] INFO: enter 'restricted' command line mode
[17:20:37.224] INFO: enter test to run
[17:20:38.603] INFO: test: timing no parameter change
[17:20:38.603] INFO: running: timing
[17:20:38.612] INFO: ######################################################################
[17:20:38.612] INFO: PixTestTiming::doTest()
[17:20:38.612] INFO: ######################################################################
[17:20:38.612] INFO: ----------------------------------------------------------------------
[17:20:38.612] INFO: PixTestTiming::TBMPhaseScan()
[17:20:38.612] INFO: ----------------------------------------------------------------------
[17:28:17.417] INFO: TBM Phase Settings: 200
[17:28:17.417] INFO: 400MHz Phase: 2
[17:28:17.417] INFO: 160MHz Phase: 6
[17:28:17.417] INFO: Functional Phase Area: 3
[17:28:17.420] INFO: Test took 458808 ms.
[17:28:17.420] INFO: PixTestTiming::TBMPhaseScan() done.
[17:28:17.420] INFO: ----------------------------------------------------------------------
[17:28:17.420] INFO: PixTestTiming::ROCDelayScan()
[17:28:17.420] INFO: ----------------------------------------------------------------------
[17:30:51.084] INFO: ROC Delay Settings: 219
[17:30:51.084] INFO: ROC Header-Trailer/Token Delay: 11
[17:30:51.084] INFO: ROC Port 0 Delay: 3
[17:30:51.084] INFO: ROC Port 1 Delay: 3
[17:30:51.084] INFO: Functional ROC Area: 5
[17:30:51.087] INFO: Test took 153667 ms.
[17:30:51.087] INFO: PixTestTiming::ROCDelayScan() done.
[17:30:51.087] INFO: ----------------------------------------------------------------------
[17:30:51.087] INFO: PixTestTiming::TimingTest()
[17:30:51.087] INFO: ----------------------------------------------------------------------
[17:31:07.202] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:31:22.135] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:31:37.111] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:31:52.078] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:32:07.071] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:32:22.041] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:32:37.028] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:32:52.012] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:33:06.990] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:33:21.964] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:33:22.342] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:33:22.358] INFO: ----------------------------------------------------------------------
[17:33:22.358] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[17:33:22.358] INFO: ----------------------------------------------------------------------
[17:33:22.358] INFO: ----------------------------------------------------------------------
[17:33:22.358] INFO: Read back bit status: 1
[17:33:22.358] INFO: ----------------------------------------------------------------------
[17:33:22.358] INFO: ----------------------------------------------------------------------
[17:33:22.358] INFO: Timings are good!
[17:33:22.358] INFO: ----------------------------------------------------------------------
[17:33:22.358] INFO: Test took 151271 ms.
[17:33:22.358] INFO: PixTestTiming::TimingTest() done.
[17:33:22.358] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//tbmParameters_C0a.dat
[17:33:22.358] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//tbmParameters_C0b.dat
[17:33:22.358] INFO: PixTestTiming::doTest took 763751 ms.
[17:33:22.358] INFO: PixTestTiming::doTest() done
[17:33:22.359] INFO: Write out TBMPhaseScan_0_V0
[17:33:22.384] INFO: Write out TBMPhaseScan_1_V0
[17:33:22.384] INFO: Write out CombinedTBMPhaseScan_V0
[17:33:22.385] INFO: Write out ROCDelayScan3_V0
[17:33:22.385] INFO: enter test to run
[17:33:31.133] INFO: test: PixelAlive no parameter change
[17:33:31.133] INFO: running: pixelalive
[17:33:31.138] INFO: ----------------------------------------------------------------------
[17:33:31.138] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[17:33:31.138] INFO: ----------------------------------------------------------------------
[17:33:31.457] INFO: Expecting 41600 events.
[17:33:35.785] INFO: 41600 events read in total (3612ms).
[17:33:35.786] INFO: Test took 4646ms.
[17:33:35.792] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:33:36.188] INFO: PixTestAlive::aliveTest() done
[17:33:36.188] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[17:33:36.192] INFO: enter test to run
[17:33:46.909] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[17:33:46.909] INFO: running: highrate
[17:33:46.909] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[17:33:47.064] INFO: ----------------------------------------------------------------------
[17:33:47.064] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[17:33:47.064] INFO: ----------------------------------------------------------------------
[17:33:47.064] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[17:33:47.064] INFO: edge/corner pixel THR is adjusted
[17:33:47.064] INFO: PixTestHighRate::trimHotPixels: step 0...
[17:33:48.022] INFO: Collecting data for 5 seconds...
[17:33:53.039] INFO: Done with hot pixel readout
[17:34:06.140] INFO: PixTest:: pg_setup set to default.


[17:34:06.141] INFO: 125 hot pixels found in step 0
[17:34:07.142] INFO: Collecting data for 5 seconds...
[17:34:12.160] INFO: Done with hot pixel readout
[17:34:25.253] INFO: PixTest:: pg_setup set to default.


[17:34:25.255] INFO: 105 hot pixels found in step 1
[17:34:26.254] INFO: Collecting data for 5 seconds...
[17:34:31.270] INFO: Done with hot pixel readout
[17:34:44.361] INFO: PixTest:: pg_setup set to default.





[17:34:44.362] INFO: 104 hot pixels found in step 2
[17:34:45.362] INFO: Collecting data for 5 seconds...
[17:34:50.378] INFO: Done with hot pixel readout
[17:35:03.453] INFO: PixTest:: pg_setup set to default.





[17:35:03.454] INFO: 130 hot pixels found in step 3
[17:35:04.455] INFO: Collecting data for 5 seconds...
[17:35:09.471] INFO: Done with hot pixel readout
[17:35:22.604] INFO: PixTest:: pg_setup set to default.





[17:35:22.605] INFO: 91 hot pixels found in step 4
[17:35:23.606] INFO: Collecting data for 5 seconds...
[17:35:28.622] INFO: Done with hot pixel readout
[17:35:41.743] INFO: PixTest:: pg_setup set to default.



[17:35:41.744] INFO: 94 hot pixels found in step 5
[17:35:42.744] INFO: Collecting data for 5 seconds...
[17:35:47.760] INFO: Done with hot pixel readout
[17:36:00.903] INFO: PixTest:: pg_setup set to default.









[17:36:00.905] INFO: 94 hot pixels found in step 6
[17:36:01.905] INFO: Collecting data for 5 seconds...
[17:36:06.922] INFO: Done with hot pixel readout
[17:36:20.058] INFO: PixTest:: pg_setup set to default.





[17:36:20.059] INFO: 81 hot pixels found in step 7
[17:36:21.060] INFO: Collecting data for 5 seconds...
[17:36:26.076] INFO: Done with hot pixel readout
[17:36:39.162] INFO: PixTest:: pg_setup set to default.









[17:36:39.164] INFO: 91 hot pixels found in step 8
[17:36:40.164] INFO: Collecting data for 5 seconds...
[17:36:45.180] INFO: Done with hot pixel readout
[17:36:58.302] INFO: PixTest:: pg_setup set to default.












[17:36:58.303] INFO: 93 hot pixels found in step 9
[17:36:59.301] INFO: Collecting data for 5 seconds...
[17:37:04.317] INFO: Done with hot pixel readout
[17:37:17.453] INFO: PixTest:: pg_setup set to default.















[17:37:17.455] INFO: 79 hot pixels found in step 10
[17:37:18.455] INFO: Collecting data for 5 seconds...
[17:37:23.471] INFO: Done with hot pixel readout
[17:37:36.572] INFO: PixTest:: pg_setup set to default.




















[17:37:36.573] INFO: 90 hot pixels found in step 11
[17:37:37.574] INFO: Collecting data for 5 seconds...
[17:37:42.590] INFO: Done with hot pixel readout
[17:37:55.745] INFO: PixTest:: pg_setup set to default.










[17:37:55.746] INFO: 74 hot pixels found in step 12
[17:37:56.746] INFO: Collecting data for 5 seconds...
[17:38:01.762] INFO: Done with hot pixel readout
[17:38:14.890] INFO: PixTest:: pg_setup set to default.
















[17:38:14.892] INFO: 78 hot pixels found in step 13
[17:38:15.893] INFO: Collecting data for 5 seconds...
[17:38:20.909] INFO: Done with hot pixel readout
[17:38:34.049] INFO: PixTest:: pg_setup set to default.
















[17:38:34.051] INFO: 62 hot pixels found in step 14
[17:38:34.096] INFO: 62 hot pixels could not be trimmed and have been masked.
[17:38:34.099] INFO: PixTest::trimHotPixels() done
[17:38:34.100] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C0.dat
[17:38:34.109] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C1.dat
[17:38:34.118] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C2.dat
[17:38:34.127] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C3.dat
[17:38:34.136] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C4.dat
[17:38:34.175] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C5.dat
[17:38:34.192] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C6.dat
[17:38:34.198] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C7.dat
[17:38:34.203] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C8.dat
[17:38:34.209] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C9.dat
[17:38:34.214] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C10.dat
[17:38:34.219] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C11.dat
[17:38:34.225] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C12.dat
[17:38:34.230] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C13.dat
[17:38:34.236] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C14.dat
[17:38:34.241] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C15.dat
[17:38:34.246] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//defaultMaskFile.dat
[17:38:34.260] INFO: enter test to run
[17:39:06.435] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[17:39:06.435] INFO: running: highrate
[17:39:06.439] INFO: ----------------------------------------------------------------------
[17:39:06.439] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[17:39:06.439] INFO: ----------------------------------------------------------------------
[17:39:06.439] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[17:39:06.439] INFO: edge/corner pixel THR is adjusted
[17:39:06.439] INFO: PixTestHighRate::trimHotPixels: step 0...
[17:39:07.397] INFO: Collecting data for 1 seconds...
[17:39:08.401] INFO: Done with hot pixel readout
[17:39:12.888] INFO: PixTest:: pg_setup set to default.
[17:39:12.889] INFO: 0 hot pixels found in step 0
[17:39:12.895] INFO: 0 hot pixels could not be trimmed and have been masked.
[17:39:12.958] INFO: PixTest::trimHotPixels() done
[17:39:12.958] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C0.dat
[17:39:12.964] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C1.dat
[17:39:12.969] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C2.dat
[17:39:12.975] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C3.dat
[17:39:12.980] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C4.dat
[17:39:12.986] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C5.dat
[17:39:12.991] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C6.dat
[17:39:12.996] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C7.dat
[17:39:12.002] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C8.dat
[17:39:13.007] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C9.dat
[17:39:13.013] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C10.dat
[17:39:13.018] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C11.dat
[17:39:13.024] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C12.dat
[17:39:13.029] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C13.dat
[17:39:13.034] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C14.dat
[17:39:13.040] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//trimParameters35_C15.dat
[17:39:13.045] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-A-NR_FPIXTest-17C-FNAL-160518-1313_2016-05-18_13h13m_1463595192/000_FPIXTest_p17//defaultMaskFile.dat
[17:39:13.055] INFO: enter test to run
[17:39:37.802] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[17:39:37.802] INFO: running: xray
[17:39:37.803] INFO: ----------------------------------------------------------------------
[17:39:37.803] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[17:39:37.803] INFO: ----------------------------------------------------------------------
[17:39:38.765] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[17:39:48.926] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[17:40:18.324] INFO: Resuming triggers.
[17:40:28.491] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[17:40:57.445] INFO: Resuming triggers.
[17:41:07.610] INFO: run duration 30 seconds, buffer almost full (81%), pausing triggers.
[17:41:36.482] INFO: Resuming triggers.
[17:41:46.649] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[17:42:15.835] INFO: Resuming triggers.
[17:42:25.999] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[17:42:55.296] INFO: Resuming triggers.
[17:43:05.463] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[17:43:35.060] INFO: Resuming triggers.
[17:43:45.222] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[17:44:14.765] INFO: Resuming triggers.
[17:44:24.931] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[17:44:54.173] INFO: Resuming triggers.
[17:45:04.335] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[17:45:33.905] INFO: Resuming triggers.
[17:45:42.759] INFO: data taking finished, elapsed time: 100 seconds.
[17:46:08.743] INFO: PixTest:: pg_setup set to default.
[17:46:08.746] INFO: PixTestXray::doPhRun() done
[17:46:08.887] INFO: enter test to run
[17:46:27.719] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[17:46:27.719] INFO: running: xray
[17:46:27.721] INFO: ----------------------------------------------------------------------
[17:46:27.721] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[17:46:27.721] INFO: ----------------------------------------------------------------------
[17:46:28.684] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[17:46:34.168] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[17:47:04.280] INFO: Resuming triggers.
[17:47:09.770] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[17:47:39.922] INFO: Resuming triggers.
[17:47:45.410] INFO: run duration 16 seconds, buffer almost full (81%), pausing triggers.
[17:48:15.533] INFO: Resuming triggers.
[17:48:21.021] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[17:48:51.167] INFO: Resuming triggers.
[17:48:56.655] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[17:49:26.816] INFO: Resuming triggers.
[17:49:32.306] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[17:50:03.110] INFO: Resuming triggers.
[17:50:08.601] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[17:50:39.334] INFO: Resuming triggers.
[17:50:44.823] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[17:51:15.227] INFO: Resuming triggers.
[17:51:20.716] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[17:51:51.622] INFO: Resuming triggers.
[17:51:57.111] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[17:52:28.336] INFO: Resuming triggers.
[17:52:33.828] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[17:53:03.981] INFO: Resuming triggers.
[17:53:09.471] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[17:53:39.562] INFO: Resuming triggers.
[17:53:45.051] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[17:54:15.156] INFO: Resuming triggers.
[17:54:20.644] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[17:54:50.781] INFO: Resuming triggers.
[17:54:56.268] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[17:55:26.332] INFO: Resuming triggers.
[17:55:31.817] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[17:56:01.939] INFO: Resuming triggers.
[17:56:07.427] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[17:56:37.484] INFO: Resuming triggers.
[17:56:42.969] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[17:57:13.057] INFO: Resuming triggers.
[17:57:14.604] INFO: data taking finished, elapsed time: 100 seconds.
[17:57:23.373] INFO: PixTest:: pg_setup set to default.
[17:57:23.377] INFO: PixTestXray::doPhRun() done
[17:57:23.528] INFO: enter test to run
[17:57:52.882] INFO: test: HighRate no parameter change
[17:57:52.882] INFO: running: highrate
[17:57:52.884] INFO: ----------------------------------------------------------------------
[17:57:52.884] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[17:57:52.884] INFO: ----------------------------------------------------------------------
[17:57:53.034] INFO: Expecting 768 events.
[17:57:54.167] INFO: 768 events read in total (418ms).
[17:57:54.167] INFO: Test took 1276ms.
[17:57:54.970] INFO: Expecting 41600 events.
[17:57:58.221] INFO: 41600 events read in total (2724ms).
[17:57:58.222] INFO: Test took 4048ms.
[17:57:58.266] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:57:58.974] INFO: Expecting 41600 events.
[17:58:02.295] INFO: 41600 events read in total (2794ms).
[17:58:02.296] INFO: Test took 4010ms.
[17:58:02.340] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:03.039] INFO: Expecting 41600 events.
[17:58:06.377] INFO: 41600 events read in total (2811ms).
[17:58:06.378] INFO: Test took 4017ms.
[17:58:06.423] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:07.124] INFO: Expecting 41600 events.
[17:58:10.460] INFO: 41600 events read in total (2809ms).
[17:58:10.462] INFO: Test took 4017ms.
[17:58:10.506] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:11.212] INFO: Expecting 41600 events.
[17:58:14.540] INFO: 41600 events read in total (2801ms).
[17:58:14.541] INFO: Test took 4014ms.
[17:58:14.585] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:15.290] INFO: Expecting 41600 events.
[17:58:18.623] INFO: 41600 events read in total (2806ms).
[17:58:18.624] INFO: Test took 4018ms.
[17:58:18.667] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:19.375] INFO: Expecting 41600 events.
[17:58:22.727] INFO: 41600 events read in total (2825ms).
[17:58:22.729] INFO: Test took 4041ms.
[17:58:22.772] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:23.479] INFO: Expecting 41600 events.
[17:58:26.826] INFO: 41600 events read in total (2820ms).
[17:58:26.828] INFO: Test took 4033ms.
[17:58:26.872] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:27.575] INFO: Expecting 41600 events.
[17:58:30.859] INFO: 41600 events read in total (2757ms).
[17:58:30.860] INFO: Test took 3967ms.
[17:58:30.903] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:31.607] INFO: Expecting 41600 events.
[17:58:34.952] INFO: 41600 events read in total (2818ms).
[17:58:34.953] INFO: Test took 4027ms.
[17:58:34.997] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:35.702] INFO: Expecting 41600 events.
[17:58:39.045] INFO: 41600 events read in total (2816ms).
[17:58:39.046] INFO: Test took 4026ms.
[17:58:39.092] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:39.792] INFO: Expecting 41600 events.
[17:58:43.125] INFO: 41600 events read in total (2806ms).
[17:58:43.126] INFO: Test took 4013ms.
[17:58:43.171] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:43.876] INFO: Expecting 41600 events.
[17:58:47.215] INFO: 41600 events read in total (2812ms).
[17:58:47.216] INFO: Test took 4023ms.
[17:58:47.260] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:47.964] INFO: Expecting 41600 events.
[17:58:51.318] INFO: 41600 events read in total (2828ms).
[17:58:51.320] INFO: Test took 4037ms.
[17:58:51.364] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:52.066] INFO: Expecting 41600 events.
[17:58:55.412] INFO: 41600 events read in total (2819ms).
[17:58:55.413] INFO: Test took 4027ms.
[17:58:55.458] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:58:56.162] INFO: Expecting 41600 events.
[17:58:59.493] INFO: 41600 events read in total (2804ms).
[17:58:59.494] INFO: Test took 4014ms.
[17:58:59.539] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:00.243] INFO: Expecting 41600 events.
[17:59:03.607] INFO: 41600 events read in total (2837ms).
[17:59:03.608] INFO: Test took 4046ms.
[17:59:03.653] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:04.354] INFO: Expecting 41600 events.
[17:59:07.699] INFO: 41600 events read in total (2818ms).
[17:59:07.701] INFO: Test took 4025ms.
[17:59:07.744] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:08.448] INFO: Expecting 41600 events.
[17:59:11.753] INFO: 41600 events read in total (2778ms).
[17:59:11.754] INFO: Test took 3987ms.
[17:59:11.799] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:12.501] INFO: Expecting 41600 events.
[17:59:15.611] INFO: 41600 events read in total (2583ms).
[17:59:15.612] INFO: Test took 3790ms.
[17:59:15.655] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:15.996] INFO: enter test to run
[17:59:23.762] INFO: test: HighRate no parameter change
[17:59:23.762] INFO: running: highrate
[17:59:23.763] INFO: ----------------------------------------------------------------------
[17:59:23.763] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[17:59:23.763] INFO: ----------------------------------------------------------------------
[17:59:24.378] INFO: Expecting 208000 events.
[17:59:36.871] INFO: 208000 events read in total (11966ms).
[17:59:36.875] INFO: Test took 13104ms.
[17:59:37.071] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:59:37.340] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[17:59:37.340] INFO: number of red-efficiency pixels: 80 76 118 159 290 206 203 127 178 194 188 151 148 81 31 27
[17:59:37.340] INFO: number of X-ray hits detected: 84191 60935 90771 142450 154723 155600 154833 109396 112426 142152 139713 120420 131391 75823 28549 28893
[17:59:37.341] 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:59:37.341] INFO: number of Vcal hits detected: 207916 207923 207881 207826 207695 207785 207790 207869 207818 207804 207807 207832 207846 207916 207969 207973
[17:59:37.341] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 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 100.0
[17:59:37.341] INFO: Vcal hit overall efficiency (%): 100.0 100.0 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 100.0
[17:59:37.341] INFO: X-ray hit rate [MHz/cm2]: 24.7 17.9 26.6 41.8 45.4 45.6 45.4 32.1 33.0 41.7 41.0 35.3 38.5 22.2 8.4 8.5
[17:59:37.341] INFO: PixTestHighRate::doXPixelAlive() done
[17:59:37.390] INFO: PixTest:: pg_setup set to default.
[17:59:37.400] INFO: enter test to run
[18:00:03.490] INFO: test: HighRate no parameter change
[18:00:03.490] INFO: running: highrate
[18:00:03.491] INFO: ----------------------------------------------------------------------
[18:00:03.491] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:00:03.491] INFO: ----------------------------------------------------------------------
[18:00:04.104] INFO: Expecting 208000 events.
[18:00:19.171] INFO: 208000 events read in total (14540ms).
[18:00:19.178] INFO: Test took 15678ms.
[18:00:19.576] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:00:19.917] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[18:00:19.917] INFO: number of red-efficiency pixels: 274 238 383 670 1078 780 739 504 564 703 793 448 558 305 69 82
[18:00:19.917] INFO: number of X-ray hits detected: 173626 126314 191906 295446 321286 323363 321326 229941 234983 295241 291354 250098 272717 158432 59924 61109
[18:00:19.917] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:00:19.917] INFO: number of Vcal hits detected: 207684 207746 207574 207215 206661 207107 207136 207428 207345 207202 207067 207479 207379 207649 207931 207917
[18:00:19.917] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.6 99.4 99.6 99.6 99.7 99.7 99.6 99.6 99.8 99.7 99.8 100.0 100.0
[18:00:19.917] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.6 99.4 99.6 99.6 99.7 99.7 99.6 99.6 99.7 99.7 99.8 100.0 100.0
[18:00:19.918] INFO: X-ray hit rate [MHz/cm2]: 50.9 37.0 56.2 86.6 94.2 94.8 94.2 67.4 68.9 86.5 85.4 73.3 79.9 46.4 17.6 17.9
[18:00:19.918] INFO: PixTestHighRate::doXPixelAlive() done
[18:00:19.966] INFO: PixTest:: pg_setup set to default.
[18:00:19.983] INFO: enter test to run
[18:00:33.905] INFO: test: HighRate no parameter change
[18:00:33.906] INFO: running: highrate
[18:00:33.907] INFO: ----------------------------------------------------------------------
[18:00:33.907] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:00:33.907] INFO: ----------------------------------------------------------------------
[18:00:34.521] INFO: Expecting 208000 events.
[18:00:52.465] INFO: 208000 events read in total (17417ms).
[18:00:52.475] INFO: Test took 18558ms.
[18:00:53.103] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:00:53.508] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[18:00:53.508] INFO: number of red-efficiency pixels: 547 529 891 1446 2299 1799 1711 1040 1235 1538 1897 1088 1253 677 143 119
[18:00:53.508] INFO: number of X-ray hits detected: 259735 189465 286347 441131 479958 483717 480884 341573 350191 441097 434704 373638 407152 237788 89841 91727
[18:00:53.508] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:00:53.508] INFO: number of Vcal hits detected: 207332 207364 206673 205916 204141 205304 205471 206606 206229 205767 205047 206571 206328 207112 207850 207878
[18:00:53.508] INFO: Vcal hit fiducial efficiency (%): 99.7 99.7 99.4 99.1 98.3 98.8 98.9 99.4 99.3 99.0 98.7 99.4 99.3 99.6 99.9 99.9
[18:00:53.508] INFO: Vcal hit overall efficiency (%): 99.7 99.7 99.4 99.0 98.1 98.7 98.8 99.3 99.1 98.9 98.6 99.3 99.2 99.6 99.9 99.9
[18:00:53.508] INFO: X-ray hit rate [MHz/cm2]: 76.1 55.5 83.9 129.3 140.7 141.8 141.0 100.1 102.6 129.3 127.4 109.5 119.3 69.7 26.3 26.9
[18:00:53.508] INFO: PixTestHighRate::doXPixelAlive() done
[18:00:53.556] INFO: PixTest:: pg_setup set to default.
[18:00:53.573] INFO: enter test to run
[18:00:57.913] INFO: test: exit no parameter change
[18:00:58.310] QUIET: Connection to board 33 closed.
[18:00:58.310] INFO: pXar: this is the end, my friend