[15:42:14.932] INFO: *** Welcome to pxar ***
[15:42:14.932] INFO: *** Today: 2016/06/08
[15:42:14.945] INFO: *** Version: v1.9.0-814-g7497
[15:42:14.945] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//dacParameters35_C15.dat
[15:42:14.946] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:42:14.946] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//defaultMaskFile.dat
[15:42:14.946] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C15.dat
[15:42:15.017] INFO: clk: 4
[15:42:15.017] INFO: ctr: 4
[15:42:15.017] INFO: sda: 19
[15:42:15.017] INFO: tin: 9
[15:42:15.017] INFO: level: 15
[15:42:15.017] INFO: triggerdelay: 0
[15:42:15.017] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:42:15.017] INFO: Log level: INFO
[15:42:15.034] QUIET: Connection to board DTB_WREKRL opened.
[15:42:15.037] 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:42:15.040] INFO: RPC call hashes of host and DTB match: 398089610
[15:42:16.573] INFO: DUT info:
[15:42:16.573] INFO: The DUT currently contains the following objects:
[15:42:16.573] INFO: 2 TBM Cores tbm08c (2 ON)
[15:42:16.573] INFO: TBM Core alpha (0): 7 registers set
[15:42:16.573] INFO: TBM Core beta (1): 7 registers set
[15:42:16.573] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:42:16.573] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.573] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.573] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.574] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:42:16.977] INFO: enter 'restricted' command line mode
[15:42:16.977] INFO: enter test to run
[15:42:18.797] INFO: test: timing no parameter change
[15:42:18.797] INFO: running: timing
[15:42:18.805] INFO: ######################################################################
[15:42:18.805] INFO: PixTestTiming::doTest()
[15:42:18.805] INFO: ######################################################################
[15:42:18.806] INFO: ----------------------------------------------------------------------
[15:42:18.806] INFO: PixTestTiming::TBMPhaseScan()
[15:42:18.806] INFO: ----------------------------------------------------------------------
[15:46:36.579] INFO: TBM Phase Settings: 212
[15:46:36.579] INFO: 400MHz Phase: 5
[15:46:36.579] INFO: 160MHz Phase: 6
[15:46:36.579] INFO: Functional Phase Area: 4
[15:46:36.588] INFO: Test took 257782 ms.
[15:46:36.588] INFO: PixTestTiming::TBMPhaseScan() done.
[15:46:36.589] INFO: ----------------------------------------------------------------------
[15:46:36.589] INFO: PixTestTiming::ROCDelayScan()
[15:46:36.589] INFO: ----------------------------------------------------------------------
[15:48:32.112] INFO: ROC Delay Settings: 219
[15:48:32.112] INFO: ROC Header-Trailer/Token Delay: 11
[15:48:32.112] INFO: ROC Port 0 Delay: 3
[15:48:32.112] INFO: ROC Port 1 Delay: 3
[15:48:32.112] INFO: Functional ROC Area: 4
[15:48:32.115] INFO: Test took 115527 ms.
[15:48:32.115] INFO: PixTestTiming::ROCDelayScan() done.
[15:48:32.115] INFO: ----------------------------------------------------------------------
[15:48:32.115] INFO: PixTestTiming::TimingTest()
[15:48:32.115] INFO: ----------------------------------------------------------------------
[15:48:48.367] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:03.425] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:18.483] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:33.527] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:48.540] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:03.567] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:18.556] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:33.578] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:48.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:03.589] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:03.967] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:03.984] INFO: ----------------------------------------------------------------------
[15:51:03.984] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:51:03.984] INFO: ----------------------------------------------------------------------
[15:51:03.984] INFO: ----------------------------------------------------------------------
[15:51:03.984] INFO: Read back bit status: 1
[15:51:03.984] INFO: ----------------------------------------------------------------------
[15:51:03.984] INFO: ----------------------------------------------------------------------
[15:51:03.984] INFO: Timings are good!
[15:51:03.984] INFO: ----------------------------------------------------------------------
[15:51:03.984] INFO: Test took 151869 ms.
[15:51:03.984] INFO: PixTestTiming::TimingTest() done.
[15:51:03.985] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:51:03.985] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:51:03.985] INFO: PixTestTiming::doTest took 525184 ms.
[15:51:03.985] INFO: PixTestTiming::doTest() done
[15:51:03.985] INFO: Write out TBMPhaseScan_0_V0
[15:51:04.013] INFO: Write out TBMPhaseScan_1_V0
[15:51:04.013] INFO: Write out CombinedTBMPhaseScan_V0
[15:51:04.025] INFO: Write out ROCDelayScan3_V0
[15:51:04.026] INFO: enter test to run
[15:53:08.640] INFO: test: PixelAlive no parameter change
[15:53:08.640] INFO: running: pixelalive
[15:53:08.644] INFO: ----------------------------------------------------------------------
[15:53:08.644] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[15:53:08.644] INFO: ----------------------------------------------------------------------
[15:53:08.969] INFO: Expecting 41600 events.
[15:53:13.291] INFO: 41600 events read in total (3606ms).
[15:53:13.292] INFO: Test took 4645ms.
[15:53:13.298] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:53:13.691] INFO: PixTestAlive::aliveTest() done
[15:53:13.691] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[15:53:13.693] INFO: enter test to run
[15:53:24.647] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:53:24.647] INFO: running: highrate
[15:53:24.648] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:53:24.810] INFO: ----------------------------------------------------------------------
[15:53:24.810] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:53:24.810] INFO: ----------------------------------------------------------------------
[15:53:24.810] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:53:24.810] INFO: edge/corner pixel THR is adjusted
[15:53:24.810] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:53:25.768] INFO: Collecting data for 5 seconds...
[15:53:30.787] INFO: Done with hot pixel readout
[15:53:43.588] INFO: PixTest:: pg_setup set to default.
[15:53:43.589] INFO: 37 hot pixels found in step 0
[15:53:44.589] INFO: Collecting data for 5 seconds...
[15:53:49.606] INFO: Done with hot pixel readout
[15:54:02.090] INFO: PixTest:: pg_setup set to default.
[15:54:02.091] INFO: 34 hot pixels found in step 1
[15:54:03.090] INFO: Collecting data for 5 seconds...
[15:54:08.106] INFO: Done with hot pixel readout
[15:54:20.729] INFO: PixTest:: pg_setup set to default.

[15:54:20.729] INFO: 33 hot pixels found in step 2
[15:54:21.728] INFO: Collecting data for 5 seconds...
[15:54:26.747] INFO: Done with hot pixel readout
[15:54:39.432] INFO: PixTest:: pg_setup set to default.
[15:54:39.433] INFO: 19 hot pixels found in step 3
[15:54:40.432] INFO: Collecting data for 5 seconds...
[15:54:45.451] INFO: Done with hot pixel readout
[15:54:58.441] INFO: PixTest:: pg_setup set to default.

[15:54:58.442] INFO: 25 hot pixels found in step 4
[15:54:59.442] INFO: Collecting data for 5 seconds...
[15:55:04.462] INFO: Done with hot pixel readout
[15:55:17.489] INFO: PixTest:: pg_setup set to default.


[15:55:17.490] INFO: 30 hot pixels found in step 5
[15:55:18.489] INFO: Collecting data for 5 seconds...
[15:55:23.509] INFO: Done with hot pixel readout
[15:55:36.406] INFO: PixTest:: pg_setup set to default.



[15:55:36.407] INFO: 32 hot pixels found in step 6
[15:55:37.406] INFO: Collecting data for 5 seconds...
[15:55:42.426] INFO: Done with hot pixel readout
[15:55:55.010] INFO: PixTest:: pg_setup set to default.
[15:55:55.011] INFO: 30 hot pixels found in step 7
[15:55:56.008] INFO: Collecting data for 5 seconds...
[15:56:01.026] INFO: Done with hot pixel readout
[15:56:14.012] INFO: PixTest:: pg_setup set to default.


[15:56:14.013] INFO: 27 hot pixels found in step 8
[15:56:15.012] INFO: Collecting data for 5 seconds...
[15:56:20.033] INFO: Done with hot pixel readout
[15:56:32.842] INFO: PixTest:: pg_setup set to default.


[15:56:32.843] INFO: 20 hot pixels found in step 9
[15:56:33.842] INFO: Collecting data for 5 seconds...
[15:56:38.858] INFO: Done with hot pixel readout
[15:56:51.497] INFO: PixTest:: pg_setup set to default.



[15:56:51.498] INFO: 32 hot pixels found in step 10
[15:56:52.497] INFO: Collecting data for 5 seconds...
[15:56:57.513] INFO: Done with hot pixel readout
[15:57:10.183] INFO: PixTest:: pg_setup set to default.



[15:57:10.184] INFO: 24 hot pixels found in step 11
[15:57:11.183] INFO: Collecting data for 5 seconds...
[15:57:16.198] INFO: Done with hot pixel readout
[15:57:28.829] INFO: PixTest:: pg_setup set to default.

[15:57:28.830] INFO: 20 hot pixels found in step 12
[15:57:29.828] INFO: Collecting data for 5 seconds...
[15:57:34.844] INFO: Done with hot pixel readout
[15:57:47.441] INFO: PixTest:: pg_setup set to default.


[15:57:47.443] INFO: 23 hot pixels found in step 13
[15:57:48.442] INFO: Collecting data for 5 seconds...
[15:57:53.458] INFO: Done with hot pixel readout
[15:58:06.091] INFO: PixTest:: pg_setup set to default.
[15:58:06.092] INFO: 15 hot pixels found in step 14
[15:58:06.134] INFO: 15 hot pixels could not be trimmed and have been masked.
[15:58:06.137] INFO: PixTest::trimHotPixels() done
[15:58:06.138] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C0.dat
[15:58:06.150] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C1.dat
[15:58:06.158] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C2.dat
[15:58:06.163] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C3.dat
[15:58:06.168] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C4.dat
[15:58:06.174] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C5.dat
[15:58:06.179] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C6.dat
[15:58:06.185] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C7.dat
[15:58:06.191] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C8.dat
[15:58:06.196] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C9.dat
[15:58:06.201] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C10.dat
[15:58:06.206] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C11.dat
[15:58:06.213] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C12.dat
[15:58:06.218] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C13.dat
[15:58:06.223] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C14.dat
[15:58:06.229] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C15.dat
[15:58:06.234] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//defaultMaskFile.dat
[15:58:06.250] INFO: enter test to run
[16:00:11.956] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200HighRate:trimhotpixels runsecondshotpixels=1;trimhotpixelthr=200<-
[16:00:11.956] INFO: running: highrate
[16:00:11.961] INFO: ----------------------------------------------------------------------
[16:00:11.961] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:00:11.961] INFO: ----------------------------------------------------------------------
[16:00:11.961] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:00:11.961] INFO: edge/corner pixel THR is adjusted
[16:00:11.961] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:00:12.919] INFO: Collecting data for 1 seconds...
[16:00:13.923] INFO: Done with hot pixel readout
[16:00:18.420] INFO: PixTest:: pg_setup set to default.
[16:00:18.421] INFO: 0 hot pixels found in step 0
[16:00:18.426] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:00:18.498] INFO: PixTest::trimHotPixels() done
[16:00:18.498] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C0.dat
[16:00:18.507] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C1.dat
[16:00:18.515] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C2.dat
[16:00:18.521] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C3.dat
[16:00:18.526] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C4.dat
[16:00:18.531] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C5.dat
[16:00:18.537] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C6.dat
[16:00:18.542] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C7.dat
[16:00:18.547] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C8.dat
[16:00:18.553] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C9.dat
[16:00:18.558] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C10.dat
[16:00:18.563] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C11.dat
[16:00:18.569] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C12.dat
[16:00:18.574] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C13.dat
[16:00:18.579] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C14.dat
[16:00:18.585] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//trimParameters35_C15.dat
[16:00:18.590] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-T-NP_FPIXTest-17C-FNAL-160602-1208_2016-06-02_12h08m_1464887318/000_FPIXTest_p17//defaultMaskFile.dat
[16:00:18.600] INFO: enter test to run
[16:04:43.370] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:04:43.370] INFO: running: xray
[16:04:43.372] INFO: ----------------------------------------------------------------------
[16:04:43.372] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:04:43.372] INFO: ----------------------------------------------------------------------
[16:04:44.335] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:04:54.797] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[16:05:24.556] INFO: Resuming triggers.
[16:05:35.020] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[16:06:05.347] INFO: Resuming triggers.
[16:06:15.810] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[16:06:46.443] INFO: Resuming triggers.
[16:06:56.908] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[16:07:27.727] INFO: Resuming triggers.
[16:07:38.196] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[16:08:08.126] INFO: Resuming triggers.
[16:08:18.591] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[16:08:48.272] INFO: Resuming triggers.
[16:08:58.740] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[16:09:28.401] INFO: Resuming triggers.
[16:09:38.871] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[16:10:08.511] INFO: Resuming triggers.
[16:10:18.976] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[16:10:48.702] INFO: Resuming triggers.
[16:10:54.857] INFO: data taking finished, elapsed time: 100 seconds.
[16:11:12.680] INFO: PixTest:: pg_setup set to default.
[16:11:12.683] INFO: PixTestXray::doPhRun() done
[16:11:12.820] INFO: enter test to run
[16:12:28.063] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:12:28.063] INFO: running: xray
[16:12:28.064] INFO: ----------------------------------------------------------------------
[16:12:28.064] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:12:28.064] INFO: ----------------------------------------------------------------------
[16:12:29.028] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:12:34.794] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[16:13:04.960] INFO: Resuming triggers.
[16:13:10.726] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[16:13:40.917] INFO: Resuming triggers.
[16:13:46.685] INFO: run duration 17 seconds, buffer almost full (81%), pausing triggers.
[16:14:16.863] INFO: Resuming triggers.
[16:14:22.628] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[16:14:52.801] INFO: Resuming triggers.
[16:14:58.566] INFO: run duration 28 seconds, buffer almost full (81%), pausing triggers.
[16:15:28.722] INFO: Resuming triggers.
[16:15:34.488] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[16:16:04.664] INFO: Resuming triggers.
[16:16:10.432] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[16:16:41.097] INFO: Resuming triggers.
[16:16:46.862] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[16:17:17.634] INFO: Resuming triggers.
[16:17:23.399] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[16:17:54.745] INFO: Resuming triggers.
[16:18:00.512] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[16:18:31.628] INFO: Resuming triggers.
[16:18:37.392] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[16:19:08.780] INFO: Resuming triggers.
[16:19:14.547] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[16:19:44.404] INFO: Resuming triggers.
[16:19:50.173] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[16:20:20.366] INFO: Resuming triggers.
[16:20:26.135] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[16:20:56.276] INFO: Resuming triggers.
[16:21:02.042] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[16:21:32.099] INFO: Resuming triggers.
[16:21:37.868] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[16:22:08.112] INFO: Resuming triggers.
[16:22:13.877] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[16:22:44.168] INFO: Resuming triggers.
[16:22:46.467] INFO: data taking finished, elapsed time: 100 seconds.
[16:22:58.749] INFO: PixTest:: pg_setup set to default.
[16:22:58.752] INFO: PixTestXray::doPhRun() done
[16:22:58.900] INFO: enter test to run
[16:26:07.017] INFO: test: HighRate no parameter change
[16:26:07.017] INFO: running: highrate
[16:26:07.037] INFO: ----------------------------------------------------------------------
[16:26:07.037] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:26:07.037] INFO: ----------------------------------------------------------------------
[16:26:07.177] INFO: Expecting 768 events.
[16:26:08.311] INFO: 768 events read in total (418ms).
[16:26:08.312] INFO: Test took 1269ms.
[16:26:09.115] INFO: Expecting 41600 events.
[16:26:12.298] INFO: 41600 events read in total (2656ms).
[16:26:12.299] INFO: Test took 3979ms.
[16:26:12.346] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:13.055] INFO: Expecting 41600 events.
[16:26:16.318] INFO: 41600 events read in total (2736ms).
[16:26:16.319] INFO: Test took 3951ms.
[16:26:16.360] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:17.069] INFO: Expecting 41600 events.
[16:26:20.379] INFO: 41600 events read in total (2783ms).
[16:26:20.381] INFO: Test took 3999ms.
[16:26:20.422] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:21.134] INFO: Expecting 41600 events.
[16:26:24.451] INFO: 41600 events read in total (2790ms).
[16:26:24.453] INFO: Test took 4009ms.
[16:26:24.496] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:25.206] INFO: Expecting 41600 events.
[16:26:28.538] INFO: 41600 events read in total (2805ms).
[16:26:28.539] INFO: Test took 4023ms.
[16:26:28.582] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:29.290] INFO: Expecting 41600 events.
[16:26:32.608] INFO: 41600 events read in total (2791ms).
[16:26:32.609] INFO: Test took 4007ms.
[16:26:32.651] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:33.361] INFO: Expecting 41600 events.
[16:26:36.676] INFO: 41600 events read in total (2788ms).
[16:26:36.677] INFO: Test took 4006ms.
[16:26:36.720] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:37.429] INFO: Expecting 41600 events.
[16:26:40.763] INFO: 41600 events read in total (2807ms).
[16:26:40.765] INFO: Test took 4023ms.
[16:26:40.808] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:41.514] INFO: Expecting 41600 events.
[16:26:44.845] INFO: 41600 events read in total (2804ms).
[16:26:44.846] INFO: Test took 4016ms.
[16:26:44.889] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:45.594] INFO: Expecting 41600 events.
[16:26:48.915] INFO: 41600 events read in total (2794ms).
[16:26:48.916] INFO: Test took 4005ms.
[16:26:48.959] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:49.666] INFO: Expecting 41600 events.
[16:26:52.995] INFO: 41600 events read in total (2802ms).
[16:26:52.996] INFO: Test took 4016ms.
[16:26:53.039] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:53.746] INFO: Expecting 41600 events.
[16:26:57.061] INFO: 41600 events read in total (2788ms).
[16:26:57.062] INFO: Test took 4000ms.
[16:26:57.104] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:57.813] INFO: Expecting 41600 events.
[16:27:01.143] INFO: 41600 events read in total (2803ms).
[16:27:01.144] INFO: Test took 4019ms.
[16:27:01.187] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:01.895] INFO: Expecting 41600 events.
[16:27:05.212] INFO: 41600 events read in total (2790ms).
[16:27:05.213] INFO: Test took 4005ms.
[16:27:05.255] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:05.964] INFO: Expecting 41600 events.
[16:27:09.293] INFO: 41600 events read in total (2802ms).
[16:27:09.294] INFO: Test took 4017ms.
[16:27:09.337] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:10.046] INFO: Expecting 41600 events.
[16:27:13.371] INFO: 41600 events read in total (2798ms).
[16:27:13.372] INFO: Test took 4014ms.
[16:27:13.415] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:14.124] INFO: Expecting 41600 events.
[16:27:17.451] INFO: 41600 events read in total (2800ms).
[16:27:17.452] INFO: Test took 4017ms.
[16:27:17.494] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:18.205] INFO: Expecting 41600 events.
[16:27:21.540] INFO: 41600 events read in total (2808ms).
[16:27:21.541] INFO: Test took 4025ms.
[16:27:21.584] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:22.290] INFO: Expecting 41600 events.
[16:27:25.587] INFO: 41600 events read in total (2770ms).
[16:27:25.588] INFO: Test took 3982ms.
[16:27:25.630] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:26.340] INFO: Expecting 41600 events.
[16:27:29.494] INFO: 41600 events read in total (2627ms).
[16:27:29.495] INFO: Test took 3843ms.
[16:27:29.536] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:29.887] INFO: enter test to run
[16:27:42.368] INFO: test: HighRate no parameter change
[16:27:42.368] INFO: running: highrate
[16:27:42.369] INFO: ----------------------------------------------------------------------
[16:27:42.369] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:27:42.369] INFO: ----------------------------------------------------------------------
[16:27:42.990] INFO: Expecting 208000 events.
[16:27:55.372] INFO: 208000 events read in total (11855ms).
[16:27:55.375] INFO: Test took 12997ms.
[16:27:55.566] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:55.835] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:27:55.835] INFO: number of red-efficiency pixels: 94 92 131 216 181 188 206 129 131 199 184 121 137 77 34 37
[16:27:55.836] INFO: number of X-ray hits detected: 82366 56655 84726 138684 148739 149482 147160 105729 102562 134470 132767 114634 114717 68897 29306 29763
[16:27:55.836] 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:27:55.836] INFO: number of Vcal hits detected: 207905 207906 207866 207773 207810 207806 207789 207869 207866 207794 207812 207877 207861 207923 207965 207963
[16:27:55.836] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[16:27:55.836] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[16:27:55.836] INFO: X-ray hit rate [MHz/cm2]: 24.1 16.6 24.8 40.6 43.6 43.8 43.1 31.0 30.1 39.4 38.9 33.6 33.6 20.2 8.6 8.7
[16:27:55.836] INFO: PixTestHighRate::doXPixelAlive() done
[16:27:55.886] INFO: PixTest:: pg_setup set to default.
[16:27:55.898] INFO: enter test to run
[16:29:17.288] INFO: test: HighRate no parameter change
[16:29:17.288] INFO: running: highrate
[16:29:17.289] INFO: ----------------------------------------------------------------------
[16:29:17.289] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:29:17.289] INFO: ----------------------------------------------------------------------
[16:29:17.912] INFO: Expecting 208000 events.
[16:29:32.735] INFO: 208000 events read in total (14296ms).
[16:29:32.741] INFO: Test took 15441ms.
[16:29:33.121] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:29:33.453] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:29:33.453] INFO: number of red-efficiency pixels: 354 221 435 787 671 616 613 387 401 708 696 420 384 311 74 82
[16:29:33.453] INFO: number of X-ray hits detected: 165118 114919 170257 278307 298659 300736 297309 214089 207149 269280 267946 230549 229518 138620 58564 60320
[16:29:33.453] 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:29:33.453] INFO: number of Vcal hits detected: 207602 207762 207493 207094 207242 207310 207324 207565 207570 207222 207221 207551 207591 207655 207926 207916
[16:29:33.453] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.6 99.7 99.7 99.7 99.8 99.8 99.7 99.7 99.8 99.8 99.9 100.0 100.0
[16:29:33.453] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.6 99.6 99.7 99.7 99.8 99.8 99.6 99.6 99.8 99.8 99.8 100.0 100.0
[16:29:33.453] INFO: X-ray hit rate [MHz/cm2]: 48.4 33.7 49.9 81.6 87.5 88.1 87.1 62.8 60.7 78.9 78.5 67.6 67.3 40.6 17.2 17.7
[16:29:33.453] INFO: PixTestHighRate::doXPixelAlive() done
[16:29:33.500] INFO: PixTest:: pg_setup set to default.
[16:29:33.516] INFO: enter test to run
[16:31:11.815] INFO: test: HighRate no parameter change
[16:31:11.815] INFO: running: highrate
[16:31:11.816] INFO: ----------------------------------------------------------------------
[16:31:11.816] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:31:11.816] INFO: ----------------------------------------------------------------------
[16:31:12.433] INFO: Expecting 208000 events.
[16:31:29.564] INFO: 208000 events read in total (16604ms).
[16:31:29.573] INFO: Test took 17747ms.
[16:31:30.131] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:31:30.521] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[16:31:30.521] INFO: number of red-efficiency pixels: 715 441 959 1805 1474 1471 1414 881 891 1705 1655 951 942 768 134 117
[16:31:30.521] INFO: number of X-ray hits detected: 249433 171768 258440 419358 449310 451802 448144 321644 311402 405731 402441 347847 347432 209503 89437 90966
[16:31:30.521] 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:31:30.521] INFO: number of Vcal hits detected: 207109 207500 206522 205253 205972 205952 206063 206857 206832 205549 205627 206820 206869 206991 207856 207880
[16:31:30.521] INFO: Vcal hit fiducial efficiency (%): 99.6 99.8 99.4 98.8 99.1 99.1 99.2 99.5 99.5 98.9 99.0 99.5 99.5 99.6 99.9 99.9
[16:31:30.521] INFO: Vcal hit overall efficiency (%): 99.6 99.8 99.3 98.7 99.0 99.0 99.1 99.5 99.4 98.8 98.9 99.4 99.5 99.5 99.9 99.9
[16:31:30.521] INFO: X-ray hit rate [MHz/cm2]: 73.1 50.3 75.8 122.9 131.7 132.4 131.4 94.3 91.3 118.9 118.0 102.0 101.8 61.4 26.2 26.7
[16:31:30.521] INFO: PixTestHighRate::doXPixelAlive() done
[16:31:30.569] INFO: PixTest:: pg_setup set to default.
[16:31:30.588] INFO: enter test to run
[16:31:39.846] INFO: test: exit no parameter change
[16:31:40.270] QUIET: Connection to board 33 closed.
[16:31:40.272] INFO: pXar: this is the end, my friend