[12:13:26.703] INFO: *** Welcome to pxar ***
[12:13:26.703] INFO: *** Today: 2016/05/27
[12:13:26.721] INFO: *** Version: v1.9.0-796-gef167-dirty
[12:13:26.721] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//dacParameters35_C15.dat
[12:13:26.722] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:13:26.722] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//defaultMaskFile.dat
[12:13:26.722] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C15.dat
[12:13:26.797] INFO: clk: 4
[12:13:26.797] INFO: ctr: 4
[12:13:26.797] INFO: sda: 19
[12:13:26.797] INFO: tin: 9
[12:13:26.797] INFO: level: 15
[12:13:26.797] INFO: triggerdelay: 0
[12:13:26.797] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[12:13:26.797] INFO: Log level: INFO
[12:13:26.814] QUIET: Connection to board DTB_WREKRL opened.
[12:13:26.818] 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:
------------------------------------------------------
[12:13:26.820] INFO: RPC call hashes of host and DTB match: 398089610
[12:13:28.347] INFO: DUT info:
[12:13:28.347] INFO: The DUT currently contains the following objects:
[12:13:28.347] INFO: 2 TBM Cores tbm08c (2 ON)
[12:13:28.347] INFO: TBM Core alpha (0): 7 registers set
[12:13:28.347] INFO: TBM Core beta (1): 7 registers set
[12:13:28.347] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:13:28.347] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.347] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.347] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.347] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.347] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.347] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.347] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.347] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.347] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.347] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.347] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.347] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.348] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.348] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.348] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.348] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:13:28.751] INFO: enter 'restricted' command line mode
[12:13:28.751] INFO: enter test to run
[12:13:30.295] INFO: test: timing no parameter change
[12:13:30.295] INFO: running: timing
[12:13:30.321] INFO: ######################################################################
[12:13:30.321] INFO: PixTestTiming::doTest()
[12:13:30.324] INFO: ######################################################################
[12:13:30.325] INFO: ----------------------------------------------------------------------
[12:13:30.325] INFO: PixTestTiming::TBMPhaseScan()
[12:13:30.325] INFO: ----------------------------------------------------------------------
[12:17:58.294] INFO: TBM Phase Settings: 240
[12:17:58.294] INFO: 400MHz Phase: 4
[12:17:58.294] INFO: 160MHz Phase: 7
[12:17:58.294] INFO: Functional Phase Area: 5
[12:17:58.303] INFO: Test took 267979 ms.
[12:17:58.303] INFO: PixTestTiming::TBMPhaseScan() done.
[12:17:58.303] INFO: ----------------------------------------------------------------------
[12:17:58.303] INFO: PixTestTiming::ROCDelayScan()
[12:17:58.303] INFO: ----------------------------------------------------------------------
[12:20:02.101] INFO: ROC Delay Settings: 228
[12:20:02.101] INFO: ROC Header-Trailer/Token Delay: 11
[12:20:02.101] INFO: ROC Port 0 Delay: 4
[12:20:02.101] INFO: ROC Port 1 Delay: 4
[12:20:02.101] INFO: Functional ROC Area: 5
[12:20:02.104] INFO: Test took 123801 ms.
[12:20:02.104] INFO: PixTestTiming::ROCDelayScan() done.
[12:20:02.105] INFO: ----------------------------------------------------------------------
[12:20:02.105] INFO: PixTestTiming::TimingTest()
[12:20:02.105] INFO: ----------------------------------------------------------------------
[12:20:18.281] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:20:33.297] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:20:48.270] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:21:03.439] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:21:18.667] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:21:33.917] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:21:48.965] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:22:04.097] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:22:19.278] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:22:34.479] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:22:34.859] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:22:34.878] INFO: ----------------------------------------------------------------------
[12:22:34.878] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:22:34.878] INFO: ----------------------------------------------------------------------
[12:22:34.878] INFO: ----------------------------------------------------------------------
[12:22:34.878] INFO: Read back bit status: 1
[12:22:34.878] INFO: ----------------------------------------------------------------------
[12:22:34.878] INFO: ----------------------------------------------------------------------
[12:22:34.878] INFO: Timings are good!
[12:22:34.878] INFO: ----------------------------------------------------------------------
[12:22:34.878] INFO: Test took 152773 ms.
[12:22:34.878] INFO: PixTestTiming::TimingTest() done.
[12:22:34.879] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:22:34.879] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:22:34.879] INFO: PixTestTiming::doTest took 544563 ms.
[12:22:34.879] INFO: PixTestTiming::doTest() done
[12:22:34.879] INFO: Write out TBMPhaseScan_0_V0
[12:22:34.909] INFO: Write out TBMPhaseScan_1_V0
[12:22:34.909] INFO: Write out CombinedTBMPhaseScan_V0
[12:22:34.935] INFO: Write out ROCDelayScan3_V0
[12:22:34.936] INFO: enter test to run
[12:23:38.995] INFO: test: PixelAlive no parameter change
[12:23:38.995] INFO: running: pixelalive
[12:23:38.999] INFO: ----------------------------------------------------------------------
[12:23:38.999] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[12:23:38.999] INFO: ----------------------------------------------------------------------
[12:23:39.321] INFO: Expecting 41600 events.
[12:23:43.646] INFO: 41600 events read in total (3610ms).
[12:23:43.647] INFO: Test took 4645ms.
[12:23:43.653] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:23:44.050] INFO: PixTestAlive::aliveTest() done
[12:23:44.050] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[12:23:44.054] INFO: enter test to run
[12:24:29.562] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:24:29.562] INFO: running: highrate
[12:24:29.563] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:24:29.714] INFO: ----------------------------------------------------------------------
[12:24:29.714] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:24:29.714] INFO: ----------------------------------------------------------------------
[12:24:29.714] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:24:29.714] INFO: edge/corner pixel THR is adjusted
[12:24:29.714] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:24:30.672] INFO: Collecting data for 5 seconds...
[12:24:35.689] INFO: Done with hot pixel readout
[12:24:48.112] INFO: PixTest:: pg_setup set to default.


[12:24:48.113] INFO: 14 hot pixels found in step 0
[12:24:49.111] INFO: Collecting data for 5 seconds...
[12:24:54.128] INFO: Done with hot pixel readout
[12:25:06.568] INFO: PixTest:: pg_setup set to default.



[12:25:06.569] INFO: 16 hot pixels found in step 1
[12:25:07.566] INFO: Collecting data for 5 seconds...
[12:25:12.583] INFO: Done with hot pixel readout
[12:25:24.938] INFO: PixTest:: pg_setup set to default.



[12:25:24.939] INFO: 16 hot pixels found in step 2
[12:25:25.935] INFO: Collecting data for 5 seconds...
[12:25:30.952] INFO: Done with hot pixel readout
[12:25:43.390] INFO: PixTest:: pg_setup set to default.



[12:25:43.390] INFO: 10 hot pixels found in step 3
[12:25:44.387] INFO: Collecting data for 5 seconds...
[12:25:49.404] INFO: Done with hot pixel readout
[12:26:01.838] INFO: PixTest:: pg_setup set to default.



[12:26:01.839] INFO: 14 hot pixels found in step 4
[12:26:02.835] INFO: Collecting data for 5 seconds...
[12:26:07.852] INFO: Done with hot pixel readout
[12:26:20.318] INFO: PixTest:: pg_setup set to default.





[12:26:20.319] INFO: 16 hot pixels found in step 5
[12:26:21.317] INFO: Collecting data for 5 seconds...
[12:26:26.334] INFO: Done with hot pixel readout
[12:26:38.743] INFO: PixTest:: pg_setup set to default.



[12:26:38.744] INFO: 15 hot pixels found in step 6
[12:26:39.742] INFO: Collecting data for 5 seconds...
[12:26:44.759] INFO: Done with hot pixel readout
[12:26:57.197] INFO: PixTest:: pg_setup set to default.



[12:26:57.198] INFO: 11 hot pixels found in step 7
[12:26:58.195] INFO: Collecting data for 5 seconds...
[12:27:03.211] INFO: Done with hot pixel readout
[12:27:15.676] INFO: PixTest:: pg_setup set to default.






[12:27:15.677] INFO: 13 hot pixels found in step 8
[12:27:16.674] INFO: Collecting data for 5 seconds...
[12:27:21.690] INFO: Done with hot pixel readout
[12:27:34.169] INFO: PixTest:: pg_setup set to default.





[12:27:34.170] INFO: 15 hot pixels found in step 9
[12:27:35.166] INFO: Collecting data for 5 seconds...
[12:27:40.183] INFO: Done with hot pixel readout
[12:27:52.636] INFO: PixTest:: pg_setup set to default.






[12:27:52.637] INFO: 17 hot pixels found in step 10
[12:27:53.634] INFO: Collecting data for 5 seconds...
[12:27:58.651] INFO: Done with hot pixel readout
[12:28:11.084] INFO: PixTest:: pg_setup set to default.





[12:28:11.085] INFO: 15 hot pixels found in step 11
[12:28:12.082] INFO: Collecting data for 5 seconds...
[12:28:17.100] INFO: Done with hot pixel readout
[12:28:29.573] INFO: PixTest:: pg_setup set to default.






[12:28:29.574] INFO: 11 hot pixels found in step 12
[12:28:30.570] INFO: Collecting data for 5 seconds...
[12:28:35.588] INFO: Done with hot pixel readout
[12:28:47.989] INFO: PixTest:: pg_setup set to default.







[12:28:47.991] INFO: 16 hot pixels found in step 13
[12:28:48.988] INFO: Collecting data for 5 seconds...
[12:28:54.004] INFO: Done with hot pixel readout
[12:29:06.447] INFO: PixTest:: pg_setup set to default.


[12:29:06.448] INFO: 14 hot pixels found in step 14
[12:29:06.488] INFO: 14 hot pixels could not be trimmed and have been masked.
[12:29:06.492] INFO: PixTest::trimHotPixels() done
[12:29:06.492] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C0.dat
[12:29:06.498] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C1.dat
[12:29:06.504] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C2.dat
[12:29:06.509] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C3.dat
[12:29:06.514] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C4.dat
[12:29:06.519] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C5.dat
[12:29:06.525] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C6.dat
[12:29:06.530] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C7.dat
[12:29:06.535] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C8.dat
[12:29:06.540] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C9.dat
[12:29:06.545] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C10.dat
[12:29:06.550] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C11.dat
[12:29:06.555] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C12.dat
[12:29:06.560] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C13.dat
[12:29:06.565] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C14.dat
[12:29:06.570] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C15.dat
[12:29:06.575] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//defaultMaskFile.dat
[12:29:06.585] INFO: enter test to run
[12:31:42.759] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:31:42.759] INFO: running: highrate
[12:31:42.764] INFO: ----------------------------------------------------------------------
[12:31:42.764] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:31:42.764] INFO: ----------------------------------------------------------------------
[12:31:42.764] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:31:42.764] INFO: edge/corner pixel THR is adjusted
[12:31:42.764] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:31:43.722] INFO: Collecting data for 1 seconds...
[12:31:44.726] INFO: Done with hot pixel readout
[12:31:49.047] INFO: PixTest:: pg_setup set to default.
[12:31:49.048] INFO: 0 hot pixels found in step 0
[12:31:49.053] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:31:49.092] INFO: PixTest::trimHotPixels() done
[12:31:49.092] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C0.dat
[12:31:49.099] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C1.dat
[12:31:49.108] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C2.dat
[12:31:49.113] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C3.dat
[12:31:49.118] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C4.dat
[12:31:49.124] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C5.dat
[12:31:49.129] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C6.dat
[12:31:49.134] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C7.dat
[12:31:49.141] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C8.dat
[12:31:49.146] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C9.dat
[12:31:49.152] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C10.dat
[12:31:49.157] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C11.dat
[12:31:49.162] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C12.dat
[12:31:49.169] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C13.dat
[12:31:49.174] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C14.dat
[12:31:49.180] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//trimParameters35_C15.dat
[12:31:49.185] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-H-NM_FPIXTest-17C-FNAL-160520-1330_2016-05-20_13h30m_1463769035/000_FPIXTest_p17//defaultMaskFile.dat
[12:31:49.196] INFO: enter test to run
[12:32:08.359] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:32:08.359] INFO: running: xray
[12:32:08.360] INFO: ----------------------------------------------------------------------
[12:32:08.360] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:32:08.360] INFO: ----------------------------------------------------------------------
[12:32:09.323] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:32:20.078] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[12:32:48.619] INFO: Resuming triggers.
[12:32:59.486] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[12:33:28.839] INFO: Resuming triggers.
[12:33:39.597] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[12:34:08.583] INFO: Resuming triggers.
[12:34:19.342] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[12:34:48.384] INFO: Resuming triggers.
[12:34:59.141] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[12:35:27.847] INFO: Resuming triggers.
[12:35:38.609] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[12:36:07.295] INFO: Resuming triggers.
[12:36:18.054] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[12:36:47.055] INFO: Resuming triggers.
[12:36:57.815] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[12:37:26.810] INFO: Resuming triggers.
[12:37:37.568] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[12:38:06.593] INFO: Resuming triggers.
[12:38:10.105] INFO: data taking finished, elapsed time: 100 seconds.
[12:38:20.060] INFO: PixTest:: pg_setup set to default.
[12:38:20.064] INFO: PixTestXray::doPhRun() done
[12:38:20.203] INFO: enter test to run
[12:38:52.332] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:38:52.332] INFO: running: xray
[12:38:52.333] INFO: ----------------------------------------------------------------------
[12:38:52.333] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:38:52.333] INFO: ----------------------------------------------------------------------
[12:38:53.298] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:38:59.313] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[12:39:28.965] INFO: Resuming triggers.
[12:39:34.983] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:40:04.707] INFO: Resuming triggers.
[12:40:10.725] INFO: run duration 17 seconds, buffer almost full (81%), pausing triggers.
[12:40:39.837] INFO: Resuming triggers.
[12:40:45.859] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[12:41:15.329] INFO: Resuming triggers.
[12:41:21.349] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[12:41:50.000] INFO: Resuming triggers.
[12:41:57.022] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[12:42:27.444] INFO: Resuming triggers.
[12:42:33.461] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[12:43:03.107] INFO: Resuming triggers.
[12:43:09.132] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[12:43:38.566] INFO: Resuming triggers.
[12:43:44.588] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[12:44:14.790] INFO: Resuming triggers.
[12:44:20.809] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[12:44:51.273] INFO: Resuming triggers.
[12:44:57.294] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[12:45:27.066] INFO: Resuming triggers.
[12:45:33.084] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[12:46:02.818] INFO: Resuming triggers.
[12:46:08.833] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[12:46:38.508] INFO: Resuming triggers.
[12:46:44.529] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[12:47:13.936] INFO: Resuming triggers.
[12:47:19.951] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[12:47:49.706] INFO: Resuming triggers.
[12:47:55.721] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[12:48:25.164] INFO: Resuming triggers.
[12:48:29.193] INFO: data taking finished, elapsed time: 100 seconds.
[12:48:49.085] INFO: PixTest:: pg_setup set to default.
[12:48:49.088] INFO: PixTestXray::doPhRun() done
[12:48:49.239] INFO: enter test to run
[12:49:28.671] INFO: test: HighRate no parameter change
[12:49:28.671] INFO: running: highrate
[12:49:28.673] INFO: ----------------------------------------------------------------------
[12:49:28.673] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:49:28.673] INFO: ----------------------------------------------------------------------
[12:49:28.814] INFO: Expecting 768 events.
[12:49:29.948] INFO: 768 events read in total (418ms).
[12:49:29.949] INFO: Test took 1269ms.
[12:49:30.752] INFO: Expecting 41600 events.
[12:49:33.877] INFO: 41600 events read in total (2598ms).
[12:49:33.878] INFO: Test took 3921ms.
[12:49:33.917] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:34.636] INFO: Expecting 41600 events.
[12:49:37.737] INFO: 41600 events read in total (2574ms).
[12:49:37.738] INFO: Test took 3802ms.
[12:49:37.777] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:38.495] INFO: Expecting 41600 events.
[12:49:41.715] INFO: 41600 events read in total (2693ms).
[12:49:41.716] INFO: Test took 3918ms.
[12:49:41.756] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:42.469] INFO: Expecting 41600 events.
[12:49:45.759] INFO: 41600 events read in total (2763ms).
[12:49:45.760] INFO: Test took 3984ms.
[12:49:45.800] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:46.512] INFO: Expecting 41600 events.
[12:49:49.759] INFO: 41600 events read in total (2720ms).
[12:49:49.760] INFO: Test took 3940ms.
[12:49:49.800] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:50.515] INFO: Expecting 41600 events.
[12:49:53.788] INFO: 41600 events read in total (2746ms).
[12:49:53.789] INFO: Test took 3968ms.
[12:49:53.830] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:54.540] INFO: Expecting 41600 events.
[12:49:57.785] INFO: 41600 events read in total (2718ms).
[12:49:57.786] INFO: Test took 3936ms.
[12:49:57.826] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:49:58.542] INFO: Expecting 41600 events.
[12:50:01.791] INFO: 41600 events read in total (2723ms).
[12:50:01.792] INFO: Test took 3946ms.
[12:50:01.832] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:02.548] INFO: Expecting 41600 events.
[12:50:05.812] INFO: 41600 events read in total (2737ms).
[12:50:05.813] INFO: Test took 3961ms.
[12:50:05.853] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:06.570] INFO: Expecting 41600 events.
[12:50:09.830] INFO: 41600 events read in total (2733ms).
[12:50:09.832] INFO: Test took 3960ms.
[12:50:09.877] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:10.582] INFO: Expecting 41600 events.
[12:50:13.874] INFO: 41600 events read in total (2765ms).
[12:50:13.875] INFO: Test took 3977ms.
[12:50:13.914] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:14.625] INFO: Expecting 41600 events.
[12:50:17.883] INFO: 41600 events read in total (2731ms).
[12:50:17.884] INFO: Test took 3950ms.
[12:50:17.924] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:18.636] INFO: Expecting 41600 events.
[12:50:21.915] INFO: 41600 events read in total (2752ms).
[12:50:21.916] INFO: Test took 3972ms.
[12:50:21.956] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:22.666] INFO: Expecting 41600 events.
[12:50:25.964] INFO: 41600 events read in total (2772ms).
[12:50:25.965] INFO: Test took 3989ms.
[12:50:26.004] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:26.720] INFO: Expecting 41600 events.
[12:50:30.015] INFO: 41600 events read in total (2768ms).
[12:50:30.016] INFO: Test took 3990ms.
[12:50:30.056] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:30.767] INFO: Expecting 41600 events.
[12:50:33.917] INFO: 41600 events read in total (2623ms).
[12:50:33.918] INFO: Test took 3842ms.
[12:50:33.957] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:34.671] INFO: Expecting 41600 events.
[12:50:37.974] INFO: 41600 events read in total (2776ms).
[12:50:37.975] INFO: Test took 3998ms.
[12:50:38.014] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:38.728] INFO: Expecting 41600 events.
[12:50:42.029] INFO: 41600 events read in total (2774ms).
[12:50:42.030] INFO: Test took 3996ms.
[12:50:42.070] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:42.784] INFO: Expecting 41600 events.
[12:50:46.060] INFO: 41600 events read in total (2749ms).
[12:50:46.061] INFO: Test took 3970ms.
[12:50:46.101] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:46.813] INFO: Expecting 41600 events.
[12:50:49.945] INFO: 41600 events read in total (2605ms).
[12:50:49.946] INFO: Test took 3825ms.
[12:50:49.985] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:50:50.339] INFO: enter test to run
[12:50:57.862] INFO: test: HighRate no parameter change
[12:50:57.863] INFO: running: highrate
[12:50:57.864] INFO: ----------------------------------------------------------------------
[12:50:57.864] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:50:57.864] INFO: ----------------------------------------------------------------------
[12:50:58.479] INFO: Expecting 208000 events.
[12:51:10.691] INFO: 208000 events read in total (11685ms).
[12:51:10.694] INFO: Test took 12824ms.
[12:51:10.868] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:51:11.130] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[12:51:11.130] INFO: number of red-efficiency pixels: 89 69 120 172 220 168 156 121 136 112 136 126 126 79 21 29
[12:51:11.130] INFO: number of X-ray hits detected: 76896 56289 84167 133425 136639 140454 140427 98960 100099 108779 115736 99497 106144 61127 26743 30504
[12:51:11.130] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:51:11.130] INFO: number of Vcal hits detected: 207910 207928 207878 207821 207773 207827 207838 207874 207862 207886 207862 207873 207873 207920 207979 207971
[12:51:11.130] 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
[12:51:11.130] 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
[12:51:11.130] INFO: X-ray hit rate [MHz/cm2]: 22.5 16.5 24.7 39.1 40.0 41.2 41.2 29.0 29.3 31.9 33.9 29.2 31.1 17.9 7.8 8.9
[12:51:11.130] INFO: PixTestHighRate::doXPixelAlive() done
[12:51:11.178] INFO: PixTest:: pg_setup set to default.
[12:51:11.190] INFO: enter test to run
[12:51:59.470] INFO: test: HighRate no parameter change
[12:51:59.470] INFO: running: highrate
[12:51:59.471] INFO: ----------------------------------------------------------------------
[12:51:59.471] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:51:59.471] INFO: ----------------------------------------------------------------------
[12:52:00.081] INFO: Expecting 208000 events.
[12:52:14.441] INFO: 208000 events read in total (13833ms).
[12:52:14.447] INFO: Test took 14967ms.
[12:52:14.790] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:52:15.114] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[12:52:15.114] INFO: number of red-efficiency pixels: 323 148 456 626 812 642 644 380 419 413 457 441 481 195 61 82
[12:52:15.114] INFO: number of X-ray hits detected: 157195 115205 173002 272473 280654 288111 286852 204155 205375 221890 237767 206056 217773 125993 55262 62462
[12:52:15.114] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:52:15.114] INFO: number of Vcal hits detected: 207644 207845 207457 207308 207058 207286 207268 207581 207546 207561 207516 207527 207482 207793 207937 207916
[12:52:15.114] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.6 99.7 99.7 99.8 99.8 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[12:52:15.114] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.7 99.5 99.7 99.6 99.8 99.8 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[12:52:15.114] INFO: X-ray hit rate [MHz/cm2]: 46.1 33.8 50.7 79.9 82.3 84.4 84.1 59.8 60.2 65.0 69.7 60.4 63.8 36.9 16.2 18.3
[12:52:15.114] INFO: PixTestHighRate::doXPixelAlive() done
[12:52:15.164] INFO: PixTest:: pg_setup set to default.
[12:52:15.183] INFO: enter test to run
[12:53:43.309] INFO: test: HighRate no parameter change
[12:53:43.310] INFO: running: highrate
[12:53:43.311] INFO: ----------------------------------------------------------------------
[12:53:43.311] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:53:43.311] INFO: ----------------------------------------------------------------------
[12:53:43.930] INFO: Expecting 208000 events.
[12:54:00.554] INFO: 208000 events read in total (16097ms).
[12:54:00.563] INFO: Test took 17244ms.
[12:54:01.122] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:01.503] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[12:54:01.503] INFO: number of red-efficiency pixels: 666 293 952 1287 1732 1523 1554 848 949 944 974 1001 1099 400 113 137
[12:54:01.503] INFO: number of X-ray hits detected: 232337 170819 255145 404433 412292 426651 426592 302014 303417 328885 352642 303858 323063 185530 80942 93314
[12:54:01.503] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:54:01.503] INFO: number of Vcal hits detected: 207099 207671 206510 206327 205533 205897 205764 206900 206874 206885 206812 206768 206622 207527 207885 207857
[12:54:01.503] INFO: Vcal hit fiducial efficiency (%): 99.6 99.9 99.4 99.3 98.9 99.1 99.1 99.5 99.5 99.5 99.5 99.5 99.4 99.8 99.9 99.9
[12:54:01.503] INFO: Vcal hit overall efficiency (%): 99.6 99.8 99.3 99.2 98.8 99.0 98.9 99.5 99.5 99.5 99.4 99.4 99.3 99.8 99.9 99.9
[12:54:01.503] INFO: X-ray hit rate [MHz/cm2]: 68.1 50.1 74.8 118.5 120.8 125.1 125.0 88.5 88.9 96.4 103.4 89.1 94.7 54.4 23.7 27.4
[12:54:01.503] INFO: PixTestHighRate::doXPixelAlive() done
[12:54:01.548] INFO: PixTest:: pg_setup set to default.
[12:54:01.559] INFO: enter test to run
[12:54:02.637] INFO: test: exit no parameter change
[12:54:03.004] QUIET: Connection to board 33 closed.
[12:54:03.012] INFO: pXar: this is the end, my friend