[10:51:08.818] INFO: *** Welcome to pxar ***
[10:51:08.818] INFO: *** Today: 2016/05/11
[10:51:08.838] INFO: *** Version: v1.9.0-796-gef167-dirty
[10:51:08.838] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//dacParameters35_C15.dat
[10:51:08.839] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:51:08.840] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//defaultMaskFile.dat
[10:51:08.840] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C15.dat
[10:51:08.910] INFO: clk: 4
[10:51:08.910] INFO: ctr: 4
[10:51:08.910] INFO: sda: 19
[10:51:08.910] INFO: tin: 9
[10:51:08.910] INFO: level: 15
[10:51:08.910] INFO: triggerdelay: 0
[10:51:08.910] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[10:51:08.910] INFO: Log level: INFO
[10:51:08.927] QUIET: Connection to board DTB_WREKRL opened.
[10:51:08.931] 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:
------------------------------------------------------
[10:51:08.934] INFO: RPC call hashes of host and DTB match: 398089610
[10:51:10.463] INFO: DUT info:
[10:51:10.463] INFO: The DUT currently contains the following objects:
[10:51:10.463] INFO: 2 TBM Cores tbm08c (2 ON)
[10:51:10.464] INFO: TBM Core alpha (0): 7 registers set
[10:51:10.464] INFO: TBM Core beta (1): 7 registers set
[10:51:10.464] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[10:51:10.464] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.464] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[10:51:10.868] INFO: enter 'restricted' command line mode
[10:51:10.868] INFO: enter test to run
[10:51:27.094] INFO: test: timing no parameter change
[10:51:27.094] INFO: running: timing
[10:51:27.103] INFO: ######################################################################
[10:51:27.103] INFO: PixTestTiming::doTest()
[10:51:27.103] INFO: ######################################################################
[10:51:27.103] INFO: ----------------------------------------------------------------------
[10:51:27.103] INFO: PixTestTiming::TBMPhaseScan()
[10:51:27.103] INFO: ----------------------------------------------------------------------
[10:57:08.198] INFO: TBM Phase Settings: 16
[10:57:08.198] INFO: 400MHz Phase: 4
[10:57:08.198] INFO: 160MHz Phase: 0
[10:57:08.198] INFO: Functional Phase Area: 3
[10:57:08.201] INFO: Test took 341098 ms.
[10:57:08.201] INFO: PixTestTiming::TBMPhaseScan() done.
[10:57:08.201] INFO: ----------------------------------------------------------------------
[10:57:08.201] INFO: PixTestTiming::ROCDelayScan()
[10:57:08.201] INFO: ----------------------------------------------------------------------
[10:59:08.226] INFO: ROC Delay Settings: 227
[10:59:08.226] INFO: ROC Header-Trailer/Token Delay: 11
[10:59:08.226] INFO: ROC Port 0 Delay: 3
[10:59:08.226] INFO: ROC Port 1 Delay: 4
[10:59:08.226] INFO: Functional ROC Area: 4
[10:59:08.229] INFO: Test took 120028 ms.
[10:59:08.229] INFO: PixTestTiming::ROCDelayScan() done.
[10:59:08.229] INFO: ----------------------------------------------------------------------
[10:59:08.229] INFO: PixTestTiming::TimingTest()
[10:59:08.229] INFO: ----------------------------------------------------------------------
[10:59:23.927] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:59:38.702] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:59:53.518] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:08.430] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:23.333] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:38.373] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:53.447] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:08.565] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:23.621] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:38.582] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:38.961] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:38.979] INFO: ----------------------------------------------------------------------
[11:01:38.980] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:01:38.980] INFO: ----------------------------------------------------------------------
[11:01:38.980] INFO: ----------------------------------------------------------------------
[11:01:38.980] INFO: Read back bit status: 1
[11:01:38.980] INFO: ----------------------------------------------------------------------
[11:01:38.980] INFO: ----------------------------------------------------------------------
[11:01:38.980] INFO: Timings are good!
[11:01:38.980] INFO: ----------------------------------------------------------------------
[11:01:38.980] INFO: Test took 150751 ms.
[11:01:38.980] INFO: PixTestTiming::TimingTest() done.
[11:01:38.995] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:01:38.995] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:01:38.995] INFO: PixTestTiming::doTest took 611897 ms.
[11:01:38.995] INFO: PixTestTiming::doTest() done
[11:01:38.996] INFO: Write out TBMPhaseScan_0_V0
[11:01:39.030] INFO: Write out TBMPhaseScan_1_V0
[11:01:39.030] INFO: Write out CombinedTBMPhaseScan_V0
[11:01:39.061] INFO: Write out ROCDelayScan3_V0
[11:01:39.062] INFO: enter test to run
[11:02:50.457] INFO: test: PixelAlive no parameter change
[11:02:50.457] INFO: running: pixelalive
[11:02:50.461] INFO: ----------------------------------------------------------------------
[11:02:50.461] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:02:50.461] INFO: ----------------------------------------------------------------------
[11:02:50.788] INFO: Expecting 41600 events.
[11:02:55.116] INFO: 41600 events read in total (3612ms).
[11:02:55.116] INFO: Test took 4651ms.
[11:02:55.123] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:02:55.526] INFO: PixTestAlive::aliveTest() done
[11:02:55.526] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 2 1 0 0 0 0 0 0 0
[11:02:55.530] INFO: enter test to run
[11:04:12.368] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:04:12.368] INFO: running: highrate
[11:04:12.369] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:04:12.518] INFO: ----------------------------------------------------------------------
[11:04:12.518] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:04:12.518] INFO: ----------------------------------------------------------------------
[11:04:12.518] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:04:12.518] INFO: edge/corner pixel THR is adjusted
[11:04:12.518] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:04:13.476] INFO: Collecting data for 5 seconds...
[11:04:18.492] INFO: Done with hot pixel readout
[11:04:30.687] INFO: PixTest:: pg_setup set to default.




[11:04:30.688] INFO: 18 hot pixels found in step 0
[11:04:31.685] INFO: Collecting data for 5 seconds...
[11:04:36.702] INFO: Done with hot pixel readout
[11:04:48.788] INFO: PixTest:: pg_setup set to default.


[11:04:48.789] INFO: 12 hot pixels found in step 1
[11:04:49.786] INFO: Collecting data for 5 seconds...
[11:04:54.803] INFO: Done with hot pixel readout
[11:05:06.945] INFO: PixTest:: pg_setup set to default.



[11:05:06.946] INFO: 16 hot pixels found in step 2
[11:05:07.943] INFO: Collecting data for 5 seconds...
[11:05:12.960] INFO: Done with hot pixel readout
[11:05:25.005] INFO: PixTest:: pg_setup set to default.

[11:05:25.006] INFO: 9 hot pixels found in step 3
[11:05:26.003] INFO: Collecting data for 5 seconds...
[11:05:31.020] INFO: Done with hot pixel readout
[11:05:43.333] INFO: PixTest:: pg_setup set to default.


[11:05:43.334] INFO: 7 hot pixels found in step 4
[11:05:44.330] INFO: Collecting data for 5 seconds...
[11:05:49.348] INFO: Done with hot pixel readout
[11:06:01.745] INFO: PixTest:: pg_setup set to default.


[11:06:01.745] INFO: 15 hot pixels found in step 5
[11:06:02.742] INFO: Collecting data for 5 seconds...
[11:06:07.759] INFO: Done with hot pixel readout
[11:06:20.075] INFO: PixTest:: pg_setup set to default.

[11:06:20.076] INFO: 7 hot pixels found in step 6
[11:06:21.073] INFO: Collecting data for 5 seconds...
[11:06:26.090] INFO: Done with hot pixel readout
[11:06:38.422] INFO: PixTest:: pg_setup set to default.

[11:06:38.423] INFO: 5 hot pixels found in step 7
[11:06:39.419] INFO: Collecting data for 5 seconds...
[11:06:44.436] INFO: Done with hot pixel readout
[11:06:56.781] INFO: PixTest:: pg_setup set to default.

[11:06:56.782] INFO: 14 hot pixels found in step 8
[11:06:57.779] INFO: Collecting data for 5 seconds...
[11:07:02.795] INFO: Done with hot pixel readout
[11:07:15.141] INFO: PixTest:: pg_setup set to default.


[11:07:15.142] INFO: 11 hot pixels found in step 9
[11:07:16.138] INFO: Collecting data for 5 seconds...
[11:07:21.155] INFO: Done with hot pixel readout
[11:07:33.513] INFO: PixTest:: pg_setup set to default.




[11:07:33.514] INFO: 13 hot pixels found in step 10
[11:07:34.511] INFO: Collecting data for 5 seconds...
[11:07:39.527] INFO: Done with hot pixel readout
[11:07:51.825] INFO: PixTest:: pg_setup set to default.


[11:07:51.826] INFO: 3 hot pixels found in step 11
[11:07:52.822] INFO: Collecting data for 5 seconds...
[11:07:57.839] INFO: Done with hot pixel readout
[11:08:10.187] INFO: PixTest:: pg_setup set to default.


[11:08:10.188] INFO: 10 hot pixels found in step 12
[11:08:11.185] INFO: Collecting data for 5 seconds...
[11:08:16.202] INFO: Done with hot pixel readout
[11:08:28.524] INFO: PixTest:: pg_setup set to default.

[11:08:28.525] INFO: 11 hot pixels found in step 13
[11:08:29.522] INFO: Collecting data for 5 seconds...
[11:08:34.539] INFO: Done with hot pixel readout
[11:08:46.893] INFO: PixTest:: pg_setup set to default.

[11:08:46.894] INFO: 11 hot pixels found in step 14
[11:08:46.934] INFO: 11 hot pixels could not be trimmed and have been masked.
[11:08:46.937] INFO: PixTest::trimHotPixels() done
[11:08:46.938] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C0.dat
[11:08:46.943] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C1.dat
[11:08:46.949] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C2.dat
[11:08:46.955] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C3.dat
[11:08:46.961] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C4.dat
[11:08:46.966] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C5.dat
[11:08:46.971] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C6.dat
[11:08:46.977] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C7.dat
[11:08:46.982] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C8.dat
[11:08:46.987] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C9.dat
[11:08:46.993] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C10.dat
[11:08:46.998] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C11.dat
[11:08:47.003] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C12.dat
[11:08:47.008] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C13.dat
[11:08:47.014] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C14.dat
[11:08:47.019] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C15.dat
[11:08:47.024] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//defaultMaskFile.dat
[11:08:47.035] INFO: enter test to run
[11:09:43.766] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:09:43.766] INFO: running: highrate
[11:09:43.771] INFO: ----------------------------------------------------------------------
[11:09:43.771] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:09:43.771] INFO: ----------------------------------------------------------------------
[11:09:43.771] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:09:43.771] INFO: edge/corner pixel THR is adjusted
[11:09:43.771] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:09:44.728] INFO: Collecting data for 1 seconds...
[11:09:45.732] INFO: Done with hot pixel readout
[11:09:50.228] INFO: PixTest:: pg_setup set to default.
[11:09:50.229] INFO: 0 hot pixels found in step 0
[11:09:50.234] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:09:50.302] INFO: PixTest::trimHotPixels() done
[11:09:50.302] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C0.dat
[11:09:50.308] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C1.dat
[11:09:50.313] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C2.dat
[11:09:50.319] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C3.dat
[11:09:50.324] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C4.dat
[11:09:50.329] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C5.dat
[11:09:50.335] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C6.dat
[11:09:50.340] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C7.dat
[11:09:50.346] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C8.dat
[11:09:50.351] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C9.dat
[11:09:50.356] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C10.dat
[11:09:50.362] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C11.dat
[11:09:50.367] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C12.dat
[11:09:50.373] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C13.dat
[11:09:50.378] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C14.dat
[11:09:50.383] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//trimParameters35_C15.dat
[11:09:50.389] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-Q-NH_FPIXTest-17C-FNAL-160506-1228_2016-05-06_12h28m_1462555703/000_FPIXTest_p17//defaultMaskFile.dat
[11:09:50.398] INFO: enter test to run
[11:10:33.214] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:10:33.214] INFO: running: xray
[11:10:33.215] INFO: ----------------------------------------------------------------------
[11:10:33.215] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:10:33.215] INFO: ----------------------------------------------------------------------
[11:10:34.178] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:10:44.850] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[11:11:14.266] INFO: Resuming triggers.
[11:11:24.940] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[11:11:54.891] INFO: Resuming triggers.
[11:12:05.565] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[11:12:35.769] INFO: Resuming triggers.
[11:12:46.443] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[11:13:16.202] INFO: Resuming triggers.
[11:13:26.876] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[11:13:56.463] INFO: Resuming triggers.
[11:14:07.141] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[11:14:36.764] INFO: Resuming triggers.
[11:14:47.438] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[11:15:17.123] INFO: Resuming triggers.
[11:15:27.800] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[11:15:57.448] INFO: Resuming triggers.
[11:16:08.123] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[11:16:37.824] INFO: Resuming triggers.
[11:16:42.099] INFO: data taking finished, elapsed time: 100 seconds.
[11:16:54.266] INFO: PixTest:: pg_setup set to default.
[11:16:54.270] INFO: PixTestXray::doPhRun() done
[11:16:54.406] INFO: enter test to run
[11:17:20.995] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:17:20.995] INFO: running: xray
[11:17:20.996] INFO: ----------------------------------------------------------------------
[11:17:20.996] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:17:20.996] INFO: ----------------------------------------------------------------------
[11:17:21.960] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:17:27.792] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[11:17:57.973] INFO: Resuming triggers.
[11:18:03.811] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:18:33.995] INFO: Resuming triggers.
[11:18:39.834] INFO: run duration 17 seconds, buffer almost full (81%), pausing triggers.
[11:19:10.038] INFO: Resuming triggers.
[11:19:15.877] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[11:19:46.132] INFO: Resuming triggers.
[11:19:51.972] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[11:20:22.078] INFO: Resuming triggers.
[11:20:27.916] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:20:58.912] INFO: Resuming triggers.
[11:21:04.752] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[11:21:35.521] INFO: Resuming triggers.
[11:21:41.358] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:22:12.573] INFO: Resuming triggers.
[11:22:18.411] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[11:22:49.642] INFO: Resuming triggers.
[11:22:55.482] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[11:23:28.113] INFO: Resuming triggers.
[11:23:33.956] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[11:24:04.493] INFO: Resuming triggers.
[11:24:10.338] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[11:24:40.461] INFO: Resuming triggers.
[11:24:46.303] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[11:25:16.499] INFO: Resuming triggers.
[11:25:22.340] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[11:25:52.569] INFO: Resuming triggers.
[11:25:58.406] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[11:26:28.687] INFO: Resuming triggers.
[11:26:34.523] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[11:27:04.732] INFO: Resuming triggers.
[11:27:10.570] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[11:27:40.756] INFO: Resuming triggers.
[11:27:41.838] INFO: data taking finished, elapsed time: 100 seconds.
[11:27:47.779] INFO: PixTest:: pg_setup set to default.
[11:27:47.782] INFO: PixTestXray::doPhRun() done
[11:27:47.934] INFO: enter test to run
[11:28:24.822] INFO: test: HighRate no parameter change
[11:28:24.822] INFO: running: highrate
[11:28:24.835] INFO: ----------------------------------------------------------------------
[11:28:24.835] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:28:24.835] INFO: ----------------------------------------------------------------------
[11:28:24.991] INFO: Expecting 768 events.
[11:28:26.121] INFO: 768 events read in total (415ms).
[11:28:26.122] INFO: Test took 1266ms.
[11:28:26.925] INFO: Expecting 41600 events.
[11:28:30.047] INFO: 41600 events read in total (2596ms).
[11:28:30.048] INFO: Test took 3916ms.
[11:28:30.086] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:30.804] INFO: Expecting 41600 events.
[11:28:34.058] INFO: 41600 events read in total (2727ms).
[11:28:34.059] INFO: Test took 3953ms.
[11:28:34.098] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:34.813] INFO: Expecting 41600 events.
[11:28:38.092] INFO: 41600 events read in total (2753ms).
[11:28:38.093] INFO: Test took 3976ms.
[11:28:38.133] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:38.846] INFO: Expecting 41600 events.
[11:28:42.111] INFO: 41600 events read in total (2738ms).
[11:28:42.112] INFO: Test took 3960ms.
[11:28:42.151] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:42.866] INFO: Expecting 41600 events.
[11:28:46.155] INFO: 41600 events read in total (2763ms).
[11:28:46.156] INFO: Test took 3985ms.
[11:28:46.196] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:46.911] INFO: Expecting 41600 events.
[11:28:50.210] INFO: 41600 events read in total (2772ms).
[11:28:50.211] INFO: Test took 3995ms.
[11:28:50.250] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:50.962] INFO: Expecting 41600 events.
[11:28:54.254] INFO: 41600 events read in total (2766ms).
[11:28:54.255] INFO: Test took 3986ms.
[11:28:54.294] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:55.005] INFO: Expecting 41600 events.
[11:28:58.297] INFO: 41600 events read in total (2765ms).
[11:28:58.298] INFO: Test took 3986ms.
[11:28:58.337] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:28:59.050] INFO: Expecting 41600 events.
[11:29:02.355] INFO: 41600 events read in total (2778ms).
[11:29:02.356] INFO: Test took 3998ms.
[11:29:02.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:03.110] INFO: Expecting 41600 events.
[11:29:06.411] INFO: 41600 events read in total (2774ms).
[11:29:06.412] INFO: Test took 3997ms.
[11:29:06.452] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:07.165] INFO: Expecting 41600 events.
[11:29:10.458] INFO: 41600 events read in total (2766ms).
[11:29:10.459] INFO: Test took 3988ms.
[11:29:10.498] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:11.214] INFO: Expecting 41600 events.
[11:29:14.514] INFO: 41600 events read in total (2773ms).
[11:29:14.515] INFO: Test took 3997ms.
[11:29:14.554] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:15.270] INFO: Expecting 41600 events.
[11:29:18.559] INFO: 41600 events read in total (2762ms).
[11:29:18.560] INFO: Test took 3986ms.
[11:29:18.600] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:19.316] INFO: Expecting 41600 events.
[11:29:22.611] INFO: 41600 events read in total (2768ms).
[11:29:22.612] INFO: Test took 3992ms.
[11:29:22.651] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:23.364] INFO: Expecting 41600 events.
[11:29:26.655] INFO: 41600 events read in total (2765ms).
[11:29:26.656] INFO: Test took 3985ms.
[11:29:26.695] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:27.407] INFO: Expecting 41600 events.
[11:29:30.700] INFO: 41600 events read in total (2766ms).
[11:29:30.701] INFO: Test took 3986ms.
[11:29:30.740] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:31.456] INFO: Expecting 41600 events.
[11:29:34.753] INFO: 41600 events read in total (2770ms).
[11:29:34.754] INFO: Test took 3995ms.
[11:29:34.793] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:35.505] INFO: Expecting 41600 events.
[11:29:38.803] INFO: 41600 events read in total (2771ms).
[11:29:38.804] INFO: Test took 3991ms.
[11:29:38.843] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:39.560] INFO: Expecting 41600 events.
[11:29:42.818] INFO: 41600 events read in total (2731ms).
[11:29:42.819] INFO: Test took 3957ms.
[11:29:42.858] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:43.573] INFO: Expecting 41600 events.
[11:29:46.719] INFO: 41600 events read in total (2619ms).
[11:29:46.720] INFO: Test took 3841ms.
[11:29:46.758] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:29:47.111] INFO: enter test to run
[11:30:05.021] INFO: test: HighRate no parameter change
[11:30:05.021] INFO: running: highrate
[11:30:05.022] INFO: ----------------------------------------------------------------------
[11:30:05.022] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:30:05.022] INFO: ----------------------------------------------------------------------
[11:30:05.637] INFO: Expecting 208000 events.
[11:30:17.770] INFO: 208000 events read in total (11606ms).
[11:30:17.773] INFO: Test took 12741ms.
[11:30:17.945] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:30:18.206] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 2 1 0 0 0 0 0 0 0
[11:30:18.206] INFO: number of red-efficiency pixels: 74 55 131 199 195 167 234 148 107 133 125 117 115 69 20 33
[11:30:18.206] INFO: number of X-ray hits detected: 75787 53645 81624 132715 141318 147594 142072 96271 83780 111710 108248 95423 94973 59386 27974 29719
[11:30:18.206] 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:30:18.206] INFO: number of Vcal hits detected: 207923 207944 207868 207790 207802 207829 207757 207751 207843 207856 207873 207881 207882 207929 207980 207967
[11:30:18.206] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[11:30:18.206] 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
[11:30:18.206] INFO: X-ray hit rate [MHz/cm2]: 22.2 15.7 23.9 38.9 41.4 43.3 41.6 28.2 24.6 32.7 31.7 28.0 27.8 17.4 8.2 8.7
[11:30:18.206] INFO: PixTestHighRate::doXPixelAlive() done
[11:30:18.253] INFO: PixTest:: pg_setup set to default.
[11:30:18.267] INFO: enter test to run
[11:32:47.884] INFO: test: HighRate no parameter change
[11:32:47.884] INFO: running: highrate
[11:32:47.885] INFO: ----------------------------------------------------------------------
[11:32:47.885] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:32:47.885] INFO: ----------------------------------------------------------------------
[11:32:48.497] INFO: Expecting 208000 events.
[11:33:02.942] INFO: 208000 events read in total (13918ms).
[11:33:02.949] INFO: Test took 15057ms.
[11:33:03.312] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:33:03.635] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 2 1 0 0 0 0 0 0 0
[11:33:03.635] INFO: number of red-efficiency pixels: 237 198 420 806 706 741 905 492 271 398 479 424 392 187 78 83
[11:33:03.635] INFO: number of X-ray hits detected: 160643 113455 174345 280130 299501 311456 300467 204447 177629 234685 228666 202235 200676 125455 59167 62357
[11:33:03.636] 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:33:03.636] INFO: number of Vcal hits detected: 207750 207785 207494 207056 207201 207164 206920 207340 207661 207561 207471 207543 207576 207801 207918 207916
[11:33:03.636] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.6 99.6 99.6 99.5 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[11:33:03.636] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.5 99.6 99.6 99.5 99.7 99.8 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[11:33:03.636] INFO: X-ray hit rate [MHz/cm2]: 47.1 33.3 51.1 82.1 87.8 91.3 88.1 59.9 52.1 68.8 67.0 59.3 58.8 36.8 17.3 18.3
[11:33:03.636] INFO: PixTestHighRate::doXPixelAlive() done
[11:33:03.680] INFO: PixTest:: pg_setup set to default.
[11:33:03.691] INFO: enter test to run
[11:33:33.539] INFO: test: HighRate no parameter change
[11:33:33.540] INFO: running: highrate
[11:33:33.541] INFO: ----------------------------------------------------------------------
[11:33:33.541] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:33:33.541] INFO: ----------------------------------------------------------------------
[11:33:34.164] INFO: Expecting 208000 events.
[11:33:51.517] INFO: 208000 events read in total (16827ms).
[11:33:51.526] INFO: Test took 17975ms.
[11:33:52.080] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:33:52.469] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 2 1 0 0 0 0 0 0 0
[11:33:52.469] INFO: number of red-efficiency pixels: 511 422 1034 1989 1633 1713 2108 1184 637 968 1308 971 950 407 131 134
[11:33:52.469] INFO: number of X-ray hits detected: 247009 173396 266159 429318 460863 478941 459393 314101 272999 361834 352626 310529 307995 193636 91448 97515
[11:33:52.469] 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:33:52.469] INFO: number of Vcal hits detected: 207387 207505 206350 204954 205681 205433 204501 206139 207202 206816 206272 206768 206845 207510 207864 207861
[11:33:52.470] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.3 98.7 99.0 98.9 98.5 99.3 99.7 99.5 99.2 99.5 99.5 99.8 99.9 99.9
[11:33:52.470] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.2 98.5 98.9 98.8 98.3 99.1 99.6 99.4 99.2 99.4 99.4 99.8 99.9 99.9
[11:33:52.470] INFO: X-ray hit rate [MHz/cm2]: 72.4 50.8 78.0 125.8 135.1 140.4 134.7 92.1 80.0 106.1 103.4 91.0 90.3 56.8 26.8 28.6
[11:33:52.470] INFO: PixTestHighRate::doXPixelAlive() done
[11:33:52.515] INFO: PixTest:: pg_setup set to default.
[11:33:52.531] INFO: enter test to run
[11:34:26.539] INFO: test: exit no parameter change
[11:34:26.963] QUIET: Connection to board 33 closed.
[11:34:26.979] INFO: pXar: this is the end, my friend