[11:02:49.916] INFO: *** Welcome to pxar ***
[11:02:49.916] INFO: *** Today: 2016/09/14
[11:02:52.624] INFO: *** Version: v1.9.0-818-g96727
[11:02:52.624] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//dacParameters35_C15.dat
[11:02:52.905] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:02:52.906] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//defaultMaskFile.dat
[11:02:52.909] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C15.dat
[11:02:53.027] INFO: clk: 4
[11:02:53.027] INFO: ctr: 4
[11:02:53.027] INFO: sda: 19
[11:02:53.027] INFO: tin: 9
[11:02:53.027] INFO: level: 15
[11:02:53.027] INFO: triggerdelay: 0
[11:02:53.027] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:02:53.027] INFO: Log level: INFO
[11:02:53.074] QUIET: Connection to board DTB_WREKRL opened.
[11:02:53.077] 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:02:53.080] INFO: RPC call hashes of host and DTB match: 398089610
[11:02:54.650] INFO: DUT info:
[11:02:54.650] INFO: The DUT currently contains the following objects:
[11:02:54.650] INFO: 2 TBM Cores tbm08c (2 ON)
[11:02:54.673] INFO: TBM Core alpha (0): 7 registers set
[11:02:54.673] INFO: TBM Core beta (1): 7 registers set
[11:02:54.673] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:02:54.673] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:54.673] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:02:55.133] INFO: enter 'restricted' command line mode
[11:02:55.134] INFO: enter test to run
[11:02:59.516] INFO: test: PixelAlive no parameter change
[11:02:59.516] INFO: running: pixelalive
[11:02:59.595] INFO: ----------------------------------------------------------------------
[11:02:59.595] 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:02:59.595] INFO: ----------------------------------------------------------------------
[11:02:59.913] INFO: Expecting 41600 events.
[11:03:04.274] INFO: 41600 events read in total (3643ms).
[11:03:04.438] INFO: Test took 4840ms.
[11:03:04.449] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:03:05.534] INFO: PixTestAlive::aliveTest() done
[11:03:05.534] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 4 0 0 0 0 0 1 0 0
[11:03:05.901] INFO: enter test to run
[11:04:36.235] INFO: test: timing no parameter change
[11:04:36.235] INFO: running: timing
[11:04:36.255] INFO: ######################################################################
[11:04:36.255] INFO: PixTestTiming::doTest()
[11:04:36.255] INFO: ######################################################################
[11:04:36.255] INFO: ----------------------------------------------------------------------
[11:04:36.255] INFO: PixTestTiming::TBMPhaseScan()
[11:04:36.255] INFO: ----------------------------------------------------------------------
[11:11:25.422] INFO: TBM Phase Settings: 232
[11:11:25.422] INFO: 400MHz Phase: 2
[11:11:25.422] INFO: 160MHz Phase: 7
[11:11:25.422] INFO: Functional Phase Area: 3
[11:11:25.440] INFO: Test took 409185 ms.
[11:11:25.440] INFO: PixTestTiming::TBMPhaseScan() done.
[11:11:25.440] INFO: ----------------------------------------------------------------------
[11:11:25.440] INFO: PixTestTiming::ROCDelayScan()
[11:11:25.440] INFO: ----------------------------------------------------------------------
[11:15:03.956] INFO: ROC Delay Settings: 227
[11:15:03.956] INFO: ROC Header-Trailer/Token Delay: 11
[11:15:03.956] INFO: ROC Port 0 Delay: 3
[11:15:03.956] INFO: ROC Port 1 Delay: 4
[11:15:03.956] INFO: Functional ROC Area: 4
[11:15:03.959] INFO: Test took 218520 ms.
[11:15:03.960] INFO: PixTestTiming::ROCDelayScan() done.
[11:15:03.960] INFO: ----------------------------------------------------------------------
[11:15:03.960] INFO: PixTestTiming::TimingTest()
[11:15:03.960] INFO: ----------------------------------------------------------------------
[11:15:20.114] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:35.110] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:50.296] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:16:05.419] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:16:20.554] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:16:35.521] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:16:50.490] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:05.515] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:20.597] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:35.613] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:35.995] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:36.011] INFO: ----------------------------------------------------------------------
[11:17:36.011] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:17:36.011] INFO: ----------------------------------------------------------------------
[11:17:36.011] INFO: ----------------------------------------------------------------------
[11:17:36.011] INFO: Read back bit status: 1
[11:17:36.011] INFO: ----------------------------------------------------------------------
[11:17:36.011] INFO: ----------------------------------------------------------------------
[11:17:36.011] INFO: Timings are good!
[11:17:36.011] INFO: ----------------------------------------------------------------------
[11:17:36.011] INFO: Test took 152051 ms.
[11:17:36.011] INFO: PixTestTiming::TimingTest() done.
[11:17:36.045] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:17:36.046] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:17:36.046] INFO: PixTestTiming::doTest took 779794 ms.
[11:17:36.046] INFO: PixTestTiming::doTest() done
[11:17:36.046] INFO: Write out TBMPhaseScan_0_V0
[11:17:36.076] INFO: Write out TBMPhaseScan_1_V0
[11:17:36.077] INFO: Write out CombinedTBMPhaseScan_V0
[11:17:36.424] INFO: Write out ROCDelayScan3_V0
[11:17:36.435] INFO: enter test to run
[11:18:22.438] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:18:22.438] INFO: running: highrate
[11:18:22.461] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:18:22.818] INFO: ----------------------------------------------------------------------
[11:18:22.818] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:18:22.818] INFO: ----------------------------------------------------------------------
[11:18:22.818] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:18:22.818] INFO: edge/corner pixel THR is adjusted
[11:18:22.818] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:18:23.918] INFO: Collecting data for 5 seconds...
[11:18:28.937] INFO: Done with hot pixel readout
[11:18:40.588] INFO: PixTest:: pg_setup set to default.
[11:18:40.589] INFO: 4 hot pixels found in step 0
[11:18:41.580] INFO: Collecting data for 5 seconds...
[11:18:46.598] INFO: Done with hot pixel readout
[11:18:58.353] INFO: PixTest:: pg_setup set to default.
[11:18:58.354] INFO: 9 hot pixels found in step 1
[11:18:59.346] INFO: Collecting data for 5 seconds...
[11:19:04.364] INFO: Done with hot pixel readout
[11:19:16.093] INFO: PixTest:: pg_setup set to default.
[11:19:16.094] INFO: 3 hot pixels found in step 2
[11:19:17.086] INFO: Collecting data for 5 seconds...
[11:19:22.104] INFO: Done with hot pixel readout
[11:19:33.826] INFO: PixTest:: pg_setup set to default.

[11:19:33.826] INFO: 7 hot pixels found in step 3
[11:19:34.819] INFO: Collecting data for 5 seconds...
[11:19:39.838] INFO: Done with hot pixel readout
[11:19:51.918] INFO: PixTest:: pg_setup set to default.

[11:19:51.919] INFO: 8 hot pixels found in step 4
[11:19:52.911] INFO: Collecting data for 5 seconds...
[11:19:57.931] INFO: Done with hot pixel readout
[11:20:09.875] INFO: PixTest:: pg_setup set to default.
[11:20:09.876] INFO: 5 hot pixels found in step 5
[11:20:10.868] INFO: Collecting data for 5 seconds...
[11:20:15.887] INFO: Done with hot pixel readout
[11:20:27.808] INFO: PixTest:: pg_setup set to default.

[11:20:27.809] INFO: 3 hot pixels found in step 6
[11:20:28.801] INFO: Collecting data for 5 seconds...
[11:20:33.819] INFO: Done with hot pixel readout
[11:20:45.679] INFO: PixTest:: pg_setup set to default.
[11:20:45.680] INFO: 6 hot pixels found in step 7
[11:20:46.672] INFO: Collecting data for 5 seconds...
[11:20:51.692] INFO: Done with hot pixel readout
[11:21:03.587] INFO: PixTest:: pg_setup set to default.
[11:21:03.588] INFO: 3 hot pixels found in step 8
[11:21:04.580] INFO: Collecting data for 5 seconds...
[11:21:09.600] INFO: Done with hot pixel readout
[11:21:21.718] INFO: PixTest:: pg_setup set to default.
[11:21:21.719] INFO: 6 hot pixels found in step 9
[11:21:22.711] INFO: Collecting data for 5 seconds...
[11:21:27.731] INFO: Done with hot pixel readout
[11:21:39.517] INFO: PixTest:: pg_setup set to default.
[11:21:39.518] INFO: 7 hot pixels found in step 10
[11:21:40.510] INFO: Collecting data for 5 seconds...
[11:21:45.531] INFO: Done with hot pixel readout
[11:21:57.585] INFO: PixTest:: pg_setup set to default.
[11:21:57.586] INFO: 4 hot pixels found in step 11
[11:21:58.579] INFO: Collecting data for 5 seconds...
[11:22:03.598] INFO: Done with hot pixel readout
[11:22:15.571] INFO: PixTest:: pg_setup set to default.
[11:22:15.572] INFO: 6 hot pixels found in step 12
[11:22:16.565] INFO: Collecting data for 5 seconds...
[11:22:21.581] INFO: Done with hot pixel readout
[11:22:33.218] INFO: PixTest:: pg_setup set to default.

[11:22:33.219] INFO: 1 hot pixels found in step 13
[11:22:33.255] INFO: 1 hot pixels could not be trimmed and have been masked.
[11:22:33.258] INFO: PixTest::trimHotPixels() done
[11:22:33.289] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C0.dat
[11:22:33.300] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C1.dat
[11:22:33.307] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C2.dat
[11:22:33.312] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C3.dat
[11:22:33.317] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C4.dat
[11:22:33.323] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C5.dat
[11:22:33.328] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C6.dat
[11:22:33.333] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C7.dat
[11:22:33.338] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C8.dat
[11:22:33.344] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C9.dat
[11:22:33.349] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C10.dat
[11:22:33.354] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C11.dat
[11:22:33.359] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C12.dat
[11:22:33.365] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C13.dat
[11:22:33.370] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C14.dat
[11:22:33.375] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C15.dat
[11:22:33.409] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//defaultMaskFile.dat
[11:22:33.424] INFO: enter test to run
[11:23:05.644] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:23:05.644] INFO: running: highrate
[11:23:05.648] INFO: ----------------------------------------------------------------------
[11:23:05.648] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:23:05.649] INFO: ----------------------------------------------------------------------
[11:23:05.649] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:23:05.649] INFO: edge/corner pixel THR is adjusted
[11:23:05.649] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:23:06.607] INFO: Collecting data for 1 seconds...
[11:23:07.611] INFO: Done with hot pixel readout
[11:23:11.508] INFO: PixTest:: pg_setup set to default.
[11:23:11.509] INFO: 0 hot pixels found in step 0
[11:23:11.514] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:23:11.612] INFO: PixTest::trimHotPixels() done
[11:23:11.612] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C0.dat
[11:23:11.621] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C1.dat
[11:23:11.626] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C2.dat
[11:23:11.631] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C3.dat
[11:23:11.636] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C4.dat
[11:23:11.642] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C5.dat
[11:23:11.647] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C6.dat
[11:23:11.652] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C7.dat
[11:23:11.657] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C8.dat
[11:23:11.662] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C9.dat
[11:23:11.668] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C10.dat
[11:23:11.673] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C11.dat
[11:23:11.678] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C12.dat
[11:23:11.683] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C13.dat
[11:23:11.688] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C14.dat
[11:23:11.693] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//trimParameters35_C15.dat
[11:23:11.698] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-9-20_FPIXTest-17C-FNAL-160908-1209-300V_2016-09-08_12h09m_1473354553/000_FPIXTest_p17//defaultMaskFile.dat
[11:23:11.709] INFO: enter test to run
[11:23:56.739] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:23:56.740] INFO: running: xray
[11:23:56.741] INFO: ----------------------------------------------------------------------
[11:23:56.741] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:23:56.741] INFO: ----------------------------------------------------------------------
[11:23:57.725] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:24:09.254] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:24:38.790] INFO: Resuming triggers.
[11:24:50.319] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[11:25:19.408] INFO: Resuming triggers.
[11:25:30.935] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:26:00.295] INFO: Resuming triggers.
[11:26:11.822] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[11:26:41.219] INFO: Resuming triggers.
[11:26:52.747] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[11:27:22.148] INFO: Resuming triggers.
[11:27:33.674] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[11:28:02.890] INFO: Resuming triggers.
[11:28:14.416] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:28:43.771] INFO: Resuming triggers.
[11:28:55.292] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[11:29:24.640] INFO: Resuming triggers.
[11:29:32.756] INFO: data taking finished, elapsed time: 100 seconds.
[11:29:53.842] INFO: PixTest:: pg_setup set to default.
[11:29:53.846] INFO: PixTestXray::doPhRun() done
[11:29:54.114] INFO: enter test to run
[11:30:45.729] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:30:45.729] INFO: running: xray
[11:30:45.730] INFO: ----------------------------------------------------------------------
[11:30:45.730] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:30:45.730] INFO: ----------------------------------------------------------------------
[11:30:46.693] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:30:53.550] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:31:24.359] INFO: Resuming triggers.
[11:31:31.217] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[11:32:01.652] INFO: Resuming triggers.
[11:32:08.510] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[11:32:39.304] INFO: Resuming triggers.
[11:32:46.164] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[11:33:16.968] INFO: Resuming triggers.
[11:33:23.828] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:33:55.035] INFO: Resuming triggers.
[11:34:01.897] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[11:34:32.829] INFO: Resuming triggers.
[11:34:39.692] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[11:35:10.361] INFO: Resuming triggers.
[11:35:17.225] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[11:35:48.533] INFO: Resuming triggers.
[11:35:55.394] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[11:36:26.437] INFO: Resuming triggers.
[11:36:33.300] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[11:37:03.727] INFO: Resuming triggers.
[11:37:10.592] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[11:37:40.665] INFO: Resuming triggers.
[11:37:47.527] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[11:38:17.670] INFO: Resuming triggers.
[11:38:24.530] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[11:38:54.598] INFO: Resuming triggers.
[11:39:01.459] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[11:39:31.441] INFO: Resuming triggers.
[11:39:35.752] INFO: data taking finished, elapsed time: 100 seconds.
[11:39:54.863] INFO: PixTest:: pg_setup set to default.
[11:39:54.866] INFO: PixTestXray::doPhRun() done
[11:39:55.015] INFO: enter test to run
[11:41:02.997] INFO: test: HighRate no parameter change
[11:41:02.997] INFO: running: highrate
[11:41:03.009] INFO: ----------------------------------------------------------------------
[11:41:03.009] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:41:03.009] INFO: ----------------------------------------------------------------------
[11:41:03.166] INFO: Expecting 768 events.
[11:41:04.300] INFO: 768 events read in total (418ms).
[11:41:04.301] INFO: Test took 1269ms.
[11:41:05.104] INFO: Expecting 41600 events.
[11:41:08.196] INFO: 41600 events read in total (2565ms).
[11:41:08.197] INFO: Test took 3833ms.
[11:41:08.232] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:08.959] INFO: Expecting 41600 events.
[11:41:12.179] INFO: 41600 events read in total (2693ms).
[11:41:12.180] INFO: Test took 3930ms.
[11:41:12.214] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:12.938] INFO: Expecting 41600 events.
[11:41:16.177] INFO: 41600 events read in total (2712ms).
[11:41:16.178] INFO: Test took 3945ms.
[11:41:16.213] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:16.936] INFO: Expecting 41600 events.
[11:41:20.172] INFO: 41600 events read in total (2709ms).
[11:41:20.173] INFO: Test took 3942ms.
[11:41:20.208] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:20.928] INFO: Expecting 41600 events.
[11:41:24.170] INFO: 41600 events read in total (2715ms).
[11:41:24.171] INFO: Test took 3944ms.
[11:41:24.207] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:24.927] INFO: Expecting 41600 events.
[11:41:28.176] INFO: 41600 events read in total (2722ms).
[11:41:28.177] INFO: Test took 3952ms.
[11:41:28.212] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:28.933] INFO: Expecting 41600 events.
[11:41:32.176] INFO: 41600 events read in total (2716ms).
[11:41:32.177] INFO: Test took 3947ms.
[11:41:32.231] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:32.935] INFO: Expecting 41600 events.
[11:41:36.180] INFO: 41600 events read in total (2718ms).
[11:41:36.181] INFO: Test took 3931ms.
[11:41:36.215] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:36.936] INFO: Expecting 41600 events.
[11:41:40.143] INFO: 41600 events read in total (2680ms).
[11:41:40.144] INFO: Test took 3911ms.
[11:41:40.179] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:40.902] INFO: Expecting 41600 events.
[11:41:44.149] INFO: 41600 events read in total (2720ms).
[11:41:44.150] INFO: Test took 3953ms.
[11:41:44.186] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:44.905] INFO: Expecting 41600 events.
[11:41:48.145] INFO: 41600 events read in total (2713ms).
[11:41:48.146] INFO: Test took 3942ms.
[11:41:48.180] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:48.902] INFO: Expecting 41600 events.
[11:41:52.140] INFO: 41600 events read in total (2711ms).
[11:41:52.141] INFO: Test took 3942ms.
[11:41:52.175] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:52.896] INFO: Expecting 41600 events.
[11:41:56.137] INFO: 41600 events read in total (2714ms).
[11:41:56.138] INFO: Test took 3943ms.
[11:41:56.174] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:56.892] INFO: Expecting 41600 events.
[11:42:00.149] INFO: 41600 events read in total (2730ms).
[11:42:00.150] INFO: Test took 3958ms.
[11:42:00.185] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:00.909] INFO: Expecting 41600 events.
[11:42:04.154] INFO: 41600 events read in total (2718ms).
[11:42:04.155] INFO: Test took 3951ms.
[11:42:04.190] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:04.913] INFO: Expecting 41600 events.
[11:42:08.165] INFO: 41600 events read in total (2725ms).
[11:42:08.166] INFO: Test took 3958ms.
[11:42:08.201] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:08.925] INFO: Expecting 41600 events.
[11:42:12.191] INFO: 41600 events read in total (2739ms).
[11:42:12.192] INFO: Test took 3973ms.
[11:42:12.227] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:12.945] INFO: Expecting 41600 events.
[11:42:16.190] INFO: 41600 events read in total (2718ms).
[11:42:16.191] INFO: Test took 3944ms.
[11:42:16.227] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:16.949] INFO: Expecting 41600 events.
[11:42:20.195] INFO: 41600 events read in total (2719ms).
[11:42:20.196] INFO: Test took 3952ms.
[11:42:20.231] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:20.951] INFO: Expecting 41600 events.
[11:42:24.072] INFO: 41600 events read in total (2594ms).
[11:42:24.073] INFO: Test took 3823ms.
[11:42:24.106] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:42:24.468] INFO: enter test to run
[11:43:14.900] INFO: test: HighRate no parameter change
[11:43:14.900] INFO: running: highrate
[11:43:14.901] INFO: ----------------------------------------------------------------------
[11:43:14.901] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:43:14.901] INFO: ----------------------------------------------------------------------
[11:43:15.528] INFO: Expecting 208000 events.
[11:43:27.690] INFO: 208000 events read in total (11635ms).
[11:43:27.693] INFO: Test took 12774ms.
[11:43:27.843] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:43:28.097] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 76 0 0 0 0 0 1 0 0
[11:43:28.097] INFO: number of red-efficiency pixels: 94 64 124 142 147 147 108 279 105 119 115 96 112 70 29 27
[11:43:28.097] INFO: number of X-ray hits detected: 72332 45166 67221 102445 106620 108006 110144 148415 75929 95097 93773 80890 82861 52566 22303 23364
[11:43:28.097] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:43:28.097] INFO: number of Vcal hits detected: 207904 207934 207876 207853 207851 207847 207889 200095 207891 207878 207883 207903 207885 207880 207970 207972
[11:43:28.097] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 97.9 99.9 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[11:43:28.097] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 96.2 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0
[11:43:28.097] INFO: X-ray hit rate [MHz/cm2]: 21.2 13.2 19.7 30.0 31.3 31.7 32.3 43.5 22.3 27.9 27.5 23.7 24.3 15.4 6.5 6.8
[11:43:28.097] INFO: PixTestHighRate::doXPixelAlive() done
[11:43:28.143] INFO: PixTest:: pg_setup set to default.
[11:43:28.155] INFO: enter test to run
[11:44:07.835] INFO: test: HighRate no parameter change
[11:44:07.835] INFO: running: highrate
[11:44:07.836] INFO: ----------------------------------------------------------------------
[11:44:07.836] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:44:07.836] INFO: ----------------------------------------------------------------------
[11:44:08.458] INFO: Expecting 208000 events.
[11:44:22.062] INFO: 208000 events read in total (13077ms).
[11:44:22.070] INFO: Test took 14225ms.
[11:44:22.370] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:22.673] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 78 0 0 0 0 0 1 0 0
[11:44:22.674] INFO: number of red-efficiency pixels: 273 122 307 422 422 509 400 456 263 370 385 262 283 177 56 64
[11:44:22.674] INFO: number of X-ray hits detected: 147965 91662 137718 209496 218852 222308 225840 234291 155232 194753 191105 165174 170539 106838 45475 47645
[11:44:22.674] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:44:22.674] INFO: number of Vcal hits detected: 207706 207871 207642 207545 207534 207453 207565 199845 207720 207607 207589 207726 207703 207765 207944 207936
[11:44:22.674] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.8 99.8 97.9 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[11:44:22.674] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.7 99.8 96.1 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[11:44:22.674] INFO: X-ray hit rate [MHz/cm2]: 43.4 26.9 40.4 61.4 64.1 65.2 66.2 68.7 45.5 57.1 56.0 48.4 50.0 31.3 13.3 14.0
[11:44:22.674] INFO: PixTestHighRate::doXPixelAlive() done
[11:44:22.721] INFO: PixTest:: pg_setup set to default.
[11:44:22.745] INFO: enter test to run
[11:44:41.939] INFO: test: HighRate no parameter change
[11:44:41.939] INFO: running: highrate
[11:44:41.940] INFO: ----------------------------------------------------------------------
[11:44:41.940] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:44:41.940] INFO: ----------------------------------------------------------------------
[11:44:42.562] INFO: Expecting 208000 events.
[11:44:57.919] INFO: 208000 events read in total (14830ms).
[11:44:57.928] INFO: Test took 15979ms.
[11:44:58.352] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:44:58.702] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 77 0 0 0 0 0 1 0 0
[11:44:58.702] INFO: number of red-efficiency pixels: 611 229 694 1013 986 1058 943 803 606 893 793 532 713 434 90 88
[11:44:58.702] INFO: number of X-ray hits detected: 223175 138634 207997 315775 329745 334608 339079 314378 234580 293451 287970 248059 256693 162882 68379 72216
[11:44:58.702] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:44:58.702] INFO: number of Vcal hits detected: 207180 207749 207054 206760 206767 206670 206841 199377 207311 206934 207064 207404 207192 207445 207909 207910
[11:44:58.702] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.5 99.5 99.4 99.5 97.6 99.7 99.5 99.6 99.7 99.7 99.8 100.0 100.0
[11:44:58.702] INFO: Vcal hit overall efficiency (%): 99.6 99.9 99.5 99.4 99.4 99.4 99.4 95.9 99.7 99.5 99.6 99.7 99.6 99.7 100.0 100.0
[11:44:58.702] INFO: X-ray hit rate [MHz/cm2]: 65.4 40.6 61.0 92.6 96.7 98.1 99.4 92.1 68.8 86.0 84.4 72.7 75.2 47.7 20.0 21.2
[11:44:58.702] INFO: PixTestHighRate::doXPixelAlive() done
[11:44:58.748] INFO: PixTest:: pg_setup set to default.
[11:44:58.761] INFO: enter test to run
[11:45:43.842] INFO: test: exit no parameter change
[11:45:44.971] QUIET: Connection to board 33 closed.
[11:45:45.193] INFO: pXar: this is the end, my friend