[12:17:23.616] INFO: *** Welcome to pxar ***
[12:17:23.616] INFO: *** Today: 2016/05/13
[12:17:23.635] INFO: *** Version: v1.9.0-796-gef167-dirty
[12:17:23.636] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//dacParameters35_C15.dat
[12:17:23.637] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:17:23.637] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//defaultMaskFile.dat
[12:17:23.637] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C15.dat
[12:17:23.711] INFO: clk: 4
[12:17:23.711] INFO: ctr: 4
[12:17:23.711] INFO: sda: 19
[12:17:23.711] INFO: tin: 9
[12:17:23.711] INFO: level: 15
[12:17:23.711] INFO: triggerdelay: 0
[12:17:23.711] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[12:17:23.711] INFO: Log level: INFO
[12:17:23.728] QUIET: Connection to board DTB_WREK4U opened.
[12:17:23.731] 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:
------------------------------------------------------
[12:17:23.734] INFO: RPC call hashes of host and DTB match: 398089610
[12:17:25.260] INFO: DUT info:
[12:17:25.260] INFO: The DUT currently contains the following objects:
[12:17:25.260] INFO: 2 TBM Cores tbm08c (2 ON)
[12:17:25.260] INFO: TBM Core alpha (0): 7 registers set
[12:17:25.260] INFO: TBM Core beta (1): 7 registers set
[12:17:25.260] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:17:25.260] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.260] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.260] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.260] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.260] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.260] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.260] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.260] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.260] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.260] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.260] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.260] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.261] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.261] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.261] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.261] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:17:25.664] INFO: enter 'restricted' command line mode
[12:17:25.664] INFO: enter test to run
[12:17:34.639] INFO: test: timing no parameter change
[12:17:34.639] INFO: running: timing
[12:17:34.648] INFO: ######################################################################
[12:17:34.648] INFO: PixTestTiming::doTest()
[12:17:34.648] INFO: ######################################################################
[12:17:34.648] INFO: ----------------------------------------------------------------------
[12:17:34.648] INFO: PixTestTiming::TBMPhaseScan()
[12:17:34.648] INFO: ----------------------------------------------------------------------
[12:23:29.559] INFO: TBM Phase Settings: 24
[12:23:29.559] INFO: 400MHz Phase: 6
[12:23:29.559] INFO: 160MHz Phase: 0
[12:23:29.559] INFO: Functional Phase Area: 3
[12:23:29.562] INFO: Test took 354914 ms.
[12:23:29.562] INFO: PixTestTiming::TBMPhaseScan() done.
[12:23:29.562] INFO: ----------------------------------------------------------------------
[12:23:29.562] INFO: PixTestTiming::ROCDelayScan()
[12:23:29.562] INFO: ----------------------------------------------------------------------
[12:26:11.350] INFO: ROC Delay Settings: 220
[12:26:11.350] INFO: ROC Header-Trailer/Token Delay: 11
[12:26:11.350] INFO: ROC Port 0 Delay: 4
[12:26:11.350] INFO: ROC Port 1 Delay: 3
[12:26:11.350] INFO: Functional ROC Area: 4
[12:26:11.353] INFO: Test took 161791 ms.
[12:26:11.353] INFO: PixTestTiming::ROCDelayScan() done.
[12:26:11.353] INFO: ----------------------------------------------------------------------
[12:26:11.353] INFO: PixTestTiming::TimingTest()
[12:26:11.353] INFO: ----------------------------------------------------------------------
[12:26:27.490] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:42.451] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:26:57.415] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:12.375] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:27.309] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:42.258] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:27:57.189] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:12.150] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:27.115] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:42.101] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:42.480] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:28:42.498] INFO: ----------------------------------------------------------------------
[12:28:42.498] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[12:28:42.498] INFO: ----------------------------------------------------------------------
[12:28:42.498] INFO: ----------------------------------------------------------------------
[12:28:42.498] INFO: Read back bit status: 1
[12:28:42.498] INFO: ----------------------------------------------------------------------
[12:28:42.498] INFO: ----------------------------------------------------------------------
[12:28:42.498] INFO: Timings are good!
[12:28:42.498] INFO: ----------------------------------------------------------------------
[12:28:42.498] INFO: Test took 151145 ms.
[12:28:42.498] INFO: PixTestTiming::TimingTest() done.
[12:28:42.498] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//tbmParameters_C0a.dat
[12:28:42.499] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:28:42.499] INFO: PixTestTiming::doTest took 667856 ms.
[12:28:42.499] INFO: PixTestTiming::doTest() done
[12:28:42.499] INFO: Write out TBMPhaseScan_0_V0
[12:28:42.528] INFO: Write out TBMPhaseScan_1_V0
[12:28:42.528] INFO: Write out CombinedTBMPhaseScan_V0
[12:28:42.529] INFO: Write out ROCDelayScan3_V0
[12:28:42.529] INFO: enter test to run
[12:28:56.810] INFO: test: PixelAlive no parameter change
[12:28:56.810] INFO: running: pixelalive
[12:28:56.814] INFO: ----------------------------------------------------------------------
[12:28:56.814] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[12:28:56.814] INFO: ----------------------------------------------------------------------
[12:28:57.139] INFO: Expecting 41600 events.
[12:29:01.456] INFO: 41600 events read in total (3602ms).
[12:29:01.456] INFO: Test took 4638ms.
[12:29:01.462] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:01.862] INFO: PixTestAlive::aliveTest() done
[12:29:01.862] INFO: number of dead pixels (per ROC): 0 1 1 1 0 0 0 0 0 0 0 0 0 1 0 0
[12:29:01.865] INFO: enter test to run
[12:29:59.433] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:29:59.433] INFO: running: highrate
[12:29:59.434] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:29:59.590] INFO: ----------------------------------------------------------------------
[12:29:59.590] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:29:59.590] INFO: ----------------------------------------------------------------------
[12:29:59.590] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:29:59.590] INFO: edge/corner pixel THR is adjusted
[12:29:59.590] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:30:00.548] INFO: Collecting data for 5 seconds...
[12:30:05.565] INFO: Done with hot pixel readout
[12:30:17.918] INFO: PixTest:: pg_setup set to default.
[12:30:17.919] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:30:17.919] INFO: 8 hot pixels found in step 0
[12:30:18.916] INFO: Collecting data for 5 seconds...
[12:30:23.934] INFO: Done with hot pixel readout
[12:30:36.289] INFO: PixTest:: pg_setup set to default.
[12:30:36.290] INFO: 11 hot pixels found in step 1
[12:30:37.285] INFO: Collecting data for 5 seconds...
[12:30:42.302] INFO: Done with hot pixel readout
[12:30:54.698] INFO: PixTest:: pg_setup set to default.
[12:30:54.699] INFO: 8 hot pixels found in step 2
[12:30:55.694] INFO: Collecting data for 5 seconds...
[12:31:00.712] INFO: Done with hot pixel readout
[12:31:12.902] INFO: PixTest:: pg_setup set to default.
[12:31:12.902] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:31:12.903] INFO: 12 hot pixels found in step 3
[12:31:13.900] INFO: Collecting data for 5 seconds...
[12:31:18.920] INFO: Done with hot pixel readout
[12:31:31.014] INFO: PixTest:: pg_setup set to default.
[12:31:31.015] INFO: 9 hot pixels found in step 4
[12:31:32.016] INFO: Collecting data for 5 seconds...
[12:31:37.036] INFO: Done with hot pixel readout
[12:31:49.080] INFO: PixTest:: pg_setup set to default.
[12:31:49.081] INFO: 9 hot pixels found in step 5
[12:31:50.076] INFO: Collecting data for 5 seconds...
[12:31:55.098] INFO: Done with hot pixel readout
[12:32:07.305] INFO: PixTest:: pg_setup set to default.
[12:32:07.306] INFO: 12 hot pixels found in step 6
[12:32:08.302] INFO: Collecting data for 5 seconds...
[12:32:13.324] INFO: Done with hot pixel readout
[12:32:25.868] INFO: PixTest:: pg_setup set to default.
[12:32:25.869] INFO: 14 hot pixels found in step 7
[12:32:26.865] INFO: Collecting data for 5 seconds...
[12:32:31.886] INFO: Done with hot pixel readout
[12:32:44.333] INFO: PixTest:: pg_setup set to default.
[12:32:44.334] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:32:44.334] INFO: 12 hot pixels found in step 8
[12:32:45.331] INFO: Collecting data for 5 seconds...
[12:32:50.352] INFO: Done with hot pixel readout
[12:33:02.777] INFO: PixTest:: pg_setup set to default.
[12:33:02.778] INFO: 7 hot pixels found in step 9
[12:33:03.775] INFO: Collecting data for 5 seconds...
[12:33:08.796] INFO: Done with hot pixel readout
[12:33:21.352] INFO: PixTest:: pg_setup set to default.
[12:33:21.353] INFO: 9 hot pixels found in step 10
[12:33:22.350] INFO: Collecting data for 5 seconds...
[12:33:27.371] INFO: Done with hot pixel readout
[12:33:40.059] INFO: PixTest:: pg_setup set to default.
[12:33:40.060] INFO: 7 hot pixels found in step 11
[12:33:41.058] INFO: Collecting data for 5 seconds...
[12:33:46.078] INFO: Done with hot pixel readout
[12:33:58.550] INFO: PixTest:: pg_setup set to default.
[12:33:58.550] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:33:58.551] INFO: 5 hot pixels found in step 12
[12:33:59.548] INFO: Collecting data for 5 seconds...
[12:34:04.567] INFO: Done with hot pixel readout
[12:34:16.898] INFO: PixTest:: pg_setup set to default.
[12:34:16.898] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:34:16.898] INFO: 5 hot pixels found in step 13
[12:34:17.894] INFO: Collecting data for 5 seconds...
[12:34:22.912] INFO: Done with hot pixel readout
[12:34:35.208] INFO: PixTest:: pg_setup set to default.
[12:34:35.209] INFO: 8 hot pixels found in step 14
[12:34:35.249] INFO: 8 hot pixels could not be trimmed and have been masked.
[12:34:35.252] INFO: PixTest::trimHotPixels() done
[12:34:35.252] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C0.dat
[12:34:35.265] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C1.dat
[12:34:35.273] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C2.dat
[12:34:35.279] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C3.dat
[12:34:35.284] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C4.dat
[12:34:35.290] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C5.dat
[12:34:35.295] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C6.dat
[12:34:35.301] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C7.dat
[12:34:35.306] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C8.dat
[12:34:35.312] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C9.dat
[12:34:35.317] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C10.dat
[12:34:35.323] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C11.dat
[12:34:35.328] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C12.dat
[12:34:35.334] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C13.dat
[12:34:35.340] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C14.dat
[12:34:35.345] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C15.dat
[12:34:35.351] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//defaultMaskFile.dat
[12:34:35.361] INFO: enter test to run
[12:34:59.871] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:34:59.871] INFO: running: highrate
[12:34:59.876] INFO: ----------------------------------------------------------------------
[12:34:59.876] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:34:59.876] INFO: ----------------------------------------------------------------------
[12:34:59.876] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:34:59.876] INFO: edge/corner pixel THR is adjusted
[12:34:59.876] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:35:00.833] INFO: Collecting data for 1 seconds...
[12:35:01.837] INFO: Done with hot pixel readout
[12:35:06.210] INFO: PixTest:: pg_setup set to default.
[12:35:06.211] INFO: 0 hot pixels found in step 0
[12:35:06.216] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:35:06.292] INFO: PixTest::trimHotPixels() done
[12:35:06.292] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C0.dat
[12:35:06.303] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C1.dat
[12:35:06.309] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C2.dat
[12:35:06.314] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C3.dat
[12:35:06.319] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C4.dat
[12:35:06.325] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C5.dat
[12:35:06.330] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C6.dat
[12:35:06.336] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C7.dat
[12:35:06.341] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C8.dat
[12:35:06.347] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C9.dat
[12:35:06.352] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C10.dat
[12:35:06.358] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C11.dat
[12:35:06.363] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C12.dat
[12:35:06.369] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C13.dat
[12:35:06.374] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C14.dat
[12:35:06.380] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//trimParameters35_C15.dat
[12:35:06.385] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Y-K-NA_FPIXTest-17C-FNAL-160509-1152_2016-05-09_11h53m_1462812787/000_FPIXTest_p17//defaultMaskFile.dat
[12:35:06.395] INFO: enter test to run
[12:35:25.727] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:35:25.727] INFO: running: xray
[12:35:25.728] INFO: ----------------------------------------------------------------------
[12:35:25.728] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:35:25.728] INFO: ----------------------------------------------------------------------
[12:35:26.691] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:35:37.447] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[12:36:07.125] INFO: Resuming triggers.
[12:36:17.883] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[12:36:47.528] INFO: Resuming triggers.
[12:36:58.279] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[12:37:27.908] INFO: Resuming triggers.
[12:37:38.663] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[12:38:08.226] INFO: Resuming triggers.
[12:38:18.981] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[12:38:48.562] INFO: Resuming triggers.
[12:38:59.320] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[12:39:28.836] INFO: Resuming triggers.
[12:39:39.588] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[12:40:09.112] INFO: Resuming triggers.
[12:40:19.866] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[12:40:49.430] INFO: Resuming triggers.
[12:41:00.186] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[12:41:29.699] INFO: Resuming triggers.
[12:41:33.244] INFO: data taking finished, elapsed time: 100 seconds.
[12:41:43.252] INFO: PixTest:: pg_setup set to default.
[12:41:43.255] INFO: PixTestXray::doPhRun() done
[12:41:43.390] INFO: enter test to run
[12:42:07.684] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:42:07.684] INFO: running: xray
[12:42:07.685] INFO: ----------------------------------------------------------------------
[12:42:07.685] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:42:07.685] INFO: ----------------------------------------------------------------------
[12:42:08.657] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:42:14.538] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[12:42:45.699] INFO: Resuming triggers.
[12:42:51.576] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[12:43:21.741] INFO: Resuming triggers.
[12:43:27.618] INFO: run duration 17 seconds, buffer almost full (81%), pausing triggers.
[12:43:58.908] INFO: Resuming triggers.
[12:44:04.787] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[12:44:36.187] INFO: Resuming triggers.
[12:44:42.069] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[12:45:12.478] INFO: Resuming triggers.
[12:45:18.356] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[12:45:48.499] INFO: Resuming triggers.
[12:45:54.380] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[12:46:24.317] INFO: Resuming triggers.
[12:46:30.192] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[12:47:00.289] INFO: Resuming triggers.
[12:47:06.165] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[12:47:36.315] INFO: Resuming triggers.
[12:47:42.192] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[12:48:12.291] INFO: Resuming triggers.
[12:48:18.170] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[12:48:48.371] INFO: Resuming triggers.
[12:48:54.247] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[12:49:24.379] INFO: Resuming triggers.
[12:49:30.259] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[12:50:00.359] INFO: Resuming triggers.
[12:50:06.237] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[12:50:36.295] INFO: Resuming triggers.
[12:50:42.177] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[12:51:12.273] INFO: Resuming triggers.
[12:51:18.148] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[12:51:48.274] INFO: Resuming triggers.
[12:51:54.149] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[12:52:24.337] INFO: Resuming triggers.
[12:52:24.761] INFO: data taking finished, elapsed time: 100 seconds.
[12:52:27.346] INFO: PixTest:: pg_setup set to default.
[12:52:27.350] INFO: PixTestXray::doPhRun() done
[12:52:27.504] INFO: enter test to run
[12:52:45.247] INFO: test: HighRate no parameter change
[12:52:45.247] INFO: running: highrate
[12:52:45.248] INFO: ----------------------------------------------------------------------
[12:52:45.248] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:52:45.248] INFO: ----------------------------------------------------------------------
[12:52:45.390] INFO: Expecting 768 events.
[12:52:46.524] INFO: 768 events read in total (418ms).
[12:52:46.525] INFO: Test took 1270ms.
[12:52:47.328] INFO: Expecting 41600 events.
[12:52:50.456] INFO: 41600 events read in total (2601ms).
[12:52:50.458] INFO: Test took 3926ms.
[12:52:50.495] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:52:51.212] INFO: Expecting 41600 events.
[12:52:54.444] INFO: 41600 events read in total (2705ms).
[12:52:54.446] INFO: Test took 3932ms.
[12:52:54.484] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:52:55.198] INFO: Expecting 41600 events.
[12:52:58.464] INFO: 41600 events read in total (2740ms).
[12:52:58.465] INFO: Test took 3961ms.
[12:52:58.503] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:52:59.216] INFO: Expecting 41600 events.
[12:53:02.486] INFO: 41600 events read in total (2743ms).
[12:53:02.487] INFO: Test took 3964ms.
[12:53:02.525] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:03.239] INFO: Expecting 41600 events.
[12:53:06.506] INFO: 41600 events read in total (2740ms).
[12:53:06.507] INFO: Test took 3963ms.
[12:53:06.545] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:07.261] INFO: Expecting 41600 events.
[12:53:10.538] INFO: 41600 events read in total (2750ms).
[12:53:10.539] INFO: Test took 3974ms.
[12:53:10.577] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:11.292] INFO: Expecting 41600 events.
[12:53:14.574] INFO: 41600 events read in total (2755ms).
[12:53:14.575] INFO: Test took 3977ms.
[12:53:14.612] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:15.332] INFO: Expecting 41600 events.
[12:53:18.615] INFO: 41600 events read in total (2756ms).
[12:53:18.616] INFO: Test took 3984ms.
[12:53:18.654] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:19.369] INFO: Expecting 41600 events.
[12:53:22.699] INFO: 41600 events read in total (2803ms).
[12:53:22.700] INFO: Test took 4027ms.
[12:53:22.738] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:23.433] INFO: Expecting 41600 events.
[12:53:26.682] INFO: 41600 events read in total (2722ms).
[12:53:26.683] INFO: Test took 3926ms.
[12:53:26.721] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:27.436] INFO: Expecting 41600 events.
[12:53:30.748] INFO: 41600 events read in total (2785ms).
[12:53:30.749] INFO: Test took 4007ms.
[12:53:30.787] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:31.502] INFO: Expecting 41600 events.
[12:53:34.779] INFO: 41600 events read in total (2751ms).
[12:53:34.780] INFO: Test took 3972ms.
[12:53:34.819] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:35.530] INFO: Expecting 41600 events.
[12:53:38.813] INFO: 41600 events read in total (2756ms).
[12:53:38.814] INFO: Test took 3976ms.
[12:53:38.853] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:39.567] INFO: Expecting 41600 events.
[12:53:42.791] INFO: 41600 events read in total (2697ms).
[12:53:42.792] INFO: Test took 3919ms.
[12:53:42.831] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:43.540] INFO: Expecting 41600 events.
[12:53:46.874] INFO: 41600 events read in total (2808ms).
[12:53:46.875] INFO: Test took 4024ms.
[12:53:46.915] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:47.621] INFO: Expecting 41600 events.
[12:53:50.883] INFO: 41600 events read in total (2735ms).
[12:53:50.884] INFO: Test took 3950ms.
[12:53:50.922] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:51.630] INFO: Expecting 41600 events.
[12:53:54.905] INFO: 41600 events read in total (2748ms).
[12:53:54.906] INFO: Test took 3965ms.
[12:53:54.945] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:55.659] INFO: Expecting 41600 events.
[12:53:58.875] INFO: 41600 events read in total (2689ms).
[12:53:58.876] INFO: Test took 3911ms.
[12:53:58.915] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:53:59.627] INFO: Expecting 41600 events.
[12:54:02.826] INFO: 41600 events read in total (2672ms).
[12:54:02.827] INFO: Test took 3892ms.
[12:54:02.866] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:03.583] INFO: Expecting 41600 events.
[12:54:06.706] INFO: 41600 events read in total (2596ms).
[12:54:06.707] INFO: Test took 3822ms.
[12:54:06.745] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:07.100] INFO: enter test to run
[12:54:42.935] INFO: test: HighRate no parameter change
[12:54:42.935] INFO: running: highrate
[12:54:42.936] INFO: ----------------------------------------------------------------------
[12:54:42.936] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:54:42.936] INFO: ----------------------------------------------------------------------
[12:54:43.557] INFO: Expecting 208000 events.
[12:54:55.952] INFO: 208000 events read in total (11868ms).
[12:54:55.956] INFO: Test took 13012ms.
[12:54:56.125] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:56.384] INFO: number of dead pixels (per ROC): 0 1 1 1 0 0 0 0 0 0 0 0 0 1 0 0
[12:54:56.384] INFO: number of red-efficiency pixels: 81 51 112 126 193 198 188 125 134 138 136 104 108 74 34 41
[12:54:56.384] INFO: number of X-ray hits detected: 72574 48424 80984 119840 132411 134127 141130 98700 99726 109882 102801 93976 94091 58162 25392 27894
[12:54:56.384] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:54:56.384] INFO: number of Vcal hits detected: 207918 207900 207836 207822 207798 207797 207809 207869 207863 207858 207860 207893 207890 207875 207964 207959
[12:54:56.384] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0
[12:54:56.384] 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 99.9 100.0 100.0
[12:54:56.384] INFO: X-ray hit rate [MHz/cm2]: 21.3 14.2 23.7 35.1 38.8 39.3 41.4 28.9 29.2 32.2 30.1 27.5 27.6 17.0 7.4 8.2
[12:54:56.384] INFO: PixTestHighRate::doXPixelAlive() done
[12:54:56.429] INFO: PixTest:: pg_setup set to default.
[12:54:56.440] INFO: enter test to run
[12:55:30.470] INFO: test: HighRate no parameter change
[12:55:30.470] INFO: running: highrate
[12:55:30.471] INFO: ----------------------------------------------------------------------
[12:55:30.471] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:55:30.471] INFO: ----------------------------------------------------------------------
[12:55:31.091] INFO: Expecting 208000 events.
[12:55:45.792] INFO: 208000 events read in total (14174ms).
[12:55:45.798] INFO: Test took 15318ms.
[12:55:46.165] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:55:46.488] INFO: number of dead pixels (per ROC): 0 1 1 1 0 0 0 0 0 0 0 0 0 1 0 0
[12:55:46.488] INFO: number of red-efficiency pixels: 270 169 457 498 795 872 733 561 505 639 503 464 367 299 92 65
[12:55:46.488] INFO: number of X-ray hits detected: 160373 106235 177084 263636 291344 296391 312194 216784 221890 241483 226989 206708 209048 127715 56913 62642
[12:55:46.488] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:55:46.488] INFO: number of Vcal hits detected: 207710 207767 207403 207412 207072 206976 207152 207336 207433 207261 207458 207492 207602 207625 207901 207934
[12:55:46.488] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.6 99.5 99.6 99.7 99.8 99.7 99.8 99.8 99.8 99.9 100.0 100.0
[12:55:46.488] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.7 99.7 99.6 99.5 99.6 99.7 99.7 99.6 99.7 99.8 99.8 99.8 100.0 100.0
[12:55:46.488] INFO: X-ray hit rate [MHz/cm2]: 47.0 31.1 51.9 77.3 85.4 86.9 91.5 63.5 65.0 70.8 66.5 60.6 61.3 37.4 16.7 18.4
[12:55:46.488] INFO: PixTestHighRate::doXPixelAlive() done
[12:55:46.533] INFO: PixTest:: pg_setup set to default.
[12:55:46.551] INFO: enter test to run
[12:56:07.014] INFO: test: HighRate no parameter change
[12:56:07.014] INFO: running: highrate
[12:56:07.015] INFO: ----------------------------------------------------------------------
[12:56:07.015] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:56:07.015] INFO: ----------------------------------------------------------------------
[12:56:07.652] INFO: Expecting 208000 events.
[12:56:24.599] INFO: 208000 events read in total (16420ms).
[12:56:24.608] INFO: Test took 17581ms.
[12:56:25.153] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:56:25.537] INFO: number of dead pixels (per ROC): 0 1 1 1 0 0 0 0 0 0 0 0 0 1 0 0
[12:56:25.537] INFO: number of red-efficiency pixels: 537 377 993 1133 1888 1940 1670 1218 1097 1407 1188 1085 842 642 165 155
[12:56:25.537] INFO: number of X-ray hits detected: 236717 157268 261012 386952 427650 436046 458258 320676 328180 356343 335198 305950 308633 189698 84479 92318
[12:56:25.537] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:56:25.537] INFO: number of Vcal hits detected: 207350 207520 206396 206511 205135 204951 205561 206172 206479 206026 206484 206622 206986 207127 207823 207842
[12:56:25.537] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.3 99.4 98.7 98.7 98.9 99.2 99.4 99.1 99.3 99.4 99.6 99.6 99.9 99.9
[12:56:25.537] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.2 99.3 98.6 98.5 98.8 99.1 99.3 99.1 99.3 99.3 99.5 99.6 99.9 99.9
[12:56:25.537] INFO: X-ray hit rate [MHz/cm2]: 69.4 46.1 76.5 113.4 125.3 127.8 134.3 94.0 96.2 104.4 98.2 89.7 90.5 55.6 24.8 27.1
[12:56:25.537] INFO: PixTestHighRate::doXPixelAlive() done
[12:56:25.583] INFO: PixTest:: pg_setup set to default.
[12:56:25.605] INFO: enter test to run
[12:56:29.174] INFO: test: exit no parameter change
[12:56:29.632] QUIET: Connection to board 32 closed.
[12:56:29.633] INFO: pXar: this is the end, my friend