[11:42:35.250] INFO: *** Welcome to pxar ***
[11:42:35.250] INFO: *** Today: 2016/05/12
[11:42:35.676] INFO: *** Version: v1.9.0-796-gef167-dirty
[11:42:35.676] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//dacParameters35_C15.dat
[11:42:35.724] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:42:35.725] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//defaultMaskFile.dat
[11:42:35.733] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C15.dat
[11:42:35.860] INFO: clk: 4
[11:42:35.860] INFO: ctr: 4
[11:42:35.860] INFO: sda: 19
[11:42:35.860] INFO: tin: 9
[11:42:35.860] INFO: level: 15
[11:42:35.860] INFO: triggerdelay: 0
[11:42:35.860] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[11:42:35.860] INFO: Log level: INFO
[11:42:35.878] QUIET: Connection to board DTB_WREKRL opened.
[11:42:35.882] 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:
------------------------------------------------------
[11:42:35.884] INFO: RPC call hashes of host and DTB match: 398089610
[11:42:37.424] INFO: DUT info:
[11:42:37.424] INFO: The DUT currently contains the following objects:
[11:42:37.424] INFO: 2 TBM Cores tbm08c (2 ON)
[11:42:37.438] INFO: TBM Core alpha (0): 7 registers set
[11:42:37.438] INFO: TBM Core beta (1): 7 registers set
[11:42:37.438] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:42:37.438] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.438] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.438] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.438] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.438] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.438] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.438] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.438] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.438] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.439] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.439] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.439] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.439] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.439] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.439] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.439] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:42:37.884] INFO: enter 'restricted' command line mode
[11:42:37.884] INFO: enter test to run
[11:42:46.335] INFO: test: timing no parameter change
[11:42:46.335] INFO: running: timing
[11:42:46.410] INFO: ######################################################################
[11:42:46.410] INFO: PixTestTiming::doTest()
[11:42:46.410] INFO: ######################################################################
[11:42:46.410] INFO: ----------------------------------------------------------------------
[11:42:46.410] INFO: PixTestTiming::TBMPhaseScan()
[11:42:46.410] INFO: ----------------------------------------------------------------------
[11:47:18.402] INFO: TBM Phase Settings: 236
[11:47:18.402] INFO: 400MHz Phase: 3
[11:47:18.402] INFO: 160MHz Phase: 7
[11:47:18.402] INFO: Functional Phase Area: 3
[11:47:18.425] INFO: Test took 272015 ms.
[11:47:18.425] INFO: PixTestTiming::TBMPhaseScan() done.
[11:47:18.425] INFO: ----------------------------------------------------------------------
[11:47:18.425] INFO: PixTestTiming::ROCDelayScan()
[11:47:18.425] INFO: ----------------------------------------------------------------------
[11:49:21.064] INFO: ROC Delay Settings: 228
[11:49:21.064] INFO: ROC Header-Trailer/Token Delay: 11
[11:49:21.064] INFO: ROC Port 0 Delay: 4
[11:49:21.064] INFO: ROC Port 1 Delay: 4
[11:49:21.064] INFO: Functional ROC Area: 5
[11:49:21.067] INFO: Test took 122642 ms.
[11:49:21.067] INFO: PixTestTiming::ROCDelayScan() done.
[11:49:21.068] INFO: ----------------------------------------------------------------------
[11:49:21.068] INFO: PixTestTiming::TimingTest()
[11:49:21.068] INFO: ----------------------------------------------------------------------
[11:49:37.199] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:52.158] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:07.111] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:22.084] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:37.062] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:52.016] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:06.966] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:21.921] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:36.896] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:51.838] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:52.220] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:52.238] INFO: ----------------------------------------------------------------------
[11:51:52.238] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:51:52.238] INFO: ----------------------------------------------------------------------
[11:51:52.238] INFO: ----------------------------------------------------------------------
[11:51:52.238] INFO: Read back bit status: 1
[11:51:52.238] INFO: ----------------------------------------------------------------------
[11:51:52.238] INFO: ----------------------------------------------------------------------
[11:51:52.238] INFO: Timings are good!
[11:51:52.238] INFO: ----------------------------------------------------------------------
[11:51:52.238] INFO: Test took 151171 ms.
[11:51:52.238] INFO: PixTestTiming::TimingTest() done.
[11:51:52.238] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:51:52.238] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:51:52.238] INFO: PixTestTiming::doTest took 545878 ms.
[11:51:52.238] INFO: PixTestTiming::doTest() done
[11:51:52.239] INFO: Write out TBMPhaseScan_0_V0
[11:51:52.398] INFO: Write out TBMPhaseScan_1_V0
[11:51:52.399] INFO: Write out CombinedTBMPhaseScan_V0
[11:51:52.399] INFO: Write out ROCDelayScan3_V0
[11:51:52.400] INFO: enter test to run
[11:52:44.026] INFO: test: PixelAlive no parameter change
[11:52:44.026] INFO: running: pixelalive
[11:52:44.031] INFO: ----------------------------------------------------------------------
[11:52:44.031] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:52:44.031] INFO: ----------------------------------------------------------------------
[11:52:44.348] INFO: Expecting 41600 events.
[11:52:48.659] INFO: 41600 events read in total (3595ms).
[11:52:48.660] INFO: Test took 4627ms.
[11:52:48.666] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:52:49.059] INFO: PixTestAlive::aliveTest() done
[11:52:49.059] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 7 0 0 0 0 0 0 0 0 0
[11:52:49.062] INFO: enter test to run
[11:53:28.554] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:53:28.554] INFO: running: highrate
[11:53:28.554] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:53:28.785] INFO: ----------------------------------------------------------------------
[11:53:28.786] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:53:28.786] INFO: ----------------------------------------------------------------------
[11:53:28.786] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:53:28.786] INFO: edge/corner pixel THR is adjusted
[11:53:28.786] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:53:29.744] INFO: Collecting data for 5 seconds...
[11:53:34.761] INFO: Done with hot pixel readout
[11:53:47.233] INFO: PixTest:: pg_setup set to default.

[11:53:47.234] INFO: 42 hot pixels found in step 0
[11:53:48.232] INFO: Collecting data for 5 seconds...
[11:53:53.249] INFO: Done with hot pixel readout
[11:54:05.703] INFO: PixTest:: pg_setup set to default.




[11:54:05.704] INFO: 37 hot pixels found in step 1
[11:54:06.703] INFO: Collecting data for 5 seconds...
[11:54:11.720] INFO: Done with hot pixel readout
[11:54:24.124] INFO: PixTest:: pg_setup set to default.
[11:54:24.125] INFO: 45 hot pixels found in step 2
[11:54:25.124] INFO: Collecting data for 5 seconds...
[11:54:30.141] INFO: Done with hot pixel readout
[11:54:42.596] INFO: PixTest:: pg_setup set to default.


[11:54:42.597] INFO: 45 hot pixels found in step 3
[11:54:43.595] INFO: Collecting data for 5 seconds...
[11:54:48.612] INFO: Done with hot pixel readout
[11:55:01.037] INFO: PixTest:: pg_setup set to default.

[11:55:01.038] INFO: 28 hot pixels found in step 4
[11:55:02.036] INFO: Collecting data for 5 seconds...
[11:55:07.053] INFO: Done with hot pixel readout
[11:55:19.527] INFO: PixTest:: pg_setup set to default.
[11:55:19.528] INFO: 39 hot pixels found in step 5
[11:55:20.526] INFO: Collecting data for 5 seconds...
[11:55:25.543] INFO: Done with hot pixel readout
[11:55:37.978] INFO: PixTest:: pg_setup set to default.


[11:55:37.979] INFO: 36 hot pixels found in step 6
[11:55:38.978] INFO: Collecting data for 5 seconds...
[11:55:43.994] INFO: Done with hot pixel readout
[11:55:56.641] INFO: PixTest:: pg_setup set to default.


[11:55:56.642] INFO: 29 hot pixels found in step 7
[11:55:57.642] INFO: Collecting data for 5 seconds...
[11:56:02.660] INFO: Done with hot pixel readout
[11:56:15.078] INFO: PixTest:: pg_setup set to default.

[11:56:15.079] INFO: 25 hot pixels found in step 8
[11:56:16.078] INFO: Collecting data for 5 seconds...
[11:56:21.097] INFO: Done with hot pixel readout
[11:56:33.484] INFO: PixTest:: pg_setup set to default.


[11:56:33.485] INFO: 35 hot pixels found in step 9
[11:56:34.484] INFO: Collecting data for 5 seconds...
[11:56:39.502] INFO: Done with hot pixel readout
[11:56:51.537] INFO: PixTest:: pg_setup set to default.


[11:56:51.538] INFO: 33 hot pixels found in step 10
[11:56:52.541] INFO: Collecting data for 5 seconds...
[11:56:57.557] INFO: Done with hot pixel readout
[11:57:09.839] INFO: PixTest:: pg_setup set to default.


[11:57:09.840] INFO: 28 hot pixels found in step 11
[11:57:10.839] INFO: Collecting data for 5 seconds...
[11:57:15.857] INFO: Done with hot pixel readout
[11:57:28.642] INFO: PixTest:: pg_setup set to default.
[11:57:28.643] INFO: 35 hot pixels found in step 12
[11:57:29.642] INFO: Collecting data for 5 seconds...
[11:57:34.662] INFO: Done with hot pixel readout
[11:57:47.205] INFO: PixTest:: pg_setup set to default.


[11:57:47.206] INFO: 25 hot pixels found in step 13
[11:57:48.204] INFO: Collecting data for 5 seconds...
[11:57:53.225] INFO: Done with hot pixel readout
[11:58:05.704] INFO: PixTest:: pg_setup set to default.



[11:58:05.706] INFO: 33 hot pixels found in step 14
[11:58:05.749] INFO: 33 hot pixels could not be trimmed and have been masked.
[11:58:05.752] INFO: PixTest::trimHotPixels() done
[11:58:05.753] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C0.dat
[11:58:05.758] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C1.dat
[11:58:05.765] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C2.dat
[11:58:05.770] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C3.dat
[11:58:05.776] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C4.dat
[11:58:05.781] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C5.dat
[11:58:05.786] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C6.dat
[11:58:05.792] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C7.dat
[11:58:05.798] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C8.dat
[11:58:05.804] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C9.dat
[11:58:05.809] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C10.dat
[11:58:05.814] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C11.dat
[11:58:05.820] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C12.dat
[11:58:05.826] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C13.dat
[11:58:05.843] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C14.dat
[11:58:05.848] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C15.dat
[11:58:05.855] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//defaultMaskFile.dat
[11:58:05.865] INFO: enter test to run
[11:58:47.224] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:58:47.224] INFO: running: highrate
[11:58:47.228] INFO: ----------------------------------------------------------------------
[11:58:47.229] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:58:47.229] INFO: ----------------------------------------------------------------------
[11:58:47.229] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:58:47.229] INFO: edge/corner pixel THR is adjusted
[11:58:47.229] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:58:48.186] INFO: Collecting data for 1 seconds...
[11:58:49.190] INFO: Done with hot pixel readout
[11:58:53.781] INFO: PixTest:: pg_setup set to default.
[11:58:53.781] INFO: 0 hot pixels found in step 0
[11:58:53.787] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:58:53.861] INFO: PixTest::trimHotPixels() done
[11:58:53.861] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C0.dat
[11:58:53.875] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C1.dat
[11:58:53.884] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C2.dat
[11:58:53.890] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C3.dat
[11:58:53.896] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C4.dat
[11:58:53.901] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C5.dat
[11:58:53.906] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C6.dat
[11:58:53.912] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C7.dat
[11:58:53.917] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C8.dat
[11:58:53.922] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C9.dat
[11:58:53.928] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C10.dat
[11:58:53.933] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C11.dat
[11:58:53.939] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C12.dat
[11:58:53.944] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C13.dat
[11:58:53.950] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C14.dat
[11:58:53.955] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//trimParameters35_C15.dat
[11:58:53.960] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-J-NJ_FPIXTest-17C-FNAL-160506-1238_2016-05-06_12h38m_1462556301/000_FPIXTest_p17//defaultMaskFile.dat
[11:58:53.970] INFO: enter test to run
[11:59:41.095] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:59:41.095] INFO: running: xray
[11:59:41.097] INFO: ----------------------------------------------------------------------
[11:59:41.097] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:59:41.097] INFO: ----------------------------------------------------------------------
[11:59:42.085] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:59:52.761] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[12:00:22.317] INFO: Resuming triggers.
[12:00:32.992] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[12:01:02.719] INFO: Resuming triggers.
[12:01:13.395] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[12:01:43.068] INFO: Resuming triggers.
[12:01:53.744] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[12:02:23.382] INFO: Resuming triggers.
[12:02:34.061] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[12:03:03.648] INFO: Resuming triggers.
[12:03:14.326] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[12:03:44.043] INFO: Resuming triggers.
[12:03:54.725] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[12:04:24.377] INFO: Resuming triggers.
[12:04:35.059] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[12:05:04.686] INFO: Resuming triggers.
[12:05:15.371] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[12:05:44.510] INFO: Resuming triggers.
[12:05:48.732] INFO: data taking finished, elapsed time: 100 seconds.
[12:06:00.588] INFO: PixTest:: pg_setup set to default.
[12:06:00.591] INFO: PixTestXray::doPhRun() done
[12:06:00.730] INFO: enter test to run
[12:06:32.028] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:06:32.028] INFO: running: xray
[12:06:32.029] INFO: ----------------------------------------------------------------------
[12:06:32.029] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:06:32.029] INFO: ----------------------------------------------------------------------
[12:06:32.002] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:06:38.910] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[12:07:09.475] INFO: Resuming triggers.
[12:07:15.384] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:07:46.214] INFO: Resuming triggers.
[12:07:52.124] INFO: run duration 17 seconds, buffer almost full (81%), pausing triggers.
[12:08:22.323] INFO: Resuming triggers.
[12:08:28.232] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[12:08:59.649] INFO: Resuming triggers.
[12:09:05.559] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[12:09:37.048] INFO: Resuming triggers.
[12:09:42.960] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[12:10:13.262] INFO: Resuming triggers.
[12:10:19.174] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[12:10:49.364] INFO: Resuming triggers.
[12:10:55.277] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[12:11:25.540] INFO: Resuming triggers.
[12:11:31.456] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[12:12:01.598] INFO: Resuming triggers.
[12:12:07.515] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[12:12:37.737] INFO: Resuming triggers.
[12:12:43.653] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[12:13:13.850] INFO: Resuming triggers.
[12:13:19.769] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[12:13:49.004] INFO: Resuming triggers.
[12:13:55.922] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[12:14:25.739] INFO: Resuming triggers.
[12:14:31.657] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[12:15:01.789] INFO: Resuming triggers.
[12:15:07.706] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[12:15:37.842] INFO: Resuming triggers.
[12:15:43.758] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[12:16:13.984] INFO: Resuming triggers.
[12:16:19.708] INFO: data taking finished, elapsed time: 100 seconds.
[12:16:49.096] INFO: PixTest:: pg_setup set to default.
[12:16:49.099] INFO: PixTestXray::doPhRun() done
[12:16:49.248] INFO: enter test to run
[12:17:29.487] INFO: test: HighRate no parameter change
[12:17:29.488] INFO: running: highrate
[12:17:29.489] INFO: ----------------------------------------------------------------------
[12:17:29.489] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:17:29.489] INFO: ----------------------------------------------------------------------
[12:17:29.630] INFO: Expecting 768 events.
[12:17:30.764] INFO: 768 events read in total (418ms).
[12:17:30.765] INFO: Test took 1270ms.
[12:17:31.568] INFO: Expecting 41600 events.
[12:17:34.690] INFO: 41600 events read in total (2595ms).
[12:17:34.691] INFO: Test took 3919ms.
[12:17:34.729] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:35.446] INFO: Expecting 41600 events.
[12:17:38.693] INFO: 41600 events read in total (2720ms).
[12:17:38.694] INFO: Test took 3947ms.
[12:17:38.733] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:39.452] INFO: Expecting 41600 events.
[12:17:42.738] INFO: 41600 events read in total (2759ms).
[12:17:42.739] INFO: Test took 3986ms.
[12:17:42.778] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:43.494] INFO: Expecting 41600 events.
[12:17:46.794] INFO: 41600 events read in total (2773ms).
[12:17:46.795] INFO: Test took 3997ms.
[12:17:46.834] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:47.551] INFO: Expecting 41600 events.
[12:17:50.859] INFO: 41600 events read in total (2781ms).
[12:17:50.860] INFO: Test took 4006ms.
[12:17:50.899] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:51.613] INFO: Expecting 41600 events.
[12:17:54.913] INFO: 41600 events read in total (2773ms).
[12:17:54.914] INFO: Test took 3995ms.
[12:17:54.954] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:55.665] INFO: Expecting 41600 events.
[12:17:58.961] INFO: 41600 events read in total (2769ms).
[12:17:58.962] INFO: Test took 3988ms.
[12:17:58.001] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:59.717] INFO: Expecting 41600 events.
[12:18:03.016] INFO: 41600 events read in total (2772ms).
[12:18:03.017] INFO: Test took 3995ms.
[12:18:03.056] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:03.769] INFO: Expecting 41600 events.
[12:18:07.070] INFO: 41600 events read in total (2774ms).
[12:18:07.071] INFO: Test took 3995ms.
[12:18:07.110] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:07.823] INFO: Expecting 41600 events.
[12:18:11.165] INFO: 41600 events read in total (2815ms).
[12:18:11.166] INFO: Test took 4037ms.
[12:18:11.207] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:11.920] INFO: Expecting 41600 events.
[12:18:15.199] INFO: 41600 events read in total (2753ms).
[12:18:15.200] INFO: Test took 3973ms.
[12:18:15.240] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:15.953] INFO: Expecting 41600 events.
[12:18:19.232] INFO: 41600 events read in total (2753ms).
[12:18:19.233] INFO: Test took 3973ms.
[12:18:19.273] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:19.988] INFO: Expecting 41600 events.
[12:18:23.312] INFO: 41600 events read in total (2798ms).
[12:18:23.313] INFO: Test took 4020ms.
[12:18:23.353] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:24.058] INFO: Expecting 41600 events.
[12:18:27.354] INFO: 41600 events read in total (2769ms).
[12:18:27.355] INFO: Test took 3982ms.
[12:18:27.394] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:28.107] INFO: Expecting 41600 events.
[12:18:31.447] INFO: 41600 events read in total (2813ms).
[12:18:31.448] INFO: Test took 4032ms.
[12:18:31.489] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:32.202] INFO: Expecting 41600 events.
[12:18:35.510] INFO: 41600 events read in total (2781ms).
[12:18:35.511] INFO: Test took 4003ms.
[12:18:35.551] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:36.259] INFO: Expecting 41600 events.
[12:18:39.562] INFO: 41600 events read in total (2776ms).
[12:18:39.563] INFO: Test took 3993ms.
[12:18:39.605] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:40.310] INFO: Expecting 41600 events.
[12:18:43.670] INFO: 41600 events read in total (2833ms).
[12:18:43.671] INFO: Test took 4045ms.
[12:18:43.711] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:44.422] INFO: Expecting 41600 events.
[12:18:47.722] INFO: 41600 events read in total (2773ms).
[12:18:47.723] INFO: Test took 3992ms.
[12:18:47.766] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:48.471] INFO: Expecting 41600 events.
[12:18:51.672] INFO: 41600 events read in total (2674ms).
[12:18:51.673] INFO: Test took 3886ms.
[12:18:51.713] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:52.066] INFO: enter test to run
[12:19:04.839] INFO: test: HighRate no parameter change
[12:19:04.839] INFO: running: highrate
[12:19:04.840] INFO: ----------------------------------------------------------------------
[12:19:04.840] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:19:04.840] INFO: ----------------------------------------------------------------------
[12:19:05.460] INFO: Expecting 208000 events.
[12:19:17.335] INFO: 208000 events read in total (11349ms).
[12:19:17.338] INFO: Test took 12490ms.
[12:19:17.509] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:19:17.768] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 7 0 0 0 0 0 0 0 0 0
[12:19:17.768] INFO: number of red-efficiency pixels: 113 56 91 157 179 227 235 128 117 117 132 102 111 56 30 43
[12:19:17.768] INFO: number of X-ray hits detected: 82130 52722 81453 128891 141220 145048 142924 98184 96485 107617 104447 92806 97608 57887 26099 29525
[12:19:17.768] 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:19:17.768] INFO: number of Vcal hits detected: 207886 207944 207909 207839 207816 207765 207413 207866 207877 207881 207862 207897 207886 207941 207969 207957
[12:19:17.768] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[12:19:17.768] INFO: Vcal hit overall efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.7 99.9 99.9 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[12:19:17.768] INFO: X-ray hit rate [MHz/cm2]: 24.1 15.5 23.9 37.8 41.4 42.5 41.9 28.8 28.3 31.5 30.6 27.2 28.6 17.0 7.6 8.7
[12:19:17.768] INFO: PixTestHighRate::doXPixelAlive() done
[12:19:17.816] INFO: PixTest:: pg_setup set to default.
[12:19:17.833] INFO: enter test to run
[12:19:38.895] INFO: test: HighRate no parameter change
[12:19:38.895] INFO: running: highrate
[12:19:38.896] INFO: ----------------------------------------------------------------------
[12:19:38.896] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:19:38.896] INFO: ----------------------------------------------------------------------
[12:19:39.516] INFO: Expecting 208000 events.
[12:19:54.285] INFO: 208000 events read in total (14242ms).
[12:19:54.292] INFO: Test took 15387ms.
[12:19:54.660] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:19:54.989] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 7 0 0 0 0 0 0 0 0 0
[12:19:54.989] INFO: number of red-efficiency pixels: 385 153 343 557 638 974 910 508 419 436 503 287 412 191 70 77
[12:19:54.989] INFO: number of X-ray hits detected: 172895 111424 170846 272466 298292 306770 302312 207421 203852 228979 222164 196463 204682 122797 54626 63003
[12:19:54.989] 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:19:54.989] INFO: number of Vcal hits detected: 207562 207842 207631 207388 207260 206822 206601 207426 207550 207525 207448 207691 207564 207803 207926 207922
[12:19:54.989] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.7 99.7 99.5 99.5 99.7 99.8 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[12:19:54.989] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.7 99.6 99.4 99.3 99.7 99.8 99.8 99.7 99.9 99.8 99.9 100.0 100.0
[12:19:54.989] INFO: X-ray hit rate [MHz/cm2]: 50.7 32.7 50.1 79.9 87.4 89.9 88.6 60.8 59.8 67.1 65.1 57.6 60.0 36.0 16.0 18.5
[12:19:54.989] INFO: PixTestHighRate::doXPixelAlive() done
[12:19:55.033] INFO: PixTest:: pg_setup set to default.
[12:19:55.049] INFO: enter test to run
[12:20:42.166] INFO: test: HighRate no parameter change
[12:20:42.166] INFO: running: highrate
[12:20:42.167] INFO: ----------------------------------------------------------------------
[12:20:42.167] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:20:42.167] INFO: ----------------------------------------------------------------------
[12:20:42.790] INFO: Expecting 208000 events.
[12:20:59.862] INFO: 208000 events read in total (16545ms).
[12:20:59.871] INFO: Test took 17695ms.
[12:21:00.447] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:21:00.830] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 7 0 0 0 0 0 0 0 0 0
[12:21:00.830] INFO: number of red-efficiency pixels: 814 427 707 1316 1534 2219 2076 1158 902 1098 1142 695 917 429 120 149
[12:21:00.830] INFO: number of X-ray hits detected: 261566 168186 259250 411533 450314 463491 453848 314643 309656 346052 334819 297066 311427 186131 83869 95444
[12:21:00.830] 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:21:00.830] INFO: number of Vcal hits detected: 206921 207517 207042 206250 205829 204303 204378 206303 206918 206623 206564 207158 206894 207504 207877 207844
[12:21:00.830] INFO: Vcal hit fiducial efficiency (%): 99.5 99.8 99.6 99.3 99.1 98.4 98.6 99.3 99.5 99.4 99.4 99.7 99.5 99.8 99.9 99.9
[12:21:00.830] INFO: Vcal hit overall efficiency (%): 99.5 99.8 99.5 99.2 99.0 98.2 98.3 99.2 99.5 99.3 99.3 99.6 99.5 99.8 99.9 99.9
[12:21:00.830] INFO: X-ray hit rate [MHz/cm2]: 76.7 49.3 76.0 120.6 132.0 135.9 133.0 92.2 90.8 101.4 98.1 87.1 91.3 54.6 24.6 28.0
[12:21:00.830] INFO: PixTestHighRate::doXPixelAlive() done
[12:21:00.884] INFO: PixTest:: pg_setup set to default.
[12:21:00.897] INFO: enter test to run
[12:21:09.718] INFO: test: exit no parameter change
[12:21:10.117] QUIET: Connection to board 33 closed.
[12:21:10.119] INFO: pXar: this is the end, my friend