[15:59:17.387] INFO: *** Welcome to pxar ***
[15:59:17.387] INFO: *** Today: 2016/04/06
[15:59:17.403] INFO: *** Version: v1.9.0-796-gef167-dirty
[15:59:17.403] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//dacParameters35_C15.dat
[15:59:17.404] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:59:17.404] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//defaultMaskFile.dat
[15:59:17.405] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C15.dat
[15:59:17.479] INFO: clk: 4
[15:59:17.479] INFO: ctr: 4
[15:59:17.479] INFO: sda: 19
[15:59:17.479] INFO: tin: 9
[15:59:17.479] INFO: level: 15
[15:59:17.479] INFO: triggerdelay: 0
[15:59:17.479] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[15:59:17.479] INFO: Log level: INFO
[15:59:17.497] QUIET: Connection to board DTB_WREKRL opened.
[15:59:17.500] 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:
------------------------------------------------------
[15:59:17.503] INFO: RPC call hashes of host and DTB match: 398089610
[15:59:19.030] INFO: DUT info:
[15:59:19.030] INFO: The DUT currently contains the following objects:
[15:59:19.030] INFO: 2 TBM Cores tbm08c (2 ON)
[15:59:19.030] INFO: TBM Core alpha (0): 7 registers set
[15:59:19.030] INFO: TBM Core beta (1): 7 registers set
[15:59:19.030] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:59:19.030] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.030] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.030] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.030] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.031] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:59:19.434] INFO: enter 'restricted' command line mode
[15:59:19.434] INFO: enter test to run
[15:59:43.407] INFO: test: timing no parameter change
[15:59:43.407] INFO: running: timing
[15:59:43.424] INFO: ######################################################################
[15:59:43.424] INFO: PixTestTiming::doTest()
[15:59:43.427] INFO: ######################################################################
[15:59:43.427] INFO: ----------------------------------------------------------------------
[15:59:43.427] INFO: PixTestTiming::TBMPhaseScan()
[15:59:43.427] INFO: ----------------------------------------------------------------------
[16:10:17.808] INFO: TBM Phase Settings: 232
[16:10:17.808] INFO: 400MHz Phase: 2
[16:10:17.808] INFO: 160MHz Phase: 7
[16:10:17.808] INFO: Functional Phase Area: 3
[16:10:17.811] INFO: Test took 634384 ms.
[16:10:17.811] INFO: PixTestTiming::TBMPhaseScan() done.
[16:10:17.811] INFO: ----------------------------------------------------------------------
[16:10:17.811] INFO: PixTestTiming::ROCDelayScan()
[16:10:17.811] INFO: ----------------------------------------------------------------------
[16:13:16.527] INFO: ROC Delay Settings: 228
[16:13:16.528] INFO: ROC Header-Trailer/Token Delay: 11
[16:13:16.528] INFO: ROC Port 0 Delay: 4
[16:13:16.528] INFO: ROC Port 1 Delay: 4
[16:13:16.528] INFO: Functional ROC Area: 3
[16:13:16.531] INFO: Test took 178720 ms.
[16:13:16.531] INFO: PixTestTiming::ROCDelayScan() done.
[16:13:16.532] INFO: ----------------------------------------------------------------------
[16:13:16.532] INFO: PixTestTiming::TimingTest()
[16:13:16.532] INFO: ----------------------------------------------------------------------
[16:13:32.670] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:13:47.671] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:14:02.664] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:14:17.651] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:14:32.654] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:14:47.637] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:02.640] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:17.630] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:32.589] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:47.590] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:47.968] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:15:47.985] INFO: ----------------------------------------------------------------------
[16:15:47.985] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:15:47.985] INFO: ----------------------------------------------------------------------
[16:15:47.985] INFO: ----------------------------------------------------------------------
[16:15:47.985] INFO: Read back bit status: 1
[16:15:47.985] INFO: ----------------------------------------------------------------------
[16:15:47.985] INFO: ----------------------------------------------------------------------
[16:15:47.985] INFO: Timings are good!
[16:15:47.985] INFO: ----------------------------------------------------------------------
[16:15:47.985] INFO: Test took 151454 ms.
[16:15:47.985] INFO: PixTestTiming::TimingTest() done.
[16:15:47.998] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:15:47.999] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:15:47.999] INFO: PixTestTiming::doTest took 964580 ms.
[16:15:47.999] INFO: PixTestTiming::doTest() done
[16:15:47.999] INFO: Write out TBMPhaseScan_0_V0
[16:15:48.034] INFO: Write out TBMPhaseScan_1_V0
[16:15:48.034] INFO: Write out CombinedTBMPhaseScan_V0
[16:15:48.035] INFO: Write out ROCDelayScan3_V0
[16:15:48.036] INFO: enter test to run
[16:16:10.087] INFO: test: PixelAlive no parameter change
[16:16:10.088] INFO: running: pixelalive
[16:16:10.092] INFO: ----------------------------------------------------------------------
[16:16:10.092] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[16:16:10.092] INFO: ----------------------------------------------------------------------
[16:16:10.415] INFO: Expecting 41600 events.
[16:16:14.761] INFO: 41600 events read in total (3631ms).
[16:16:14.762] INFO: Test took 4667ms.
[16:16:14.776] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:16:15.162] INFO: PixTestAlive::aliveTest() done
[16:16:15.162] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 0 0 0 160 0 0 1 0 0 2
[16:16:15.165] INFO: enter test to run
[16:16:39.863] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:16:39.863] INFO: running: highrate
[16:16:39.863] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:16:40.011] INFO: ----------------------------------------------------------------------
[16:16:40.012] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:16:40.012] INFO: ----------------------------------------------------------------------
[16:16:40.012] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:16:40.012] INFO: edge/corner pixel THR is adjusted
[16:16:40.012] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:16:40.968] INFO: Collecting data for 5 seconds...
[16:16:45.978] INFO: Done with hot pixel readout
[16:16:55.680] INFO: PixTest:: pg_setup set to default.
[16:16:55.681] INFO: 7 hot pixels found in step 0
[16:16:56.677] INFO: Collecting data for 5 seconds...
[16:17:01.694] INFO: Done with hot pixel readout
[16:17:13.954] INFO: PixTest:: pg_setup set to default.

[16:17:13.955] INFO: 8 hot pixels found in step 1
[16:17:14.952] INFO: Collecting data for 5 seconds...
[16:17:19.969] INFO: Done with hot pixel readout
[16:17:32.224] INFO: PixTest:: pg_setup set to default.

[16:17:32.225] INFO: 9 hot pixels found in step 2
[16:17:33.222] INFO: Collecting data for 5 seconds...
[16:17:38.239] INFO: Done with hot pixel readout
[16:17:50.509] INFO: PixTest:: pg_setup set to default.


[16:17:50.510] INFO: 6 hot pixels found in step 3
[16:17:51.506] INFO: Collecting data for 5 seconds...
[16:17:56.525] INFO: Done with hot pixel readout
[16:18:08.732] INFO: PixTest:: pg_setup set to default.


[16:18:08.733] INFO: 12 hot pixels found in step 4
[16:18:09.729] INFO: Collecting data for 5 seconds...
[16:18:14.747] INFO: Done with hot pixel readout
[16:18:26.995] INFO: PixTest:: pg_setup set to default.



[16:18:26.996] INFO: 10 hot pixels found in step 5
[16:18:27.992] INFO: Collecting data for 5 seconds...
[16:18:33.010] INFO: Done with hot pixel readout
[16:18:45.302] INFO: PixTest:: pg_setup set to default.

[16:18:45.303] INFO: 11 hot pixels found in step 6
[16:18:46.301] INFO: Collecting data for 5 seconds...
[16:18:51.317] INFO: Done with hot pixel readout
[16:19:03.628] INFO: PixTest:: pg_setup set to default.
[16:19:03.629] INFO: 5 hot pixels found in step 7
[16:19:04.627] INFO: Collecting data for 5 seconds...
[16:19:09.645] INFO: Done with hot pixel readout
[16:19:21.852] INFO: PixTest:: pg_setup set to default.
[16:19:21.852] INFO: 1 hot pixels found in step 8
[16:19:22.849] INFO: Collecting data for 5 seconds...
[16:19:27.867] INFO: Done with hot pixel readout
[16:19:39.997] INFO: PixTest:: pg_setup set to default.
[16:19:39.998] INFO: 5 hot pixels found in step 9
[16:19:40.994] INFO: Collecting data for 5 seconds...
[16:19:46.011] INFO: Done with hot pixel readout
[16:19:58.174] INFO: PixTest:: pg_setup set to default.
[16:19:58.175] INFO: 5 hot pixels found in step 10
[16:19:59.172] INFO: Collecting data for 5 seconds...
[16:20:04.190] INFO: Done with hot pixel readout
[16:20:16.344] INFO: PixTest:: pg_setup set to default.
[16:20:16.345] INFO: 6 hot pixels found in step 11
[16:20:17.345] INFO: Collecting data for 5 seconds...
[16:20:22.361] INFO: Done with hot pixel readout
[16:20:34.329] INFO: PixTest:: pg_setup set to default.

[16:20:34.330] INFO: 7 hot pixels found in step 12
[16:20:35.330] INFO: Collecting data for 5 seconds...
[16:20:40.347] INFO: Done with hot pixel readout
[16:20:52.485] INFO: PixTest:: pg_setup set to default.
[16:20:52.486] INFO: 1 hot pixels found in step 13
[16:20:53.483] INFO: Collecting data for 5 seconds...
[16:20:58.501] INFO: Done with hot pixel readout
[16:21:10.704] INFO: PixTest:: pg_setup set to default.
[16:21:10.705] INFO: 5 hot pixels found in step 14
[16:21:10.746] INFO: 5 hot pixels could not be trimmed and have been masked.
[16:21:10.749] INFO: PixTest::trimHotPixels() done
[16:21:10.749] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C0.dat
[16:21:10.754] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C1.dat
[16:21:10.760] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C2.dat
[16:21:10.766] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C3.dat
[16:21:10.772] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C4.dat
[16:21:10.777] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C5.dat
[16:21:10.782] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C6.dat
[16:21:10.788] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C7.dat
[16:21:10.793] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C8.dat
[16:21:10.798] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C9.dat
[16:21:10.803] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C10.dat
[16:21:10.809] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C11.dat
[16:21:10.814] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C12.dat
[16:21:10.819] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C13.dat
[16:21:10.824] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C14.dat
[16:21:10.830] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C15.dat
[16:21:10.835] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//defaultMaskFile.dat
[16:21:10.845] INFO: enter test to run
[16:21:37.221] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:21:37.221] INFO: running: highrate
[16:21:37.226] INFO: ----------------------------------------------------------------------
[16:21:37.226] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:21:37.226] INFO: ----------------------------------------------------------------------
[16:21:37.226] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:21:37.226] INFO: edge/corner pixel THR is adjusted
[16:21:37.226] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:21:38.184] INFO: Collecting data for 1 seconds...
[16:21:39.188] INFO: Done with hot pixel readout
[16:21:43.381] INFO: PixTest:: pg_setup set to default.
[16:21:43.382] INFO: 0 hot pixels found in step 0
[16:21:43.387] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:21:43.474] INFO: PixTest::trimHotPixels() done
[16:21:43.474] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C0.dat
[16:21:43.483] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C1.dat
[16:21:43.489] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C2.dat
[16:21:43.494] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C3.dat
[16:21:43.499] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C4.dat
[16:21:43.505] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C5.dat
[16:21:43.510] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C6.dat
[16:21:43.515] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C7.dat
[16:21:43.520] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C8.dat
[16:21:43.525] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C9.dat
[16:21:43.531] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C10.dat
[16:21:43.536] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C11.dat
[16:21:43.541] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C12.dat
[16:21:43.546] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C13.dat
[16:21:43.552] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C14.dat
[16:21:43.557] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//trimParameters35_C15.dat
[16:21:43.562] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-G-2-09_FPIXTest-17C-FNAL-160401-1148_2016-04-01_11h48m_1459529315/000_FPIXTest_p17//defaultMaskFile.dat
[16:21:43.578] INFO: enter test to run
[16:22:13.365] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:22:13.365] INFO: running: xray
[16:22:13.366] INFO: ----------------------------------------------------------------------
[16:22:13.366] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:22:13.366] INFO: ----------------------------------------------------------------------
[16:22:14.329] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:22:25.451] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[16:22:54.687] INFO: Resuming triggers.
[16:23:05.913] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[16:23:35.278] INFO: Resuming triggers.
[16:23:46.398] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[16:24:15.878] INFO: Resuming triggers.
[16:24:26.998] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[16:24:56.439] INFO: Resuming triggers.
[16:25:07.562] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[16:25:36.987] INFO: Resuming triggers.
[16:25:48.107] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[16:26:17.555] INFO: Resuming triggers.
[16:26:28.675] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[16:26:56.040] INFO: Resuming triggers.
[16:27:07.164] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[16:27:36.476] INFO: Resuming triggers.
[16:27:47.604] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[16:28:17.284] INFO: Resuming triggers.
[16:28:17.510] INFO: data taking finished, elapsed time: 100 seconds.
[16:28:18.603] INFO: PixTest:: pg_setup set to default.
[16:28:18.606] INFO: PixTestXray::doPhRun() done
[16:28:18.748] INFO: enter test to run
[16:28:47.618] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:28:47.618] INFO: running: xray
[16:28:47.619] INFO: ----------------------------------------------------------------------
[16:28:47.619] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:28:47.619] INFO: ----------------------------------------------------------------------
[16:28:48.592] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:28:54.866] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[16:29:24.856] INFO: Resuming triggers.
[16:29:31.133] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[16:30:01.139] INFO: Resuming triggers.
[16:30:07.414] INFO: run duration 18 seconds, buffer almost full (81%), pausing triggers.
[16:30:37.513] INFO: Resuming triggers.
[16:30:43.789] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[16:31:13.878] INFO: Resuming triggers.
[16:31:20.155] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[16:31:50.127] INFO: Resuming triggers.
[16:31:56.402] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[16:32:26.379] INFO: Resuming triggers.
[16:32:32.653] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[16:33:02.613] INFO: Resuming triggers.
[16:33:08.886] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[16:33:38.909] INFO: Resuming triggers.
[16:33:45.181] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[16:34:15.109] INFO: Resuming triggers.
[16:34:21.382] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[16:34:51.437] INFO: Resuming triggers.
[16:34:57.707] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[16:35:27.721] INFO: Resuming triggers.
[16:35:33.995] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[16:36:04.011] INFO: Resuming triggers.
[16:36:10.282] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[16:36:40.266] INFO: Resuming triggers.
[16:36:46.537] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[16:37:13.281] INFO: Resuming triggers.
[16:37:19.550] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[16:37:49.527] INFO: Resuming triggers.
[16:37:55.762] INFO: data taking finished, elapsed time: 100 seconds.
[16:38:25.581] INFO: PixTest:: pg_setup set to default.
[16:38:25.585] INFO: PixTestXray::doPhRun() done
[16:38:25.745] INFO: enter test to run
[16:39:06.573] INFO: test: HighRate no parameter change
[16:39:06.573] INFO: running: highrate
[16:39:06.575] INFO: ----------------------------------------------------------------------
[16:39:06.575] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:39:06.575] INFO: ----------------------------------------------------------------------
[16:39:06.716] INFO: Expecting 768 events.
[16:39:07.850] INFO: 768 events read in total (419ms).
[16:39:07.850] INFO: Test took 1269ms.
[16:39:08.653] INFO: Expecting 41600 events.
[16:39:11.790] INFO: 41600 events read in total (2611ms).
[16:39:11.791] INFO: Test took 3932ms.
[16:39:11.826] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:12.552] INFO: Expecting 41600 events.
[16:39:15.788] INFO: 41600 events read in total (2709ms).
[16:39:15.789] INFO: Test took 3945ms.
[16:39:15.826] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:16.548] INFO: Expecting 41600 events.
[16:39:19.821] INFO: 41600 events read in total (2746ms).
[16:39:19.822] INFO: Test took 3978ms.
[16:39:19.858] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:20.580] INFO: Expecting 41600 events.
[16:39:23.852] INFO: 41600 events read in total (2746ms).
[16:39:23.853] INFO: Test took 3977ms.
[16:39:23.890] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:24.611] INFO: Expecting 41600 events.
[16:39:27.858] INFO: 41600 events read in total (2720ms).
[16:39:27.859] INFO: Test took 3951ms.
[16:39:27.896] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:28.615] INFO: Expecting 41600 events.
[16:39:31.879] INFO: 41600 events read in total (2737ms).
[16:39:31.880] INFO: Test took 3967ms.
[16:39:31.916] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:32.635] INFO: Expecting 41600 events.
[16:39:35.912] INFO: 41600 events read in total (2750ms).
[16:39:35.913] INFO: Test took 3977ms.
[16:39:35.949] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:36.670] INFO: Expecting 41600 events.
[16:39:39.951] INFO: 41600 events read in total (2754ms).
[16:39:39.952] INFO: Test took 3984ms.
[16:39:39.989] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:40.704] INFO: Expecting 41600 events.
[16:39:43.975] INFO: 41600 events read in total (2744ms).
[16:39:43.976] INFO: Test took 3968ms.
[16:39:44.013] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:44.733] INFO: Expecting 41600 events.
[16:39:47.996] INFO: 41600 events read in total (2736ms).
[16:39:47.997] INFO: Test took 3964ms.
[16:39:48.034] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:48.755] INFO: Expecting 41600 events.
[16:39:52.028] INFO: 41600 events read in total (2746ms).
[16:39:52.029] INFO: Test took 3976ms.
[16:39:52.065] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:52.786] INFO: Expecting 41600 events.
[16:39:56.056] INFO: 41600 events read in total (2743ms).
[16:39:56.057] INFO: Test took 3972ms.
[16:39:56.094] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:39:56.810] INFO: Expecting 41600 events.
[16:40:00.078] INFO: 41600 events read in total (2741ms).
[16:40:00.079] INFO: Test took 3966ms.
[16:40:00.115] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:00.834] INFO: Expecting 41600 events.
[16:40:04.100] INFO: 41600 events read in total (2739ms).
[16:40:04.101] INFO: Test took 3966ms.
[16:40:04.137] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:04.859] INFO: Expecting 41600 events.
[16:40:08.119] INFO: 41600 events read in total (2734ms).
[16:40:08.120] INFO: Test took 3963ms.
[16:40:08.157] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:08.878] INFO: Expecting 41600 events.
[16:40:12.163] INFO: 41600 events read in total (2758ms).
[16:40:12.164] INFO: Test took 3987ms.
[16:40:12.199] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:12.921] INFO: Expecting 41600 events.
[16:40:16.204] INFO: 41600 events read in total (2756ms).
[16:40:16.205] INFO: Test took 3986ms.
[16:40:16.241] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:16.958] INFO: Expecting 41600 events.
[16:40:20.228] INFO: 41600 events read in total (2744ms).
[16:40:20.229] INFO: Test took 3969ms.
[16:40:20.265] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:20.986] INFO: Expecting 41600 events.
[16:40:24.232] INFO: 41600 events read in total (2720ms).
[16:40:24.233] INFO: Test took 3949ms.
[16:40:24.270] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:24.987] INFO: Expecting 41600 events.
[16:40:28.023] INFO: 41600 events read in total (2509ms).
[16:40:28.024] INFO: Test took 3735ms.
[16:40:28.059] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:28.419] INFO: enter test to run
[16:40:39.933] INFO: test: HighRate no parameter change
[16:40:39.933] INFO: running: highrate
[16:40:39.934] INFO: ----------------------------------------------------------------------
[16:40:39.934] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:40:39.934] INFO: ----------------------------------------------------------------------
[16:40:40.549] INFO: Expecting 208000 events.
[16:40:52.542] INFO: 208000 events read in total (11466ms).
[16:40:52.545] INFO: Test took 12601ms.
[16:40:52.697] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:40:52.952] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 0 0 0 129 0 0 1 0 0 2
[16:40:52.953] INFO: number of red-efficiency pixels: 92 74 93 148 161 175 161 106 124 282 135 100 124 67 25 42
[16:40:52.953] INFO: number of X-ray hits detected: 67361 47125 71459 119976 123792 127760 119900 82075 79270 106129 108501 93824 99556 56567 25385 31562
[16:40:52.953] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:40:52.953] INFO: number of Vcal hits detected: 207810 207926 207907 207849 207832 207823 207838 207890 207873 199916 207863 207895 207826 207929 207975 207859
[16:40:52.953] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.2 99.9 100.0 99.9 100.0 100.0 100.0
[16:40:52.953] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 96.1 99.9 99.9 99.9 100.0 100.0 99.9
[16:40:52.953] INFO: X-ray hit rate [MHz/cm2]: 19.7 13.8 20.9 35.2 36.3 37.4 35.1 24.1 23.2 31.1 31.8 27.5 29.2 16.6 7.4 9.3
[16:40:52.953] INFO: PixTestHighRate::doXPixelAlive() done
[16:40:52.997] INFO: PixTest:: pg_setup set to default.
[16:40:53.012] INFO: enter test to run
[16:41:10.644] INFO: test: HighRate no parameter change
[16:41:10.644] INFO: running: highrate
[16:41:10.646] INFO: ----------------------------------------------------------------------
[16:41:10.646] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:41:10.646] INFO: ----------------------------------------------------------------------
[16:41:11.256] INFO: Expecting 208000 events.
[16:41:25.205] INFO: 208000 events read in total (13422ms).
[16:41:25.210] INFO: Test took 14556ms.
[16:41:25.535] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:41:25.844] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 0 0 0 56 0 0 1 0 0 2
[16:41:25.844] INFO: number of red-efficiency pixels: 205 188 344 583 522 526 628 276 328 497 506 324 318 194 82 80
[16:41:25.844] INFO: number of X-ray hits detected: 141162 99681 149855 249609 260232 268561 251316 171212 166009 220654 227598 194752 208676 118578 53262 66095
[16:41:25.844] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:41:25.844] INFO: number of Vcal hits detected: 207686 207806 207609 207349 207433 207430 207310 207707 207645 199784 207443 207655 207610 207795 207918 207822
[16:41:25.844] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.7 99.7 99.9 99.8 97.3 99.8 99.9 99.8 99.9 100.0 100.0
[16:41:25.844] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.7 99.7 99.7 99.7 99.9 99.8 96.0 99.7 99.8 99.8 99.9 100.0 99.9
[16:41:25.844] INFO: X-ray hit rate [MHz/cm2]: 41.4 29.2 43.9 73.2 76.3 78.7 73.7 50.2 48.7 64.7 66.7 57.1 61.2 34.8 15.6 19.4
[16:41:25.844] INFO: PixTestHighRate::doXPixelAlive() done
[16:41:25.892] INFO: PixTest:: pg_setup set to default.
[16:41:25.906] INFO: enter test to run
[16:41:45.748] INFO: test: HighRate no parameter change
[16:41:45.748] INFO: running: highrate
[16:41:45.749] INFO: ----------------------------------------------------------------------
[16:41:45.749] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:41:45.749] INFO: ----------------------------------------------------------------------
[16:41:46.365] INFO: Expecting 208000 events.
[16:42:02.488] INFO: 208000 events read in total (15596ms).
[16:42:02.496] INFO: Test took 16738ms.
[16:42:02.994] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:42:03.359] INFO: number of dead pixels (per ROC): 2 0 0 0 0 0 0 0 0 63 0 0 1 0 0 2
[16:42:03.359] INFO: number of red-efficiency pixels: 402 361 771 1300 1231 1284 1516 653 683 1002 1235 660 771 406 124 118
[16:42:03.359] INFO: number of X-ray hits detected: 215295 150754 227869 379427 393981 404548 380797 261397 253763 329724 346087 298491 317903 179621 81720 100973
[16:42:03.359] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:42:03.359] INFO: number of Vcal hits detected: 207436 207595 206912 206262 206401 206343 205933 207195 207163 199175 206391 207253 207062 207534 207875 207778
[16:42:03.359] INFO: Vcal hit fiducial efficiency (%): 99.8 99.8 99.5 99.2 99.3 99.3 99.1 99.6 99.6 97.2 99.3 99.7 99.6 99.8 99.9 99.9
[16:42:03.359] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.5 99.2 99.2 99.2 99.0 99.6 99.6 95.8 99.2 99.6 99.5 99.8 99.9 99.9
[16:42:03.359] INFO: X-ray hit rate [MHz/cm2]: 63.1 44.2 66.8 111.2 115.5 118.6 111.6 76.6 74.4 96.6 101.4 87.5 93.2 52.6 24.0 29.6
[16:42:03.359] INFO: PixTestHighRate::doXPixelAlive() done
[16:42:03.405] INFO: PixTest:: pg_setup set to default.
[16:42:03.426] INFO: enter test to run
[16:42:40.740] INFO: test: exit no parameter change
[16:42:41.136] QUIET: Connection to board 33 closed.
[16:42:41.137] INFO: pXar: this is the end, my friend