[13:41:15.065] INFO: *** Welcome to pxar ***
[13:41:15.065] INFO: *** Today: 2016/04/18
[13:41:15.087] INFO: *** Version: v1.9.0-796-gef167-dirty
[13:41:15.087] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//dacParameters35_C15.dat
[13:41:15.088] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:41:15.088] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//defaultMaskFile.dat
[13:41:15.088] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C15.dat
[13:41:15.162] INFO: clk: 4
[13:41:15.162] INFO: ctr: 4
[13:41:15.162] INFO: sda: 19
[13:41:15.162] INFO: tin: 9
[13:41:15.162] INFO: level: 15
[13:41:15.162] INFO: triggerdelay: 0
[13:41:15.162] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[13:41:15.162] INFO: Log level: INFO
[13:41:15.180] QUIET: Connection to board DTB_WREKRL opened.
[13:41:15.184] 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:
------------------------------------------------------
[13:41:15.187] INFO: RPC call hashes of host and DTB match: 398089610
[13:41:16.716] INFO: DUT info:
[13:41:16.716] INFO: The DUT currently contains the following objects:
[13:41:16.716] INFO: 2 TBM Cores tbm08c (2 ON)
[13:41:16.716] INFO: TBM Core alpha (0): 7 registers set
[13:41:16.716] INFO: TBM Core beta (1): 7 registers set
[13:41:16.716] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:41:16.716] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.716] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:16.717] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:41:17.120] INFO: enter 'restricted' command line mode
[13:41:17.120] INFO: enter test to run
[13:41:23.507] INFO: test: timing no parameter change
[13:41:23.507] INFO: running: timing
[13:41:23.536] INFO: ######################################################################
[13:41:23.536] INFO: PixTestTiming::doTest()
[13:41:23.539] INFO: ######################################################################
[13:41:23.540] INFO: ----------------------------------------------------------------------
[13:41:23.540] INFO: PixTestTiming::TBMPhaseScan()
[13:41:23.540] INFO: ----------------------------------------------------------------------
[13:49:29.389] INFO: TBM Phase Settings: 224
[13:49:29.389] INFO: 400MHz Phase: 0
[13:49:29.389] INFO: 160MHz Phase: 7
[13:49:29.389] INFO: Functional Phase Area: 4
[13:49:29.398] INFO: Test took 485859 ms.
[13:49:29.398] INFO: PixTestTiming::TBMPhaseScan() done.
[13:49:29.398] INFO: ----------------------------------------------------------------------
[13:49:29.398] INFO: PixTestTiming::ROCDelayScan()
[13:49:29.398] INFO: ----------------------------------------------------------------------
[13:52:31.682] INFO: ROC Delay Settings: 228
[13:52:31.682] INFO: ROC Header-Trailer/Token Delay: 11
[13:52:31.682] INFO: ROC Port 0 Delay: 4
[13:52:31.682] INFO: ROC Port 1 Delay: 4
[13:52:31.682] INFO: Functional ROC Area: 3
[13:52:31.686] INFO: Test took 182288 ms.
[13:52:31.686] INFO: PixTestTiming::ROCDelayScan() done.
[13:52:31.686] INFO: ----------------------------------------------------------------------
[13:52:31.686] INFO: PixTestTiming::TimingTest()
[13:52:31.686] INFO: ----------------------------------------------------------------------
[13:52:47.827] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:53:02.815] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:53:17.779] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:53:32.781] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:53:47.747] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:54:02.726] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:54:17.723] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:54:32.709] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:54:47.673] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:55:02.688] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:55:03.069] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:55:03.088] INFO: ----------------------------------------------------------------------
[13:55:03.088] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[13:55:03.088] INFO: ----------------------------------------------------------------------
[13:55:03.088] INFO: ----------------------------------------------------------------------
[13:55:03.088] INFO: Read back bit status: 1
[13:55:03.088] INFO: ----------------------------------------------------------------------
[13:55:03.088] INFO: ----------------------------------------------------------------------
[13:55:03.088] INFO: Timings are good!
[13:55:03.088] INFO: ----------------------------------------------------------------------
[13:55:03.088] INFO: Test took 151402 ms.
[13:55:03.088] INFO: PixTestTiming::TimingTest() done.
[13:55:03.105] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//tbmParameters_C0a.dat
[13:55:03.105] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:55:03.105] INFO: PixTestTiming::doTest took 819574 ms.
[13:55:03.105] INFO: PixTestTiming::doTest() done
[13:55:03.105] INFO: Write out TBMPhaseScan_0_V0
[13:55:03.136] INFO: Write out TBMPhaseScan_1_V0
[13:55:03.136] INFO: Write out CombinedTBMPhaseScan_V0
[13:55:03.171] INFO: Write out ROCDelayScan3_V0
[13:55:03.172] INFO: enter test to run
[13:57:48.156] INFO: test: PixelAlive no parameter change
[13:57:48.156] INFO: running: pixelalive
[13:57:48.161] INFO: ----------------------------------------------------------------------
[13:57:48.161] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[13:57:48.161] INFO: ----------------------------------------------------------------------
[13:57:48.479] INFO: Expecting 41600 events.
[13:57:52.817] INFO: 41600 events read in total (3623ms).
[13:57:52.818] INFO: Test took 4655ms.
[13:57:52.824] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:57:53.219] INFO: PixTestAlive::aliveTest() done
[13:57:53.220] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0
[13:57:53.223] INFO: enter test to run
[13:58:18.940] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:58:18.940] INFO: running: highrate
[13:58:18.940] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:58:19.093] INFO: ----------------------------------------------------------------------
[13:58:19.093] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:58:19.093] INFO: ----------------------------------------------------------------------
[13:58:19.093] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:58:19.093] INFO: edge/corner pixel THR is adjusted
[13:58:19.093] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:58:20.050] INFO: Collecting data for 5 seconds...
[13:58:25.067] INFO: Done with hot pixel readout
[13:58:37.281] INFO: PixTest:: pg_setup set to default.
[13:58:37.282] INFO: 6 hot pixels found in step 0
[13:58:38.279] INFO: Collecting data for 5 seconds...
[13:58:43.297] INFO: Done with hot pixel readout
[13:58:55.510] INFO: PixTest:: pg_setup set to default.
[13:58:55.510] INFO: 5 hot pixels found in step 1
[13:58:56.508] INFO: Collecting data for 5 seconds...
[13:59:01.526] INFO: Done with hot pixel readout
[13:59:13.666] INFO: PixTest:: pg_setup set to default.
[13:59:13.667] INFO: 5 hot pixels found in step 2
[13:59:14.663] INFO: Collecting data for 5 seconds...
[13:59:19.680] INFO: Done with hot pixel readout
[13:59:31.883] INFO: PixTest:: pg_setup set to default.
[13:59:31.883] INFO: 6 hot pixels found in step 3
[13:59:32.879] INFO: Collecting data for 5 seconds...
[13:59:37.896] INFO: Done with hot pixel readout
[13:59:50.098] INFO: PixTest:: pg_setup set to default.
[13:59:50.099] INFO: 4 hot pixels found in step 4
[13:59:51.095] INFO: Collecting data for 5 seconds...
[13:59:56.111] INFO: Done with hot pixel readout
[14:00:08.261] INFO: PixTest:: pg_setup set to default.
[14:00:08.262] INFO: 4 hot pixels found in step 5
[14:00:09.260] INFO: Collecting data for 5 seconds...
[14:00:14.277] INFO: Done with hot pixel readout
[14:00:26.457] INFO: PixTest:: pg_setup set to default.
[14:00:26.458] INFO: 4 hot pixels found in step 6
[14:00:27.454] INFO: Collecting data for 5 seconds...
[14:00:32.471] INFO: Done with hot pixel readout
[14:00:44.696] INFO: PixTest:: pg_setup set to default.
[14:00:44.697] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:00:44.697] INFO: 4 hot pixels found in step 7
[14:00:45.693] INFO: Collecting data for 5 seconds...
[14:00:50.710] INFO: Done with hot pixel readout
[14:01:00.714] INFO: PixTest:: pg_setup set to default.
[14:01:00.714] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:01:00.715] INFO: 8 hot pixels found in step 8
[14:01:01.711] INFO: Collecting data for 5 seconds...
[14:01:06.722] INFO: Done with hot pixel readout
[14:01:17.280] INFO: PixTest:: pg_setup set to default.
[14:01:17.280] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[14:01:17.281] INFO: 4 hot pixels found in step 9
[14:01:18.277] INFO: Collecting data for 5 seconds...
[14:01:23.294] INFO: Done with hot pixel readout
[14:01:35.472] INFO: PixTest:: pg_setup set to default.
[14:01:35.473] INFO: 6 hot pixels found in step 10
[14:01:36.470] INFO: Collecting data for 5 seconds...
[14:01:41.487] INFO: Done with hot pixel readout
[14:01:53.746] INFO: PixTest:: pg_setup set to default.
[14:01:53.747] INFO: 6 hot pixels found in step 11
[14:01:54.743] INFO: Collecting data for 5 seconds...
[14:01:59.760] INFO: Done with hot pixel readout
[14:02:11.916] INFO: PixTest:: pg_setup set to default.
[14:02:11.917] INFO: 5 hot pixels found in step 12
[14:02:12.913] INFO: Collecting data for 5 seconds...
[14:02:17.930] INFO: Done with hot pixel readout
[14:02:30.166] INFO: PixTest:: pg_setup set to default.
[14:02:30.167] INFO: 9 hot pixels found in step 13
[14:02:31.163] INFO: Collecting data for 5 seconds...
[14:02:36.180] INFO: Done with hot pixel readout
[14:02:48.392] INFO: PixTest:: pg_setup set to default.
[14:02:48.392] INFO: 3 hot pixels found in step 14
[14:02:48.432] INFO: 3 hot pixels could not be trimmed and have been masked.
[14:02:48.435] INFO: PixTest::trimHotPixels() done
[14:02:48.435] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C0.dat
[14:02:48.441] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C1.dat
[14:02:48.448] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C2.dat
[14:02:48.453] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C3.dat
[14:02:48.458] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C4.dat
[14:02:48.464] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C5.dat
[14:02:48.469] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C6.dat
[14:02:48.474] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C7.dat
[14:02:48.479] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C8.dat
[14:02:48.484] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C9.dat
[14:02:48.489] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C10.dat
[14:02:48.495] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C11.dat
[14:02:48.500] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C12.dat
[14:02:48.505] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C13.dat
[14:02:48.510] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C14.dat
[14:02:48.515] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C15.dat
[14:02:48.520] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//defaultMaskFile.dat
[14:02:48.530] INFO: enter test to run
[14:05:26.417] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[14:05:26.417] INFO: running: highrate
[14:05:26.421] INFO: ----------------------------------------------------------------------
[14:05:26.421] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[14:05:26.421] INFO: ----------------------------------------------------------------------
[14:05:26.421] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[14:05:26.421] INFO: edge/corner pixel THR is adjusted
[14:05:26.421] INFO: PixTestHighRate::trimHotPixels: step 0...
[14:05:27.379] INFO: Collecting data for 1 seconds...
[14:05:28.383] INFO: Done with hot pixel readout
[14:05:32.679] INFO: PixTest:: pg_setup set to default.
[14:05:32.680] INFO: 0 hot pixels found in step 0
[14:05:32.685] INFO: 0 hot pixels could not be trimmed and have been masked.
[14:05:32.769] INFO: PixTest::trimHotPixels() done
[14:05:32.769] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C0.dat
[14:05:32.779] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C1.dat
[14:05:32.784] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C2.dat
[14:05:32.789] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C3.dat
[14:05:32.794] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C4.dat
[14:05:32.800] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C5.dat
[14:05:32.805] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C6.dat
[14:05:32.810] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C7.dat
[14:05:32.815] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C8.dat
[14:05:32.820] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C9.dat
[14:05:32.825] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C10.dat
[14:05:32.831] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C11.dat
[14:05:32.836] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C12.dat
[14:05:32.841] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C13.dat
[14:05:32.846] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C14.dat
[14:05:32.852] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//trimParameters35_C15.dat
[14:05:32.857] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-2-16_FPIXTest-17C-FNAL-160415-0858_2016-04-15_08h58m_1460728701/000_FPIXTest_p17//defaultMaskFile.dat
[14:05:32.867] INFO: enter test to run
[14:05:56.080] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[14:05:56.080] INFO: running: xray
[14:05:56.081] INFO: ----------------------------------------------------------------------
[14:05:56.081] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:05:56.081] INFO: ----------------------------------------------------------------------
[14:05:57.044] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:06:08.016] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[14:06:37.470] INFO: Resuming triggers.
[14:06:48.444] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[14:07:17.946] INFO: Resuming triggers.
[14:07:28.924] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[14:07:58.446] INFO: Resuming triggers.
[14:08:09.428] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[14:08:38.939] INFO: Resuming triggers.
[14:08:49.918] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[14:09:19.427] INFO: Resuming triggers.
[14:09:30.408] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[14:09:59.825] INFO: Resuming triggers.
[14:10:10.804] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[14:10:40.260] INFO: Resuming triggers.
[14:10:51.237] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[14:11:16.579] INFO: Resuming triggers.
[14:11:27.557] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[14:11:56.884] INFO: Resuming triggers.
[14:11:58.425] INFO: data taking finished, elapsed time: 100 seconds.
[14:12:02.946] INFO: PixTest:: pg_setup set to default.
[14:12:02.950] INFO: PixTestXray::doPhRun() done
[14:12:03.128] INFO: enter test to run
[14:12:32.406] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[14:12:32.406] INFO: running: xray
[14:12:32.407] INFO: ----------------------------------------------------------------------
[14:12:32.407] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[14:12:32.407] INFO: ----------------------------------------------------------------------
[14:12:33.381] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[14:12:39.397] INFO: run duration 5 seconds, buffer almost full (81%), pausing triggers.
[14:13:09.387] INFO: Resuming triggers.
[14:13:15.403] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[14:13:45.447] INFO: Resuming triggers.
[14:13:51.465] INFO: run duration 17 seconds, buffer almost full (81%), pausing triggers.
[14:14:21.455] INFO: Resuming triggers.
[14:14:27.471] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[14:14:57.527] INFO: Resuming triggers.
[14:15:03.537] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[14:15:33.569] INFO: Resuming triggers.
[14:15:39.585] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[14:16:09.613] INFO: Resuming triggers.
[14:16:15.630] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[14:16:45.640] INFO: Resuming triggers.
[14:16:51.653] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[14:17:21.670] INFO: Resuming triggers.
[14:17:27.687] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[14:17:57.633] INFO: Resuming triggers.
[14:18:03.645] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[14:18:33.599] INFO: Resuming triggers.
[14:18:39.614] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[14:19:09.764] INFO: Resuming triggers.
[14:19:15.780] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[14:19:45.721] INFO: Resuming triggers.
[14:19:51.735] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[14:20:21.749] INFO: Resuming triggers.
[14:20:27.763] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[14:20:57.984] INFO: Resuming triggers.
[14:21:03.997] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[14:21:29.434] INFO: Resuming triggers.
[14:21:35.449] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[14:22:05.439] INFO: Resuming triggers.
[14:22:09.537] INFO: data taking finished, elapsed time: 100 seconds.
[14:22:30.380] INFO: PixTest:: pg_setup set to default.
[14:22:30.383] INFO: PixTestXray::doPhRun() done
[14:22:30.535] INFO: enter test to run
[14:24:12.656] INFO: test: HighRate no parameter change
[14:24:12.657] INFO: running: highrate
[14:24:12.658] INFO: ----------------------------------------------------------------------
[14:24:12.658] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[14:24:12.658] INFO: ----------------------------------------------------------------------
[14:24:12.798] INFO: Expecting 768 events.
[14:24:13.932] INFO: 768 events read in total (418ms).
[14:24:13.932] INFO: Test took 1268ms.
[14:24:14.735] INFO: Expecting 41600 events.
[14:24:17.869] INFO: 41600 events read in total (2607ms).
[14:24:17.870] INFO: Test took 3930ms.
[14:24:17.905] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:18.626] INFO: Expecting 41600 events.
[14:24:21.855] INFO: 41600 events read in total (2702ms).
[14:24:21.856] INFO: Test took 3933ms.
[14:24:21.893] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:22.610] INFO: Expecting 41600 events.
[14:24:25.865] INFO: 41600 events read in total (2728ms).
[14:24:25.866] INFO: Test took 3954ms.
[14:24:25.902] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:26.621] INFO: Expecting 41600 events.
[14:24:29.884] INFO: 41600 events read in total (2736ms).
[14:24:29.885] INFO: Test took 3963ms.
[14:24:29.921] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:30.640] INFO: Expecting 41600 events.
[14:24:33.892] INFO: 41600 events read in total (2725ms).
[14:24:33.893] INFO: Test took 3952ms.
[14:24:33.929] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:34.647] INFO: Expecting 41600 events.
[14:24:37.887] INFO: 41600 events read in total (2713ms).
[14:24:37.888] INFO: Test took 3939ms.
[14:24:37.924] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:38.642] INFO: Expecting 41600 events.
[14:24:41.921] INFO: 41600 events read in total (2752ms).
[14:24:41.922] INFO: Test took 3980ms.
[14:24:41.959] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:42.676] INFO: Expecting 41600 events.
[14:24:45.941] INFO: 41600 events read in total (2738ms).
[14:24:45.942] INFO: Test took 3964ms.
[14:24:45.978] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:46.696] INFO: Expecting 41600 events.
[14:24:49.960] INFO: 41600 events read in total (2737ms).
[14:24:49.961] INFO: Test took 3963ms.
[14:24:49.996] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:50.715] INFO: Expecting 41600 events.
[14:24:53.972] INFO: 41600 events read in total (2730ms).
[14:24:53.973] INFO: Test took 3958ms.
[14:24:54.008] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:54.732] INFO: Expecting 41600 events.
[14:24:58.005] INFO: 41600 events read in total (2747ms).
[14:24:58.006] INFO: Test took 3978ms.
[14:24:58.042] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:24:58.764] INFO: Expecting 41600 events.
[14:25:02.022] INFO: 41600 events read in total (2731ms).
[14:25:02.023] INFO: Test took 3961ms.
[14:25:02.059] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:25:02.780] INFO: Expecting 41600 events.
[14:25:06.040] INFO: 41600 events read in total (2734ms).
[14:25:06.041] INFO: Test took 3962ms.
[14:25:06.077] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:25:06.796] INFO: Expecting 41600 events.
[14:25:10.073] INFO: 41600 events read in total (2750ms).
[14:25:10.074] INFO: Test took 3977ms.
[14:25:10.110] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:25:10.828] INFO: Expecting 41600 events.
[14:25:14.092] INFO: 41600 events read in total (2737ms).
[14:25:14.093] INFO: Test took 3963ms.
[14:25:14.129] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:25:14.848] INFO: Expecting 41600 events.
[14:25:18.103] INFO: 41600 events read in total (2728ms).
[14:25:18.104] INFO: Test took 3957ms.
[14:25:18.141] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:25:18.862] INFO: Expecting 41600 events.
[14:25:22.131] INFO: 41600 events read in total (2742ms).
[14:25:22.132] INFO: Test took 3971ms.
[14:25:22.170] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:25:22.884] INFO: Expecting 41600 events.
[14:25:26.146] INFO: 41600 events read in total (2735ms).
[14:25:26.147] INFO: Test took 3957ms.
[14:25:26.185] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:25:26.903] INFO: Expecting 41600 events.
[14:25:30.128] INFO: 41600 events read in total (2699ms).
[14:25:30.129] INFO: Test took 3925ms.
[14:25:30.164] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:25:30.888] INFO: Expecting 41600 events.
[14:25:34.020] INFO: 41600 events read in total (2605ms).
[14:25:34.021] INFO: Test took 3837ms.
[14:25:34.056] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:25:34.410] INFO: enter test to run
[14:26:06.008] INFO: test: HighRate no parameter change
[14:26:06.008] INFO: running: highrate
[14:26:06.009] INFO: ----------------------------------------------------------------------
[14:26:06.009] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:26:06.009] INFO: ----------------------------------------------------------------------
[14:26:06.623] INFO: Expecting 208000 events.
[14:26:18.610] INFO: 208000 events read in total (11460ms).
[14:26:18.613] INFO: Test took 12596ms.
[14:26:18.765] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:26:19.021] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0
[14:26:19.021] INFO: number of red-efficiency pixels: 91 56 114 153 139 179 121 106 157 145 140 132 132 70 33 33
[14:26:19.021] INFO: number of X-ray hits detected: 67688 41959 74373 110507 117635 118920 120041 88018 89387 117149 107435 98324 99989 59194 23233 25979
[14:26:19.021] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:26:19.021] INFO: number of Vcal hits detected: 207907 207941 207883 207846 207857 207818 207876 207892 207743 207851 207856 207862 207867 207930 207967 207967
[14:26:19.021] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[14:26:19.021] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[14:26:19.021] INFO: X-ray hit rate [MHz/cm2]: 19.8 12.3 21.8 32.4 34.5 34.9 35.2 25.8 26.2 34.3 31.5 28.8 29.3 17.4 6.8 7.6
[14:26:19.021] INFO: PixTestHighRate::doXPixelAlive() done
[14:26:19.070] INFO: PixTest:: pg_setup set to default.
[14:26:19.080] INFO: enter test to run
[14:26:39.863] INFO: test: HighRate no parameter change
[14:26:39.863] INFO: running: highrate
[14:26:39.864] INFO: ----------------------------------------------------------------------
[14:26:39.865] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:26:39.865] INFO: ----------------------------------------------------------------------
[14:26:40.484] INFO: Expecting 208000 events.
[14:26:54.825] INFO: 208000 events read in total (13814ms).
[14:26:54.831] INFO: Test took 14958ms.
[14:26:55.182] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:26:55.502] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0
[14:26:55.502] INFO: number of red-efficiency pixels: 250 162 414 606 568 725 546 358 475 710 601 527 551 281 75 61
[14:26:55.502] INFO: number of X-ray hits detected: 155176 95588 168515 252515 268972 271692 274662 202350 207102 266255 246393 224732 228809 135288 53391 58682
[14:26:55.502] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:26:55.502] INFO: number of Vcal hits detected: 207735 207827 207516 207334 207375 207164 207392 207595 207370 207197 207330 207411 207390 207695 207924 207939
[14:26:55.502] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.6 99.7 99.8 99.8 99.6 99.7 99.7 99.7 99.9 100.0 100.0
[14:26:55.502] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.6 99.7 99.8 99.7 99.6 99.7 99.7 99.7 99.9 100.0 100.0
[14:26:55.502] INFO: X-ray hit rate [MHz/cm2]: 45.5 28.0 49.4 74.0 78.8 79.6 80.5 59.3 60.7 78.0 72.2 65.9 67.1 39.7 15.6 17.2
[14:26:55.502] INFO: PixTestHighRate::doXPixelAlive() done
[14:26:55.548] INFO: PixTest:: pg_setup set to default.
[14:26:55.560] INFO: enter test to run
[14:27:27.767] INFO: test: HighRate no parameter change
[14:27:27.767] INFO: running: highrate
[14:27:27.768] INFO: ----------------------------------------------------------------------
[14:27:27.768] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[14:27:27.768] INFO: ----------------------------------------------------------------------
[14:27:28.388] INFO: Expecting 208000 events.
[14:27:44.887] INFO: 208000 events read in total (15972ms).
[14:27:44.895] INFO: Test took 17118ms.
[14:27:45.422] INFO: Fetched DAQ statistics. Counters are being reset now.
[14:27:45.795] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0
[14:27:45.795] INFO: number of red-efficiency pixels: 530 287 851 1325 1261 1605 1237 726 950 1600 1287 1191 1174 576 105 115
[14:27:45.795] INFO: number of X-ray hits detected: 224445 139005 246317 367817 390683 395021 400162 293904 300465 387120 358842 327396 331561 197678 77764 85943
[14:27:45.795] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[14:27:45.795] INFO: number of Vcal hits detected: 207390 207684 206740 206245 206327 205735 206355 207095 206703 205772 206344 206478 206504 207252 207890 207881
[14:27:45.795] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.5 99.2 99.3 99.0 99.3 99.6 99.5 99.0 99.3 99.3 99.3 99.7 99.9 99.9
[14:27:45.795] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.4 99.2 99.2 98.9 99.2 99.6 99.4 98.9 99.2 99.3 99.3 99.6 99.9 99.9
[14:27:45.795] INFO: X-ray hit rate [MHz/cm2]: 65.8 40.7 72.2 107.8 114.5 115.8 117.3 86.1 88.1 113.5 105.2 96.0 97.2 57.9 22.8 25.2
[14:27:45.795] INFO: PixTestHighRate::doXPixelAlive() done
[14:27:45.845] INFO: PixTest:: pg_setup set to default.
[14:27:45.861] INFO: enter test to run
[14:27:55.183] INFO: test: exit no parameter change
[14:27:55.566] QUIET: Connection to board 33 closed.
[14:27:55.568] INFO: pXar: this is the end, my friend