[15:46:24.395] INFO: *** Welcome to pxar ***
[15:46:24.395] INFO: *** Today: 2016/05/06
[15:46:24.580] INFO: *** Version: v1.9.0-796-gef167-dirty
[15:46:24.580] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//dacParameters35_C15.dat
[15:46:24.914] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:46:24.914] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//defaultMaskFile.dat
[15:46:24.940] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C15.dat
[15:46:26.149] INFO: clk: 4
[15:46:26.149] INFO: ctr: 4
[15:46:26.149] INFO: sda: 19
[15:46:26.149] INFO: tin: 9
[15:46:26.149] INFO: level: 15
[15:46:26.149] INFO: triggerdelay: 0
[15:46:26.149] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[15:46:26.149] INFO: Log level: INFO
[15:46:26.168] QUIET: Connection to board DTB_WREKRL opened.
[15:46:26.171] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[15:46:26.174] INFO: RPC call hashes of host and DTB match: 398089610
[15:46:27.700] INFO: DUT info:
[15:46:27.700] INFO: The DUT currently contains the following objects:
[15:46:27.700] INFO: 2 TBM Cores tbm08c (2 ON)
[15:46:27.700] INFO: TBM Core alpha (0): 7 registers set
[15:46:27.700] INFO: TBM Core beta (1): 7 registers set
[15:46:27.700] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:46:27.700] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.700] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.700] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.700] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.700] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.700] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.700] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.700] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.700] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.700] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.701] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.701] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.701] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.701] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.701] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:27.701] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:46:28.119] INFO: enter 'restricted' command line mode
[15:46:28.119] INFO: enter test to run
[15:46:39.264] INFO: test: PixelAlive no parameter change
[15:46:39.264] INFO: running: pixelalive
[15:46:39.273] INFO: ----------------------------------------------------------------------
[15:46:39.273] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[15:46:39.273] INFO: ----------------------------------------------------------------------
[15:46:39.598] INFO: Expecting 41600 events.
[15:46:43.945] INFO: 41600 events read in total (3628ms).
[15:46:44.111] INFO: Test took 4835ms.
[15:46:44.126] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:46:44.387] INFO: PixTestAlive::aliveTest() done
[15:46:44.387] INFO: number of dead pixels (per ROC): 0 0 0 3 1 0 0 0 0 0 1 3 0 1 0 0
[15:46:44.422] INFO: enter test to run
[15:47:17.999] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:47:17.000] INFO: running: highrate
[15:47:17.000] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:47:18.255] INFO: ----------------------------------------------------------------------
[15:47:18.255] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:47:18.255] INFO: ----------------------------------------------------------------------
[15:47:18.255] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:47:18.255] INFO: edge/corner pixel THR is adjusted
[15:47:18.255] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:47:19.214] INFO: Collecting data for 5 seconds...
[15:47:24.233] INFO: Done with hot pixel readout


















[15:47:37.519] INFO: PixTest:: pg_setup set to default.












[15:47:37.551] INFO: 463 hot pixels found in step 0
[15:47:38.547] INFO: Collecting data for 5 seconds...
[15:47:43.569] INFO: Done with hot pixel readout
[15:47:56.726] INFO: PixTest:: pg_setup set to default.




























[15:47:56.728] INFO: 426 hot pixels found in step 1
[15:47:57.726] INFO: Collecting data for 5 seconds...
[15:48:02.745] INFO: Done with hot pixel readout
[15:48:15.845] INFO: PixTest:: pg_setup set to default.






























[15:48:15.847] INFO: 397 hot pixels found in step 2
[15:48:16.847] INFO: Collecting data for 5 seconds...
[15:48:21.866] INFO: Done with hot pixel readout
[15:48:34.854] INFO: PixTest:: pg_setup set to default.















































[15:48:34.856] INFO: 347 hot pixels found in step 3
[15:48:35.855] INFO: Collecting data for 5 seconds...
[15:48:40.871] INFO: Done with hot pixel readout
[15:48:53.888] INFO: PixTest:: pg_setup set to default.




























































[15:48:53.891] INFO: 325 hot pixels found in step 4
[15:48:54.889] INFO: Collecting data for 5 seconds...
[15:48:59.905] INFO: Done with hot pixel readout
[15:49:12.907] INFO: PixTest:: pg_setup set to default.































































[15:49:12.909] INFO: 312 hot pixels found in step 5
[15:49:13.908] INFO: Collecting data for 5 seconds...
[15:49:18.925] INFO: Done with hot pixel readout
[15:49:31.963] INFO: PixTest:: pg_setup set to default.














































































[15:49:31.966] INFO: 279 hot pixels found in step 6
[15:49:32.963] INFO: Collecting data for 5 seconds...
[15:49:37.980] INFO: Done with hot pixel readout
[15:49:50.924] INFO: PixTest:: pg_setup set to default.



























































































[15:49:50.927] INFO: 292 hot pixels found in step 7
[15:49:51.925] INFO: Collecting data for 5 seconds...
[15:49:56.941] INFO: Done with hot pixel readout
[15:50:09.948] INFO: PixTest:: pg_setup set to default.




























































































[15:50:09.950] INFO: 267 hot pixels found in step 8
[15:50:10.948] INFO: Collecting data for 5 seconds...
[15:50:15.964] INFO: Done with hot pixel readout
[15:50:28.976] INFO: PixTest:: pg_setup set to default.









































































[15:50:28.978] INFO: 244 hot pixels found in step 9
[15:50:29.976] INFO: Collecting data for 5 seconds...
[15:50:34.992] INFO: Done with hot pixel readout
[15:50:48.068] INFO: PixTest:: pg_setup set to default.
























































































[15:50:48.071] INFO: 252 hot pixels found in step 10
[15:50:49.069] INFO: Collecting data for 5 seconds...
[15:50:54.085] INFO: Done with hot pixel readout
[15:51:07.090] INFO: PixTest:: pg_setup set to default.























































































[15:51:07.092] INFO: 217 hot pixels found in step 11
[15:51:08.090] INFO: Collecting data for 5 seconds...
[15:51:13.106] INFO: Done with hot pixel readout
[15:51:26.165] INFO: PixTest:: pg_setup set to default.







































































































[15:51:26.170] INFO: 230 hot pixels found in step 12
[15:51:27.173] INFO: Collecting data for 5 seconds...
[15:51:32.191] INFO: Done with hot pixel readout
[15:51:45.242] INFO: PixTest:: pg_setup set to default.








































































































[15:51:45.244] INFO: 229 hot pixels found in step 13
[15:51:46.242] INFO: Collecting data for 5 seconds...
[15:51:51.258] INFO: Done with hot pixel readout
[15:52:04.320] INFO: PixTest:: pg_setup set to default.





















































































[15:52:04.322] INFO: 189 hot pixels found in step 14
[15:52:04.365] INFO: 189 hot pixels could not be trimmed and have been masked.
[15:52:04.369] INFO: PixTest::trimHotPixels() done
[15:52:04.383] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C0.dat
[15:52:04.395] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C1.dat
[15:52:04.406] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C2.dat
[15:52:04.412] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C3.dat
[15:52:04.417] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C4.dat
[15:52:04.423] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C5.dat
[15:52:04.428] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C6.dat
[15:52:04.434] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C7.dat
[15:52:04.439] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C8.dat
[15:52:04.458] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C9.dat
[15:52:04.463] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C10.dat
[15:52:04.469] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C11.dat
[15:52:04.474] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C12.dat
[15:52:04.480] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C13.dat
[15:52:04.485] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C14.dat
[15:52:04.491] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C15.dat
[15:52:04.496] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//defaultMaskFile.dat
[15:52:04.507] INFO: enter test to run
[15:52:52.077] INFO: test: timing no parameter change
[15:52:52.077] INFO: running: timing
[15:52:52.101] INFO: ######################################################################
[15:52:52.101] INFO: PixTestTiming::doTest()
[15:52:52.110] INFO: ######################################################################
[15:52:52.110] INFO: ----------------------------------------------------------------------
[15:52:52.110] INFO: PixTestTiming::TBMPhaseScan()
[15:52:52.110] INFO: ----------------------------------------------------------------------
[15:57:50.487] INFO: TBM Phase Settings: 252
[15:57:50.487] INFO: 400MHz Phase: 7
[15:57:50.487] INFO: 160MHz Phase: 7
[15:57:50.487] INFO: Functional Phase Area: 3
[15:57:50.497] INFO: Test took 298387 ms.
[15:57:50.497] INFO: PixTestTiming::TBMPhaseScan() done.
[15:57:50.497] INFO: ----------------------------------------------------------------------
[15:57:50.497] INFO: PixTestTiming::ROCDelayScan()
[15:57:50.497] INFO: ----------------------------------------------------------------------
[16:01:30.791] INFO: ROC Delay Settings: 228
[16:01:30.791] INFO: ROC Header-Trailer/Token Delay: 11
[16:01:30.791] INFO: ROC Port 0 Delay: 4
[16:01:30.791] INFO: ROC Port 1 Delay: 4
[16:01:30.791] INFO: Functional ROC Area: 5
[16:01:30.795] INFO: Test took 220298 ms.
[16:01:30.795] INFO: PixTestTiming::ROCDelayScan() done.
[16:01:30.795] INFO: ----------------------------------------------------------------------
[16:01:30.795] INFO: PixTestTiming::TimingTest()
[16:01:30.795] INFO: ----------------------------------------------------------------------
[16:01:46.929] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:02:01.949] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:02:16.917] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:02:31.901] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:02:46.888] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:03:01.863] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:03:16.844] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:03:31.829] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:03:46.828] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:01.821] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:02.207] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:04:02.218] INFO: ----------------------------------------------------------------------
[16:04:02.218] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:04:02.218] INFO: ----------------------------------------------------------------------
[16:04:02.218] INFO: ----------------------------------------------------------------------
[16:04:02.218] INFO: Read back bit status: 1
[16:04:02.218] INFO: ----------------------------------------------------------------------
[16:04:02.218] INFO: ----------------------------------------------------------------------
[16:04:02.218] INFO: Timings are good!
[16:04:02.218] INFO: ----------------------------------------------------------------------
[16:04:02.218] INFO: Test took 151423 ms.
[16:04:02.219] INFO: PixTestTiming::TimingTest() done.
[16:04:02.236] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:04:02.236] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:04:02.236] INFO: PixTestTiming::doTest took 670138 ms.
[16:04:02.236] INFO: PixTestTiming::doTest() done
[16:04:02.237] INFO: Write out TBMPhaseScan_0_V0
[16:04:02.237] INFO: Write out TBMPhaseScan_1_V0
[16:04:02.237] INFO: Write out CombinedTBMPhaseScan_V0
[16:04:02.270] INFO: Write out ROCDelayScan3_V0
[16:04:02.270] INFO: enter test to run
[16:05:02.040] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:05:02.040] INFO: running: highrate
[16:05:02.045] INFO: ----------------------------------------------------------------------
[16:05:02.045] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:05:02.045] INFO: ----------------------------------------------------------------------
[16:05:02.045] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:05:02.045] INFO: edge/corner pixel THR is adjusted
[16:05:02.045] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:05:02.002] INFO: Collecting data for 1 seconds...
[16:05:04.006] INFO: Done with hot pixel readout
[16:05:08.419] INFO: PixTest:: pg_setup set to default.
[16:05:08.420] INFO: 0 hot pixels found in step 0
[16:05:08.425] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:05:08.499] INFO: PixTest::trimHotPixels() done
[16:05:08.499] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C0.dat
[16:05:08.510] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C1.dat
[16:05:08.516] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C2.dat
[16:05:08.521] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C3.dat
[16:05:08.527] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C4.dat
[16:05:08.535] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C5.dat
[16:05:08.543] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C6.dat
[16:05:08.552] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C7.dat
[16:05:08.561] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C8.dat
[16:05:08.570] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C9.dat
[16:05:08.579] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C10.dat
[16:05:08.587] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C11.dat
[16:05:08.597] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C12.dat
[16:05:08.606] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C13.dat
[16:05:08.614] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C14.dat
[16:05:08.624] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//trimParameters35_C15.dat
[16:05:08.633] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-E-NF_FPIXTest-17C-FNAL-160428-1309_2016-04-28_13h09m_1461866950/000_FPIXTest_p17//defaultMaskFile.dat
[16:05:08.645] INFO: enter test to run
[16:05:28.087] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:05:28.088] INFO: running: xray
[16:05:28.089] INFO: ----------------------------------------------------------------------
[16:05:28.089] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:05:28.089] INFO: ----------------------------------------------------------------------
[16:05:29.053] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:05:39.428] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[16:06:08.736] INFO: Resuming triggers.
[16:06:19.115] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[16:06:48.722] INFO: Resuming triggers.
[16:06:59.100] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[16:07:28.777] INFO: Resuming triggers.
[16:07:39.149] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[16:08:08.820] INFO: Resuming triggers.
[16:08:19.194] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[16:08:49.347] INFO: Resuming triggers.
[16:08:59.723] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[16:09:29.965] INFO: Resuming triggers.
[16:09:40.339] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[16:10:10.563] INFO: Resuming triggers.
[16:10:20.937] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[16:10:50.545] INFO: Resuming triggers.
[16:11:00.920] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[16:11:30.528] INFO: Resuming triggers.
[16:11:37.506] INFO: data taking finished, elapsed time: 100 seconds.
[16:11:57.721] INFO: PixTest:: pg_setup set to default.
[16:11:57.725] INFO: PixTestXray::doPhRun() done
[16:11:57.866] INFO: enter test to run
[16:13:00.820] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:13:00.820] INFO: running: xray
[16:13:00.821] INFO: ----------------------------------------------------------------------
[16:13:00.822] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:13:00.822] INFO: ----------------------------------------------------------------------
[16:13:01.785] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:13:07.652] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[16:13:37.840] INFO: Resuming triggers.
[16:13:43.709] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[16:14:13.900] INFO: Resuming triggers.
[16:14:19.770] INFO: run duration 17 seconds, buffer almost full (81%), pausing triggers.
[16:14:49.841] INFO: Resuming triggers.
[16:14:55.706] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[16:15:25.989] INFO: Resuming triggers.
[16:15:31.856] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[16:16:02.061] INFO: Resuming triggers.
[16:16:07.928] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[16:16:38.656] INFO: Resuming triggers.
[16:16:44.517] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[16:17:14.426] INFO: Resuming triggers.
[16:17:20.292] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[16:17:50.490] INFO: Resuming triggers.
[16:17:56.354] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[16:18:26.543] INFO: Resuming triggers.
[16:18:32.405] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[16:19:02.566] INFO: Resuming triggers.
[16:19:08.431] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[16:19:38.810] INFO: Resuming triggers.
[16:19:44.674] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[16:20:15.984] INFO: Resuming triggers.
[16:20:21.849] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[16:20:53.428] INFO: Resuming triggers.
[16:20:59.294] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[16:21:30.057] INFO: Resuming triggers.
[16:21:35.919] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[16:22:06.163] INFO: Resuming triggers.
[16:22:12.023] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[16:22:42.204] INFO: Resuming triggers.
[16:22:48.070] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[16:23:18.051] INFO: Resuming triggers.
[16:23:18.691] INFO: data taking finished, elapsed time: 100 seconds.
[16:23:22.343] INFO: PixTest:: pg_setup set to default.
[16:23:22.346] INFO: PixTestXray::doPhRun() done
[16:23:22.494] INFO: enter test to run
[16:24:25.023] INFO: test: HighRate no parameter change
[16:24:25.023] INFO: running: highrate
[16:24:25.024] INFO: ----------------------------------------------------------------------
[16:24:25.024] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:24:25.024] INFO: ----------------------------------------------------------------------
[16:24:25.166] INFO: Expecting 768 events.
[16:24:26.300] INFO: 768 events read in total (418ms).
[16:24:26.300] INFO: Test took 1268ms.
[16:24:27.103] INFO: Expecting 41600 events.
[16:24:30.382] INFO: 41600 events read in total (2752ms).
[16:24:30.383] INFO: Test took 4076ms.
[16:24:30.432] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:31.130] INFO: Expecting 41600 events.
[16:24:34.489] INFO: 41600 events read in total (2832ms).
[16:24:34.490] INFO: Test took 4034ms.
[16:24:34.540] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:35.232] INFO: Expecting 41600 events.
[16:24:38.630] INFO: 41600 events read in total (2871ms).
[16:24:38.632] INFO: Test took 4067ms.
[16:24:38.680] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:39.376] INFO: Expecting 41600 events.
[16:24:42.772] INFO: 41600 events read in total (2869ms).
[16:24:42.773] INFO: Test took 4069ms.
[16:24:42.822] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:43.520] INFO: Expecting 41600 events.
[16:24:46.921] INFO: 41600 events read in total (2875ms).
[16:24:46.922] INFO: Test took 4076ms.
[16:24:46.973] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:47.661] INFO: Expecting 41600 events.
[16:24:51.050] INFO: 41600 events read in total (2862ms).
[16:24:51.051] INFO: Test took 4056ms.
[16:24:51.102] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:51.794] INFO: Expecting 41600 events.
[16:24:55.213] INFO: 41600 events read in total (2892ms).
[16:24:55.215] INFO: Test took 4089ms.
[16:24:55.271] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:55.955] INFO: Expecting 41600 events.
[16:24:59.365] INFO: 41600 events read in total (2883ms).
[16:24:59.366] INFO: Test took 4070ms.
[16:24:59.416] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:00.108] INFO: Expecting 41600 events.
[16:25:03.508] INFO: 41600 events read in total (2873ms).
[16:25:03.509] INFO: Test took 4070ms.
[16:25:03.559] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:04.255] INFO: Expecting 41600 events.
[16:25:07.657] INFO: 41600 events read in total (2876ms).
[16:25:07.659] INFO: Test took 4076ms.
[16:25:07.709] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:08.402] INFO: Expecting 41600 events.
[16:25:11.810] INFO: 41600 events read in total (2881ms).
[16:25:11.811] INFO: Test took 4078ms.
[16:25:11.861] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:12.555] INFO: Expecting 41600 events.
[16:25:15.960] INFO: 41600 events read in total (2878ms).
[16:25:15.962] INFO: Test took 4077ms.
[16:25:16.012] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:16.704] INFO: Expecting 41600 events.
[16:25:20.093] INFO: 41600 events read in total (2862ms).
[16:25:20.094] INFO: Test took 4057ms.
[16:25:20.143] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:20.839] INFO: Expecting 41600 events.
[16:25:24.244] INFO: 41600 events read in total (2878ms).
[16:25:24.246] INFO: Test took 4078ms.
[16:25:24.295] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:24.992] INFO: Expecting 41600 events.
[16:25:28.406] INFO: 41600 events read in total (2887ms).
[16:25:28.407] INFO: Test took 4088ms.
[16:25:28.458] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:29.151] INFO: Expecting 41600 events.
[16:25:32.557] INFO: 41600 events read in total (2879ms).
[16:25:32.558] INFO: Test took 4076ms.
[16:25:32.607] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:33.301] INFO: Expecting 41600 events.
[16:25:36.701] INFO: 41600 events read in total (2873ms).
[16:25:36.702] INFO: Test took 4071ms.
[16:25:36.753] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:37.448] INFO: Expecting 41600 events.
[16:25:40.861] INFO: 41600 events read in total (2886ms).
[16:25:40.863] INFO: Test took 4087ms.
[16:25:40.912] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:41.605] INFO: Expecting 41600 events.
[16:25:44.967] INFO: 41600 events read in total (2836ms).
[16:25:44.968] INFO: Test took 4031ms.
[16:25:45.018] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:45.714] INFO: Expecting 41600 events.
[16:25:48.910] INFO: 41600 events read in total (2669ms).
[16:25:48.911] INFO: Test took 3869ms.
[16:25:48.960] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:49.296] INFO: enter test to run
[16:26:39.966] INFO: test: HighRate no parameter change
[16:26:39.966] INFO: running: highrate
[16:26:39.967] INFO: ----------------------------------------------------------------------
[16:26:39.967] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:26:39.967] INFO: ----------------------------------------------------------------------
[16:26:40.590] INFO: Expecting 208000 events.
[16:26:53.430] INFO: 208000 events read in total (12314ms).
[16:26:53.434] INFO: Test took 13456ms.
[16:26:53.655] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:26:53.933] INFO: number of dead pixels (per ROC): 0 0 0 3 1 0 0 0 0 0 1 3 0 1 0 0
[16:26:53.933] INFO: number of red-efficiency pixels: 141 91 175 285 305 328 263 194 155 206 228 208 175 123 40 35
[16:26:53.933] INFO: number of X-ray hits detected: 102161 69471 106970 174053 186578 186460 187873 130033 118119 154332 148076 129698 135596 80756 34946 36748
[16:26:53.933] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:26:53.934] INFO: number of Vcal hits detected: 207843 207904 207814 207556 207631 207654 207725 207802 207841 207783 207717 207640 207819 207825 207960 207965
[16:26:53.934] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.9 99.9 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[16:26:53.934] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.8 99.9 99.9 100.0 100.0
[16:26:53.934] INFO: X-ray hit rate [MHz/cm2]: 29.9 20.4 31.4 51.0 54.7 54.7 55.1 38.1 34.6 45.2 43.4 38.0 39.7 23.7 10.2 10.8
[16:26:53.934] INFO: PixTestHighRate::doXPixelAlive() done
[16:26:53.987] INFO: PixTest:: pg_setup set to default.
[16:26:53.003] INFO: enter test to run
[16:27:08.790] INFO: test: HighRate no parameter change
[16:27:08.790] INFO: running: highrate
[16:27:08.791] INFO: ----------------------------------------------------------------------
[16:27:08.791] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:27:08.791] INFO: ----------------------------------------------------------------------
[16:27:09.416] INFO: Expecting 208000 events.
[16:27:24.304] INFO: 208000 events read in total (14361ms).
[16:27:24.312] INFO: Test took 15512ms.
[16:27:24.713] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:27:25.054] INFO: number of dead pixels (per ROC): 0 0 0 3 1 0 0 0 0 0 1 3 0 1 0 0
[16:27:25.054] INFO: number of red-efficiency pixels: 288 207 524 995 976 1098 797 611 381 553 664 486 477 353 64 73
[16:27:25.054] INFO: number of X-ray hits detected: 180368 122728 190264 308990 331032 331024 332816 232012 210845 274243 261687 230687 240292 144341 62663 65285
[16:27:25.054] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:27:25.054] INFO: number of Vcal hits detected: 207653 207782 207345 206659 206773 206651 207038 207271 207590 207383 207202 207326 207486 207551 207932 207927
[16:27:25.054] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.7 99.5 99.5 99.4 99.6 99.7 99.8 99.7 99.7 99.8 99.8 99.8 100.0 100.0
[16:27:25.054] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.4 99.4 99.4 99.5 99.6 99.8 99.7 99.6 99.7 99.8 99.8 100.0 100.0
[16:27:25.055] INFO: X-ray hit rate [MHz/cm2]: 52.9 36.0 55.8 90.6 97.0 97.0 97.6 68.0 61.8 80.4 76.7 67.6 70.4 42.3 18.4 19.1
[16:27:25.055] INFO: PixTestHighRate::doXPixelAlive() done
[16:27:25.099] INFO: PixTest:: pg_setup set to default.
[16:27:25.115] INFO: enter test to run
[16:27:50.742] INFO: test: HighRate no parameter change
[16:27:50.742] INFO: running: highrate
[16:27:50.743] INFO: ----------------------------------------------------------------------
[16:27:50.743] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:27:50.743] INFO: ----------------------------------------------------------------------
[16:27:51.366] INFO: Expecting 208000 events.
[16:28:08.961] INFO: 208000 events read in total (17068ms).
[16:28:08.970] INFO: Test took 18218ms.
[16:28:09.564] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:28:09.967] INFO: number of dead pixels (per ROC): 0 0 0 3 1 0 0 0 0 0 1 3 0 1 0 0
[16:28:09.967] INFO: number of red-efficiency pixels: 579 428 1104 2096 2028 2308 1833 1386 791 1258 1564 977 1107 698 124 134
[16:28:09.967] INFO: number of X-ray hits detected: 264656 180055 277792 451104 482797 481452 486790 339661 307506 401192 383072 337260 351430 211017 92061 96273
[16:28:09.967] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:28:09.967] INFO: number of Vcal hits detected: 207247 207500 206138 204429 204721 203996 205176 205878 207049 206395 205817 206647 206638 206994 207869 207858
[16:28:09.967] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.2 98.5 98.6 98.3 98.8 99.1 99.6 99.3 99.1 99.5 99.4 99.6 99.9 99.9
[16:28:09.967] INFO: Vcal hit overall efficiency (%): 99.6 99.8 99.1 98.3 98.4 98.1 98.6 99.0 99.5 99.2 99.0 99.3 99.3 99.5 99.9 99.9
[16:28:09.967] INFO: X-ray hit rate [MHz/cm2]: 77.6 52.8 81.4 132.2 141.5 141.1 142.7 99.6 90.1 117.6 112.3 98.9 103.0 61.9 27.0 28.2
[16:28:09.967] INFO: PixTestHighRate::doXPixelAlive() done
[16:28:10.013] INFO: PixTest:: pg_setup set to default.
[16:28:10.032] INFO: enter test to run
[16:28:13.997] INFO: test: exit no parameter change
[16:28:14.429] QUIET: Connection to board 33 closed.
[16:28:14.430] INFO: pXar: this is the end, my friend