[10:03:44.078] INFO: *** Welcome to pxar ***
[10:03:44.078] INFO: *** Today: 2016/05/04
[10:03:45.822] INFO: *** Version: v1.9.0-796-gef167-dirty
[10:03:45.822] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//dacParameters35_C15.dat
[10:03:46.050] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:03:46.050] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//defaultMaskFile.dat
[10:03:46.050] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C15.dat
[10:03:47.069] INFO: clk: 4
[10:03:47.069] INFO: ctr: 4
[10:03:47.069] INFO: sda: 19
[10:03:47.069] INFO: tin: 9
[10:03:47.069] INFO: level: 15
[10:03:47.069] INFO: triggerdelay: 0
[10:03:47.069] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[10:03:47.069] INFO: Log level: INFO
[10:03:47.087] QUIET: Connection to board DTB_WREK4U opened.
[10:03:47.090] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 32
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREK4U
MAC address: 40D855118020
Hostname: pixelDTB032
Comment:
------------------------------------------------------
[10:03:47.093] INFO: RPC call hashes of host and DTB match: 398089610
[10:03:48.619] INFO: DUT info:
[10:03:48.619] INFO: The DUT currently contains the following objects:
[10:03:48.619] INFO: 2 TBM Cores tbm08c (2 ON)
[10:03:48.619] INFO: TBM Core alpha (0): 7 registers set
[10:03:48.619] INFO: TBM Core beta (1): 7 registers set
[10:03:48.619] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[10:03:48.619] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.619] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.619] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.619] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.619] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.619] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.619] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.620] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.620] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.620] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.620] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.620] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.620] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.620] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.620] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:48.620] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[10:03:49.041] INFO: enter 'restricted' command line mode
[10:03:49.041] INFO: enter test to run
[10:03:50.191] INFO: test: timinfg no parameter change
[10:03:50.192] INFO: running: timinfg
[10:03:50.192] INFO: command ->timinfg<- not known, ignored
[10:03:50.192] INFO: enter test to run
[10:03:53.224] INFO: test: timing no parameter change
[10:03:53.224] INFO: running: timing
[10:03:53.248] INFO: ######################################################################
[10:03:53.248] INFO: PixTestTiming::doTest()
[10:03:53.248] INFO: ######################################################################
[10:03:53.248] INFO: ----------------------------------------------------------------------
[10:03:53.248] INFO: PixTestTiming::TBMPhaseScan()
[10:03:53.248] INFO: ----------------------------------------------------------------------
[10:08:38.932] INFO: TBM Phase Settings: 224
[10:08:38.932] INFO: 400MHz Phase: 0
[10:08:38.932] INFO: 160MHz Phase: 7
[10:08:38.932] INFO: Functional Phase Area: 3
[10:08:38.946] INFO: Test took 285698 ms.
[10:08:38.946] INFO: PixTestTiming::TBMPhaseScan() done.
[10:08:38.947] INFO: ----------------------------------------------------------------------
[10:08:38.947] INFO: PixTestTiming::ROCDelayScan()
[10:08:38.947] INFO: ----------------------------------------------------------------------
[10:10:30.912] INFO: ROC Delay Settings: 228
[10:10:30.912] INFO: ROC Header-Trailer/Token Delay: 11
[10:10:30.912] INFO: ROC Port 0 Delay: 4
[10:10:30.912] INFO: ROC Port 1 Delay: 4
[10:10:30.912] INFO: Functional ROC Area: 3
[10:10:30.915] INFO: Test took 111968 ms.
[10:10:30.915] INFO: PixTestTiming::ROCDelayScan() done.
[10:10:30.916] INFO: ----------------------------------------------------------------------
[10:10:30.916] INFO: PixTestTiming::TimingTest()
[10:10:30.916] INFO: ----------------------------------------------------------------------
[10:10:47.075] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:02.067] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:17.050] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:32.021] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:11:47.083] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:12:02.304] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:12:17.427] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:12:32.488] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:12:47.481] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:13:02.478] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:13:02.855] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:13:02.873] INFO: ----------------------------------------------------------------------
[10:13:02.873] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[10:13:02.873] INFO: ----------------------------------------------------------------------
[10:13:02.873] INFO: ----------------------------------------------------------------------
[10:13:02.873] INFO: Read back bit status: 1
[10:13:02.873] INFO: ----------------------------------------------------------------------
[10:13:02.873] INFO: ----------------------------------------------------------------------
[10:13:02.873] INFO: Timings are good!
[10:13:02.873] INFO: ----------------------------------------------------------------------
[10:13:02.873] INFO: Test took 151957 ms.
[10:13:02.873] INFO: PixTestTiming::TimingTest() done.
[10:13:02.874] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//tbmParameters_C0a.dat
[10:13:02.874] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:13:02.874] INFO: PixTestTiming::doTest took 549631 ms.
[10:13:02.874] INFO: PixTestTiming::doTest() done
[10:13:02.874] INFO: Write out TBMPhaseScan_0_V0
[10:13:02.903] INFO: Write out TBMPhaseScan_1_V0
[10:13:02.903] INFO: Write out CombinedTBMPhaseScan_V0
[10:13:02.937] INFO: Write out ROCDelayScan3_V0
[10:13:02.938] INFO: enter test to run
[10:13:49.763] INFO: test: PixelAlive no parameter change
[10:13:49.763] INFO: running: pixelalive
[10:13:49.792] INFO: ----------------------------------------------------------------------
[10:13:49.792] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[10:13:49.792] INFO: ----------------------------------------------------------------------
[10:13:50.116] INFO: Expecting 41600 events.
[10:13:54.448] INFO: 41600 events read in total (3616ms).
[10:13:54.449] INFO: Test took 4653ms.
[10:13:54.455] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:13:54.853] INFO: PixTestAlive::aliveTest() done
[10:13:54.853] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:13:54.857] INFO: enter test to run
[10:15:05.603] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:15:05.603] INFO: running: highrate
[10:15:05.618] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:15:05.800] INFO: ----------------------------------------------------------------------
[10:15:05.800] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:15:05.800] INFO: ----------------------------------------------------------------------
[10:15:05.800] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:15:05.800] INFO: edge/corner pixel THR is adjusted
[10:15:05.800] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:15:06.758] INFO: Collecting data for 5 seconds...
[10:15:11.775] INFO: Done with hot pixel readout
[10:15:23.816] INFO: PixTest:: pg_setup set to default.
[10:15:23.817] INFO: 13 hot pixels found in step 0
[10:15:24.812] INFO: Collecting data for 5 seconds...
[10:15:29.829] INFO: Done with hot pixel readout
[10:15:41.833] INFO: PixTest:: pg_setup set to default.

[10:15:41.834] INFO: 20 hot pixels found in step 1
[10:15:42.828] INFO: Collecting data for 5 seconds...
[10:15:47.844] INFO: Done with hot pixel readout
[10:15:59.879] INFO: PixTest:: pg_setup set to default.
[10:15:59.880] INFO: 15 hot pixels found in step 2
[10:16:00.874] INFO: Collecting data for 5 seconds...
[10:16:05.891] INFO: Done with hot pixel readout
[10:16:17.937] INFO: PixTest:: pg_setup set to default.

[10:16:17.938] INFO: 20 hot pixels found in step 3
[10:16:18.932] INFO: Collecting data for 5 seconds...
[10:16:23.948] INFO: Done with hot pixel readout
[10:16:35.975] INFO: PixTest:: pg_setup set to default.


[10:16:35.976] INFO: 13 hot pixels found in step 4
[10:16:36.972] INFO: Collecting data for 5 seconds...
[10:16:41.988] INFO: Done with hot pixel readout
[10:16:54.027] INFO: PixTest:: pg_setup set to default.
[10:16:54.028] INFO: 12 hot pixels found in step 5
[10:16:55.023] INFO: Collecting data for 5 seconds...
[10:17:00.040] INFO: Done with hot pixel readout
[10:17:12.079] INFO: PixTest:: pg_setup set to default.
[10:17:12.080] INFO: 11 hot pixels found in step 6
[10:17:13.075] INFO: Collecting data for 5 seconds...
[10:17:18.092] INFO: Done with hot pixel readout
[10:17:30.155] INFO: PixTest:: pg_setup set to default.

[10:17:30.156] INFO: 15 hot pixels found in step 7
[10:17:31.151] INFO: Collecting data for 5 seconds...
[10:17:36.167] INFO: Done with hot pixel readout
[10:17:48.204] INFO: PixTest:: pg_setup set to default.
[10:17:48.204] INFO: 12 hot pixels found in step 8
[10:17:49.199] INFO: Collecting data for 5 seconds...
[10:17:54.216] INFO: Done with hot pixel readout
[10:18:06.275] INFO: PixTest:: pg_setup set to default.
[10:18:06.276] INFO: 13 hot pixels found in step 9
[10:18:07.270] INFO: Collecting data for 5 seconds...
[10:18:12.287] INFO: Done with hot pixel readout
[10:18:24.347] INFO: PixTest:: pg_setup set to default.
[10:18:24.347] INFO: 21 hot pixels found in step 10
[10:18:25.343] INFO: Collecting data for 5 seconds...
[10:18:30.361] INFO: Done with hot pixel readout
[10:18:42.399] INFO: PixTest:: pg_setup set to default.
[10:18:42.400] INFO: 8 hot pixels found in step 11
[10:18:43.394] INFO: Collecting data for 5 seconds...
[10:18:48.411] INFO: Done with hot pixel readout
[10:19:00.464] INFO: PixTest:: pg_setup set to default.
[10:19:00.465] INFO: 8 hot pixels found in step 12
[10:19:01.459] INFO: Collecting data for 5 seconds...
[10:19:06.475] INFO: Done with hot pixel readout
[10:19:18.496] INFO: PixTest:: pg_setup set to default.
[10:19:18.497] INFO: 10 hot pixels found in step 13
[10:19:19.491] INFO: Collecting data for 5 seconds...
[10:19:24.513] INFO: Done with hot pixel readout
[10:19:36.361] INFO: PixTest:: pg_setup set to default.


[10:19:36.362] INFO: 14 hot pixels found in step 14
[10:19:36.401] INFO: 14 hot pixels could not be trimmed and have been masked.
[10:19:36.404] INFO: PixTest::trimHotPixels() done
[10:19:36.405] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C0.dat
[10:19:36.411] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C1.dat
[10:19:36.420] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C2.dat
[10:19:36.426] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C3.dat
[10:19:36.431] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C4.dat
[10:19:36.437] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C5.dat
[10:19:36.442] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C6.dat
[10:19:36.448] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C7.dat
[10:19:36.453] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C8.dat
[10:19:36.459] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C9.dat
[10:19:36.464] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C10.dat
[10:19:36.469] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C11.dat
[10:19:36.475] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C12.dat
[10:19:36.480] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C13.dat
[10:19:36.486] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C14.dat
[10:19:36.491] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C15.dat
[10:19:36.496] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//defaultMaskFile.dat
[10:19:36.507] INFO: enter test to run
[10:20:01.449] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:20:01.449] INFO: running: highrate
[10:20:01.453] INFO: ----------------------------------------------------------------------
[10:20:01.453] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:20:01.453] INFO: ----------------------------------------------------------------------
[10:20:01.453] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:20:01.453] INFO: edge/corner pixel THR is adjusted
[10:20:01.453] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:20:02.410] INFO: Collecting data for 1 seconds...
[10:20:03.414] INFO: Done with hot pixel readout
[10:20:07.699] INFO: PixTest:: pg_setup set to default.
[10:20:07.700] INFO: 0 hot pixels found in step 0
[10:20:07.705] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:20:07.786] INFO: PixTest::trimHotPixels() done
[10:20:07.786] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C0.dat
[10:20:07.792] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C1.dat
[10:20:07.798] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C2.dat
[10:20:07.803] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C3.dat
[10:20:07.809] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C4.dat
[10:20:07.814] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C5.dat
[10:20:07.820] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C6.dat
[10:20:07.825] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C7.dat
[10:20:07.831] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C8.dat
[10:20:07.836] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C9.dat
[10:20:07.841] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C10.dat
[10:20:07.847] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C11.dat
[10:20:07.852] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C12.dat
[10:20:07.858] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C13.dat
[10:20:07.863] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C14.dat
[10:20:07.869] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//trimParameters35_C15.dat
[10:20:07.874] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-04_FPIXTest-17C-FNAL-160429-1430_2016-04-29_14h30m_1461958228/000_FPIXTest_p17//defaultMaskFile.dat
[10:20:07.884] INFO: enter test to run
[10:20:47.720] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:20:47.720] INFO: running: xray
[10:20:47.729] INFO: ----------------------------------------------------------------------
[10:20:47.729] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:20:47.729] INFO: ----------------------------------------------------------------------
[10:20:48.692] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:20:59.795] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[10:21:29.538] INFO: Resuming triggers.
[10:21:40.646] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[10:22:10.112] INFO: Resuming triggers.
[10:22:21.213] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[10:22:51.143] INFO: Resuming triggers.
[10:23:02.254] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[10:23:31.836] INFO: Resuming triggers.
[10:23:42.944] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[10:24:12.242] INFO: Resuming triggers.
[10:24:23.351] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[10:24:52.668] INFO: Resuming triggers.
[10:25:03.778] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[10:25:33.173] INFO: Resuming triggers.
[10:25:44.286] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[10:26:13.791] INFO: Resuming triggers.
[10:26:24.898] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[10:26:54.420] INFO: Resuming triggers.
[10:26:54.792] INFO: data taking finished, elapsed time: 100 seconds.
[10:26:56.265] INFO: PixTest:: pg_setup set to default.
[10:26:56.268] INFO: PixTestXray::doPhRun() done
[10:26:56.422] INFO: enter test to run
[10:27:19.581] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[10:27:19.582] INFO: running: xray
[10:27:19.583] INFO: ----------------------------------------------------------------------
[10:27:19.583] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:27:19.583] INFO: ----------------------------------------------------------------------
[10:27:20.558] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:27:26.913] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[10:27:56.954] INFO: Resuming triggers.
[10:28:03.312] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[10:28:33.324] INFO: Resuming triggers.
[10:28:39.676] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[10:29:09.719] INFO: Resuming triggers.
[10:29:16.069] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[10:29:46.138] INFO: Resuming triggers.
[10:29:52.490] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[10:30:22.656] INFO: Resuming triggers.
[10:30:28.005] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[10:31:00.145] INFO: Resuming triggers.
[10:31:06.494] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[10:31:37.853] INFO: Resuming triggers.
[10:31:44.205] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[10:32:14.750] INFO: Resuming triggers.
[10:32:21.097] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[10:32:51.082] INFO: Resuming triggers.
[10:32:57.431] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[10:33:27.482] INFO: Resuming triggers.
[10:33:33.832] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[10:34:04.573] INFO: Resuming triggers.
[10:34:10.924] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[10:34:41.338] INFO: Resuming triggers.
[10:34:47.693] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[10:35:17.761] INFO: Resuming triggers.
[10:35:24.110] INFO: run duration 88 seconds, buffer almost full (81%), pausing triggers.
[10:35:54.198] INFO: Resuming triggers.
[10:36:00.554] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[10:36:30.605] INFO: Resuming triggers.
[10:36:35.680] INFO: data taking finished, elapsed time: 100 seconds.
[10:36:59.878] INFO: PixTest:: pg_setup set to default.
[10:36:59.881] INFO: PixTestXray::doPhRun() done
[10:37:00.028] INFO: enter test to run
[10:37:58.441] INFO: test: HighRate no parameter change
[10:37:58.441] INFO: running: highrate
[10:37:58.470] INFO: ----------------------------------------------------------------------
[10:37:58.471] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[10:37:58.471] INFO: ----------------------------------------------------------------------
[10:37:58.612] INFO: Expecting 768 events.
[10:37:59.746] INFO: 768 events read in total (418ms).
[10:37:59.746] INFO: Test took 1268ms.
[10:38:00.550] INFO: Expecting 41600 events.
[10:38:03.682] INFO: 41600 events read in total (2605ms).
[10:38:03.683] INFO: Test took 3929ms.
[10:38:03.727] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:04.438] INFO: Expecting 41600 events.
[10:38:07.670] INFO: 41600 events read in total (2705ms).
[10:38:07.671] INFO: Test took 3924ms.
[10:38:07.708] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:08.426] INFO: Expecting 41600 events.
[10:38:11.688] INFO: 41600 events read in total (2735ms).
[10:38:11.689] INFO: Test took 3962ms.
[10:38:11.726] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:12.441] INFO: Expecting 41600 events.
[10:38:15.698] INFO: 41600 events read in total (2730ms).
[10:38:15.699] INFO: Test took 3953ms.
[10:38:15.737] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:16.455] INFO: Expecting 41600 events.
[10:38:19.731] INFO: 41600 events read in total (2749ms).
[10:38:19.732] INFO: Test took 3976ms.
[10:38:19.769] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:20.487] INFO: Expecting 41600 events.
[10:38:23.737] INFO: 41600 events read in total (2723ms).
[10:38:23.738] INFO: Test took 3949ms.
[10:38:23.776] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:24.492] INFO: Expecting 41600 events.
[10:38:27.761] INFO: 41600 events read in total (2742ms).
[10:38:27.762] INFO: Test took 3966ms.
[10:38:27.799] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:28.518] INFO: Expecting 41600 events.
[10:38:31.789] INFO: 41600 events read in total (2744ms).
[10:38:31.790] INFO: Test took 3972ms.
[10:38:31.827] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:32.544] INFO: Expecting 41600 events.
[10:38:35.822] INFO: 41600 events read in total (2751ms).
[10:38:35.823] INFO: Test took 3976ms.
[10:38:35.860] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:36.579] INFO: Expecting 41600 events.
[10:38:39.856] INFO: 41600 events read in total (2750ms).
[10:38:39.857] INFO: Test took 3977ms.
[10:38:39.895] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:40.614] INFO: Expecting 41600 events.
[10:38:43.888] INFO: 41600 events read in total (2747ms).
[10:38:43.889] INFO: Test took 3975ms.
[10:38:43.926] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:44.645] INFO: Expecting 41600 events.
[10:38:47.919] INFO: 41600 events read in total (2747ms).
[10:38:47.920] INFO: Test took 3976ms.
[10:38:47.957] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:48.676] INFO: Expecting 41600 events.
[10:38:51.950] INFO: 41600 events read in total (2747ms).
[10:38:51.951] INFO: Test took 3975ms.
[10:38:51.987] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:52.706] INFO: Expecting 41600 events.
[10:38:55.994] INFO: 41600 events read in total (2761ms).
[10:38:55.995] INFO: Test took 3988ms.
[10:38:56.032] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:56.749] INFO: Expecting 41600 events.
[10:39:00.025] INFO: 41600 events read in total (2749ms).
[10:39:00.026] INFO: Test took 3974ms.
[10:39:00.064] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:39:00.780] INFO: Expecting 41600 events.
[10:39:04.057] INFO: 41600 events read in total (2750ms).
[10:39:04.058] INFO: Test took 3974ms.
[10:39:04.095] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:39:04.812] INFO: Expecting 41600 events.
[10:39:08.090] INFO: 41600 events read in total (2751ms).
[10:39:08.091] INFO: Test took 3976ms.
[10:39:08.128] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:39:08.846] INFO: Expecting 41600 events.
[10:39:12.109] INFO: 41600 events read in total (2736ms).
[10:39:12.110] INFO: Test took 3961ms.
[10:39:12.147] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:39:12.865] INFO: Expecting 41600 events.
[10:39:16.104] INFO: 41600 events read in total (2713ms).
[10:39:16.105] INFO: Test took 3938ms.
[10:39:16.142] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:39:16.859] INFO: Expecting 41600 events.
[10:39:19.968] INFO: 41600 events read in total (2582ms).
[10:39:19.969] INFO: Test took 3808ms.
[10:39:19.005] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:39:20.370] INFO: enter test to run
[10:39:51.208] INFO: test: HighRate no parameter change
[10:39:51.208] INFO: running: highrate
[10:39:51.209] INFO: ----------------------------------------------------------------------
[10:39:51.209] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:39:51.209] INFO: ----------------------------------------------------------------------
[10:39:51.825] INFO: Expecting 208000 events.
[10:40:03.924] INFO: 208000 events read in total (11572ms).
[10:40:03.928] INFO: Test took 12710ms.
[10:40:04.089] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:40:04.346] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:40:04.346] INFO: number of red-efficiency pixels: 89 68 80 181 165 199 194 115 107 140 123 95 115 61 32 43
[10:40:04.346] INFO: number of X-ray hits detected: 72588 50652 76804 125901 131251 137562 131362 92775 81935 101592 100755 86309 92584 53546 25432 30259
[10:40:04.346] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:40:04.346] INFO: number of Vcal hits detected: 207908 207930 207905 207811 207833 207795 207802 207884 207892 207857 207876 207901 207882 207938 207968 207957
[10:40:04.346] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[10:40:04.346] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[10:40:04.346] INFO: X-ray hit rate [MHz/cm2]: 21.3 14.8 22.5 36.9 38.5 40.3 38.5 27.2 24.0 29.8 29.5 25.3 27.1 15.7 7.5 8.9
[10:40:04.346] INFO: PixTestHighRate::doXPixelAlive() done
[10:40:04.395] INFO: PixTest:: pg_setup set to default.
[10:40:04.409] INFO: enter test to run
[10:40:30.736] INFO: test: HighRate no parameter change
[10:40:30.736] INFO: running: highrate
[10:40:30.737] INFO: ----------------------------------------------------------------------
[10:40:30.737] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:40:30.737] INFO: ----------------------------------------------------------------------
[10:40:31.353] INFO: Expecting 208000 events.
[10:40:45.382] INFO: 208000 events read in total (13502ms).
[10:40:45.388] INFO: Test took 14641ms.
[10:40:45.701] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:40:46.012] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:40:46.012] INFO: number of red-efficiency pixels: 239 131 270 699 711 694 691 348 316 409 392 298 365 138 57 79
[10:40:46.012] INFO: number of X-ray hits detected: 146285 101755 153528 253306 264548 274682 263691 186499 166151 204680 202352 173613 187414 107702 51461 61125
[10:40:46.012] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:40:46.012] INFO: number of Vcal hits detected: 207748 207866 207691 207212 207213 207223 207211 207624 207672 207565 207580 207689 207611 207856 207942 207917
[10:40:46.012] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.7 99.6 99.7 99.6 99.8 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[10:40:46.012] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.6 99.6 99.6 99.6 99.8 99.8 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[10:40:46.012] INFO: X-ray hit rate [MHz/cm2]: 42.9 29.8 45.0 74.2 77.5 80.5 77.3 54.7 48.7 60.0 59.3 50.9 54.9 31.6 15.1 17.9
[10:40:46.012] INFO: PixTestHighRate::doXPixelAlive() done
[10:40:46.060] INFO: PixTest:: pg_setup set to default.
[10:40:46.074] INFO: enter test to run
[10:42:14.047] INFO: test: HighRate no parameter change
[10:42:14.047] INFO: running: highrate
[10:42:14.048] INFO: ----------------------------------------------------------------------
[10:42:14.048] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:42:14.048] INFO: ----------------------------------------------------------------------
[10:42:14.686] INFO: Expecting 208000 events.
[10:42:30.967] INFO: 208000 events read in total (15754ms).
[10:42:30.975] INFO: Test took 16916ms.
[10:42:31.485] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:42:31.848] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:42:31.848] INFO: number of red-efficiency pixels: 564 320 596 1518 1620 1492 1588 688 557 1020 890 716 811 291 93 101
[10:42:31.848] INFO: number of X-ray hits detected: 219061 152136 230578 377236 392763 410173 392083 278577 247465 304803 300168 259037 278342 160770 77173 91424
[10:42:31.848] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:42:31.848] INFO: number of Vcal hits detected: 207332 207650 207237 205939 205743 205911 205765 207175 207371 206764 206921 207132 207063 207675 207903 207894
[10:42:31.848] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.7 99.1 99.0 99.1 99.0 99.6 99.7 99.5 99.5 99.6 99.6 99.9 100.0 100.0
[10:42:31.848] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.6 99.0 98.9 99.0 98.9 99.6 99.7 99.4 99.5 99.6 99.5 99.8 100.0 99.9
[10:42:31.848] INFO: X-ray hit rate [MHz/cm2]: 64.2 44.6 67.6 110.6 115.1 120.2 114.9 81.7 72.5 89.3 88.0 75.9 81.6 47.1 22.6 26.8
[10:42:31.848] INFO: PixTestHighRate::doXPixelAlive() done
[10:42:31.893] INFO: PixTest:: pg_setup set to default.
[10:42:31.912] INFO: enter test to run
[10:42:57.271] INFO: test: exit no parameter change
[10:42:57.710] QUIET: Connection to board 32 closed.
[10:42:57.710] INFO: pXar: this is the end, my friend