[09:29:04.608] INFO: *** Welcome to pxar ***
[09:29:04.608] INFO: *** Today: 2016/04/26
[09:29:04.630] INFO: *** Version: v1.9.0-796-gef167-dirty
[09:29:04.630] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//dacParameters35_C15.dat
[09:29:04.631] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:29:04.631] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//defaultMaskFile.dat
[09:29:04.631] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C15.dat
[09:29:04.700] INFO: clk: 4
[09:29:04.700] INFO: ctr: 4
[09:29:04.700] INFO: sda: 19
[09:29:04.700] INFO: tin: 9
[09:29:04.700] INFO: level: 15
[09:29:04.700] INFO: triggerdelay: 0
[09:29:04.700] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[09:29:04.700] INFO: Log level: INFO
[09:29:04.718] QUIET: Connection to board DTB_WREKRL opened.
[09:29:04.721] 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:
------------------------------------------------------
[09:29:04.724] INFO: RPC call hashes of host and DTB match: 398089610
[09:29:06.257] INFO: DUT info:
[09:29:06.257] INFO: The DUT currently contains the following objects:
[09:29:06.257] INFO: 2 TBM Cores tbm08c (2 ON)
[09:29:06.257] INFO: TBM Core alpha (0): 7 registers set
[09:29:06.257] INFO: TBM Core beta (1): 7 registers set
[09:29:06.257] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[09:29:06.257] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.257] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[09:29:06.660] INFO: enter 'restricted' command line mode
[09:29:06.660] INFO: enter test to run
[09:29:08.565] INFO: test: timing no parameter change
[09:29:08.565] INFO: running: timing
[09:29:08.573] INFO: ######################################################################
[09:29:08.574] INFO: PixTestTiming::doTest()
[09:29:08.574] INFO: ######################################################################
[09:29:08.574] INFO: ----------------------------------------------------------------------
[09:29:08.574] INFO: PixTestTiming::TBMPhaseScan()
[09:29:08.574] INFO: ----------------------------------------------------------------------
[09:35:11.049] INFO: TBM Phase Settings: 236
[09:35:11.049] INFO: 400MHz Phase: 3
[09:35:11.049] INFO: 160MHz Phase: 7
[09:35:11.049] INFO: Functional Phase Area: 4
[09:35:11.072] INFO: Test took 362498 ms.
[09:35:11.072] INFO: PixTestTiming::TBMPhaseScan() done.
[09:35:11.072] INFO: ----------------------------------------------------------------------
[09:35:11.073] INFO: PixTestTiming::ROCDelayScan()
[09:35:11.073] INFO: ----------------------------------------------------------------------
[09:38:44.634] INFO: ROC Delay Settings: 227
[09:38:44.635] INFO: ROC Header-Trailer/Token Delay: 11
[09:38:44.635] INFO: ROC Port 0 Delay: 3
[09:38:44.635] INFO: ROC Port 1 Delay: 4
[09:38:44.635] INFO: Functional ROC Area: 4
[09:38:44.638] INFO: Test took 213566 ms.
[09:38:44.638] INFO: PixTestTiming::ROCDelayScan() done.
[09:38:44.638] INFO: ----------------------------------------------------------------------
[09:38:44.638] INFO: PixTestTiming::TimingTest()
[09:38:44.638] INFO: ----------------------------------------------------------------------
[09:39:00.808] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:39:15.779] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:39:30.730] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:39:45.710] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:40:00.670] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:40:15.638] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:40:30.587] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:40:45.578] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:41:00.564] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:41:15.550] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:41:15.928] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:41:15.946] INFO: ----------------------------------------------------------------------
[09:41:15.946] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[09:41:15.946] INFO: ----------------------------------------------------------------------
[09:41:15.946] INFO: ----------------------------------------------------------------------
[09:41:15.946] INFO: Read back bit status: 1
[09:41:15.946] INFO: ----------------------------------------------------------------------
[09:41:15.946] INFO: ----------------------------------------------------------------------
[09:41:15.946] INFO: Timings are good!
[09:41:15.946] INFO: ----------------------------------------------------------------------
[09:41:15.946] INFO: Test took 151308 ms.
[09:41:15.946] INFO: PixTestTiming::TimingTest() done.
[09:41:15.946] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//tbmParameters_C0a.dat
[09:41:15.947] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:41:15.947] INFO: PixTestTiming::doTest took 727378 ms.
[09:41:15.947] INFO: PixTestTiming::doTest() done
[09:41:15.947] INFO: Write out TBMPhaseScan_0_V0
[09:41:15.973] INFO: Write out TBMPhaseScan_1_V0
[09:41:15.974] INFO: Write out CombinedTBMPhaseScan_V0
[09:41:15.974] INFO: Write out ROCDelayScan3_V0
[09:41:15.975] INFO: enter test to run
[09:41:34.015] INFO: test: PixelAlive no parameter change
[09:41:34.015] INFO: running: pixelalive
[09:41:34.019] INFO: ----------------------------------------------------------------------
[09:41:34.019] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[09:41:34.019] INFO: ----------------------------------------------------------------------
[09:41:34.334] INFO: Expecting 41600 events.
[09:41:38.289] INFO: 41600 events read in total (3239ms).
[09:41:38.290] INFO: Test took 4269ms.
[09:41:38.296] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:41:38.698] INFO: PixTestAlive::aliveTest() done
[09:41:38.698] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[09:41:38.701] INFO: enter test to run
[09:42:21.135] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[09:42:21.135] INFO: running: highrate
[09:42:21.136] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[09:42:21.365] INFO: ----------------------------------------------------------------------
[09:42:21.365] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[09:42:21.365] INFO: ----------------------------------------------------------------------
[09:42:21.365] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[09:42:21.365] INFO: edge/corner pixel THR is adjusted
[09:42:21.365] INFO: PixTestHighRate::trimHotPixels: step 0...
[09:42:22.324] INFO: Collecting data for 5 seconds...
[09:42:27.340] INFO: Done with hot pixel readout
[09:42:39.633] INFO: PixTest:: pg_setup set to default.
[09:42:39.634] INFO: 14 hot pixels found in step 0
[09:42:40.633] INFO: Collecting data for 5 seconds...
[09:42:45.649] INFO: Done with hot pixel readout
[09:42:57.978] INFO: PixTest:: pg_setup set to default.
[09:42:57.979] INFO: 13 hot pixels found in step 1
[09:42:58.978] INFO: Collecting data for 5 seconds...
[09:43:03.995] INFO: Done with hot pixel readout
[09:43:16.329] INFO: PixTest:: pg_setup set to default.
[09:43:16.330] INFO: 13 hot pixels found in step 2
[09:43:17.329] INFO: Collecting data for 5 seconds...
[09:43:22.345] INFO: Done with hot pixel readout
[09:43:34.688] INFO: PixTest:: pg_setup set to default.
[09:43:34.689] INFO: 16 hot pixels found in step 3
[09:43:35.689] INFO: Collecting data for 5 seconds...
[09:43:40.706] INFO: Done with hot pixel readout
[09:43:53.059] INFO: PixTest:: pg_setup set to default.
[09:43:53.060] INFO: 9 hot pixels found in step 4
[09:43:54.060] INFO: Collecting data for 5 seconds...
[09:43:59.077] INFO: Done with hot pixel readout
[09:44:11.408] INFO: PixTest:: pg_setup set to default.
[09:44:11.409] INFO: 8 hot pixels found in step 5
[09:44:12.409] INFO: Collecting data for 5 seconds...
[09:44:17.424] INFO: Done with hot pixel readout
[09:44:29.578] INFO: PixTest:: pg_setup set to default.

[09:44:29.579] INFO: 11 hot pixels found in step 6
[09:44:30.579] INFO: Collecting data for 5 seconds...
[09:44:35.595] INFO: Done with hot pixel readout
[09:44:47.962] INFO: PixTest:: pg_setup set to default.

[09:44:47.963] INFO: 7 hot pixels found in step 7
[09:44:48.963] INFO: Collecting data for 5 seconds...
[09:44:53.978] INFO: Done with hot pixel readout
[09:45:06.308] INFO: PixTest:: pg_setup set to default.

[09:45:06.309] INFO: 6 hot pixels found in step 8
[09:45:07.309] INFO: Collecting data for 5 seconds...
[09:45:12.325] INFO: Done with hot pixel readout
[09:45:24.641] INFO: PixTest:: pg_setup set to default.

[09:45:24.642] INFO: 4 hot pixels found in step 9
[09:45:25.642] INFO: Collecting data for 5 seconds...
[09:45:30.659] INFO: Done with hot pixel readout
[09:45:42.943] INFO: PixTest:: pg_setup set to default.
[09:45:42.944] INFO: 4 hot pixels found in step 10
[09:45:43.945] INFO: Collecting data for 5 seconds...
[09:45:48.962] INFO: Done with hot pixel readout
[09:46:01.306] INFO: PixTest:: pg_setup set to default.
[09:46:01.307] INFO: 4 hot pixels found in step 11
[09:46:02.306] INFO: Collecting data for 5 seconds...
[09:46:07.322] INFO: Done with hot pixel readout
[09:46:19.717] INFO: PixTest:: pg_setup set to default.

[09:46:19.718] INFO: 6 hot pixels found in step 12
[09:46:20.718] INFO: Collecting data for 5 seconds...
[09:46:25.733] INFO: Done with hot pixel readout
[09:46:38.085] INFO: PixTest:: pg_setup set to default.
[09:46:38.085] INFO: 4 hot pixels found in step 13
[09:46:39.086] INFO: Collecting data for 5 seconds...
[09:46:44.102] INFO: Done with hot pixel readout
[09:46:56.409] INFO: PixTest:: pg_setup set to default.

[09:46:56.410] INFO: 2 hot pixels found in step 14
[09:46:56.453] INFO: 2 hot pixels could not be trimmed and have been masked.
[09:46:56.457] INFO: PixTest::trimHotPixels() done
[09:46:56.457] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C0.dat
[09:46:56.463] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C1.dat
[09:46:56.469] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C2.dat
[09:46:56.474] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C3.dat
[09:46:56.479] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C4.dat
[09:46:56.484] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C5.dat
[09:46:56.490] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C6.dat
[09:46:56.495] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C7.dat
[09:46:56.501] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C8.dat
[09:46:56.506] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C9.dat
[09:46:56.511] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C10.dat
[09:46:56.517] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C11.dat
[09:46:56.522] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C12.dat
[09:46:56.527] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C13.dat
[09:46:56.533] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C14.dat
[09:46:56.538] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C15.dat
[09:46:56.544] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//defaultMaskFile.dat
[09:46:56.554] INFO: enter test to run
[09:47:37.293] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[09:47:37.293] INFO: running: highrate
[09:47:37.297] INFO: ----------------------------------------------------------------------
[09:47:37.297] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[09:47:37.297] INFO: ----------------------------------------------------------------------
[09:47:37.297] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[09:47:37.297] INFO: edge/corner pixel THR is adjusted
[09:47:37.297] INFO: PixTestHighRate::trimHotPixels: step 0...
[09:47:38.255] INFO: Collecting data for 1 seconds...
[09:47:39.258] INFO: Done with hot pixel readout
[09:47:43.682] INFO: PixTest:: pg_setup set to default.
[09:47:43.683] INFO: 0 hot pixels found in step 0
[09:47:43.688] INFO: 0 hot pixels could not be trimmed and have been masked.
[09:47:43.763] INFO: PixTest::trimHotPixels() done
[09:47:43.764] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C0.dat
[09:47:43.772] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C1.dat
[09:47:43.778] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C2.dat
[09:47:43.783] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C3.dat
[09:47:43.788] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C4.dat
[09:47:43.794] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C5.dat
[09:47:43.799] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C6.dat
[09:47:43.804] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C7.dat
[09:47:43.809] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C8.dat
[09:47:43.815] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C9.dat
[09:47:43.820] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C10.dat
[09:47:43.825] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C11.dat
[09:47:43.831] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C12.dat
[09:47:43.836] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C13.dat
[09:47:43.841] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C14.dat
[09:47:43.846] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//trimParameters35_C15.dat
[09:47:43.852] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-M-NG_FPIXTest-17C-FNAL-160421-1341_2016-04-21_13h41m_1461264105/000_FPIXTest_p17//defaultMaskFile.dat
[09:47:43.867] INFO: enter test to run
[09:48:06.988] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[09:48:06.988] INFO: running: xray
[09:48:06.989] INFO: ----------------------------------------------------------------------
[09:48:06.989] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[09:48:06.990] INFO: ----------------------------------------------------------------------
[09:48:07.972] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[09:48:18.552] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[09:48:47.435] INFO: Resuming triggers.
[09:48:58.125] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[09:49:27.589] INFO: Resuming triggers.
[09:49:38.171] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[09:50:07.583] INFO: Resuming triggers.
[09:50:18.163] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[09:50:47.641] INFO: Resuming triggers.
[09:50:58.222] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[09:51:27.698] INFO: Resuming triggers.
[09:51:38.278] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[09:52:02.345] INFO: Resuming triggers.
[09:52:12.930] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[09:52:42.338] INFO: Resuming triggers.
[09:52:52.919] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[09:53:22.270] INFO: Resuming triggers.
[09:53:32.851] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[09:54:02.315] INFO: Resuming triggers.
[09:54:07.416] INFO: data taking finished, elapsed time: 100 seconds.
[09:54:21.889] INFO: PixTest:: pg_setup set to default.
[09:54:21.892] INFO: PixTestXray::doPhRun() done
[09:54:22.030] INFO: enter test to run
[09:55:07.585] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[09:55:07.585] INFO: running: xray
[09:55:07.586] INFO: ----------------------------------------------------------------------
[09:55:07.587] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[09:55:07.587] INFO: ----------------------------------------------------------------------
[09:55:08.550] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[09:55:14.370] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[09:55:44.421] INFO: Resuming triggers.
[09:55:50.237] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[09:56:20.328] INFO: Resuming triggers.
[09:56:26.146] INFO: run duration 17 seconds, buffer almost full (81%), pausing triggers.
[09:56:56.153] INFO: Resuming triggers.
[09:57:01.972] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[09:57:31.986] INFO: Resuming triggers.
[09:57:37.801] INFO: run duration 28 seconds, buffer almost full (81%), pausing triggers.
[09:58:07.806] INFO: Resuming triggers.
[09:58:13.624] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[09:58:43.687] INFO: Resuming triggers.
[09:58:49.505] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[09:59:19.530] INFO: Resuming triggers.
[09:59:25.344] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[09:59:55.442] INFO: Resuming triggers.
[10:00:01.254] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[10:00:31.308] INFO: Resuming triggers.
[10:00:37.124] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[10:01:07.156] INFO: Resuming triggers.
[10:01:12.971] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[10:01:43.071] INFO: Resuming triggers.
[10:01:48.881] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[10:02:15.774] INFO: Resuming triggers.
[10:02:21.587] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[10:02:51.606] INFO: Resuming triggers.
[10:02:57.417] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[10:03:27.520] INFO: Resuming triggers.
[10:03:33.332] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[10:04:03.340] INFO: Resuming triggers.
[10:04:09.156] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[10:04:39.195] INFO: Resuming triggers.
[10:04:45.005] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[10:05:15.114] INFO: Resuming triggers.
[10:05:16.573] INFO: data taking finished, elapsed time: 100 seconds.
[10:05:24.400] INFO: PixTest:: pg_setup set to default.
[10:05:24.403] INFO: PixTestXray::doPhRun() done
[10:05:24.556] INFO: enter test to run
[10:06:07.260] INFO: test: HighRate no parameter change
[10:06:07.260] INFO: running: highrate
[10:06:07.261] INFO: ----------------------------------------------------------------------
[10:06:07.262] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[10:06:07.262] INFO: ----------------------------------------------------------------------
[10:06:07.402] INFO: Expecting 768 events.
[10:06:08.536] INFO: 768 events read in total (419ms).
[10:06:08.536] INFO: Test took 1268ms.
[10:06:09.339] INFO: Expecting 41600 events.
[10:06:12.537] INFO: 41600 events read in total (2671ms).
[10:06:12.538] INFO: Test took 3994ms.
[10:06:12.577] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:13.295] INFO: Expecting 41600 events.
[10:06:16.566] INFO: 41600 events read in total (2744ms).
[10:06:16.567] INFO: Test took 3971ms.
[10:06:16.607] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:17.320] INFO: Expecting 41600 events.
[10:06:20.602] INFO: 41600 events read in total (2755ms).
[10:06:20.603] INFO: Test took 3975ms.
[10:06:20.643] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:21.358] INFO: Expecting 41600 events.
[10:06:24.656] INFO: 41600 events read in total (2771ms).
[10:06:24.657] INFO: Test took 3992ms.
[10:06:24.698] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:25.409] INFO: Expecting 41600 events.
[10:06:28.689] INFO: 41600 events read in total (2753ms).
[10:06:28.690] INFO: Test took 3971ms.
[10:06:28.731] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:29.442] INFO: Expecting 41600 events.
[10:06:32.735] INFO: 41600 events read in total (2766ms).
[10:06:32.737] INFO: Test took 3985ms.
[10:06:32.777] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:33.491] INFO: Expecting 41600 events.
[10:06:36.801] INFO: 41600 events read in total (2783ms).
[10:06:36.802] INFO: Test took 4005ms.
[10:06:36.843] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:37.553] INFO: Expecting 41600 events.
[10:06:40.843] INFO: 41600 events read in total (2763ms).
[10:06:40.844] INFO: Test took 3982ms.
[10:06:40.885] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:41.595] INFO: Expecting 41600 events.
[10:06:44.886] INFO: 41600 events read in total (2764ms).
[10:06:44.887] INFO: Test took 3982ms.
[10:06:44.928] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:45.637] INFO: Expecting 41600 events.
[10:06:48.955] INFO: 41600 events read in total (2791ms).
[10:06:48.956] INFO: Test took 4007ms.
[10:06:48.997] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:49.706] INFO: Expecting 41600 events.
[10:06:53.002] INFO: 41600 events read in total (2769ms).
[10:06:53.003] INFO: Test took 3985ms.
[10:06:53.042] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:53.758] INFO: Expecting 41600 events.
[10:06:57.048] INFO: 41600 events read in total (2764ms).
[10:06:57.049] INFO: Test took 3986ms.
[10:06:57.089] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:06:57.805] INFO: Expecting 41600 events.
[10:07:01.115] INFO: 41600 events read in total (2784ms).
[10:07:01.116] INFO: Test took 4006ms.
[10:07:01.156] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:01.870] INFO: Expecting 41600 events.
[10:07:05.168] INFO: 41600 events read in total (2771ms).
[10:07:05.169] INFO: Test took 3992ms.
[10:07:05.209] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:05.920] INFO: Expecting 41600 events.
[10:07:09.215] INFO: 41600 events read in total (2768ms).
[10:07:09.216] INFO: Test took 3987ms.
[10:07:09.257] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:09.968] INFO: Expecting 41600 events.
[10:07:13.269] INFO: 41600 events read in total (2774ms).
[10:07:13.270] INFO: Test took 3993ms.
[10:07:13.309] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:14.023] INFO: Expecting 41600 events.
[10:07:17.335] INFO: 41600 events read in total (2785ms).
[10:07:17.336] INFO: Test took 4006ms.
[10:07:17.375] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:18.086] INFO: Expecting 41600 events.
[10:07:21.384] INFO: 41600 events read in total (2771ms).
[10:07:21.385] INFO: Test took 3988ms.
[10:07:21.425] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:22.140] INFO: Expecting 41600 events.
[10:07:25.399] INFO: 41600 events read in total (2732ms).
[10:07:25.400] INFO: Test took 3953ms.
[10:07:25.440] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:26.152] INFO: Expecting 41600 events.
[10:07:29.271] INFO: 41600 events read in total (2592ms).
[10:07:29.272] INFO: Test took 3812ms.
[10:07:29.311] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:29.666] INFO: enter test to run
[10:07:36.404] INFO: test: HighRate no parameter change
[10:07:36.404] INFO: running: highrate
[10:07:36.405] INFO: ----------------------------------------------------------------------
[10:07:36.405] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:07:36.405] INFO: ----------------------------------------------------------------------
[10:07:37.019] INFO: Expecting 208000 events.
[10:07:49.189] INFO: 208000 events read in total (11643ms).
[10:07:49.193] INFO: Test took 12782ms.
[10:07:49.367] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:07:49.629] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:07:49.629] INFO: number of red-efficiency pixels: 89 51 95 137 198 135 160 95 102 180 171 145 177 111 22 32
[10:07:49.629] INFO: number of X-ray hits detected: 82199 52050 76527 117936 127597 127422 131968 92140 102747 133005 134571 113144 120891 73998 27269 28147
[10:07:49.629] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:07:49.629] INFO: number of Vcal hits detected: 207911 207949 207902 207862 207796 207861 207835 207902 207898 207815 207823 207853 207819 207886 207978 207966
[10:07:49.629] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[10:07:49.629] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[10:07:49.629] INFO: X-ray hit rate [MHz/cm2]: 24.1 15.3 22.4 34.6 37.4 37.3 38.7 27.0 30.1 39.0 39.4 33.2 35.4 21.7 8.0 8.3
[10:07:49.629] INFO: PixTestHighRate::doXPixelAlive() done
[10:07:49.676] INFO: PixTest:: pg_setup set to default.
[10:07:49.689] INFO: enter test to run
[10:08:24.323] INFO: test: HighRate no parameter change
[10:08:24.323] INFO: running: highrate
[10:08:24.325] INFO: ----------------------------------------------------------------------
[10:08:24.325] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:08:24.325] INFO: ----------------------------------------------------------------------
[10:08:24.943] INFO: Expecting 208000 events.
[10:08:39.277] INFO: 208000 events read in total (13807ms).
[10:08:39.284] INFO: Test took 14951ms.
[10:08:39.639] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:08:39.959] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:08:39.959] INFO: number of red-efficiency pixels: 326 155 272 487 645 498 497 323 339 536 558 441 662 257 56 55
[10:08:39.959] INFO: number of X-ray hits detected: 167589 107009 157740 242023 261995 260419 269999 189242 210965 273221 276617 233618 248461 152361 55758 58995
[10:08:39.959] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:08:39.959] INFO: number of Vcal hits detected: 207645 207834 207703 207462 207263 207464 207456 207648 207634 207401 207369 207523 207249 207715 207944 207943
[10:08:39.959] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.9 99.8 99.7 99.8 99.8 99.8 99.8 99.7 99.7 99.8 99.7 99.9 100.0 100.0
[10:08:39.959] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.9 99.7 99.6 99.7 99.7 99.8 99.8 99.7 99.7 99.8 99.6 99.9 100.0 100.0
[10:08:39.959] INFO: X-ray hit rate [MHz/cm2]: 49.1 31.4 46.2 70.9 76.8 76.3 79.1 55.5 61.8 80.1 81.1 68.5 72.8 44.7 16.3 17.3
[10:08:39.959] INFO: PixTestHighRate::doXPixelAlive() done
[10:08:40.004] INFO: PixTest:: pg_setup set to default.
[10:08:40.018] INFO: enter test to run
[10:09:06.763] INFO: test: HighRate no parameter change
[10:09:06.763] INFO: running: highrate
[10:09:06.764] INFO: ----------------------------------------------------------------------
[10:09:06.764] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:09:06.764] INFO: ----------------------------------------------------------------------
[10:09:07.379] INFO: Expecting 208000 events.
[10:09:24.477] INFO: 208000 events read in total (16572ms).
[10:09:24.486] INFO: Test took 17713ms.
[10:09:25.058] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:09:25.442] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:09:25.442] INFO: number of red-efficiency pixels: 746 342 631 1108 1697 1272 1282 718 808 1353 1434 1075 1523 647 131 120
[10:09:25.442] INFO: number of X-ray hits detected: 258428 165140 242922 371826 401775 400698 415759 291636 323928 418557 422887 359065 382451 234401 86129 90648
[10:09:25.442] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:09:25.442] INFO: number of Vcal hits detected: 206974 207626 207187 206589 205602 206288 206289 207129 207002 206185 206045 206646 205879 207144 207863 207873
[10:09:25.442] INFO: Vcal hit fiducial efficiency (%): 99.6 99.8 99.7 99.4 99.0 99.2 99.3 99.6 99.6 99.2 99.1 99.4 99.1 99.6 99.9 99.9
[10:09:25.442] INFO: Vcal hit overall efficiency (%): 99.5 99.8 99.6 99.3 98.8 99.2 99.2 99.6 99.5 99.1 99.1 99.3 99.0 99.6 99.9 99.9
[10:09:25.442] INFO: X-ray hit rate [MHz/cm2]: 75.7 48.4 71.2 109.0 117.8 117.4 121.9 85.5 94.9 122.7 124.0 105.2 112.1 68.7 25.2 26.6
[10:09:25.442] INFO: PixTestHighRate::doXPixelAlive() done
[10:09:25.488] INFO: PixTest:: pg_setup set to default.
[10:09:25.501] INFO: enter test to run
[10:09:33.963] INFO: test: exit no parameter change
[10:09:34.338] QUIET: Connection to board 33 closed.
[10:09:34.339] INFO: pXar: this is the end, my friend