[12:07:59.400] INFO: *** Welcome to pxar ***
[12:07:59.400] INFO: *** Today: 2016/05/05
[12:07:59.417] INFO: *** Version: v1.9.0-796-gef167-dirty
[12:07:59.417] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//dacParameters35_C15.dat
[12:07:59.452] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:07:59.453] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//defaultMaskFile.dat
[12:07:59.457] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C15.dat
[12:07:59.553] INFO: clk: 4
[12:07:59.553] INFO: ctr: 4
[12:07:59.553] INFO: sda: 19
[12:07:59.553] INFO: tin: 9
[12:07:59.553] INFO: level: 15
[12:07:59.553] INFO: triggerdelay: 0
[12:07:59.553] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[12:07:59.553] INFO: Log level: INFO
[12:07:59.568] QUIET: Connection to board DTB_WREK4U opened.
[12:07:59.571] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 32
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREK4U
MAC address: 40D855118020
Hostname: pixelDTB032
Comment:
------------------------------------------------------
[12:07:59.574] INFO: RPC call hashes of host and DTB match: 398089610
[12:08:01.115] INFO: DUT info:
[12:08:01.115] INFO: The DUT currently contains the following objects:
[12:08:01.115] INFO: 2 TBM Cores tbm08c (2 ON)
[12:08:01.115] INFO: TBM Core alpha (0): 7 registers set
[12:08:01.115] INFO: TBM Core beta (1): 7 registers set
[12:08:01.115] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:08:01.115] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.115] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.116] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:08:01.519] INFO: enter 'restricted' command line mode
[12:08:01.519] INFO: enter test to run
[12:08:12.241] INFO: test: timing no parameter change
[12:08:12.241] INFO: running: timing
[12:08:12.250] INFO: ######################################################################
[12:08:12.250] INFO: PixTestTiming::doTest()
[12:08:12.250] INFO: ######################################################################
[12:08:12.250] INFO: ----------------------------------------------------------------------
[12:08:12.250] INFO: PixTestTiming::TBMPhaseScan()
[12:08:12.250] INFO: ----------------------------------------------------------------------
[12:14:18.571] INFO: TBM Phase Settings: 248
[12:14:18.571] INFO: 400MHz Phase: 6
[12:14:18.571] INFO: 160MHz Phase: 7
[12:14:18.571] INFO: Functional Phase Area: 3
[12:14:18.574] INFO: Test took 366324 ms.
[12:14:18.574] INFO: PixTestTiming::TBMPhaseScan() done.
[12:14:18.575] INFO: ----------------------------------------------------------------------
[12:14:18.575] INFO: PixTestTiming::ROCDelayScan()
[12:14:18.575] INFO: ----------------------------------------------------------------------
[12:16:17.047] INFO: ROC Delay Settings: 228
[12:16:17.047] INFO: ROC Header-Trailer/Token Delay: 11
[12:16:17.047] INFO: ROC Port 0 Delay: 4
[12:16:17.047] INFO: ROC Port 1 Delay: 4
[12:16:17.047] INFO: Functional ROC Area: 4
[12:16:17.051] INFO: Test took 118476 ms.
[12:16:17.051] INFO: PixTestTiming::ROCDelayScan() done.
[12:16:17.051] INFO: ----------------------------------------------------------------------
[12:16:17.051] INFO: PixTestTiming::TimingTest()
[12:16:17.051] INFO: ----------------------------------------------------------------------
[12:16:33.228] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:16:48.237] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:03.222] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:18.199] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:33.185] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:48.163] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:03.126] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:18.136] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:33.135] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:48.388] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:48.766] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:48.784] INFO: ----------------------------------------------------------------------
[12:18:48.784] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:18:48.784] INFO: ----------------------------------------------------------------------
[12:18:48.784] INFO: ----------------------------------------------------------------------
[12:18:48.784] INFO: Read back bit status: 1
[12:18:48.784] INFO: ----------------------------------------------------------------------
[12:18:48.784] INFO: ----------------------------------------------------------------------
[12:18:48.784] INFO: Timings are good!
[12:18:48.784] INFO: ----------------------------------------------------------------------
[12:18:48.784] INFO: Test took 151733 ms.
[12:18:48.784] INFO: PixTestTiming::TimingTest() done.
[12:18:48.798] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:18:48.798] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:18:48.798] INFO: PixTestTiming::doTest took 636553 ms.
[12:18:48.798] INFO: PixTestTiming::doTest() done
[12:18:48.799] INFO: Write out TBMPhaseScan_0_V0
[12:18:48.835] INFO: Write out TBMPhaseScan_1_V0
[12:18:48.835] INFO: Write out CombinedTBMPhaseScan_V0
[12:18:48.852] INFO: Write out ROCDelayScan3_V0
[12:18:48.853] INFO: enter test to run
[12:18:58.460] INFO: test: PixelAlive no parameter change
[12:18:58.460] INFO: running: pixelalive
[12:18:58.464] INFO: ----------------------------------------------------------------------
[12:18:58.464] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[12:18:58.464] INFO: ----------------------------------------------------------------------
[12:18:58.803] INFO: Expecting 41600 events.
[12:19:03.195] INFO: 41600 events read in total (3677ms).
[12:19:03.195] INFO: Test took 4728ms.
[12:19:03.202] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:19:03.600] INFO: PixTestAlive::aliveTest() done
[12:19:03.600] INFO: number of dead pixels (per ROC): 1 0 0 0 0 80 0 0 0 0 0 0 0 0 0 1
[12:19:03.603] INFO: enter test to run
[12:20:25.267] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:20:25.267] INFO: running: highrate
[12:20:25.267] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:20:25.490] INFO: ----------------------------------------------------------------------
[12:20:25.490] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:20:25.490] INFO: ----------------------------------------------------------------------
[12:20:25.490] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:20:25.490] INFO: edge/corner pixel THR is adjusted
[12:20:25.490] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:20:26.447] INFO: Collecting data for 5 seconds...
[12:20:31.467] INFO: Done with hot pixel readout
[12:20:43.658] INFO: PixTest:: pg_setup set to default.
[12:20:43.659] INFO: 26 hot pixels found in step 0
[12:20:44.655] INFO: Collecting data for 5 seconds...
[12:20:49.672] INFO: Done with hot pixel readout
[12:21:01.770] INFO: PixTest:: pg_setup set to default.
[12:21:01.770] INFO: 18 hot pixels found in step 1
[12:21:02.766] INFO: Collecting data for 5 seconds...
[12:21:07.782] INFO: Done with hot pixel readout
[12:21:19.924] INFO: PixTest:: pg_setup set to default.
[12:21:19.925] INFO: 18 hot pixels found in step 2
[12:21:20.921] INFO: Collecting data for 5 seconds...
[12:21:25.937] INFO: Done with hot pixel readout
[12:21:38.097] INFO: PixTest:: pg_setup set to default.
[12:21:38.098] INFO: 14 hot pixels found in step 3
[12:21:39.093] INFO: Collecting data for 5 seconds...
[12:21:44.110] INFO: Done with hot pixel readout
[12:21:56.254] INFO: PixTest:: pg_setup set to default.
[12:21:56.255] INFO: 7 hot pixels found in step 4
[12:21:57.250] INFO: Collecting data for 5 seconds...
[12:22:02.267] INFO: Done with hot pixel readout
[12:22:14.392] INFO: PixTest:: pg_setup set to default.

[12:22:14.393] INFO: 7 hot pixels found in step 5
[12:22:15.389] INFO: Collecting data for 5 seconds...
[12:22:20.405] INFO: Done with hot pixel readout
[12:22:32.724] INFO: PixTest:: pg_setup set to default.


[12:22:32.725] INFO: 14 hot pixels found in step 6
[12:22:33.721] INFO: Collecting data for 5 seconds...
[12:22:38.737] INFO: Done with hot pixel readout
[12:22:50.765] INFO: PixTest:: pg_setup set to default.



[12:22:50.766] INFO: 16 hot pixels found in step 7
[12:22:51.762] INFO: Collecting data for 5 seconds...
[12:22:56.780] INFO: Done with hot pixel readout
[12:23:08.670] INFO: PixTest:: pg_setup set to default.

[12:23:08.671] INFO: 12 hot pixels found in step 8
[12:23:09.668] INFO: Collecting data for 5 seconds...
[12:23:14.685] INFO: Done with hot pixel readout
[12:23:26.772] INFO: PixTest:: pg_setup set to default.

[12:23:26.773] INFO: 8 hot pixels found in step 9
[12:23:27.769] INFO: Collecting data for 5 seconds...
[12:23:32.785] INFO: Done with hot pixel readout
[12:23:44.814] INFO: PixTest:: pg_setup set to default.

[12:23:44.815] INFO: 6 hot pixels found in step 10
[12:23:45.811] INFO: Collecting data for 5 seconds...
[12:23:50.828] INFO: Done with hot pixel readout
[12:24:02.906] INFO: PixTest:: pg_setup set to default.

[12:24:02.907] INFO: 9 hot pixels found in step 11
[12:24:03.904] INFO: Collecting data for 5 seconds...
[12:24:08.921] INFO: Done with hot pixel readout
[12:24:21.040] INFO: PixTest:: pg_setup set to default.
[12:24:21.041] INFO: 2 hot pixels found in step 12
[12:24:22.037] INFO: Collecting data for 5 seconds...
[12:24:27.053] INFO: Done with hot pixel readout
[12:24:39.123] INFO: PixTest:: pg_setup set to default.

[12:24:39.124] INFO: 11 hot pixels found in step 13
[12:24:40.120] INFO: Collecting data for 5 seconds...
[12:24:45.137] INFO: Done with hot pixel readout
[12:24:57.255] INFO: PixTest:: pg_setup set to default.

[12:24:57.255] INFO: 5 hot pixels found in step 14
[12:24:57.295] INFO: 5 hot pixels could not be trimmed and have been masked.
[12:24:57.298] INFO: PixTest::trimHotPixels() done
[12:24:57.299] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C0.dat
[12:24:57.304] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C1.dat
[12:24:57.311] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C2.dat
[12:24:57.316] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C3.dat
[12:24:57.322] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C4.dat
[12:24:57.327] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C5.dat
[12:24:57.332] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C6.dat
[12:24:57.338] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C7.dat
[12:24:57.343] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C8.dat
[12:24:57.348] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C9.dat
[12:24:57.354] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C10.dat
[12:24:57.359] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C11.dat
[12:24:57.364] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C12.dat
[12:24:57.370] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C13.dat
[12:24:57.375] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C14.dat
[12:24:57.380] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C15.dat
[12:24:57.385] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//defaultMaskFile.dat
[12:24:57.395] INFO: enter test to run
[12:25:40.137] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:25:40.137] INFO: running: highrate
[12:25:40.141] INFO: ----------------------------------------------------------------------
[12:25:40.141] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:25:40.141] INFO: ----------------------------------------------------------------------
[12:25:40.141] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:25:40.141] INFO: edge/corner pixel THR is adjusted
[12:25:40.141] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:25:41.100] INFO: Collecting data for 1 seconds...
[12:25:42.104] INFO: Done with hot pixel readout
[12:25:46.355] INFO: PixTest:: pg_setup set to default.
[12:25:46.356] INFO: 0 hot pixels found in step 0
[12:25:46.361] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:25:46.441] INFO: PixTest::trimHotPixels() done
[12:25:46.441] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C0.dat
[12:25:46.452] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C1.dat
[12:25:46.458] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C2.dat
[12:25:46.463] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C3.dat
[12:25:46.468] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C4.dat
[12:25:46.474] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C5.dat
[12:25:46.479] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C6.dat
[12:25:46.484] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C7.dat
[12:25:46.489] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C8.dat
[12:25:46.495] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C9.dat
[12:25:46.500] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C10.dat
[12:25:46.505] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C11.dat
[12:25:46.511] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C12.dat
[12:25:46.516] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C13.dat
[12:25:46.521] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C14.dat
[12:25:46.526] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//trimParameters35_C15.dat
[12:25:46.531] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-3-39_FPIXTest-17C-FNAL-160427-1301_2016-04-27_13h02m_1461780121/000_FPIXTest_p17//defaultMaskFile.dat
[12:25:46.541] INFO: enter test to run
[12:26:26.416] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:26:26.416] INFO: running: xray
[12:26:26.418] INFO: ----------------------------------------------------------------------
[12:26:26.418] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:26:26.418] INFO: ----------------------------------------------------------------------
[12:26:27.381] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:26:38.417] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[12:27:07.999] INFO: Resuming triggers.
[12:27:19.039] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[12:27:48.623] INFO: Resuming triggers.
[12:27:59.663] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[12:28:29.207] INFO: Resuming triggers.
[12:28:40.250] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[12:29:09.753] INFO: Resuming triggers.
[12:29:20.791] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[12:29:50.668] INFO: Resuming triggers.
[12:30:01.705] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[12:30:31.634] INFO: Resuming triggers.
[12:30:42.671] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[12:31:13.083] INFO: Resuming triggers.
[12:31:24.123] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[12:31:53.587] INFO: Resuming triggers.
[12:32:04.630] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[12:32:34.132] INFO: Resuming triggers.
[12:32:35.127] INFO: data taking finished, elapsed time: 100 seconds.
[12:32:38.156] INFO: PixTest:: pg_setup set to default.
[12:32:38.160] INFO: PixTestXray::doPhRun() done
[12:32:38.299] INFO: enter test to run
[12:33:07.565] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:33:07.566] INFO: running: xray
[12:33:07.567] INFO: ----------------------------------------------------------------------
[12:33:07.567] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:33:07.567] INFO: ----------------------------------------------------------------------
[12:33:08.548] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:33:14.736] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:33:45.732] INFO: Resuming triggers.
[12:33:51.919] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[12:34:21.982] INFO: Resuming triggers.
[12:34:28.170] INFO: run duration 18 seconds, buffer almost full (81%), pausing triggers.
[12:34:58.085] INFO: Resuming triggers.
[12:35:04.273] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[12:35:34.315] INFO: Resuming triggers.
[12:35:40.505] INFO: run duration 30 seconds, buffer almost full (81%), pausing triggers.
[12:36:10.627] INFO: Resuming triggers.
[12:36:16.817] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[12:36:46.826] INFO: Resuming triggers.
[12:36:53.014] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[12:37:23.061] INFO: Resuming triggers.
[12:37:29.247] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[12:37:59.271] INFO: Resuming triggers.
[12:38:05.459] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[12:38:35.536] INFO: Resuming triggers.
[12:38:41.725] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[12:39:11.726] INFO: Resuming triggers.
[12:39:17.912] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[12:39:48.007] INFO: Resuming triggers.
[12:39:54.191] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[12:40:24.215] INFO: Resuming triggers.
[12:40:30.401] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[12:41:01.547] INFO: Resuming triggers.
[12:41:07.732] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[12:41:38.831] INFO: Resuming triggers.
[12:41:45.013] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[12:42:16.046] INFO: Resuming triggers.
[12:42:22.232] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[12:42:52.214] INFO: Resuming triggers.
[12:42:53.561] INFO: data taking finished, elapsed time: 100 seconds.
[12:43:00.432] INFO: PixTest:: pg_setup set to default.
[12:43:00.436] INFO: PixTestXray::doPhRun() done
[12:43:00.585] INFO: enter test to run
[12:44:14.721] INFO: test: HighRate no parameter change
[12:44:14.721] INFO: running: highrate
[12:44:14.722] INFO: ----------------------------------------------------------------------
[12:44:14.722] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:44:14.722] INFO: ----------------------------------------------------------------------
[12:44:14.862] INFO: Expecting 768 events.
[12:44:15.991] INFO: 768 events read in total (414ms).
[12:44:15.992] INFO: Test took 1264ms.
[12:44:16.794] INFO: Expecting 41600 events.
[12:44:19.921] INFO: 41600 events read in total (2600ms).
[12:44:19.922] INFO: Test took 3924ms.
[12:44:19.958] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:44:20.683] INFO: Expecting 41600 events.
[12:44:23.890] INFO: 41600 events read in total (2678ms).
[12:44:23.891] INFO: Test took 3915ms.
[12:44:23.928] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:44:24.645] INFO: Expecting 41600 events.
[12:44:27.879] INFO: 41600 events read in total (2707ms).
[12:44:27.880] INFO: Test took 3933ms.
[12:44:27.916] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:44:28.637] INFO: Expecting 41600 events.
[12:44:31.888] INFO: 41600 events read in total (2724ms).
[12:44:31.889] INFO: Test took 3953ms.
[12:44:31.926] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:44:32.644] INFO: Expecting 41600 events.
[12:44:35.919] INFO: 41600 events read in total (2748ms).
[12:44:35.920] INFO: Test took 3976ms.
[12:44:35.956] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:44:36.675] INFO: Expecting 41600 events.
[12:44:39.949] INFO: 41600 events read in total (2747ms).
[12:44:39.950] INFO: Test took 3975ms.
[12:44:39.987] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:44:40.702] INFO: Expecting 41600 events.
[12:44:43.966] INFO: 41600 events read in total (2738ms).
[12:44:43.967] INFO: Test took 3962ms.
[12:44:44.005] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:44:44.719] INFO: Expecting 41600 events.
[12:44:47.981] INFO: 41600 events read in total (2736ms).
[12:44:47.982] INFO: Test took 3959ms.
[12:44:48.019] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:44:48.738] INFO: Expecting 41600 events.
[12:44:51.987] INFO: 41600 events read in total (2722ms).
[12:44:51.988] INFO: Test took 3951ms.
[12:44:52.025] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:44:52.744] INFO: Expecting 41600 events.
[12:44:55.987] INFO: 41600 events read in total (2716ms).
[12:44:55.988] INFO: Test took 3944ms.
[12:44:56.025] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:44:56.739] INFO: Expecting 41600 events.
[12:44:59.969] INFO: 41600 events read in total (2703ms).
[12:44:59.970] INFO: Test took 3927ms.
[12:45:00.007] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:00.728] INFO: Expecting 41600 events.
[12:45:03.995] INFO: 41600 events read in total (2740ms).
[12:45:03.996] INFO: Test took 3971ms.
[12:45:04.033] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:04.744] INFO: Expecting 41600 events.
[12:45:08.064] INFO: 41600 events read in total (2793ms).
[12:45:08.065] INFO: Test took 4014ms.
[12:45:08.102] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:08.818] INFO: Expecting 41600 events.
[12:45:12.084] INFO: 41600 events read in total (2739ms).
[12:45:12.085] INFO: Test took 3965ms.
[12:45:12.122] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:12.837] INFO: Expecting 41600 events.
[12:45:16.092] INFO: 41600 events read in total (2728ms).
[12:45:16.093] INFO: Test took 3953ms.
[12:45:16.129] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:16.849] INFO: Expecting 41600 events.
[12:45:20.104] INFO: 41600 events read in total (2728ms).
[12:45:20.105] INFO: Test took 3957ms.
[12:45:20.142] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:20.864] INFO: Expecting 41600 events.
[12:45:24.131] INFO: 41600 events read in total (2740ms).
[12:45:24.132] INFO: Test took 3970ms.
[12:45:24.169] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:24.884] INFO: Expecting 41600 events.
[12:45:28.144] INFO: 41600 events read in total (2733ms).
[12:45:28.145] INFO: Test took 3957ms.
[12:45:28.181] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:28.903] INFO: Expecting 41600 events.
[12:45:32.127] INFO: 41600 events read in total (2697ms).
[12:45:32.128] INFO: Test took 3929ms.
[12:45:32.164] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:32.887] INFO: Expecting 41600 events.
[12:45:35.987] INFO: 41600 events read in total (2573ms).
[12:45:35.988] INFO: Test took 3805ms.
[12:45:36.023] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:45:36.383] INFO: enter test to run
[12:45:57.920] INFO: test: HighRate no parameter change
[12:45:57.920] INFO: running: highrate
[12:45:57.921] INFO: ----------------------------------------------------------------------
[12:45:57.921] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:45:57.921] INFO: ----------------------------------------------------------------------
[12:45:58.542] INFO: Expecting 208000 events.
[12:46:10.512] INFO: 208000 events read in total (11444ms).
[12:46:10.515] INFO: Test took 12586ms.
[12:46:10.670] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:46:10.924] INFO: number of dead pixels (per ROC): 1 0 0 1 0 53 0 0 0 0 0 0 0 0 0 1
[12:46:10.924] INFO: number of red-efficiency pixels: 82 43 84 157 148 211 165 100 90 144 144 110 119 59 25 35
[12:46:10.924] INFO: number of X-ray hits detected: 70598 48264 70352 117702 120090 123135 123296 83062 78448 106778 105784 91626 96988 56695 23702 26205
[12:46:10.924] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:46:10.924] INFO: number of Vcal hits detected: 207868 207957 207916 207788 207848 205186 207831 207899 207909 207850 207856 207888 207880 207914 207974 207916
[12:46:10.924] 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 100.0 100.0 100.0
[12:46:10.924] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.9 99.9 98.6 99.9 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[12:46:10.924] INFO: X-ray hit rate [MHz/cm2]: 20.7 14.1 20.6 34.5 35.2 36.1 36.1 24.3 23.0 31.3 31.0 26.9 28.4 16.6 6.9 7.7
[12:46:10.924] INFO: PixTestHighRate::doXPixelAlive() done
[12:46:10.969] INFO: PixTest:: pg_setup set to default.
[12:46:10.984] INFO: enter test to run
[12:46:36.959] INFO: test: HighRate no parameter change
[12:46:36.960] INFO: running: highrate
[12:46:36.961] INFO: ----------------------------------------------------------------------
[12:46:36.961] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:46:36.961] INFO: ----------------------------------------------------------------------
[12:46:37.579] INFO: Expecting 208000 events.
[12:46:51.684] INFO: 208000 events read in total (13578ms).
[12:46:51.690] INFO: Test took 14721ms.
[12:46:52.015] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:46:52.327] INFO: number of dead pixels (per ROC): 1 0 0 0 0 53 0 0 0 0 0 0 0 0 0 1
[12:46:52.327] INFO: number of red-efficiency pixels: 269 122 322 478 486 717 672 428 320 507 442 318 435 194 60 76
[12:46:52.327] INFO: number of X-ray hits detected: 154695 105077 153938 255689 262287 268030 268180 182121 171368 232910 229918 199860 211370 122784 51605 57171
[12:46:52.327] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:46:52.327] INFO: number of Vcal hits detected: 207657 207869 207649 207429 207458 204583 207242 207528 207668 207437 207523 207667 207537 207771 207937 207875
[12:46:52.327] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.8 99.7 99.7 99.8 99.8 99.7 99.8 99.9 99.8 99.9 100.0 100.0
[12:46:52.327] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.7 99.7 98.4 99.6 99.8 99.8 99.7 99.8 99.8 99.8 99.9 100.0 99.9
[12:46:52.327] INFO: X-ray hit rate [MHz/cm2]: 45.3 30.8 45.1 74.9 76.9 78.6 78.6 53.4 50.2 68.3 67.4 58.6 62.0 36.0 15.1 16.8
[12:46:52.327] INFO: PixTestHighRate::doXPixelAlive() done
[12:46:52.374] INFO: PixTest:: pg_setup set to default.
[12:46:52.387] INFO: enter test to run
[12:47:11.095] INFO: test: HighRate no parameter change
[12:47:11.095] INFO: running: highrate
[12:47:11.096] INFO: ----------------------------------------------------------------------
[12:47:11.096] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:47:11.096] INFO: ----------------------------------------------------------------------
[12:47:11.716] INFO: Expecting 208000 events.
[12:47:28.069] INFO: 208000 events read in total (15826ms).
[12:47:28.077] INFO: Test took 16972ms.
[12:47:28.585] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:47:28.955] INFO: number of dead pixels (per ROC): 1 0 0 1 0 53 0 0 0 0 0 0 0 0 0 1
[12:47:28.955] INFO: number of red-efficiency pixels: 543 306 734 1175 1185 1707 1679 989 680 1310 1050 714 1073 438 122 114
[12:47:28.955] INFO: number of X-ray hits detected: 235799 159114 233729 388111 398704 407174 408193 278441 262297 354581 350400 305282 323426 188480 80106 87802
[12:47:28.955] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:47:28.955] INFO: number of Vcal hits detected: 207264 207668 206996 206454 206490 202948 205586 206610 207191 206278 206676 207169 206681 207458 207875 207830
[12:47:28.955] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.6 99.4 99.3 98.9 99.0 99.4 99.6 99.3 99.4 99.7 99.4 99.8 99.9 99.9
[12:47:28.955] INFO: Vcal hit overall efficiency (%): 99.6 99.8 99.5 99.3 99.3 97.6 98.8 99.3 99.6 99.2 99.4 99.6 99.4 99.7 99.9 99.9
[12:47:28.955] INFO: X-ray hit rate [MHz/cm2]: 69.1 46.6 68.5 113.8 116.9 119.3 119.6 81.6 76.9 103.9 102.7 89.5 94.8 55.2 23.5 25.7
[12:47:28.955] INFO: PixTestHighRate::doXPixelAlive() done
[12:47:29.005] INFO: PixTest:: pg_setup set to default.
[12:47:29.022] INFO: enter test to run
[12:49:06.846] INFO: test: exit no parameter change
[12:49:07.230] QUIET: Connection to board 32 closed.
[12:49:07.231] INFO: pXar: this is the end, my friend