[11:41:02.020] INFO: *** Welcome to pxar ***
[11:41:02.020] INFO: *** Today: 2016/09/28
[11:41:02.761] INFO: *** Version: v1.9.0-818-g96727
[11:41:02.761] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//dacParameters35_C15.dat
[11:41:02.832] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:41:02.832] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//defaultMaskFile.dat
[11:41:02.838] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C15.dat
[11:41:02.953] INFO: clk: 4
[11:41:02.953] INFO: ctr: 4
[11:41:02.953] INFO: sda: 19
[11:41:02.953] INFO: tin: 9
[11:41:02.953] INFO: level: 15
[11:41:02.953] INFO: triggerdelay: 0
[11:41:02.953] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[11:41:02.953] INFO: Log level: INFO
[11:41:02.972] QUIET: Connection to board DTB_WREKRL opened.
[11:41:02.975] 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:
------------------------------------------------------
[11:41:02.978] INFO: RPC call hashes of host and DTB match: 398089610
[11:41:04.509] INFO: DUT info:
[11:41:04.509] INFO: The DUT currently contains the following objects:
[11:41:04.509] INFO: 2 TBM Cores tbm08c (2 ON)
[11:41:04.521] INFO: TBM Core alpha (0): 7 registers set
[11:41:04.521] INFO: TBM Core beta (1): 7 registers set
[11:41:04.521] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:41:04.521] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.521] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:04.948] INFO: enter 'restricted' command line mode
[11:41:04.948] INFO: enter test to run
[11:41:14.761] INFO: test: PixelAlive no parameter change
[11:41:14.761] INFO: running: pixelalive
[11:41:14.843] INFO: ----------------------------------------------------------------------
[11:41:14.843] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:41:14.843] INFO: ----------------------------------------------------------------------
[11:41:15.175] INFO: Expecting 41600 events.
[11:41:19.514] INFO: 41600 events read in total (3620ms).
[11:41:19.678] INFO: Test took 4832ms.
[11:41:19.686] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:41:20.244] INFO: PixTestAlive::aliveTest() done
[11:41:20.244] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 0 160 0 0 1 0 0 0 0 0
[11:41:20.408] INFO: enter test to run
[11:41:31.337] INFO: test: timing no parameter change
[11:41:31.337] INFO: running: timing
[11:41:31.340] INFO: ######################################################################
[11:41:31.340] INFO: PixTestTiming::doTest()
[11:41:31.340] INFO: ######################################################################
[11:41:31.340] INFO: ----------------------------------------------------------------------
[11:41:31.340] INFO: PixTestTiming::TBMPhaseScan()
[11:41:31.340] INFO: ----------------------------------------------------------------------
[11:47:15.286] INFO: TBM Phase Settings: 244
[11:47:15.286] INFO: 400MHz Phase: 5
[11:47:15.286] INFO: 160MHz Phase: 7
[11:47:15.286] INFO: Functional Phase Area: 5
[11:47:15.306] INFO: Test took 343966 ms.
[11:47:15.306] INFO: PixTestTiming::TBMPhaseScan() done.
[11:47:15.307] INFO: ----------------------------------------------------------------------
[11:47:15.307] INFO: PixTestTiming::ROCDelayScan()
[11:47:15.307] INFO: ----------------------------------------------------------------------
[11:49:20.558] INFO: ROC Delay Settings: 227
[11:49:20.558] INFO: ROC Header-Trailer/Token Delay: 11
[11:49:20.558] INFO: ROC Port 0 Delay: 3
[11:49:20.558] INFO: ROC Port 1 Delay: 4
[11:49:20.558] INFO: Functional ROC Area: 5
[11:49:20.562] INFO: Test took 125255 ms.
[11:49:20.562] INFO: PixTestTiming::ROCDelayScan() done.
[11:49:20.562] INFO: ----------------------------------------------------------------------
[11:49:20.562] INFO: PixTestTiming::TimingTest()
[11:49:20.562] INFO: ----------------------------------------------------------------------
[11:49:36.713] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:49:51.668] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:06.596] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:21.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:36.558] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:50:51.532] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:06.476] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:21.402] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:36.370] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:51.353] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:51.731] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:51.749] INFO: ----------------------------------------------------------------------
[11:51:51.749] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:51:51.749] INFO: ----------------------------------------------------------------------
[11:51:51.749] INFO: ----------------------------------------------------------------------
[11:51:51.749] INFO: Read back bit status: 1
[11:51:51.749] INFO: ----------------------------------------------------------------------
[11:51:51.749] INFO: ----------------------------------------------------------------------
[11:51:51.749] INFO: Timings are good!
[11:51:51.749] INFO: ----------------------------------------------------------------------
[11:51:51.749] INFO: Test took 151187 ms.
[11:51:51.749] INFO: PixTestTiming::TimingTest() done.
[11:51:51.749] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:51:51.749] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:51:51.749] INFO: PixTestTiming::doTest took 620412 ms.
[11:51:51.749] INFO: PixTestTiming::doTest() done
[11:51:51.749] INFO: Write out TBMPhaseScan_0_V0
[11:51:51.749] INFO: Write out TBMPhaseScan_1_V0
[11:51:51.750] INFO: Write out CombinedTBMPhaseScan_V0
[11:51:51.751] INFO: Write out ROCDelayScan3_V0
[11:51:51.751] INFO: enter test to run
[11:52:29.644] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:52:29.644] INFO: running: highrate
[11:52:29.645] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:52:29.866] INFO: ----------------------------------------------------------------------
[11:52:29.866] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:52:29.866] INFO: ----------------------------------------------------------------------
[11:52:29.867] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:52:29.867] INFO: edge/corner pixel THR is adjusted
[11:52:29.867] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:52:30.824] INFO: Collecting data for 5 seconds...
[11:52:35.842] INFO: Done with hot pixel readout
[11:52:47.647] INFO: PixTest:: pg_setup set to default.
[11:52:47.647] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:52:47.648] INFO: 11 hot pixels found in step 0
[11:52:48.644] INFO: Collecting data for 5 seconds...
[11:52:53.661] INFO: Done with hot pixel readout
[11:53:04.776] INFO: PixTest:: pg_setup set to default.
[11:53:04.777] INFO: 12 hot pixels found in step 1
[11:53:05.770] INFO: Collecting data for 5 seconds...
[11:53:10.788] INFO: Done with hot pixel readout
[11:53:22.367] INFO: PixTest:: pg_setup set to default.
[11:53:22.367] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:53:22.367] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:53:22.367] INFO: 16 hot pixels found in step 2
[11:53:23.361] INFO: Collecting data for 5 seconds...
[11:53:28.380] INFO: Done with hot pixel readout
[11:53:39.992] INFO: PixTest:: pg_setup set to default.
[11:53:39.993] INFO: 11 hot pixels found in step 3
[11:53:40.987] INFO: Collecting data for 5 seconds...
[11:53:45.006] INFO: Done with hot pixel readout
[11:53:57.725] INFO: PixTest:: pg_setup set to default.
[11:53:57.726] INFO: 15 hot pixels found in step 4
[11:53:58.720] INFO: Collecting data for 5 seconds...
[11:54:03.738] INFO: Done with hot pixel readout
[11:54:15.373] INFO: PixTest:: pg_setup set to default.
[11:54:15.374] INFO: 9 hot pixels found in step 5
[11:54:16.367] INFO: Collecting data for 5 seconds...
[11:54:21.384] INFO: Done with hot pixel readout
[11:54:33.122] INFO: PixTest:: pg_setup set to default.
[11:54:33.122] INFO: 10 hot pixels found in step 6
[11:54:34.117] INFO: Collecting data for 5 seconds...
[11:54:39.138] INFO: Done with hot pixel readout
[11:54:50.689] INFO: PixTest:: pg_setup set to default.
[11:54:50.690] INFO: 11 hot pixels found in step 7
[11:54:51.684] INFO: Collecting data for 5 seconds...
[11:54:56.703] INFO: Done with hot pixel readout
[11:55:08.055] INFO: PixTest:: pg_setup set to default.
[11:55:08.055] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:55:08.056] INFO: 8 hot pixels found in step 8
[11:55:09.050] INFO: Collecting data for 5 seconds...
[11:55:14.069] INFO: Done with hot pixel readout
[11:55:25.641] INFO: PixTest:: pg_setup set to default.
[11:55:25.642] INFO: 7 hot pixels found in step 9
[11:55:26.636] INFO: Collecting data for 5 seconds...
[11:55:31.655] INFO: Done with hot pixel readout
[11:55:42.943] INFO: PixTest:: pg_setup set to default.
[11:55:42.944] INFO: 7 hot pixels found in step 10
[11:55:43.936] INFO: Collecting data for 5 seconds...
[11:55:48.955] INFO: Done with hot pixel readout
[11:56:00.536] INFO: PixTest:: pg_setup set to default.
[11:56:00.536] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:56:00.537] INFO: 8 hot pixels found in step 11
[11:56:01.529] INFO: Collecting data for 5 seconds...
[11:56:06.549] INFO: Done with hot pixel readout
[11:56:18.233] INFO: PixTest:: pg_setup set to default.
[11:56:18.234] INFO: 8 hot pixels found in step 12
[11:56:19.227] INFO: Collecting data for 5 seconds...
[11:56:24.245] INFO: Done with hot pixel readout
[11:56:35.744] INFO: PixTest:: pg_setup set to default.
[11:56:35.744] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:56:35.745] INFO: 5 hot pixels found in step 13
[11:56:36.738] INFO: Collecting data for 5 seconds...
[11:56:41.755] INFO: Done with hot pixel readout
[11:56:52.977] INFO: PixTest:: pg_setup set to default.
[11:56:52.977] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[11:56:52.978] INFO: 4 hot pixels found in step 14
[11:56:53.018] INFO: 4 hot pixels could not be trimmed and have been masked.
[11:56:53.021] INFO: PixTest::trimHotPixels() done
[11:56:53.039] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C0.dat
[11:56:53.045] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C1.dat
[11:56:53.051] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C2.dat
[11:56:53.057] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C3.dat
[11:56:53.065] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C4.dat
[11:56:53.075] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C5.dat
[11:56:53.082] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C6.dat
[11:56:53.088] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C7.dat
[11:56:53.093] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C8.dat
[11:56:53.099] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C9.dat
[11:56:53.104] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C10.dat
[11:56:53.110] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C11.dat
[11:56:53.115] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C12.dat
[11:56:53.120] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C13.dat
[11:56:53.126] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C14.dat
[11:56:53.154] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C15.dat
[11:56:53.162] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//defaultMaskFile.dat
[11:56:53.172] INFO: enter test to run
[11:57:27.570] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:57:27.570] INFO: running: highrate
[11:57:27.575] INFO: ----------------------------------------------------------------------
[11:57:27.575] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:57:27.575] INFO: ----------------------------------------------------------------------
[11:57:27.575] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:57:27.575] INFO: edge/corner pixel THR is adjusted
[11:57:27.575] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:57:28.533] INFO: Collecting data for 1 seconds...
[11:57:29.536] INFO: Done with hot pixel readout
[11:57:33.498] INFO: PixTest:: pg_setup set to default.
[11:57:33.499] INFO: 0 hot pixels found in step 0
[11:57:33.504] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:57:33.594] INFO: PixTest::trimHotPixels() done
[11:57:33.594] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C0.dat
[11:57:33.600] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C1.dat
[11:57:33.607] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C2.dat
[11:57:33.614] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C3.dat
[11:57:33.620] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C4.dat
[11:57:33.626] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C5.dat
[11:57:33.631] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C6.dat
[11:57:33.636] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C7.dat
[11:57:33.642] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C8.dat
[11:57:33.647] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C9.dat
[11:57:33.653] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C10.dat
[11:57:33.658] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C11.dat
[11:57:33.663] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C12.dat
[11:57:33.669] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C13.dat
[11:57:33.674] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C14.dat
[11:57:33.679] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//trimParameters35_C15.dat
[11:57:33.685] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-21_FPIXTest-17C-FNAL-160923-1305-150V_2016-09-23_13h05m_1474653933/000_FPIXTest_p17//defaultMaskFile.dat
[11:57:33.694] INFO: enter test to run
[11:58:09.219] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:58:09.219] INFO: running: xray
[11:58:09.233] INFO: ----------------------------------------------------------------------
[11:58:09.233] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:58:09.233] INFO: ----------------------------------------------------------------------
[11:58:10.221] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:58:21.745] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[11:58:50.941] INFO: Resuming triggers.
[11:59:02.463] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[11:59:31.660] INFO: Resuming triggers.
[11:59:43.180] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[12:00:12.269] INFO: Resuming triggers.
[12:00:23.792] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[12:00:53.070] INFO: Resuming triggers.
[12:01:04.592] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[12:01:34.023] INFO: Resuming triggers.
[12:01:45.546] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[12:02:14.762] INFO: Resuming triggers.
[12:02:26.288] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[12:02:55.630] INFO: Resuming triggers.
[12:03:07.159] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[12:03:36.569] INFO: Resuming triggers.
[12:03:44.704] INFO: data taking finished, elapsed time: 100 seconds.
[12:04:05.698] INFO: PixTest:: pg_setup set to default.
[12:04:05.702] INFO: PixTestXray::doPhRun() done
[12:04:05.891] INFO: enter test to run
[12:04:39.607] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:04:39.607] INFO: running: xray
[12:04:39.608] INFO: ----------------------------------------------------------------------
[12:04:39.608] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:04:39.609] INFO: ----------------------------------------------------------------------
[12:04:40.573] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:04:47.345] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:05:18.228] INFO: Resuming triggers.
[12:05:24.004] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[12:05:55.901] INFO: Resuming triggers.
[12:06:02.676] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[12:06:33.494] INFO: Resuming triggers.
[12:06:40.264] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[12:07:11.584] INFO: Resuming triggers.
[12:07:18.353] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[12:07:49.377] INFO: Resuming triggers.
[12:07:56.143] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[12:08:27.200] INFO: Resuming triggers.
[12:08:33.968] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[12:09:05.418] INFO: Resuming triggers.
[12:09:12.186] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[12:09:43.854] INFO: Resuming triggers.
[12:09:50.625] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[12:10:21.549] INFO: Resuming triggers.
[12:10:28.314] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[12:10:58.545] INFO: Resuming triggers.
[12:11:05.314] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[12:11:35.546] INFO: Resuming triggers.
[12:11:42.316] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[12:12:12.490] INFO: Resuming triggers.
[12:12:19.259] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[12:12:49.491] INFO: Resuming triggers.
[12:12:56.262] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[12:13:26.491] INFO: Resuming triggers.
[12:13:32.060] INFO: data taking finished, elapsed time: 100 seconds.
[12:13:57.210] INFO: PixTest:: pg_setup set to default.
[12:13:57.213] INFO: PixTestXray::doPhRun() done
[12:13:57.363] INFO: enter test to run
[12:14:35.275] INFO: test: HighRate no parameter change
[12:14:35.275] INFO: running: highrate
[12:14:35.293] INFO: ----------------------------------------------------------------------
[12:14:35.293] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:14:35.293] INFO: ----------------------------------------------------------------------
[12:14:35.447] INFO: Expecting 768 events.
[12:14:36.581] INFO: 768 events read in total (418ms).
[12:14:36.581] INFO: Test took 1268ms.
[12:14:37.385] INFO: Expecting 41600 events.
[12:14:40.495] INFO: 41600 events read in total (2584ms).
[12:14:40.496] INFO: Test took 3907ms.
[12:14:40.529] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:41.256] INFO: Expecting 41600 events.
[12:14:44.447] INFO: 41600 events read in total (2664ms).
[12:14:44.448] INFO: Test took 3902ms.
[12:14:44.482] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:45.207] INFO: Expecting 41600 events.
[12:14:48.422] INFO: 41600 events read in total (2689ms).
[12:14:48.423] INFO: Test took 3923ms.
[12:14:48.457] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:49.183] INFO: Expecting 41600 events.
[12:14:52.404] INFO: 41600 events read in total (2694ms).
[12:14:52.405] INFO: Test took 3931ms.
[12:14:52.438] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:53.165] INFO: Expecting 41600 events.
[12:14:56.389] INFO: 41600 events read in total (2697ms).
[12:14:56.390] INFO: Test took 3935ms.
[12:14:56.423] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:57.150] INFO: Expecting 41600 events.
[12:15:00.387] INFO: 41600 events read in total (2710ms).
[12:15:00.388] INFO: Test took 3947ms.
[12:15:00.421] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:01.146] INFO: Expecting 41600 events.
[12:15:04.415] INFO: 41600 events read in total (2742ms).
[12:15:04.416] INFO: Test took 3978ms.
[12:15:04.449] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:05.172] INFO: Expecting 41600 events.
[12:15:08.404] INFO: 41600 events read in total (2705ms).
[12:15:08.405] INFO: Test took 3938ms.
[12:15:08.438] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:09.163] INFO: Expecting 41600 events.
[12:15:12.394] INFO: 41600 events read in total (2704ms).
[12:15:12.395] INFO: Test took 3938ms.
[12:15:12.428] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:13.152] INFO: Expecting 41600 events.
[12:15:16.382] INFO: 41600 events read in total (2703ms).
[12:15:16.383] INFO: Test took 3937ms.
[12:15:16.416] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:17.143] INFO: Expecting 41600 events.
[12:15:20.363] INFO: 41600 events read in total (2693ms).
[12:15:20.364] INFO: Test took 3931ms.
[12:15:20.397] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:21.122] INFO: Expecting 41600 events.
[12:15:24.338] INFO: 41600 events read in total (2689ms).
[12:15:24.339] INFO: Test took 3923ms.
[12:15:24.373] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:25.101] INFO: Expecting 41600 events.
[12:15:28.341] INFO: 41600 events read in total (2713ms).
[12:15:28.341] INFO: Test took 3951ms.
[12:15:28.375] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:29.097] INFO: Expecting 41600 events.
[12:15:32.328] INFO: 41600 events read in total (2704ms).
[12:15:32.329] INFO: Test took 3937ms.
[12:15:32.362] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:33.089] INFO: Expecting 41600 events.
[12:15:36.324] INFO: 41600 events read in total (2708ms).
[12:15:36.325] INFO: Test took 3945ms.
[12:15:36.359] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:37.085] INFO: Expecting 41600 events.
[12:15:40.322] INFO: 41600 events read in total (2710ms).
[12:15:40.323] INFO: Test took 3946ms.
[12:15:40.357] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:41.084] INFO: Expecting 41600 events.
[12:15:44.318] INFO: 41600 events read in total (2707ms).
[12:15:44.318] INFO: Test took 3943ms.
[12:15:44.351] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:45.078] INFO: Expecting 41600 events.
[12:15:48.299] INFO: 41600 events read in total (2694ms).
[12:15:48.300] INFO: Test took 3931ms.
[12:15:48.333] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:49.056] INFO: Expecting 41600 events.
[12:15:52.249] INFO: 41600 events read in total (2666ms).
[12:15:52.250] INFO: Test took 3899ms.
[12:15:52.284] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:53.009] INFO: Expecting 41600 events.
[12:15:56.060] INFO: 41600 events read in total (2524ms).
[12:15:56.061] INFO: Test took 3757ms.
[12:15:56.094] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:56.460] INFO: enter test to run
[12:16:00.627] INFO: test: HighRate no parameter change
[12:16:00.627] INFO: running: highrate
[12:16:00.628] INFO: ----------------------------------------------------------------------
[12:16:00.628] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:16:00.628] INFO: ----------------------------------------------------------------------
[12:16:01.243] INFO: Expecting 208000 events.
[12:16:13.047] INFO: 208000 events read in total (11277ms).
[12:16:13.050] INFO: Test took 12415ms.
[12:16:13.190] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:16:13.440] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 0 160 23 0 0 0 0 0 0 0
[12:16:13.440] INFO: number of red-efficiency pixels: 92 66 76 135 154 161 160 254 189 128 102 93 87 63 31 27
[12:16:13.440] INFO: number of X-ray hits detected: 68182 45634 67930 104148 107472 114228 111118 76983 71519 94312 95724 80085 82130 49865 21166 24626
[12:16:13.440] 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:16:13.440] INFO: number of Vcal hits detected: 207907 207932 207923 207860 207839 207776 207834 199905 206590 207870 207895 207905 207911 207936 207969 207973
[12:16:13.440] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0
[12:16:13.440] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 96.1 99.3 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[12:16:13.440] INFO: X-ray hit rate [MHz/cm2]: 20.0 13.4 19.9 30.5 31.5 33.5 32.6 22.6 21.0 27.6 28.1 23.5 24.1 14.6 6.2 7.2
[12:16:13.440] INFO: PixTestHighRate::doXPixelAlive() done
[12:16:13.491] INFO: PixTest:: pg_setup set to default.
[12:16:13.505] INFO: enter test to run
[12:16:34.730] INFO: test: HighRate no parameter change
[12:16:34.730] INFO: running: highrate
[12:16:34.731] INFO: ----------------------------------------------------------------------
[12:16:34.731] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:16:34.732] INFO: ----------------------------------------------------------------------
[12:16:35.348] INFO: Expecting 208000 events.
[12:16:48.934] INFO: 208000 events read in total (13059ms).
[12:16:48.941] INFO: Test took 14199ms.
[12:16:49.237] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:16:49.536] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 0 160 24 0 0 0 0 0 0 0
[12:16:49.536] INFO: number of red-efficiency pixels: 251 133 242 426 535 598 543 509 412 430 346 300 268 209 53 42
[12:16:49.536] INFO: number of X-ray hits detected: 142859 96069 142387 217916 226215 238505 231585 163540 151012 197581 198884 168219 172429 105112 44076 53043
[12:16:49.536] 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:16:49.536] INFO: number of Vcal hits detected: 207721 207858 207725 207529 207398 207272 207411 199618 206162 207533 207636 207679 207723 207778 207947 207958
[12:16:49.536] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.7 99.8 99.7 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[12:16:49.536] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.7 99.7 96.0 99.1 99.8 99.8 99.8 99.9 99.9 100.0 100.0
[12:16:49.536] INFO: X-ray hit rate [MHz/cm2]: 41.9 28.2 41.7 63.9 66.3 69.9 67.9 47.9 44.3 57.9 58.3 49.3 50.5 30.8 12.9 15.5
[12:16:49.536] INFO: PixTestHighRate::doXPixelAlive() done
[12:16:49.586] INFO: PixTest:: pg_setup set to default.
[12:16:49.601] INFO: enter test to run
[12:17:11.434] INFO: test: HighRate no parameter change
[12:17:11.434] INFO: running: highrate
[12:17:11.435] INFO: ----------------------------------------------------------------------
[12:17:11.435] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:17:11.435] INFO: ----------------------------------------------------------------------
[12:17:12.047] INFO: Expecting 208000 events.
[12:17:27.437] INFO: 208000 events read in total (14863ms).
[12:17:27.449] INFO: Test took 16005ms.
[12:17:27.891] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:17:28.240] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 0 160 24 0 0 0 0 0 0 0
[12:17:28.240] INFO: number of red-efficiency pixels: 566 274 582 942 1292 1431 1326 871 728 973 802 718 555 483 111 108
[12:17:28.240] INFO: number of X-ray hits detected: 214906 144730 213993 329377 340891 360336 347026 244617 227689 297399 300562 253837 259702 158373 66357 79719
[12:17:28.240] 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:17:28.240] INFO: number of Vcal hits detected: 207310 207697 207267 206837 206308 205986 206205 199098 205683 206818 207054 207157 207368 207359 207885 207890
[12:17:28.240] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.7 99.5 99.3 99.1 99.2 99.6 99.5 99.5 99.6 99.7 99.7 99.7 99.9 99.9
[12:17:28.240] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.6 99.4 99.2 99.0 99.1 95.7 98.9 99.4 99.5 99.6 99.7 99.7 99.9 99.9
[12:17:28.240] INFO: X-ray hit rate [MHz/cm2]: 63.0 42.4 62.7 96.5 99.9 105.6 101.7 71.7 66.7 87.2 88.1 74.4 76.1 46.4 19.4 23.4
[12:17:28.240] INFO: PixTestHighRate::doXPixelAlive() done
[12:17:28.291] INFO: PixTest:: pg_setup set to default.
[12:17:28.313] INFO: enter test to run
[12:18:08.538] INFO: test: exit no parameter change
[12:18:08.929] QUIET: Connection to board 33 closed.
[12:18:08.938] INFO: pXar: this is the end, my friend