[17:41:11.018] INFO: *** Welcome to pxar ***
[17:41:11.018] INFO: *** Today: 2016/05/13
[17:41:11.049] INFO: *** Version: v1.9.0-796-gef167-dirty
[17:41:11.050] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//dacParameters35_C15.dat
[17:41:11.050] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//tbmParameters_C0b.dat
[17:41:11.050] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//defaultMaskFile.dat
[17:41:11.062] INFO: MASKED Roc 3 col/row: 28 78
[17:41:11.062] INFO: MASKED Roc 11 col/row: 12 61
[17:41:11.062] INFO: MASKED Roc 11 col/row: 12 62
[17:41:11.063] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C15.dat
[17:41:11.084] INFO: masking Roc 3 col/row: 28 78
[17:41:11.118] INFO: masking Roc 11 col/row: 12 61
[17:41:11.118] INFO: masking Roc 11 col/row: 12 62
[17:41:11.139] INFO: clk: 4
[17:41:11.139] INFO: ctr: 4
[17:41:11.139] INFO: sda: 19
[17:41:11.139] INFO: tin: 9
[17:41:11.139] INFO: level: 15
[17:41:11.139] INFO: triggerdelay: 0
[17:41:11.139] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[17:41:11.139] INFO: Log level: INFO
[17:41:11.153] QUIET: Connection to board DTB_WREKRL opened.
[17:41:11.156] 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:
------------------------------------------------------
[17:41:11.159] INFO: RPC call hashes of host and DTB match: 398089610
[17:41:12.689] INFO: DUT info:
[17:41:12.689] INFO: The DUT currently contains the following objects:
[17:41:12.689] INFO: 2 TBM Cores tbm08c (2 ON)
[17:41:12.689] INFO: TBM Core alpha (0): 7 registers set
[17:41:12.689] INFO: TBM Core beta (1): 7 registers set
[17:41:12.689] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[17:41:12.689] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 3: 19 DACs set, Pixels: 1 masked, 0 active.
[17:41:12.689] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 11: 19 DACs set, Pixels: 2 masked, 0 active.
[17:41:12.689] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:12.689] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[17:41:13.093] INFO: enter 'restricted' command line mode
[17:41:13.093] INFO: enter test to run
[17:42:19.080] INFO: test: timing no parameter change
[17:42:19.080] INFO: running: timing
[17:42:19.101] INFO: ######################################################################
[17:42:19.101] INFO: PixTestTiming::doTest()
[17:42:19.101] INFO: ######################################################################
[17:42:19.101] INFO: ----------------------------------------------------------------------
[17:42:19.101] INFO: PixTestTiming::TBMPhaseScan()
[17:42:19.101] INFO: ----------------------------------------------------------------------
[17:47:54.343] INFO: TBM Phase Settings: 16
[17:47:54.343] INFO: 400MHz Phase: 4
[17:47:54.343] INFO: 160MHz Phase: 0
[17:47:54.343] INFO: Functional Phase Area: 3
[17:47:54.346] INFO: Test took 335245 ms.
[17:47:54.346] INFO: PixTestTiming::TBMPhaseScan() done.
[17:47:54.347] INFO: ROC 3 masking pixel 28/78
[17:47:54.347] INFO: ROC 11 masking pixel 12/61
[17:47:54.347] INFO: ROC 11 masking pixel 12/62
[17:47:54.347] INFO: ----------------------------------------------------------------------
[17:47:54.347] INFO: PixTestTiming::ROCDelayScan()
[17:47:54.347] INFO: ----------------------------------------------------------------------
[17:49:59.606] INFO: ROC Delay Settings: 228
[17:49:59.606] INFO: ROC Header-Trailer/Token Delay: 11
[17:49:59.606] INFO: ROC Port 0 Delay: 4
[17:49:59.606] INFO: ROC Port 1 Delay: 4
[17:49:59.606] INFO: Functional ROC Area: 5
[17:49:59.609] INFO: Test took 125262 ms.
[17:49:59.609] INFO: PixTestTiming::ROCDelayScan() done.
[17:49:59.609] INFO: ROC 3 masking pixel 28/78
[17:49:59.610] INFO: ROC 11 masking pixel 12/61
[17:49:59.610] INFO: ROC 11 masking pixel 12/62
[17:49:59.610] INFO: ----------------------------------------------------------------------
[17:49:59.610] INFO: PixTestTiming::TimingTest()
[17:49:59.610] INFO: ----------------------------------------------------------------------
[17:50:15.732] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:50:30.680] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:50:45.632] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:51:00.524] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:51:15.474] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:51:30.441] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:51:45.391] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:52:00.356] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:52:15.344] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:52:30.332] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:52:30.714] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:52:30.732] INFO: ----------------------------------------------------------------------
[17:52:30.732] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[17:52:30.732] INFO: ----------------------------------------------------------------------
[17:52:30.732] INFO: ----------------------------------------------------------------------
[17:52:30.732] INFO: Read back bit status: 1
[17:52:30.732] INFO: ----------------------------------------------------------------------
[17:52:30.732] INFO: ----------------------------------------------------------------------
[17:52:30.732] INFO: Timings are good!
[17:52:30.732] INFO: ----------------------------------------------------------------------
[17:52:30.732] INFO: Test took 151122 ms.
[17:52:30.732] INFO: PixTestTiming::TimingTest() done.
[17:52:30.733] INFO: ROC 3 masking pixel 28/78
[17:52:30.733] INFO: ROC 11 masking pixel 12/61
[17:52:30.733] INFO: ROC 11 masking pixel 12/62
[17:52:30.733] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//tbmParameters_C0a.dat
[17:52:30.733] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//tbmParameters_C0b.dat
[17:52:30.733] INFO: PixTestTiming::doTest took 611637 ms.
[17:52:30.733] INFO: PixTestTiming::doTest() done
[17:52:30.733] INFO: ROC 3 masking pixel 28/78
[17:52:30.733] INFO: ROC 11 masking pixel 12/61
[17:52:30.733] INFO: ROC 11 masking pixel 12/62
[17:52:30.733] INFO: Write out TBMPhaseScan_0_V0
[17:52:30.761] INFO: Write out TBMPhaseScan_1_V0
[17:52:30.761] INFO: Write out CombinedTBMPhaseScan_V0
[17:52:30.761] INFO: Write out ROCDelayScan3_V0
[17:52:30.762] INFO: enter test to run
[17:52:43.020] INFO: test: PixelAlive no parameter change
[17:52:43.020] INFO: running: pixelalive
[17:52:43.024] INFO: ----------------------------------------------------------------------
[17:52:43.024] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[17:52:43.024] INFO: ----------------------------------------------------------------------
[17:52:43.027] INFO: ROC 3 masking pixel 28/78
[17:52:43.027] INFO: ROC 11 masking pixel 12/61
[17:52:43.027] INFO: ROC 11 masking pixel 12/62
[17:52:43.347] INFO: Expecting 41600 events.
[17:52:47.676] INFO: 41600 events read in total (3614ms).
[17:52:47.677] INFO: Test took 4650ms.
[17:52:47.683] INFO: Fetched DAQ statistics. Counters are being reset now.
[17:52:48.079] INFO: PixTestAlive::aliveTest() done
[17:52:48.080] INFO: number of dead pixels (per ROC): 0 0 1 5 0 0 0 0 0 0 0 2 3 0 0 0
[17:52:48.080] INFO: ROC 3 masking pixel 28/78
[17:52:48.080] INFO: ROC 11 masking pixel 12/61
[17:52:48.080] INFO: ROC 11 masking pixel 12/62
[17:52:48.083] INFO: enter test to run
[17:53:06.675] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[17:53:06.675] INFO: running: highrate
[17:53:06.675] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[17:53:06.826] INFO: ----------------------------------------------------------------------
[17:53:06.826] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[17:53:06.826] INFO: ----------------------------------------------------------------------
[17:53:06.826] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[17:53:06.826] INFO: edge/corner pixel THR is adjusted
[17:53:06.826] INFO: PixTestHighRate::trimHotPixels: step 0...
[17:53:07.785] INFO: Collecting data for 5 seconds...
[17:53:12.801] INFO: Done with hot pixel readout
[17:53:24.624] INFO: PixTest:: pg_setup set to default.
[17:53:24.624] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[17:53:24.625] INFO: 6 hot pixels found in step 0
[17:53:25.617] INFO: Collecting data for 5 seconds...
[17:53:30.634] INFO: Done with hot pixel readout
[17:53:42.498] INFO: PixTest:: pg_setup set to default.
[17:53:42.499] INFO: 4 hot pixels found in step 1
[17:53:43.491] INFO: Collecting data for 5 seconds...
[17:53:48.507] INFO: Done with hot pixel readout
[17:54:00.332] INFO: PixTest:: pg_setup set to default.
[17:54:00.332] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[17:54:00.332] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[17:54:00.333] INFO: 3 hot pixels found in step 2
[17:54:01.325] INFO: Collecting data for 5 seconds...
[17:54:06.341] INFO: Done with hot pixel readout
[17:54:18.146] INFO: PixTest:: pg_setup set to default.
[17:54:18.147] INFO: 2 hot pixels found in step 3
[17:54:19.140] INFO: Collecting data for 5 seconds...
[17:54:24.157] INFO: Done with hot pixel readout
[17:54:35.970] INFO: PixTest:: pg_setup set to default.
[17:54:35.970] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[17:54:35.970] INFO: 4 hot pixels found in step 4
[17:54:36.963] INFO: Collecting data for 5 seconds...
[17:54:41.979] INFO: Done with hot pixel readout
[17:54:53.816] INFO: PixTest:: pg_setup set to default.
[17:54:53.817] INFO: 3 hot pixels found in step 5
[17:54:54.809] INFO: Collecting data for 5 seconds...
[17:54:59.825] INFO: Done with hot pixel readout
[17:55:11.687] INFO: PixTest:: pg_setup set to default.
[17:55:11.687] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[17:55:11.687] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[17:55:11.688] INFO: 7 hot pixels found in step 6
[17:55:12.680] INFO: Collecting data for 5 seconds...
[17:55:17.696] INFO: Done with hot pixel readout
[17:55:29.527] INFO: PixTest:: pg_setup set to default.
[17:55:29.528] INFO: 2 hot pixels found in step 7
[17:55:30.521] INFO: Collecting data for 5 seconds...
[17:55:35.537] INFO: Done with hot pixel readout
[17:55:47.399] INFO: PixTest:: pg_setup set to default.
[17:55:47.399] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[17:55:47.400] INFO: 4 hot pixels found in step 8
[17:55:48.393] INFO: Collecting data for 5 seconds...
[17:55:53.409] INFO: Done with hot pixel readout
[17:56:05.198] INFO: PixTest:: pg_setup set to default.
[17:56:05.199] INFO: 2 hot pixels found in step 9
[17:56:06.191] INFO: Collecting data for 5 seconds...
[17:56:11.209] INFO: Done with hot pixel readout
[17:56:23.064] INFO: PixTest:: pg_setup set to default.
[17:56:23.064] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[17:56:23.064] INFO: 5 hot pixels found in step 10
[17:56:24.057] INFO: Collecting data for 5 seconds...
[17:56:29.074] INFO: Done with hot pixel readout
[17:56:40.830] INFO: PixTest:: pg_setup set to default.
[17:56:40.830] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[17:56:40.831] INFO: 2 hot pixels found in step 11
[17:56:41.823] INFO: Collecting data for 5 seconds...
[17:56:46.842] INFO: Done with hot pixel readout
[17:56:58.459] INFO: PixTest:: pg_setup set to default.
[17:56:58.460] INFO: 2 hot pixels found in step 12
[17:56:59.452] INFO: Collecting data for 5 seconds...
[17:57:04.469] INFO: Done with hot pixel readout
[17:57:16.183] INFO: PixTest:: pg_setup set to default.
[17:57:16.183] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[17:57:16.184] INFO: 4 hot pixels found in step 13
[17:57:17.175] INFO: Collecting data for 5 seconds...
[17:57:22.192] INFO: Done with hot pixel readout
[17:57:34.080] INFO: PixTest:: pg_setup set to default.
[17:57:34.080] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[17:57:34.080] INFO: 2 hot pixels found in step 14
[17:57:34.117] INFO: 2 hot pixels could not be trimmed and have been masked.
[17:57:34.120] INFO: PixTest::trimHotPixels() done
[17:57:34.120] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C0.dat
[17:57:34.126] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C1.dat
[17:57:34.132] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C2.dat
[17:57:34.137] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C3.dat
[17:57:34.143] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C4.dat
[17:57:34.148] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C5.dat
[17:57:34.154] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C6.dat
[17:57:34.159] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C7.dat
[17:57:34.164] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C8.dat
[17:57:34.170] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C9.dat
[17:57:34.175] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C10.dat
[17:57:34.180] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C11.dat
[17:57:34.186] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C12.dat
[17:57:34.191] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C13.dat
[17:57:34.196] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C14.dat
[17:57:34.202] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C15.dat
[17:57:34.207] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//defaultMaskFile.dat
[17:57:34.217] INFO: enter test to run
[17:58:02.065] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[17:58:02.065] INFO: running: highrate
[17:58:02.070] INFO: ----------------------------------------------------------------------
[17:58:02.070] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[17:58:02.070] INFO: ----------------------------------------------------------------------
[17:58:02.070] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[17:58:02.070] INFO: edge/corner pixel THR is adjusted
[17:58:02.070] INFO: PixTestHighRate::trimHotPixels: step 0...
[17:58:03.027] INFO: Collecting data for 1 seconds...
[17:58:04.031] INFO: Done with hot pixel readout
[17:58:08.074] INFO: PixTest:: pg_setup set to default.
[17:58:08.075] INFO: 0 hot pixels found in step 0
[17:58:08.081] INFO: 0 hot pixels could not be trimmed and have been masked.
[17:58:08.158] INFO: PixTest::trimHotPixels() done
[17:58:08.159] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C0.dat
[17:58:08.166] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C1.dat
[17:58:08.175] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C2.dat
[17:58:08.180] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C3.dat
[17:58:08.186] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C4.dat
[17:58:08.191] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C5.dat
[17:58:08.197] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C6.dat
[17:58:08.202] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C7.dat
[17:58:08.208] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C8.dat
[17:58:08.213] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C9.dat
[17:58:08.219] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C10.dat
[17:58:08.224] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C11.dat
[17:58:08.230] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C12.dat
[17:58:08.235] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C13.dat
[17:58:08.241] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C14.dat
[17:58:08.246] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//trimParameters35_C15.dat
[17:58:08.252] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-3-05_FPIXTest-17C-FNAL-160510-1228_2016-05-10_12h35m_1462901749/000_FPIXTest_p17//defaultMaskFile.dat
[17:58:08.262] INFO: enter test to run
[17:58:26.737] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[17:58:26.737] INFO: running: xray
[17:58:26.739] INFO: ----------------------------------------------------------------------
[17:58:26.739] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[17:58:26.739] INFO: ----------------------------------------------------------------------
[17:58:26.742] INFO: ROC 3 masking pixel 28/78
[17:58:26.742] INFO: ROC 11 masking pixel 12/61
[17:58:26.742] INFO: ROC 11 masking pixel 12/62
[17:58:27.702] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[17:58:39.288] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[17:59:09.781] INFO: Resuming triggers.
[17:59:21.462] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[17:59:51.257] INFO: Resuming triggers.
[18:00:02.845] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[18:00:32.508] INFO: Resuming triggers.
[18:00:44.094] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[18:01:13.825] INFO: Resuming triggers.
[18:01:25.419] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[18:01:55.181] INFO: Resuming triggers.
[18:02:06.769] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[18:02:36.513] INFO: Resuming triggers.
[18:02:48.098] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[18:03:17.895] INFO: Resuming triggers.
[18:03:29.484] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[18:03:59.254] INFO: Resuming triggers.
[18:04:06.878] INFO: data taking finished, elapsed time: 100 seconds.
[18:04:26.691] INFO: PixTest:: pg_setup set to default.
[18:04:26.694] INFO: PixTestXray::doPhRun() done
[18:04:26.835] INFO: enter test to run
[18:04:51.318] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[18:04:51.318] INFO: running: xray
[18:04:51.319] INFO: ----------------------------------------------------------------------
[18:04:51.319] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[18:04:51.320] INFO: ----------------------------------------------------------------------
[18:04:51.323] INFO: ROC 3 masking pixel 28/78
[18:04:51.323] INFO: ROC 11 masking pixel 12/61
[18:04:51.323] INFO: ROC 11 masking pixel 12/62
[18:04:52.291] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[18:04:59.037] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[18:05:29.525] INFO: Resuming triggers.
[18:05:36.275] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[18:06:06.744] INFO: Resuming triggers.
[18:06:13.495] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[18:06:43.985] INFO: Resuming triggers.
[18:06:50.733] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[18:07:21.952] INFO: Resuming triggers.
[18:07:28.703] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[18:07:59.677] INFO: Resuming triggers.
[18:08:06.427] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[18:08:37.964] INFO: Resuming triggers.
[18:08:44.716] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[18:09:16.408] INFO: Resuming triggers.
[18:09:23.160] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[18:09:54.746] INFO: Resuming triggers.
[18:10:01.501] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[18:10:31.844] INFO: Resuming triggers.
[18:10:38.596] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[18:11:09.135] INFO: Resuming triggers.
[18:11:15.885] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[18:11:46.402] INFO: Resuming triggers.
[18:11:53.152] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[18:12:23.641] INFO: Resuming triggers.
[18:12:30.390] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[18:13:00.904] INFO: Resuming triggers.
[18:13:07.655] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[18:13:38.155] INFO: Resuming triggers.
[18:13:43.985] INFO: data taking finished, elapsed time: 100 seconds.
[18:14:10.418] INFO: PixTest:: pg_setup set to default.
[18:14:10.422] INFO: PixTestXray::doPhRun() done
[18:14:10.572] INFO: enter test to run
[18:14:29.498] INFO: test: HighRate no parameter change
[18:14:29.498] INFO: running: highrate
[18:14:29.522] INFO: ----------------------------------------------------------------------
[18:14:29.522] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[18:14:29.522] INFO: ----------------------------------------------------------------------
[18:14:29.677] INFO: Expecting 768 events.
[18:14:30.812] INFO: 768 events read in total (419ms).
[18:14:30.812] INFO: Test took 1269ms.
[18:14:30.817] INFO: ROC 3 masking pixel 28/78
[18:14:30.817] INFO: ROC 11 masking pixel 12/61
[18:14:30.817] INFO: ROC 11 masking pixel 12/62
[18:14:31.615] INFO: Expecting 41600 events.
[18:14:34.724] INFO: 41600 events read in total (2582ms).
[18:14:34.724] INFO: Test took 3904ms.
[18:14:34.755] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:14:35.487] INFO: Expecting 41600 events.
[18:14:38.686] INFO: 41600 events read in total (2672ms).
[18:14:38.687] INFO: Test took 3916ms.
[18:14:38.719] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:14:39.450] INFO: Expecting 41600 events.
[18:14:42.668] INFO: 41600 events read in total (2691ms).
[18:14:42.669] INFO: Test took 3932ms.
[18:14:42.700] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:14:43.427] INFO: Expecting 41600 events.
[18:14:46.645] INFO: 41600 events read in total (2691ms).
[18:14:46.646] INFO: Test took 3929ms.
[18:14:46.677] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:14:47.408] INFO: Expecting 41600 events.
[18:14:50.637] INFO: 41600 events read in total (2702ms).
[18:14:50.638] INFO: Test took 3944ms.
[18:14:50.669] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:14:51.397] INFO: Expecting 41600 events.
[18:14:54.621] INFO: 41600 events read in total (2697ms).
[18:14:54.622] INFO: Test took 3936ms.
[18:14:54.653] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:14:55.382] INFO: Expecting 41600 events.
[18:14:58.604] INFO: 41600 events read in total (2696ms).
[18:14:58.605] INFO: Test took 3936ms.
[18:14:58.637] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:14:59.365] INFO: Expecting 41600 events.
[18:15:02.589] INFO: 41600 events read in total (2698ms).
[18:15:02.590] INFO: Test took 3936ms.
[18:15:02.621] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:03.350] INFO: Expecting 41600 events.
[18:15:06.572] INFO: 41600 events read in total (2695ms).
[18:15:06.573] INFO: Test took 3935ms.
[18:15:06.605] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:07.330] INFO: Expecting 41600 events.
[18:15:10.558] INFO: 41600 events read in total (2701ms).
[18:15:10.559] INFO: Test took 3936ms.
[18:15:10.591] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:11.320] INFO: Expecting 41600 events.
[18:15:14.544] INFO: 41600 events read in total (2697ms).
[18:15:14.545] INFO: Test took 3936ms.
[18:15:14.576] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:15.307] INFO: Expecting 41600 events.
[18:15:18.548] INFO: 41600 events read in total (2714ms).
[18:15:18.549] INFO: Test took 3956ms.
[18:15:18.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:19.307] INFO: Expecting 41600 events.
[18:15:22.531] INFO: 41600 events read in total (2698ms).
[18:15:22.532] INFO: Test took 3933ms.
[18:15:22.563] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:23.288] INFO: Expecting 41600 events.
[18:15:26.527] INFO: 41600 events read in total (2712ms).
[18:15:26.528] INFO: Test took 3948ms.
[18:15:26.560] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:27.287] INFO: Expecting 41600 events.
[18:15:30.522] INFO: 41600 events read in total (2708ms).
[18:15:30.523] INFO: Test took 3945ms.
[18:15:30.555] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:31.280] INFO: Expecting 41600 events.
[18:15:34.512] INFO: 41600 events read in total (2705ms).
[18:15:34.513] INFO: Test took 3941ms.
[18:15:34.545] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:35.275] INFO: Expecting 41600 events.
[18:15:38.506] INFO: 41600 events read in total (2704ms).
[18:15:38.507] INFO: Test took 3943ms.
[18:15:38.538] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:39.268] INFO: Expecting 41600 events.
[18:15:42.501] INFO: 41600 events read in total (2706ms).
[18:15:42.502] INFO: Test took 3947ms.
[18:15:42.534] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:43.262] INFO: Expecting 41600 events.
[18:15:46.472] INFO: 41600 events read in total (2683ms).
[18:15:46.473] INFO: Test took 3922ms.
[18:15:46.505] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:47.234] INFO: Expecting 41600 events.
[18:15:50.321] INFO: 41600 events read in total (2561ms).
[18:15:50.322] INFO: Test took 3799ms.
[18:15:50.353] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:15:50.721] INFO: enter test to run
[18:16:33.273] INFO: test: HighRate no parameter change
[18:16:33.273] INFO: running: highrate
[18:16:33.274] INFO: ----------------------------------------------------------------------
[18:16:33.274] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:16:33.274] INFO: ----------------------------------------------------------------------
[18:16:33.282] INFO: ROC 3 masking pixel 28/78
[18:16:33.282] INFO: ROC 11 masking pixel 12/61
[18:16:33.282] INFO: ROC 11 masking pixel 12/62
[18:16:33.883] INFO: Expecting 208000 events.
[18:16:45.799] INFO: 208000 events read in total (11389ms).
[18:16:45.803] INFO: Test took 12520ms.
[18:16:45.947] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:16:46.200] INFO: number of dead pixels (per ROC): 0 0 1 5 0 0 0 0 0 0 0 2 2 0 0 0
[18:16:46.200] INFO: number of red-efficiency pixels: 92 54 101 151 169 182 123 122 101 127 116 105 99 73 22 25
[18:16:46.200] INFO: number of X-ray hits detected: 67246 44807 70276 110449 116101 118385 108833 83863 77624 96163 94943 82674 86411 52524 23172 28538
[18:16:46.200] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:16:46.200] INFO: number of Vcal hits detected: 207908 207946 207848 207599 207826 207813 207877 207874 207899 207868 207880 207794 207753 207927 207978 207975
[18:16:46.200] 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
[18:16:46.200] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.8 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[18:16:46.200] INFO: X-ray hit rate [MHz/cm2]: 19.7 13.1 20.6 32.4 34.0 34.7 31.9 24.6 22.8 28.2 27.8 24.2 25.3 15.4 6.8 8.4
[18:16:46.200] INFO: PixTestHighRate::doXPixelAlive() done
[18:16:46.248] INFO: PixTest:: pg_setup set to default.
[18:16:46.263] INFO: enter test to run
[18:16:58.025] INFO: test: HighRate no parameter change
[18:16:58.025] INFO: running: highrate
[18:16:58.026] INFO: ----------------------------------------------------------------------
[18:16:58.026] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:16:58.026] INFO: ----------------------------------------------------------------------
[18:16:58.034] INFO: ROC 3 masking pixel 28/78
[18:16:58.034] INFO: ROC 11 masking pixel 12/61
[18:16:58.034] INFO: ROC 11 masking pixel 12/62
[18:16:58.639] INFO: Expecting 208000 events.
[18:17:12.323] INFO: 208000 events read in total (13157ms).
[18:17:12.329] INFO: Test took 14294ms.
[18:17:12.622] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:17:12.927] INFO: number of dead pixels (per ROC): 0 0 1 5 0 0 0 0 0 0 0 2 2 0 0 0
[18:17:12.927] INFO: number of red-efficiency pixels: 242 125 302 483 542 567 449 387 291 362 398 296 298 197 60 76
[18:17:12.927] INFO: number of X-ray hits detected: 138211 92848 145067 227319 240019 244313 223070 172398 159402 197365 196140 169806 177739 108711 47880 59555
[18:17:12.927] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:17:12.927] INFO: number of Vcal hits detected: 207735 207873 207616 207236 207394 207382 207511 207586 207694 207616 207569 207589 207538 207792 207935 207922
[18:17:12.927] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.8 99.8 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[18:17:12.927] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.6 99.7 99.7 99.8 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[18:17:12.927] INFO: X-ray hit rate [MHz/cm2]: 40.5 27.2 42.5 66.6 70.4 71.6 65.4 50.5 46.7 57.8 57.5 49.8 52.1 31.9 14.0 17.5
[18:17:12.927] INFO: PixTestHighRate::doXPixelAlive() done
[18:17:12.974] INFO: PixTest:: pg_setup set to default.
[18:17:12.989] INFO: enter test to run
[18:17:25.793] INFO: test: HighRate no parameter change
[18:17:25.793] INFO: running: highrate
[18:17:25.794] INFO: ----------------------------------------------------------------------
[18:17:25.794] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[18:17:25.794] INFO: ----------------------------------------------------------------------
[18:17:25.803] INFO: ROC 3 masking pixel 28/78
[18:17:25.803] INFO: ROC 11 masking pixel 12/61
[18:17:25.803] INFO: ROC 11 masking pixel 12/62
[18:17:26.409] INFO: Expecting 208000 events.
[18:17:41.858] INFO: 208000 events read in total (14923ms).
[18:17:41.865] INFO: Test took 16061ms.
[18:17:42.297] INFO: Fetched DAQ statistics. Counters are being reset now.
[18:17:42.641] INFO: number of dead pixels (per ROC): 0 0 1 5 0 0 0 0 0 0 0 2 2 0 0 0
[18:17:42.641] INFO: number of red-efficiency pixels: 529 286 655 1030 1241 1325 961 721 511 841 880 646 622 432 114 99
[18:17:42.641] INFO: number of X-ray hits detected: 204244 137709 213095 335163 353091 358152 328980 254893 236084 290385 289494 252215 262487 161023 71193 87630
[18:17:42.641] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[18:17:42.641] INFO: number of Vcal hits detected: 207360 207684 207109 206519 206405 206261 206812 207104 207428 207003 206931 207155 207141 207501 207880 207898
[18:17:42.641] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.6 99.4 99.3 99.2 99.5 99.6 99.7 99.6 99.5 99.7 99.7 99.8 99.9 100.0
[18:17:42.641] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.6 99.3 99.2 99.2 99.4 99.6 99.7 99.5 99.5 99.6 99.6 99.8 99.9 100.0
[18:17:42.641] INFO: X-ray hit rate [MHz/cm2]: 59.9 40.4 62.5 98.2 103.5 105.0 96.4 74.7 69.2 85.1 84.9 73.9 76.9 47.2 20.9 25.7
[18:17:42.641] INFO: PixTestHighRate::doXPixelAlive() done
[18:17:42.687] INFO: PixTest:: pg_setup set to default.
[18:17:42.703] INFO: enter test to run
[18:17:46.425] INFO: test: exit no parameter change
[18:17:46.840] QUIET: Connection to board 33 closed.
[18:17:46.842] INFO: pXar: this is the end, my friend