[15:12:11.443] INFO: *** Welcome to pxar ***
[15:12:11.443] INFO: *** Today: 2016/10/27
[15:12:15.535] INFO: *** Version: v1.9.0-818-g96727
[15:12:15.535] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//dacParameters35_C15.dat
[15:12:16.099] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:12:16.099] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//defaultMaskFile.dat
[15:12:16.133] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C15.dat
[15:12:16.558] INFO: clk: 4
[15:12:16.558] INFO: ctr: 4
[15:12:16.558] INFO: sda: 19
[15:12:16.558] INFO: tin: 9
[15:12:16.558] INFO: level: 15
[15:12:16.558] INFO: triggerdelay: 0
[15:12:16.558] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:12:16.558] INFO: Log level: INFO
[15:12:16.597] QUIET: Connection to board DTB_WREHUL opened.
[15:12:16.600] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 30
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREHUL
MAC address: 40D85511801E
Hostname: pixelDTB030
Comment:
------------------------------------------------------
[15:12:16.603] INFO: RPC call hashes of host and DTB match: 398089610
[15:12:18.148] INFO: DUT info:
[15:12:18.148] INFO: The DUT currently contains the following objects:
[15:12:18.148] INFO: 2 TBM Cores tbm08c (2 ON)
[15:12:18.169] INFO: TBM Core alpha (0): 7 registers set
[15:12:18.169] INFO: TBM Core beta (1): 7 registers set
[15:12:18.170] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:12:18.170] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.170] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:12:18.630] INFO: enter 'restricted' command line mode
[15:12:18.630] INFO: enter test to run
[15:12:25.408] INFO: test: PixelAlive no parameter change
[15:12:25.408] INFO: running: pixelalive
[15:12:25.492] INFO: ----------------------------------------------------------------------
[15:12:25.492] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[15:12:25.492] INFO: ----------------------------------------------------------------------
[15:12:25.815] INFO: Expecting 41600 events.
[15:12:30.216] INFO: 41600 events read in total (3683ms).
[15:12:30.377] INFO: Test took 4882ms.
[15:12:30.383] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:12:31.027] INFO: PixTestAlive::aliveTest() done
[15:12:31.027] INFO: number of dead pixels (per ROC): 1 0 2 1 0 0 0 0 0 0 0 0 0 0 0 0
[15:12:31.241] INFO: enter test to run
[15:12:49.719] INFO: test: timing no parameter change
[15:12:49.720] INFO: running: timing
[15:12:49.723] INFO: ######################################################################
[15:12:49.723] INFO: PixTestTiming::doTest()
[15:12:49.723] INFO: ######################################################################
[15:12:49.723] INFO: ----------------------------------------------------------------------
[15:12:49.723] INFO: PixTestTiming::TBMPhaseScan()
[15:12:49.723] INFO: ----------------------------------------------------------------------
[15:18:44.839] INFO: TBM Phase Settings: 224
[15:18:44.839] INFO: 400MHz Phase: 0
[15:18:44.839] INFO: 160MHz Phase: 7
[15:18:44.839] INFO: Functional Phase Area: 3
[15:18:44.855] INFO: Test took 355132 ms.
[15:18:44.855] INFO: PixTestTiming::TBMPhaseScan() done.
[15:18:44.855] INFO: ----------------------------------------------------------------------
[15:18:44.855] INFO: PixTestTiming::ROCDelayScan()
[15:18:44.855] INFO: ----------------------------------------------------------------------
[15:20:50.087] INFO: ROC Delay Settings: 228
[15:20:50.087] INFO: ROC Header-Trailer/Token Delay: 11
[15:20:50.087] INFO: ROC Port 0 Delay: 4
[15:20:50.087] INFO: ROC Port 1 Delay: 4
[15:20:50.087] INFO: Functional ROC Area: 4
[15:20:50.090] INFO: Test took 125235 ms.
[15:20:50.090] INFO: PixTestTiming::ROCDelayScan() done.
[15:20:50.091] INFO: ----------------------------------------------------------------------
[15:20:50.091] INFO: PixTestTiming::TimingTest()
[15:20:50.091] INFO: ----------------------------------------------------------------------
[15:21:06.421] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:21.562] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:36.714] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:51.994] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:22:07.180] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:22:22.420] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:22:37.659] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:22:52.905] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:23:08.027] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:23:23.035] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:23:23.412] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:23:23.429] INFO: ----------------------------------------------------------------------
[15:23:23.429] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:23:23.429] INFO: ----------------------------------------------------------------------
[15:23:23.429] INFO: ----------------------------------------------------------------------
[15:23:23.429] INFO: Read back bit status: 1
[15:23:23.429] INFO: ----------------------------------------------------------------------
[15:23:23.429] INFO: ----------------------------------------------------------------------
[15:23:23.429] INFO: Timings are good!
[15:23:23.429] INFO: ----------------------------------------------------------------------
[15:23:23.429] INFO: Test took 153338 ms.
[15:23:23.429] INFO: PixTestTiming::TimingTest() done.
[15:23:23.430] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:23:23.452] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:23:23.452] INFO: PixTestTiming::doTest took 633732 ms.
[15:23:23.452] INFO: PixTestTiming::doTest() done
[15:23:23.453] INFO: Write out TBMPhaseScan_0_V0
[15:23:23.453] INFO: Write out TBMPhaseScan_1_V0
[15:23:23.453] INFO: Write out CombinedTBMPhaseScan_V0
[15:23:23.455] INFO: Write out ROCDelayScan3_V0
[15:23:23.456] INFO: enter test to run
[15:25:11.211] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:25:11.211] INFO: running: highrate
[15:25:11.227] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:25:12.069] INFO: ----------------------------------------------------------------------
[15:25:12.069] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:25:12.069] INFO: ----------------------------------------------------------------------
[15:25:12.069] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:25:12.083] INFO: edge/corner pixel THR is adjusted
[15:25:12.083] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:25:13.042] INFO: Collecting data for 5 seconds...
[15:25:18.061] INFO: Done with hot pixel readout
[15:25:30.196] INFO: PixTest:: pg_setup set to default.
[15:25:30.197] INFO: 3 hot pixels found in step 0
[15:25:31.190] INFO: Collecting data for 5 seconds...
[15:25:36.209] INFO: Done with hot pixel readout
[15:25:48.170] INFO: PixTest:: pg_setup set to default.
[15:25:48.171] INFO: 6 hot pixels found in step 1
[15:25:49.163] INFO: Collecting data for 5 seconds...
[15:25:54.184] INFO: Done with hot pixel readout
[15:26:06.291] INFO: PixTest:: pg_setup set to default.
[15:26:06.291] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:26:06.291] INFO: 9 hot pixels found in step 2
[15:26:07.285] INFO: Collecting data for 5 seconds...
[15:26:12.306] INFO: Done with hot pixel readout
[15:26:24.193] INFO: PixTest:: pg_setup set to default.
[15:26:24.193] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:26:24.193] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:26:24.194] INFO: 9 hot pixels found in step 3
[15:26:25.187] INFO: Collecting data for 5 seconds...
[15:26:30.208] INFO: Done with hot pixel readout
[15:26:42.299] INFO: PixTest:: pg_setup set to default.
[15:26:42.300] INFO: 7 hot pixels found in step 4
[15:26:43.294] INFO: Collecting data for 5 seconds...
[15:26:48.312] INFO: Done with hot pixel readout
[15:27:00.164] INFO: PixTest:: pg_setup set to default.
[15:27:00.165] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:27:00.165] INFO: 3 hot pixels found in step 5
[15:27:01.159] INFO: Collecting data for 5 seconds...
[15:27:06.179] INFO: Done with hot pixel readout
[15:27:18.129] INFO: PixTest:: pg_setup set to default.
[15:27:18.130] INFO: 5 hot pixels found in step 6
[15:27:19.123] INFO: Collecting data for 5 seconds...
[15:27:24.139] INFO: Done with hot pixel readout
[15:27:35.902] INFO: PixTest:: pg_setup set to default.
[15:27:35.903] INFO: 6 hot pixels found in step 7
[15:27:36.896] INFO: Collecting data for 5 seconds...
[15:27:41.912] INFO: Done with hot pixel readout
[15:27:53.658] INFO: PixTest:: pg_setup set to default.
[15:27:53.659] INFO: 10 hot pixels found in step 8
[15:27:54.652] INFO: Collecting data for 5 seconds...
[15:27:59.669] INFO: Done with hot pixel readout
[15:28:11.455] INFO: PixTest:: pg_setup set to default.
[15:28:11.455] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:28:11.456] INFO: 8 hot pixels found in step 9
[15:28:12.450] INFO: Collecting data for 5 seconds...
[15:28:17.466] INFO: Done with hot pixel readout
[15:28:29.152] INFO: PixTest:: pg_setup set to default.
[15:28:29.153] INFO: 7 hot pixels found in step 10
[15:28:30.146] INFO: Collecting data for 5 seconds...
[15:28:35.163] INFO: Done with hot pixel readout
[15:28:46.907] INFO: PixTest:: pg_setup set to default.
[15:28:46.907] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:28:46.908] INFO: 5 hot pixels found in step 11
[15:28:47.900] INFO: Collecting data for 5 seconds...
[15:28:52.917] INFO: Done with hot pixel readout
[15:29:04.615] INFO: PixTest:: pg_setup set to default.
[15:29:04.615] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:29:04.616] INFO: 4 hot pixels found in step 12
[15:29:05.609] INFO: Collecting data for 5 seconds...
[15:29:10.626] INFO: Done with hot pixel readout
[15:29:22.386] INFO: PixTest:: pg_setup set to default.
[15:29:22.387] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:29:22.387] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:29:22.387] INFO: 8 hot pixels found in step 13
[15:29:23.380] INFO: Collecting data for 5 seconds...
[15:29:28.397] INFO: Done with hot pixel readout
[15:29:39.113] INFO: PixTest:: pg_setup set to default.
[15:29:39.114] INFO: 3 hot pixels found in step 14
[15:29:39.150] INFO: 3 hot pixels could not be trimmed and have been masked.
[15:29:39.154] INFO: PixTest::trimHotPixels() done
[15:29:39.154] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C0.dat
[15:29:39.160] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C1.dat
[15:29:39.166] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C2.dat
[15:29:39.172] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C3.dat
[15:29:39.177] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C4.dat
[15:29:39.182] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C5.dat
[15:29:39.188] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C6.dat
[15:29:39.193] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C7.dat
[15:29:39.198] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C8.dat
[15:29:39.204] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C9.dat
[15:29:39.209] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C10.dat
[15:29:39.214] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C11.dat
[15:29:39.219] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C12.dat
[15:29:39.225] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C13.dat
[15:29:39.230] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C14.dat
[15:29:39.235] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C15.dat
[15:29:39.241] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//defaultMaskFile.dat
[15:29:39.251] INFO: enter test to run
[15:30:47.488] INFO: test: [AHighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:30:47.488] INFO: running: [ahighrate
[15:30:47.488] INFO: command ->[ahighrate<- not known, ignored
[15:30:47.489] INFO: enter test to run
[15:31:18.024] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:31:18.024] INFO: running: highrate
[15:31:18.029] INFO: ----------------------------------------------------------------------
[15:31:18.029] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:31:18.029] INFO: ----------------------------------------------------------------------
[15:31:18.029] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:31:18.029] INFO: edge/corner pixel THR is adjusted
[15:31:18.029] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:31:18.987] INFO: Collecting data for 1 seconds...
[15:31:19.991] INFO: Done with hot pixel readout
[15:31:23.955] INFO: PixTest:: pg_setup set to default.
[15:31:23.955] INFO: 0 hot pixels found in step 0
[15:31:23.961] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:31:24.053] INFO: PixTest::trimHotPixels() done
[15:31:24.053] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C0.dat
[15:31:24.063] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C1.dat
[15:31:24.069] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C2.dat
[15:31:24.074] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C3.dat
[15:31:24.079] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C4.dat
[15:31:24.084] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C5.dat
[15:31:24.090] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C6.dat
[15:31:24.095] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C7.dat
[15:31:24.100] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C8.dat
[15:31:24.105] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C9.dat
[15:31:24.110] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C10.dat
[15:31:24.116] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C11.dat
[15:31:24.121] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C12.dat
[15:31:24.126] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C13.dat
[15:31:24.132] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C14.dat
[15:31:24.137] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//trimParameters35_C15.dat
[15:31:24.142] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-5-45_FPIXTest-17C-FNAL-161024-1542-150V_2016-10-24_15h42m_1477341723/000_FPIXTest_p17//defaultMaskFile.dat
[15:31:24.152] INFO: enter test to run
[15:31:59.072] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:31:59.072] INFO: running: xray
[15:31:59.073] INFO: ----------------------------------------------------------------------
[15:31:59.073] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:31:59.073] INFO: ----------------------------------------------------------------------
[15:32:00.055] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:32:11.493] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:32:40.860] INFO: Resuming triggers.
[15:32:52.298] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:33:21.832] INFO: Resuming triggers.
[15:33:33.266] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[15:34:02.689] INFO: Resuming triggers.
[15:34:14.127] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:34:43.526] INFO: Resuming triggers.
[15:34:54.960] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[15:35:24.952] INFO: Resuming triggers.
[15:35:36.390] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[15:36:06.231] INFO: Resuming triggers.
[15:36:17.672] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[15:36:46.875] INFO: Resuming triggers.
[15:36:58.313] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[15:37:27.406] INFO: Resuming triggers.
[15:37:36.249] INFO: data taking finished, elapsed time: 100 seconds.
[15:37:59.103] INFO: PixTest:: pg_setup set to default.
[15:37:59.107] INFO: PixTestXray::doPhRun() done
[15:37:59.382] INFO: enter test to run
[15:38:52.077] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:38:52.077] INFO: running: xray
[15:38:52.078] INFO: ----------------------------------------------------------------------
[15:38:52.078] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:38:52.078] INFO: ----------------------------------------------------------------------
[15:38:53.042] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:38:59.717] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:39:31.492] INFO: Resuming triggers.
[15:39:38.169] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[15:40:09.445] INFO: Resuming triggers.
[15:40:16.119] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[15:40:46.947] INFO: Resuming triggers.
[15:40:53.618] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[15:41:25.096] INFO: Resuming triggers.
[15:41:31.770] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[15:42:03.326] INFO: Resuming triggers.
[15:42:09.997] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[15:42:40.272] INFO: Resuming triggers.
[15:42:46.946] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[15:43:17.103] INFO: Resuming triggers.
[15:43:23.749] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[15:43:54.097] INFO: Resuming triggers.
[15:44:00.767] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[15:44:31.230] INFO: Resuming triggers.
[15:44:37.899] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[15:45:08.125] INFO: Resuming triggers.
[15:45:14.793] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[15:45:45.068] INFO: Resuming triggers.
[15:45:51.736] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[15:46:22.264] INFO: Resuming triggers.
[15:46:28.931] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[15:46:59.143] INFO: Resuming triggers.
[15:47:05.810] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[15:47:36.085] INFO: Resuming triggers.
[15:47:42.755] INFO: run duration 99 seconds, buffer almost full (81%), pausing triggers.
[15:48:12.931] INFO: Resuming triggers.
[15:48:13.235] INFO: data taking finished, elapsed time: 100 seconds.
[15:48:14.994] INFO: PixTest:: pg_setup set to default.
[15:48:14.997] INFO: PixTestXray::doPhRun() done
[15:48:15.179] INFO: enter test to run
[15:49:38.321] INFO: test: HighRate no parameter change
[15:49:38.321] INFO: running: highrate
[15:49:38.351] INFO: ----------------------------------------------------------------------
[15:49:38.351] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:49:38.351] INFO: ----------------------------------------------------------------------
[15:49:38.575] INFO: Expecting 768 events.
[15:49:39.732] INFO: 768 events read in total (435ms).
[15:49:39.732] INFO: Test took 1291ms.
[15:49:40.535] INFO: Expecting 41600 events.
[15:49:43.659] INFO: 41600 events read in total (2597ms).
[15:49:43.660] INFO: Test took 3798ms.
[15:49:43.696] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:44.421] INFO: Expecting 41600 events.
[15:49:47.689] INFO: 41600 events read in total (2741ms).
[15:49:47.690] INFO: Test took 3940ms.
[15:49:47.763] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:48.449] INFO: Expecting 41600 events.
[15:49:51.809] INFO: 41600 events read in total (2833ms).
[15:49:51.810] INFO: Test took 4027ms.
[15:49:51.844] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:52.565] INFO: Expecting 41600 events.
[15:49:55.752] INFO: 41600 events read in total (2660ms).
[15:49:55.753] INFO: Test took 3891ms.
[15:49:55.788] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:56.508] INFO: Expecting 41600 events.
[15:49:59.811] INFO: 41600 events read in total (2776ms).
[15:49:59.812] INFO: Test took 4006ms.
[15:49:59.847] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:00.559] INFO: Expecting 41600 events.
[15:50:03.753] INFO: 41600 events read in total (2667ms).
[15:50:03.754] INFO: Test took 3889ms.
[15:50:03.789] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:04.510] INFO: Expecting 41600 events.
[15:50:07.826] INFO: 41600 events read in total (2789ms).
[15:50:07.827] INFO: Test took 4021ms.
[15:50:07.862] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:08.585] INFO: Expecting 41600 events.
[15:50:11.819] INFO: 41600 events read in total (2708ms).
[15:50:11.820] INFO: Test took 3939ms.
[15:50:11.855] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:12.574] INFO: Expecting 41600 events.
[15:50:15.848] INFO: 41600 events read in total (2747ms).
[15:50:15.849] INFO: Test took 3976ms.
[15:50:15.886] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:16.595] INFO: Expecting 41600 events.
[15:50:19.871] INFO: 41600 events read in total (2749ms).
[15:50:19.872] INFO: Test took 3961ms.
[15:50:19.907] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:20.626] INFO: Expecting 41600 events.
[15:50:23.916] INFO: 41600 events read in total (2763ms).
[15:50:23.917] INFO: Test took 3992ms.
[15:50:23.952] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:24.666] INFO: Expecting 41600 events.
[15:50:28.029] INFO: 41600 events read in total (2836ms).
[15:50:28.030] INFO: Test took 4060ms.
[15:50:28.066] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:28.780] INFO: Expecting 41600 events.
[15:50:31.982] INFO: 41600 events read in total (2676ms).
[15:50:31.983] INFO: Test took 3899ms.
[15:50:32.019] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:32.740] INFO: Expecting 41600 events.
[15:50:36.063] INFO: 41600 events read in total (2796ms).
[15:50:36.064] INFO: Test took 4027ms.
[15:50:36.100] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:36.818] INFO: Expecting 41600 events.
[15:50:40.115] INFO: 41600 events read in total (2770ms).
[15:50:40.304] INFO: Test took 4186ms.
[15:50:40.344] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:40.976] INFO: Expecting 41600 events.
[15:50:44.155] INFO: 41600 events read in total (2652ms).
[15:50:44.156] INFO: Test took 3792ms.
[15:50:44.190] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:44.907] INFO: Expecting 41600 events.
[15:50:48.205] INFO: 41600 events read in total (2771ms).
[15:50:48.206] INFO: Test took 3998ms.
[15:50:48.240] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:48.961] INFO: Expecting 41600 events.
[15:50:52.166] INFO: 41600 events read in total (2678ms).
[15:50:52.167] INFO: Test took 3909ms.
[15:50:52.201] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:52.926] INFO: Expecting 41600 events.
[15:50:56.178] INFO: 41600 events read in total (2725ms).
[15:50:56.180] INFO: Test took 3961ms.
[15:50:56.216] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:56.927] INFO: Expecting 41600 events.
[15:51:00.120] INFO: 41600 events read in total (2666ms).
[15:51:00.121] INFO: Test took 3887ms.
[15:51:00.155] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:00.518] INFO: enter test to run
[15:51:17.840] INFO: test: HighRate no parameter change
[15:51:17.840] INFO: running: highrate
[15:51:17.841] INFO: ----------------------------------------------------------------------
[15:51:17.841] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:51:17.841] INFO: ----------------------------------------------------------------------
[15:51:18.500] INFO: Expecting 208000 events.
[15:51:30.525] INFO: 208000 events read in total (11498ms).
[15:51:30.528] INFO: Test took 12643ms.
[15:51:30.679] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:51:30.934] INFO: number of dead pixels (per ROC): 1 0 2 1 0 0 0 0 0 0 0 0 0 0 0 0
[15:51:30.957] INFO: number of red-efficiency pixels: 79 47 78 137 140 134 137 105 103 152 126 87 115 59 20 35
[15:51:30.957] INFO: number of X-ray hits detected: 63025 42134 66342 101391 103150 114403 114828 77115 77346 106276 104906 87640 89259 56102 21037 24228
[15:51:30.957] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:51:30.957] INFO: number of Vcal hits detected: 207870 207953 207823 207806 207855 207863 207859 207894 207897 207843 207872 207911 207882 207941 207979 207964
[15:51:30.957] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[15:51:30.957] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 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
[15:51:30.957] INFO: X-ray hit rate [MHz/cm2]: 18.5 12.3 19.4 29.7 30.2 33.5 33.7 22.6 22.7 31.2 30.7 25.7 26.2 16.4 6.2 7.1
[15:51:30.957] INFO: PixTestHighRate::doXPixelAlive() done
[15:51:31.010] INFO: PixTest:: pg_setup set to default.
[15:51:31.025] INFO: enter test to run
[15:52:04.248] INFO: test: HighRate no parameter change
[15:52:04.248] INFO: running: highrate
[15:52:04.249] INFO: ----------------------------------------------------------------------
[15:52:04.249] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:52:04.249] INFO: ----------------------------------------------------------------------
[15:52:04.870] INFO: Expecting 208000 events.
[15:52:18.681] INFO: 208000 events read in total (13285ms).
[15:52:18.686] INFO: Test took 14428ms.
[15:52:18.991] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:52:19.300] INFO: number of dead pixels (per ROC): 1 0 2 1 0 0 0 0 0 0 0 0 0 0 0 0
[15:52:19.300] INFO: number of red-efficiency pixels: 176 126 209 387 436 442 408 312 272 453 466 269 344 190 72 48
[15:52:19.300] INFO: number of X-ray hits detected: 129994 87086 137345 208172 212972 236147 236825 158480 161883 219499 218301 181387 185737 115619 43654 50855
[15:52:19.300] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:52:19.300] INFO: number of Vcal hits detected: 207765 207870 207682 207538 207536 207524 207556 207666 207714 207495 207492 207716 207633 207798 207924 207952
[15:52:19.300] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[15:52:19.300] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.8 99.8 99.8 99.8 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[15:52:19.300] INFO: X-ray hit rate [MHz/cm2]: 38.1 25.5 40.3 61.0 62.4 69.2 69.4 46.5 47.4 64.3 64.0 53.2 54.4 33.9 12.8 14.9
[15:52:19.300] INFO: PixTestHighRate::doXPixelAlive() done
[15:52:19.347] INFO: PixTest:: pg_setup set to default.
[15:52:19.362] INFO: enter test to run
[15:52:53.887] INFO: test: HighRate no parameter change
[15:52:53.887] INFO: running: highrate
[15:52:53.889] INFO: ----------------------------------------------------------------------
[15:52:53.889] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:52:53.889] INFO: ----------------------------------------------------------------------
[15:52:54.506] INFO: Expecting 208000 events.
[15:53:10.238] INFO: 208000 events read in total (15205ms).
[15:53:10.245] INFO: Test took 16347ms.
[15:53:10.709] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:53:11.067] INFO: number of dead pixels (per ROC): 1 0 2 1 0 0 0 0 0 0 0 0 0 0 0 0
[15:53:11.067] INFO: number of red-efficiency pixels: 365 264 477 875 1062 1043 975 722 592 1183 1086 584 815 380 101 104
[15:53:11.067] INFO: number of X-ray hits detected: 198959 132658 208929 316900 324485 360431 360076 243092 245210 334808 332274 274680 283014 176010 67047 77335
[15:53:11.067] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[15:53:11.067] INFO: number of Vcal hits detected: 207535 207715 207329 206896 206671 206707 206810 207075 207297 206514 206625 207328 207070 207540 207898 207891
[15:53:11.067] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.6 99.4 99.4 99.5 99.6 99.7 99.3 99.4 99.7 99.6 99.8 100.0 100.0
[15:53:11.067] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.5 99.4 99.4 99.4 99.6 99.7 99.3 99.3 99.7 99.6 99.8 100.0 99.9
[15:53:11.067] INFO: X-ray hit rate [MHz/cm2]: 58.3 38.9 61.2 92.9 95.1 105.6 105.5 71.3 71.9 98.1 97.4 80.5 83.0 51.6 19.7 22.7
[15:53:11.067] INFO: PixTestHighRate::doXPixelAlive() done
[15:53:11.114] INFO: PixTest:: pg_setup set to default.
[15:53:11.130] INFO: enter test to run
[15:53:53.559] INFO: test: exit no parameter change
[15:53:54.523] QUIET: Connection to board 30 closed.
[15:53:54.867] INFO: pXar: this is the end, my friend