[11:04:18.268] INFO: *** Welcome to pxar ***
[11:04:18.268] INFO: *** Today: 2016/04/12
[11:04:18.288] INFO: *** Version: v1.9.0-796-gef167-dirty
[11:04:18.288] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//dacParameters35_C15.dat
[11:04:18.289] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:04:18.289] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//defaultMaskFile.dat
[11:04:18.289] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C15.dat
[11:04:18.365] INFO: clk: 4
[11:04:18.365] INFO: ctr: 4
[11:04:18.365] INFO: sda: 19
[11:04:18.365] INFO: tin: 9
[11:04:18.365] INFO: level: 15
[11:04:18.365] INFO: triggerdelay: 0
[11:04:18.365] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[11:04:18.365] INFO: Log level: INFO
[11:04:18.383] QUIET: Connection to board DTB_WREKRL opened.
[11:04:18.386] 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:04:18.389] INFO: RPC call hashes of host and DTB match: 398089610
[11:04:19.915] INFO: DUT info:
[11:04:19.915] INFO: The DUT currently contains the following objects:
[11:04:19.915] INFO: 2 TBM Cores tbm08c (2 ON)
[11:04:19.915] INFO: TBM Core alpha (0): 7 registers set
[11:04:19.915] INFO: TBM Core beta (1): 7 registers set
[11:04:19.915] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:04:19.915] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.915] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:19.916] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:04:20.319] INFO: enter 'restricted' command line mode
[11:04:20.319] INFO: enter test to run
[11:04:29.940] INFO: test: timing no parameter change
[11:04:29.940] INFO: running: timing
[11:04:29.949] INFO: ######################################################################
[11:04:29.949] INFO: PixTestTiming::doTest()
[11:04:29.949] INFO: ######################################################################
[11:04:29.949] INFO: ----------------------------------------------------------------------
[11:04:29.949] INFO: PixTestTiming::TBMPhaseScan()
[11:04:29.949] INFO: ----------------------------------------------------------------------
[11:09:02.787] INFO: TBM Phase Settings: 236
[11:09:02.787] INFO: 400MHz Phase: 3
[11:09:02.787] INFO: 160MHz Phase: 7
[11:09:02.787] INFO: Functional Phase Area: 4
[11:09:02.790] INFO: Test took 272841 ms.
[11:09:02.790] INFO: PixTestTiming::TBMPhaseScan() done.
[11:09:02.791] INFO: ----------------------------------------------------------------------
[11:09:02.791] INFO: PixTestTiming::ROCDelayScan()
[11:09:02.791] INFO: ----------------------------------------------------------------------
[11:11:02.592] INFO: ROC Delay Settings: 228
[11:11:02.592] INFO: ROC Header-Trailer/Token Delay: 11
[11:11:02.592] INFO: ROC Port 0 Delay: 4
[11:11:02.592] INFO: ROC Port 1 Delay: 4
[11:11:02.592] INFO: Functional ROC Area: 4
[11:11:02.595] INFO: Test took 119805 ms.
[11:11:02.595] INFO: PixTestTiming::ROCDelayScan() done.
[11:11:02.595] INFO: ----------------------------------------------------------------------
[11:11:02.595] INFO: PixTestTiming::TimingTest()
[11:11:02.595] INFO: ----------------------------------------------------------------------
[11:11:18.567] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:11:33.565] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:11:48.598] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:12:03.595] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:12:18.588] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:12:33.561] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:12:48.537] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:03.502] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:18.492] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:33.505] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:33.887] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:33.905] INFO: ----------------------------------------------------------------------
[11:13:33.905] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:13:33.905] INFO: ----------------------------------------------------------------------
[11:13:33.905] INFO: ----------------------------------------------------------------------
[11:13:33.905] INFO: Read back bit status: 1
[11:13:33.905] INFO: ----------------------------------------------------------------------
[11:13:33.905] INFO: ----------------------------------------------------------------------
[11:13:33.905] INFO: Timings are good!
[11:13:33.905] INFO: ----------------------------------------------------------------------
[11:13:33.905] INFO: Test took 151310 ms.
[11:13:33.905] INFO: PixTestTiming::TimingTest() done.
[11:13:33.905] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:13:33.905] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:13:33.905] INFO: PixTestTiming::doTest took 543961 ms.
[11:13:33.905] INFO: PixTestTiming::doTest() done
[11:13:33.905] INFO: Write out TBMPhaseScan_0_V0
[11:13:33.933] INFO: Write out TBMPhaseScan_1_V0
[11:13:33.933] INFO: Write out CombinedTBMPhaseScan_V0
[11:13:33.934] INFO: Write out ROCDelayScan3_V0
[11:13:33.934] INFO: enter test to run
[11:13:49.944] INFO: test: PixelAlive no parameter change
[11:13:49.944] INFO: running: pixelalive
[11:13:49.949] INFO: ----------------------------------------------------------------------
[11:13:49.949] 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:13:49.949] INFO: ----------------------------------------------------------------------
[11:13:50.266] INFO: Expecting 41600 events.
[11:13:54.592] INFO: 41600 events read in total (3610ms).
[11:13:54.593] INFO: Test took 4642ms.
[11:13:54.599] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:54.995] INFO: PixTestAlive::aliveTest() done
[11:13:54.995] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[11:13:54.998] INFO: enter test to run
[11:14:38.088] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:14:38.088] INFO: running: highrate
[11:14:38.088] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:14:38.239] INFO: ----------------------------------------------------------------------
[11:14:38.239] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:14:38.239] INFO: ----------------------------------------------------------------------
[11:14:38.239] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:14:38.239] INFO: edge/corner pixel THR is adjusted
[11:14:38.239] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:14:39.197] INFO: Collecting data for 5 seconds...
[11:14:44.214] INFO: Done with hot pixel readout
[11:14:56.323] INFO: PixTest:: pg_setup set to default.
[11:14:56.324] INFO: 30 hot pixels found in step 0
[11:14:57.319] INFO: Collecting data for 5 seconds...
[11:15:02.335] INFO: Done with hot pixel readout
[11:15:14.470] INFO: PixTest:: pg_setup set to default.
[11:15:14.471] INFO: 31 hot pixels found in step 1
[11:15:15.467] INFO: Collecting data for 5 seconds...
[11:15:20.483] INFO: Done with hot pixel readout
[11:15:32.654] INFO: PixTest:: pg_setup set to default.

[11:15:32.655] INFO: 30 hot pixels found in step 2
[11:15:33.650] INFO: Collecting data for 5 seconds...
[11:15:38.667] INFO: Done with hot pixel readout
[11:15:50.841] INFO: PixTest:: pg_setup set to default.
[11:15:50.842] INFO: 28 hot pixels found in step 3
[11:15:51.837] INFO: Collecting data for 5 seconds...
[11:15:56.854] INFO: Done with hot pixel readout
[11:16:09.018] INFO: PixTest:: pg_setup set to default.


[11:16:09.019] INFO: 31 hot pixels found in step 4
[11:16:10.014] INFO: Collecting data for 5 seconds...
[11:16:15.030] INFO: Done with hot pixel readout
[11:16:27.188] INFO: PixTest:: pg_setup set to default.





[11:16:27.189] INFO: 27 hot pixels found in step 5
[11:16:28.186] INFO: Collecting data for 5 seconds...
[11:16:33.203] INFO: Done with hot pixel readout
[11:16:45.363] INFO: PixTest:: pg_setup set to default.





[11:16:45.364] INFO: 23 hot pixels found in step 6
[11:16:46.359] INFO: Collecting data for 5 seconds...
[11:16:51.375] INFO: Done with hot pixel readout
[11:17:03.507] INFO: PixTest:: pg_setup set to default.






[11:17:03.508] INFO: 12 hot pixels found in step 7
[11:17:04.504] INFO: Collecting data for 5 seconds...
[11:17:09.521] INFO: Done with hot pixel readout
[11:17:21.676] INFO: PixTest:: pg_setup set to default.





[11:17:21.677] INFO: 11 hot pixels found in step 8
[11:17:22.672] INFO: Collecting data for 5 seconds...
[11:17:27.689] INFO: Done with hot pixel readout
[11:17:39.845] INFO: PixTest:: pg_setup set to default.




[11:17:39.846] INFO: 12 hot pixels found in step 9
[11:17:40.841] INFO: Collecting data for 5 seconds...
[11:17:45.858] INFO: Done with hot pixel readout
[11:17:58.047] INFO: PixTest:: pg_setup set to default.






[11:17:58.048] INFO: 15 hot pixels found in step 10
[11:17:59.043] INFO: Collecting data for 5 seconds...
[11:18:04.060] INFO: Done with hot pixel readout
[11:18:16.244] INFO: PixTest:: pg_setup set to default.




[11:18:16.245] INFO: 12 hot pixels found in step 11
[11:18:17.241] INFO: Collecting data for 5 seconds...
[11:18:22.257] INFO: Done with hot pixel readout
[11:18:34.424] INFO: PixTest:: pg_setup set to default.





[11:18:34.425] INFO: 18 hot pixels found in step 12
[11:18:35.423] INFO: Collecting data for 5 seconds...
[11:18:40.439] INFO: Done with hot pixel readout
[11:18:52.595] INFO: PixTest:: pg_setup set to default.




[11:18:52.596] INFO: 9 hot pixels found in step 13
[11:18:53.591] INFO: Collecting data for 5 seconds...
[11:18:58.608] INFO: Done with hot pixel readout
[11:19:10.724] INFO: PixTest:: pg_setup set to default.



[11:19:10.725] INFO: 15 hot pixels found in step 14
[11:19:10.765] INFO: 15 hot pixels could not be trimmed and have been masked.
[11:19:10.768] INFO: PixTest::trimHotPixels() done
[11:19:10.768] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C0.dat
[11:19:10.774] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C1.dat
[11:19:10.781] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C2.dat
[11:19:10.788] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C3.dat
[11:19:10.793] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C4.dat
[11:19:10.799] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C5.dat
[11:19:10.804] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C6.dat
[11:19:10.810] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C7.dat
[11:19:10.816] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C8.dat
[11:19:10.822] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C9.dat
[11:19:10.827] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C10.dat
[11:19:10.832] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C11.dat
[11:19:10.838] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C12.dat
[11:19:10.843] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C13.dat
[11:19:10.849] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C14.dat
[11:19:10.854] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C15.dat
[11:19:10.859] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//defaultMaskFile.dat
[11:19:10.870] INFO: enter test to run
[11:20:04.037] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:20:04.038] INFO: running: highrate
[11:20:04.042] INFO: ----------------------------------------------------------------------
[11:20:04.042] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:20:04.042] INFO: ----------------------------------------------------------------------
[11:20:04.042] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:20:04.042] INFO: edge/corner pixel THR is adjusted
[11:20:04.042] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:20:04.000] INFO: Collecting data for 1 seconds...
[11:20:05.004] INFO: Done with hot pixel readout
[11:20:10.265] INFO: PixTest:: pg_setup set to default.
[11:20:10.266] INFO: 0 hot pixels found in step 0
[11:20:10.271] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:20:10.353] INFO: PixTest::trimHotPixels() done
[11:20:10.354] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C0.dat
[11:20:10.363] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C1.dat
[11:20:10.369] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C2.dat
[11:20:10.374] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C3.dat
[11:20:10.379] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C4.dat
[11:20:10.384] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C5.dat
[11:20:10.389] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C6.dat
[11:20:10.395] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C7.dat
[11:20:10.400] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C8.dat
[11:20:10.405] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C9.dat
[11:20:10.410] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C10.dat
[11:20:10.416] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C11.dat
[11:20:10.421] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C12.dat
[11:20:10.426] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C13.dat
[11:20:10.431] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C14.dat
[11:20:10.437] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//trimParameters35_C15.dat
[11:20:10.442] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-K-2-03_FPIXTest-17C-FNAL-160408-0917_2016-04-08_09h17m_1460125040/000_FPIXTest_p17//defaultMaskFile.dat
[11:20:10.458] INFO: enter test to run
[11:21:13.605] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:21:13.605] INFO: running: xray
[11:21:13.606] INFO: ----------------------------------------------------------------------
[11:21:13.606] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:21:13.606] INFO: ----------------------------------------------------------------------
[11:21:14.567] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:21:25.206] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[11:21:54.552] INFO: Resuming triggers.
[11:22:05.195] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[11:22:34.659] INFO: Resuming triggers.
[11:22:45.305] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[11:23:14.937] INFO: Resuming triggers.
[11:23:25.583] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[11:23:55.078] INFO: Resuming triggers.
[11:24:05.722] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[11:24:35.431] INFO: Resuming triggers.
[11:24:46.075] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[11:25:15.569] INFO: Resuming triggers.
[11:25:26.216] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[11:25:55.732] INFO: Resuming triggers.
[11:26:06.376] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[11:26:35.751] INFO: Resuming triggers.
[11:26:46.400] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[11:27:16.035] INFO: Resuming triggers.
[11:27:20.559] INFO: data taking finished, elapsed time: 100 seconds.
[11:27:33.355] INFO: PixTest:: pg_setup set to default.
[11:27:33.359] INFO: PixTestXray::doPhRun() done
[11:27:33.505] INFO: enter test to run
[11:27:50.266] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:27:50.266] INFO: running: xray
[11:27:50.267] INFO: ----------------------------------------------------------------------
[11:27:50.267] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:27:50.267] INFO: ----------------------------------------------------------------------
[11:27:51.231] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:27:57.393] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:28:27.463] INFO: Resuming triggers.
[11:28:33.624] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[11:29:03.386] INFO: Resuming triggers.
[11:29:09.550] INFO: run duration 18 seconds, buffer almost full (81%), pausing triggers.
[11:29:39.476] INFO: Resuming triggers.
[11:29:45.636] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[11:30:15.625] INFO: Resuming triggers.
[11:30:21.781] INFO: run duration 30 seconds, buffer almost full (81%), pausing triggers.
[11:30:51.907] INFO: Resuming triggers.
[11:30:58.066] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[11:31:25.525] INFO: Resuming triggers.
[11:31:31.682] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[11:32:01.581] INFO: Resuming triggers.
[11:32:07.737] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[11:32:37.779] INFO: Resuming triggers.
[11:32:43.935] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[11:33:13.889] INFO: Resuming triggers.
[11:33:20.045] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[11:33:50.042] INFO: Resuming triggers.
[11:33:56.200] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[11:34:26.178] INFO: Resuming triggers.
[11:34:32.339] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[11:35:02.502] INFO: Resuming triggers.
[11:35:08.660] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[11:35:38.484] INFO: Resuming triggers.
[11:35:44.645] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[11:36:14.707] INFO: Resuming triggers.
[11:36:20.864] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[11:36:50.939] INFO: Resuming triggers.
[11:36:57.101] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[11:37:27.178] INFO: Resuming triggers.
[11:37:28.959] INFO: data taking finished, elapsed time: 100 seconds.
[11:37:37.987] INFO: PixTest:: pg_setup set to default.
[11:37:37.990] INFO: PixTestXray::doPhRun() done
[11:37:38.139] INFO: enter test to run
[11:38:03.517] INFO: test: HighRate no parameter change
[11:38:03.517] INFO: running: highrate
[11:38:03.519] INFO: ----------------------------------------------------------------------
[11:38:03.519] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:38:03.519] INFO: ----------------------------------------------------------------------
[11:38:03.658] INFO: Expecting 768 events.
[11:38:04.792] INFO: 768 events read in total (418ms).
[11:38:04.792] INFO: Test took 1267ms.
[11:38:05.595] INFO: Expecting 41600 events.
[11:38:08.693] INFO: 41600 events read in total (2571ms).
[11:38:08.694] INFO: Test took 3895ms.
[11:38:08.730] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:09.454] INFO: Expecting 41600 events.
[11:38:12.654] INFO: 41600 events read in total (2673ms).
[11:38:12.655] INFO: Test took 3907ms.
[11:38:12.692] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:13.414] INFO: Expecting 41600 events.
[11:38:16.672] INFO: 41600 events read in total (2731ms).
[11:38:16.673] INFO: Test took 3963ms.
[11:38:16.711] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:17.426] INFO: Expecting 41600 events.
[11:38:20.683] INFO: 41600 events read in total (2730ms).
[11:38:20.684] INFO: Test took 3953ms.
[11:38:20.721] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:21.440] INFO: Expecting 41600 events.
[11:38:24.693] INFO: 41600 events read in total (2726ms).
[11:38:24.694] INFO: Test took 3954ms.
[11:38:24.732] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:25.452] INFO: Expecting 41600 events.
[11:38:28.707] INFO: 41600 events read in total (2728ms).
[11:38:28.708] INFO: Test took 3957ms.
[11:38:28.745] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:29.462] INFO: Expecting 41600 events.
[11:38:32.743] INFO: 41600 events read in total (2754ms).
[11:38:32.744] INFO: Test took 3980ms.
[11:38:32.780] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:33.500] INFO: Expecting 41600 events.
[11:38:36.772] INFO: 41600 events read in total (2745ms).
[11:38:36.773] INFO: Test took 3975ms.
[11:38:36.809] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:37.526] INFO: Expecting 41600 events.
[11:38:40.805] INFO: 41600 events read in total (2752ms).
[11:38:40.806] INFO: Test took 3977ms.
[11:38:40.844] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:41.561] INFO: Expecting 41600 events.
[11:38:44.837] INFO: 41600 events read in total (2749ms).
[11:38:44.839] INFO: Test took 3975ms.
[11:38:44.875] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:45.593] INFO: Expecting 41600 events.
[11:38:48.859] INFO: 41600 events read in total (2739ms).
[11:38:48.860] INFO: Test took 3965ms.
[11:38:48.895] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:49.615] INFO: Expecting 41600 events.
[11:38:52.891] INFO: 41600 events read in total (2749ms).
[11:38:52.892] INFO: Test took 3977ms.
[11:38:52.929] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:53.649] INFO: Expecting 41600 events.
[11:38:56.936] INFO: 41600 events read in total (2760ms).
[11:38:56.937] INFO: Test took 3988ms.
[11:38:56.975] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:38:57.694] INFO: Expecting 41600 events.
[11:39:00.964] INFO: 41600 events read in total (2743ms).
[11:39:00.965] INFO: Test took 3971ms.
[11:39:00.001] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:01.717] INFO: Expecting 41600 events.
[11:39:04.996] INFO: 41600 events read in total (2752ms).
[11:39:04.997] INFO: Test took 3977ms.
[11:39:05.034] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:05.750] INFO: Expecting 41600 events.
[11:39:09.021] INFO: 41600 events read in total (2744ms).
[11:39:09.022] INFO: Test took 3968ms.
[11:39:09.059] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:09.779] INFO: Expecting 41600 events.
[11:39:13.041] INFO: 41600 events read in total (2735ms).
[11:39:13.042] INFO: Test took 3965ms.
[11:39:13.079] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:13.798] INFO: Expecting 41600 events.
[11:39:17.054] INFO: 41600 events read in total (2729ms).
[11:39:17.055] INFO: Test took 3957ms.
[11:39:17.093] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:17.805] INFO: Expecting 41600 events.
[11:39:21.067] INFO: 41600 events read in total (2735ms).
[11:39:21.068] INFO: Test took 3957ms.
[11:39:21.105] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:21.824] INFO: Expecting 41600 events.
[11:39:24.988] INFO: 41600 events read in total (2637ms).
[11:39:24.989] INFO: Test took 3865ms.
[11:39:25.026] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:25.383] INFO: enter test to run
[11:39:39.509] INFO: test: HighRate no parameter change
[11:39:39.509] INFO: running: highrate
[11:39:39.510] INFO: ----------------------------------------------------------------------
[11:39:39.510] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:39:39.510] INFO: ----------------------------------------------------------------------
[11:39:40.126] INFO: Expecting 208000 events.
[11:39:52.151] INFO: 208000 events read in total (11498ms).
[11:39:52.155] INFO: Test took 12635ms.
[11:39:52.312] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:39:52.570] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[11:39:52.570] INFO: number of red-efficiency pixels: 99 51 86 122 168 116 167 85 124 119 148 121 188 83 41 27
[11:39:52.570] INFO: number of X-ray hits detected: 75200 47637 70877 116809 122272 119498 123958 89234 88446 109164 110717 98974 100541 60409 25774 27457
[11:39:52.570] 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:39:52.570] INFO: number of Vcal hits detected: 207898 207947 207910 207877 207827 207879 207828 207915 207875 207878 207796 207877 207737 207914 207959 207972
[11:39:52.570] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[11:39:52.570] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[11:39:52.570] INFO: X-ray hit rate [MHz/cm2]: 22.0 14.0 20.8 34.2 35.8 35.0 36.3 26.2 25.9 32.0 32.5 29.0 29.5 17.7 7.6 8.0
[11:39:52.570] INFO: PixTestHighRate::doXPixelAlive() done
[11:39:52.615] INFO: PixTest:: pg_setup set to default.
[11:39:52.628] INFO: enter test to run
[11:40:27.524] INFO: test: HighRate no parameter change
[11:40:27.524] INFO: running: highrate
[11:40:27.526] INFO: ----------------------------------------------------------------------
[11:40:27.526] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:40:27.526] INFO: ----------------------------------------------------------------------
[11:40:28.140] INFO: Expecting 208000 events.
[11:40:42.253] INFO: 208000 events read in total (13586ms).
[11:40:42.259] INFO: Test took 14725ms.
[11:40:42.589] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:40:42.904] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[11:40:42.904] INFO: number of red-efficiency pixels: 311 133 262 433 659 478 551 332 369 400 558 392 552 300 54 90
[11:40:42.904] INFO: number of X-ray hits detected: 159194 102273 151159 248918 260100 253528 263113 189174 187740 233868 233711 210170 212804 129420 54747 59165
[11:40:42.904] 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:40:42.904] INFO: number of Vcal hits detected: 207658 207861 207723 207537 207238 207489 207378 207646 207600 207573 207340 207585 207214 207669 207945 207909
[11:40:42.904] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.7 99.8 99.8 99.8 99.7 99.8 99.6 99.9 100.0 100.0
[11:40:42.904] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.9 99.8 99.6 99.8 99.7 99.8 99.8 99.8 99.7 99.8 99.6 99.8 100.0 100.0
[11:40:42.904] INFO: X-ray hit rate [MHz/cm2]: 46.7 30.0 44.3 73.0 76.2 74.3 77.1 55.4 55.0 68.5 68.5 61.6 62.4 37.9 16.0 17.3
[11:40:42.904] INFO: PixTestHighRate::doXPixelAlive() done
[11:40:42.954] INFO: PixTest:: pg_setup set to default.
[11:40:42.969] INFO: enter test to run
[11:40:55.828] INFO: test: HighRate no parameter change
[11:40:55.828] INFO: running: highrate
[11:40:55.829] INFO: ----------------------------------------------------------------------
[11:40:55.829] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:40:55.829] INFO: ----------------------------------------------------------------------
[11:40:56.443] INFO: Expecting 208000 events.
[11:41:12.880] INFO: 208000 events read in total (15910ms).
[11:41:12.889] INFO: Test took 17049ms.
[11:41:13.408] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:13.779] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[11:41:13.779] INFO: number of red-efficiency pixels: 711 310 569 1056 1607 1139 1307 703 836 955 1322 842 1145 681 117 106
[11:41:13.779] INFO: number of X-ray hits detected: 244060 156624 229460 380668 396094 387202 402075 288060 287663 355772 357361 319307 323318 197441 82993 90085
[11:41:13.779] 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:41:13.779] INFO: number of Vcal hits detected: 207055 207649 207276 206685 205707 206530 206308 207122 206991 206826 206202 206988 206388 207099 207877 207891
[11:41:13.780] INFO: Vcal hit fiducial efficiency (%): 99.6 99.9 99.7 99.4 99.0 99.4 99.3 99.6 99.6 99.5 99.2 99.6 99.3 99.6 99.9 99.9
[11:41:13.780] INFO: Vcal hit overall efficiency (%): 99.5 99.8 99.7 99.4 98.9 99.3 99.2 99.6 99.5 99.4 99.1 99.5 99.2 99.6 99.9 99.9
[11:41:13.780] INFO: X-ray hit rate [MHz/cm2]: 71.5 45.9 67.3 111.6 116.1 113.5 117.9 84.4 84.3 104.3 104.7 93.6 94.8 57.9 24.3 26.4
[11:41:13.780] INFO: PixTestHighRate::doXPixelAlive() done
[11:41:13.828] INFO: PixTest:: pg_setup set to default.
[11:41:13.845] INFO: enter test to run
[11:41:19.044] INFO: test: exit no parameter change
[11:41:19.394] QUIET: Connection to board 33 closed.
[11:41:19.394] INFO: pXar: this is the end, my friend