[15:09:53.519] INFO: *** Welcome to pxar ***
[15:09:53.519] INFO: *** Today: 2016/10/06
[15:09:54.749] INFO: *** Version: v1.9.0-818-g96727
[15:09:54.766] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//dacParameters35_C15.dat
[15:09:54.844] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:09:54.845] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//defaultMaskFile.dat
[15:09:54.846] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C15.dat
[15:09:54.940] INFO: clk: 4
[15:09:54.940] INFO: ctr: 4
[15:09:54.940] INFO: sda: 19
[15:09:54.940] INFO: tin: 9
[15:09:54.940] INFO: level: 15
[15:09:54.940] INFO: triggerdelay: 0
[15:09:54.940] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[15:09:54.940] INFO: Log level: INFO
[15:09:54.957] QUIET: Connection to board DTB_WREKRL opened.
[15:09:54.960] 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:
------------------------------------------------------
[15:09:54.963] INFO: RPC call hashes of host and DTB match: 398089610
[15:09:56.502] INFO: DUT info:
[15:09:56.502] INFO: The DUT currently contains the following objects:
[15:09:56.502] INFO: 2 TBM Cores tbm08c (2 ON)
[15:09:56.502] INFO: TBM Core alpha (0): 7 registers set
[15:09:56.502] INFO: TBM Core beta (1): 7 registers set
[15:09:56.502] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[15:09:56.502] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.502] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[15:09:56.927] INFO: enter 'restricted' command line mode
[15:09:56.927] INFO: enter test to run
[15:10:02.714] INFO: test: PixelAlive no parameter change
[15:10:02.714] INFO: running: pixelalive
[15:10:02.772] INFO: ----------------------------------------------------------------------
[15:10:02.772] 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:10:02.772] INFO: ----------------------------------------------------------------------
[15:10:03.095] INFO: Expecting 41600 events.
[15:10:07.408] INFO: 41600 events read in total (3595ms).
[15:10:07.573] INFO: Test took 4798ms.
[15:10:07.582] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:10:08.118] INFO: PixTestAlive::aliveTest() done
[15:10:08.118] INFO: number of dead pixels (per ROC): 0 0 0 2 0 0 0 0 0 0 0 0 0 0 0 0
[15:10:08.262] INFO: enter test to run
[15:10:12.474] INFO: test: timing no parameter change
[15:10:12.474] INFO: running: timing
[15:10:12.477] INFO: ######################################################################
[15:10:12.478] INFO: PixTestTiming::doTest()
[15:10:12.478] INFO: ######################################################################
[15:10:12.478] INFO: ----------------------------------------------------------------------
[15:10:12.478] INFO: PixTestTiming::TBMPhaseScan()
[15:10:12.478] INFO: ----------------------------------------------------------------------
[15:16:24.908] INFO: TBM Phase Settings: 200
[15:16:24.908] INFO: 400MHz Phase: 2
[15:16:24.908] INFO: 160MHz Phase: 6
[15:16:24.908] INFO: Functional Phase Area: 3
[15:16:24.926] INFO: Test took 372448 ms.
[15:16:24.927] INFO: PixTestTiming::TBMPhaseScan() done.
[15:16:24.927] INFO: ----------------------------------------------------------------------
[15:16:24.927] INFO: PixTestTiming::ROCDelayScan()
[15:16:24.927] INFO: ----------------------------------------------------------------------
[15:19:43.989] INFO: ROC Delay Settings: 219
[15:19:43.989] INFO: ROC Header-Trailer/Token Delay: 11
[15:19:43.989] INFO: ROC Port 0 Delay: 3
[15:19:43.989] INFO: ROC Port 1 Delay: 3
[15:19:43.989] INFO: Functional ROC Area: 4
[15:19:43.992] INFO: Test took 199065 ms.
[15:19:43.992] INFO: PixTestTiming::ROCDelayScan() done.
[15:19:43.992] INFO: ----------------------------------------------------------------------
[15:19:43.992] INFO: PixTestTiming::TimingTest()
[15:19:43.992] INFO: ----------------------------------------------------------------------
[15:20:00.132] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:15.045] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:29.986] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:44.944] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:20:59.864] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:14.817] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:29.763] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:44.719] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:21:59.743] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:22:14.662] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:22:15.044] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:22:15.062] INFO: ----------------------------------------------------------------------
[15:22:15.062] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[15:22:15.062] INFO: ----------------------------------------------------------------------
[15:22:15.062] INFO: ----------------------------------------------------------------------
[15:22:15.062] INFO: Read back bit status: 1
[15:22:15.062] INFO: ----------------------------------------------------------------------
[15:22:15.062] INFO: ----------------------------------------------------------------------
[15:22:15.062] INFO: Timings are good!
[15:22:15.062] INFO: ----------------------------------------------------------------------
[15:22:15.062] INFO: Test took 151070 ms.
[15:22:15.062] INFO: PixTestTiming::TimingTest() done.
[15:22:15.062] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//tbmParameters_C0a.dat
[15:22:15.062] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//tbmParameters_C0b.dat
[15:22:15.062] INFO: PixTestTiming::doTest took 722588 ms.
[15:22:15.062] INFO: PixTestTiming::doTest() done
[15:22:15.062] INFO: Write out TBMPhaseScan_0_V0
[15:22:15.063] INFO: Write out TBMPhaseScan_1_V0
[15:22:15.063] INFO: Write out CombinedTBMPhaseScan_V0
[15:22:15.064] INFO: Write out ROCDelayScan3_V0
[15:22:15.064] INFO: enter test to run
[15:23:04.349] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[15:23:04.349] INFO: running: highrate
[15:23:04.364] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[15:23:04.598] INFO: ----------------------------------------------------------------------
[15:23:04.598] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[15:23:04.598] INFO: ----------------------------------------------------------------------
[15:23:04.598] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[15:23:04.598] INFO: edge/corner pixel THR is adjusted
[15:23:04.598] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:23:05.555] INFO: Collecting data for 5 seconds...
[15:23:10.575] INFO: Done with hot pixel readout
[15:23:22.542] INFO: PixTest:: pg_setup set to default.
[15:23:22.543] INFO: 4 hot pixels found in step 0
[15:23:23.538] INFO: Collecting data for 5 seconds...
[15:23:28.554] INFO: Done with hot pixel readout
[15:23:40.092] INFO: PixTest:: pg_setup set to default.
[15:23:40.092] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:23:40.093] INFO: 7 hot pixels found in step 1
[15:23:41.087] INFO: Collecting data for 5 seconds...
[15:23:46.105] INFO: Done with hot pixel readout
[15:23:58.140] INFO: PixTest:: pg_setup set to default.
[15:23:58.141] INFO: 9 hot pixels found in step 2
[15:23:59.136] INFO: Collecting data for 5 seconds...
[15:24:04.154] INFO: Done with hot pixel readout
[15:24:16.224] INFO: PixTest:: pg_setup set to default.
[15:24:16.224] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:24:16.225] INFO: 6 hot pixels found in step 3
[15:24:17.219] INFO: Collecting data for 5 seconds...
[15:24:22.238] INFO: Done with hot pixel readout
[15:24:34.304] INFO: PixTest:: pg_setup set to default.
[15:24:34.304] INFO: 4 hot pixels found in step 4
[15:24:35.299] INFO: Collecting data for 5 seconds...
[15:24:40.319] INFO: Done with hot pixel readout
[15:24:51.886] INFO: PixTest:: pg_setup set to default.
[15:24:51.886] INFO: 4 hot pixels found in step 5
[15:24:52.880] INFO: Collecting data for 5 seconds...
[15:24:57.897] INFO: Done with hot pixel readout
[15:25:09.767] INFO: PixTest:: pg_setup set to default.
[15:25:09.767] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:25:09.768] INFO: 4 hot pixels found in step 6
[15:25:10.762] INFO: Collecting data for 5 seconds...
[15:25:15.780] INFO: Done with hot pixel readout
[15:25:27.311] INFO: PixTest:: pg_setup set to default.
[15:25:27.312] INFO: 3 hot pixels found in step 7
[15:25:28.306] INFO: Collecting data for 5 seconds...
[15:25:33.325] INFO: Done with hot pixel readout
[15:25:44.989] INFO: PixTest:: pg_setup set to default.
[15:25:44.989] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:25:44.990] INFO: 7 hot pixels found in step 8
[15:25:45.984] INFO: Collecting data for 5 seconds...
[15:25:50.002] INFO: Done with hot pixel readout
[15:26:03.094] INFO: PixTest:: pg_setup set to default.
[15:26:03.095] INFO: 3 hot pixels found in step 9
[15:26:04.089] INFO: Collecting data for 5 seconds...
[15:26:09.108] INFO: Done with hot pixel readout
[15:26:21.465] INFO: PixTest:: pg_setup set to default.
[15:26:21.466] INFO: 4 hot pixels found in step 10
[15:26:22.459] INFO: Collecting data for 5 seconds...
[15:26:27.476] INFO: Done with hot pixel readout
[15:26:39.630] INFO: PixTest:: pg_setup set to default.
[15:26:39.630] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:26:39.631] INFO: 5 hot pixels found in step 11
[15:26:40.625] INFO: Collecting data for 5 seconds...
[15:26:45.644] INFO: Done with hot pixel readout
[15:26:57.861] INFO: PixTest:: pg_setup set to default.
[15:26:57.861] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[15:26:57.862] INFO: 2 hot pixels found in step 12
[15:26:58.856] INFO: Collecting data for 5 seconds...
[15:27:03.875] INFO: Done with hot pixel readout
[15:27:15.005] INFO: PixTest:: pg_setup set to default.
[15:27:15.006] INFO: 4 hot pixels found in step 13
[15:27:16.000] INFO: Collecting data for 5 seconds...
[15:27:22.019] INFO: Done with hot pixel readout
[15:27:34.172] INFO: PixTest:: pg_setup set to default.
[15:27:34.173] INFO: 2 hot pixels found in step 14
[15:27:34.211] INFO: 2 hot pixels could not be trimmed and have been masked.
[15:27:34.215] INFO: PixTest::trimHotPixels() done
[15:27:34.215] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C0.dat
[15:27:34.221] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C1.dat
[15:27:34.226] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C2.dat
[15:27:34.232] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C3.dat
[15:27:34.237] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C4.dat
[15:27:34.242] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C5.dat
[15:27:34.248] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C6.dat
[15:27:34.253] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C7.dat
[15:27:34.258] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C8.dat
[15:27:34.264] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C9.dat
[15:27:34.269] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C10.dat
[15:27:34.274] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C11.dat
[15:27:34.280] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C12.dat
[15:27:34.285] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C13.dat
[15:27:34.290] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C14.dat
[15:27:34.296] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C15.dat
[15:27:34.301] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//defaultMaskFile.dat
[15:27:34.311] INFO: enter test to run
[15:28:58.451] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[15:28:58.451] INFO: running: highrate
[15:28:58.456] INFO: ----------------------------------------------------------------------
[15:28:58.456] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[15:28:58.456] INFO: ----------------------------------------------------------------------
[15:28:58.456] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[15:28:58.456] INFO: edge/corner pixel THR is adjusted
[15:28:58.456] INFO: PixTestHighRate::trimHotPixels: step 0...
[15:28:59.414] INFO: Collecting data for 1 seconds...
[15:29:00.418] INFO: Done with hot pixel readout
[15:29:04.543] INFO: PixTest:: pg_setup set to default.
[15:29:04.544] INFO: 0 hot pixels found in step 0
[15:29:04.549] INFO: 0 hot pixels could not be trimmed and have been masked.
[15:29:04.637] INFO: PixTest::trimHotPixels() done
[15:29:04.638] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C0.dat
[15:29:04.648] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C1.dat
[15:29:04.653] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C2.dat
[15:29:04.658] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C3.dat
[15:29:04.664] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C4.dat
[15:29:04.669] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C5.dat
[15:29:04.675] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C6.dat
[15:29:04.680] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C7.dat
[15:29:04.686] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C8.dat
[15:29:04.691] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C9.dat
[15:29:04.697] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C10.dat
[15:29:04.702] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C11.dat
[15:29:04.708] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C12.dat
[15:29:04.714] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C13.dat
[15:29:04.719] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C14.dat
[15:29:04.724] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//trimParameters35_C15.dat
[15:29:04.730] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-1-14_FPIXTest-17C-FNAL-161003-1214-150V_2016-10-03_12h14m_1475514868/000_FPIXTest_p17//defaultMaskFile.dat
[15:29:04.739] INFO: enter test to run
[15:29:38.763] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[15:29:38.763] INFO: running: xray
[15:29:38.764] INFO: ----------------------------------------------------------------------
[15:29:38.764] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:29:38.764] INFO: ----------------------------------------------------------------------
[15:29:39.735] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:29:50.952] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[15:30:20.241] INFO: Resuming triggers.
[15:30:31.560] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[15:31:01.016] INFO: Resuming triggers.
[15:31:12.233] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[15:31:41.588] INFO: Resuming triggers.
[15:31:52.806] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[15:32:21.899] INFO: Resuming triggers.
[15:32:33.116] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[15:33:02.337] INFO: Resuming triggers.
[15:33:13.554] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[15:33:42.925] INFO: Resuming triggers.
[15:33:54.139] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[15:34:23.366] INFO: Resuming triggers.
[15:34:34.580] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[15:35:03.877] INFO: Resuming triggers.
[15:35:14.472] INFO: data taking finished, elapsed time: 100 seconds.
[15:35:42.217] INFO: PixTest:: pg_setup set to default.
[15:35:42.220] INFO: PixTestXray::doPhRun() done
[15:35:42.466] INFO: enter test to run
[15:36:12.664] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[15:36:12.664] INFO: running: xray
[15:36:12.665] INFO: ----------------------------------------------------------------------
[15:36:12.665] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[15:36:12.665] INFO: ----------------------------------------------------------------------
[15:36:13.636] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[15:36:20.103] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[15:36:51.034] INFO: Resuming triggers.
[15:36:57.501] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[15:37:28.368] INFO: Resuming triggers.
[15:37:34.835] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[15:38:05.543] INFO: Resuming triggers.
[15:38:12.013] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[15:38:41.734] INFO: Resuming triggers.
[15:38:48.205] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[15:39:19.801] INFO: Resuming triggers.
[15:39:26.271] INFO: run duration 38 seconds, buffer almost full (81%), pausing triggers.
[15:39:57.824] INFO: Resuming triggers.
[15:40:04.295] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[15:40:35.402] INFO: Resuming triggers.
[15:40:41.873] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[15:41:12.159] INFO: Resuming triggers.
[15:41:18.631] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[15:41:48.798] INFO: Resuming triggers.
[15:41:55.272] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[15:42:25.453] INFO: Resuming triggers.
[15:42:31.928] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[15:43:01.975] INFO: Resuming triggers.
[15:43:08.452] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[15:43:38.677] INFO: Resuming triggers.
[15:43:45.154] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[15:44:15.303] INFO: Resuming triggers.
[15:44:21.778] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[15:44:52.241] INFO: Resuming triggers.
[15:44:58.717] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[15:45:28.738] INFO: Resuming triggers.
[15:45:32.012] INFO: data taking finished, elapsed time: 100 seconds.
[15:45:47.467] INFO: PixTest:: pg_setup set to default.
[15:45:47.470] INFO: PixTestXray::doPhRun() done
[15:45:47.619] INFO: enter test to run
[15:47:27.587] INFO: test: HighRate no parameter change
[15:47:27.587] INFO: running: highrate
[15:47:27.601] INFO: ----------------------------------------------------------------------
[15:47:27.601] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[15:47:27.601] INFO: ----------------------------------------------------------------------
[15:47:27.755] INFO: Expecting 768 events.
[15:47:28.889] INFO: 768 events read in total (419ms).
[15:47:28.889] INFO: Test took 1268ms.
[15:47:29.692] INFO: Expecting 41600 events.
[15:47:32.793] INFO: 41600 events read in total (2575ms).
[15:47:32.794] INFO: Test took 3897ms.
[15:47:32.828] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:33.552] INFO: Expecting 41600 events.
[15:47:36.736] INFO: 41600 events read in total (2657ms).
[15:47:36.737] INFO: Test took 3890ms.
[15:47:36.772] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:37.497] INFO: Expecting 41600 events.
[15:47:40.729] INFO: 41600 events read in total (2706ms).
[15:47:40.730] INFO: Test took 3939ms.
[15:47:40.765] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:41.488] INFO: Expecting 41600 events.
[15:47:44.735] INFO: 41600 events read in total (2720ms).
[15:47:44.736] INFO: Test took 3952ms.
[15:47:44.772] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:45.491] INFO: Expecting 41600 events.
[15:47:48.746] INFO: 41600 events read in total (2718ms).
[15:47:48.747] INFO: Test took 3955ms.
[15:47:48.782] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:49.505] INFO: Expecting 41600 events.
[15:47:52.756] INFO: 41600 events read in total (2724ms).
[15:47:52.757] INFO: Test took 3956ms.
[15:47:52.793] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:53.515] INFO: Expecting 41600 events.
[15:47:56.764] INFO: 41600 events read in total (2722ms).
[15:47:56.765] INFO: Test took 3953ms.
[15:47:56.800] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:47:57.525] INFO: Expecting 41600 events.
[15:48:00.783] INFO: 41600 events read in total (2732ms).
[15:48:00.784] INFO: Test took 3965ms.
[15:48:00.819] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:01.543] INFO: Expecting 41600 events.
[15:48:04.800] INFO: 41600 events read in total (2730ms).
[15:48:04.801] INFO: Test took 3964ms.
[15:48:04.837] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:05.557] INFO: Expecting 41600 events.
[15:48:08.822] INFO: 41600 events read in total (2738ms).
[15:48:08.823] INFO: Test took 3968ms.
[15:48:08.859] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:09.580] INFO: Expecting 41600 events.
[15:48:12.841] INFO: 41600 events read in total (2734ms).
[15:48:12.842] INFO: Test took 3964ms.
[15:48:12.877] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:13.598] INFO: Expecting 41600 events.
[15:48:16.852] INFO: 41600 events read in total (2727ms).
[15:48:16.853] INFO: Test took 3956ms.
[15:48:16.890] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:17.613] INFO: Expecting 41600 events.
[15:48:20.833] INFO: 41600 events read in total (2693ms).
[15:48:20.834] INFO: Test took 3926ms.
[15:48:20.869] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:21.590] INFO: Expecting 41600 events.
[15:48:24.845] INFO: 41600 events read in total (2728ms).
[15:48:24.846] INFO: Test took 3958ms.
[15:48:24.882] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:25.605] INFO: Expecting 41600 events.
[15:48:28.862] INFO: 41600 events read in total (2730ms).
[15:48:28.863] INFO: Test took 3962ms.
[15:48:28.898] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:29.620] INFO: Expecting 41600 events.
[15:48:32.868] INFO: 41600 events read in total (2721ms).
[15:48:32.869] INFO: Test took 3952ms.
[15:48:32.906] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:33.625] INFO: Expecting 41600 events.
[15:48:36.901] INFO: 41600 events read in total (2749ms).
[15:48:36.902] INFO: Test took 3976ms.
[15:48:36.939] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:37.657] INFO: Expecting 41600 events.
[15:48:40.961] INFO: 41600 events read in total (2778ms).
[15:48:40.962] INFO: Test took 4003ms.
[15:48:40.999] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:41.702] INFO: Expecting 41600 events.
[15:48:44.928] INFO: 41600 events read in total (2699ms).
[15:48:44.929] INFO: Test took 3912ms.
[15:48:44.964] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:45.682] INFO: Expecting 41600 events.
[15:48:48.679] INFO: 41600 events read in total (2470ms).
[15:48:48.681] INFO: Test took 3698ms.
[15:48:48.718] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:48:49.088] INFO: enter test to run
[15:48:55.171] INFO: test: HighRate no parameter change
[15:48:55.171] INFO: running: highrate
[15:48:55.172] INFO: ----------------------------------------------------------------------
[15:48:55.172] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:48:55.172] INFO: ----------------------------------------------------------------------
[15:48:55.789] INFO: Expecting 208000 events.
[15:49:07.757] INFO: 208000 events read in total (11441ms).
[15:49:07.761] INFO: Test took 12582ms.
[15:49:07.916] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:08.173] INFO: number of dead pixels (per ROC): 0 0 0 2 0 0 0 0 0 0 0 0 0 0 0 0
[15:49:08.173] INFO: number of red-efficiency pixels: 66 51 93 179 148 145 139 77 103 165 130 113 95 76 22 29
[15:49:08.173] INFO: number of X-ray hits detected: 63635 41735 67470 109822 109974 115569 116731 81501 82486 113365 111448 93399 93277 58671 21978 25939
[15:49:08.173] 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:49:08.173] INFO: number of Vcal hits detected: 207933 207948 207905 207718 207845 207852 207859 207922 207895 207831 207868 207883 207905 207921 207978 207971
[15:49:08.173] 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 99.9 100.0 100.0 100.0 100.0
[15:49:08.173] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0
[15:49:08.173] INFO: X-ray hit rate [MHz/cm2]: 18.7 12.2 19.8 32.2 32.2 33.9 34.2 23.9 24.2 33.2 32.7 27.4 27.3 17.2 6.4 7.6
[15:49:08.173] INFO: PixTestHighRate::doXPixelAlive() done
[15:49:08.219] INFO: PixTest:: pg_setup set to default.
[15:49:08.235] INFO: enter test to run
[15:49:38.266] INFO: test: HighRate no parameter change
[15:49:38.266] INFO: running: highrate
[15:49:38.268] INFO: ----------------------------------------------------------------------
[15:49:38.268] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:49:38.268] INFO: ----------------------------------------------------------------------
[15:49:38.885] INFO: Expecting 208000 events.
[15:49:52.766] INFO: 208000 events read in total (13354ms).
[15:49:52.771] INFO: Test took 14494ms.
[15:49:53.123] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:49:53.431] INFO: number of dead pixels (per ROC): 0 0 0 2 0 0 0 0 0 0 0 0 0 0 0 0
[15:49:53.431] INFO: number of red-efficiency pixels: 211 121 281 530 502 343 587 265 288 514 352 366 318 234 66 72
[15:49:53.431] INFO: number of X-ray hits detected: 131479 85840 138890 225128 225931 236189 241059 167515 169984 233529 229858 191862 192023 119097 44809 54019
[15:49:53.431] 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:49:53.431] INFO: number of Vcal hits detected: 207779 207870 207696 207325 207452 207635 207351 207717 207691 207435 207623 207605 207657 207741 207931 207928
[15:49:53.431] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.7 99.8 99.8 99.7 99.9 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[15:49:53.431] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.7 99.7 99.8 99.7 99.9 99.9 99.7 99.8 99.8 99.8 99.9 100.0 100.0
[15:49:53.431] INFO: X-ray hit rate [MHz/cm2]: 38.5 25.2 40.7 66.0 66.2 69.2 70.7 49.1 49.8 68.4 67.4 56.2 56.3 34.9 13.1 15.8
[15:49:53.431] INFO: PixTestHighRate::doXPixelAlive() done
[15:49:53.478] INFO: PixTest:: pg_setup set to default.
[15:49:53.493] INFO: enter test to run
[15:50:16.642] INFO: test: HighRate no parameter change
[15:50:16.642] INFO: running: highrate
[15:50:16.643] INFO: ----------------------------------------------------------------------
[15:50:16.643] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[15:50:16.643] INFO: ----------------------------------------------------------------------
[15:50:17.281] INFO: Expecting 208000 events.
[15:50:33.036] INFO: 208000 events read in total (15228ms).
[15:50:33.045] INFO: Test took 16391ms.
[15:50:33.531] INFO: Fetched DAQ statistics. Counters are being reset now.
[15:50:33.902] INFO: number of dead pixels (per ROC): 0 0 0 2 0 0 0 0 0 0 0 0 0 0 0 0
[15:50:33.902] INFO: number of red-efficiency pixels: 358 246 648 1235 1183 916 1250 567 646 1311 877 851 631 574 109 134
[15:50:33.902] INFO: number of X-ray hits detected: 201733 131918 213879 344337 345519 360940 368139 256549 261918 357242 351434 293085 295132 184189 69237 82849
[15:50:33.902] 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:50:33.902] INFO: number of Vcal hits detected: 207591 207730 207148 206317 206494 206902 206341 207331 207227 206268 206952 206944 207281 207273 207883 207859
[15:50:33.902] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.3 99.3 99.5 99.3 99.7 99.7 99.2 99.5 99.6 99.7 99.7 99.9 99.9
[15:50:33.902] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.6 99.2 99.3 99.5 99.2 99.7 99.6 99.2 99.5 99.5 99.7 99.7 99.9 99.9
[15:50:33.902] INFO: X-ray hit rate [MHz/cm2]: 59.1 38.7 62.7 100.9 101.3 105.8 107.9 75.2 76.8 104.7 103.0 85.9 86.5 54.0 20.3 24.3
[15:50:33.902] INFO: PixTestHighRate::doXPixelAlive() done
[15:50:33.947] INFO: PixTest:: pg_setup set to default.
[15:50:33.963] INFO: enter test to run
[15:51:14.754] INFO: test: exit no parameter change
[15:51:15.290] QUIET: Connection to board 33 closed.
[15:51:15.304] INFO: pXar: this is the end, my friend