[10:15:24.516] INFO: *** Welcome to pxar ***
[10:15:24.516] INFO: *** Today: 2016/04/29
[10:15:24.531] INFO: *** Version: v1.9.0-796-gef167-dirty
[10:15:24.531] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//dacParameters35_C15.dat
[10:15:24.531] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:15:24.532] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//defaultMaskFile.dat
[10:15:24.532] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C15.dat
[10:15:24.605] INFO: clk: 4
[10:15:24.605] INFO: ctr: 4
[10:15:24.605] INFO: sda: 19
[10:15:24.605] INFO: tin: 9
[10:15:24.605] INFO: level: 15
[10:15:24.605] INFO: triggerdelay: 0
[10:15:24.605] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[10:15:24.605] INFO: Log level: INFO
[10:15:24.623] QUIET: Connection to board DTB_WREKRL opened.
[10:15:24.626] 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:
------------------------------------------------------
[10:15:24.629] INFO: RPC call hashes of host and DTB match: 398089610
[10:15:26.156] INFO: DUT info:
[10:15:26.156] INFO: The DUT currently contains the following objects:
[10:15:26.156] INFO: 2 TBM Cores tbm08c (2 ON)
[10:15:26.156] INFO: TBM Core alpha (0): 7 registers set
[10:15:26.156] INFO: TBM Core beta (1): 7 registers set
[10:15:26.156] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[10:15:26.156] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.156] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.157] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[10:15:26.560] INFO: enter 'restricted' command line mode
[10:15:26.560] INFO: enter test to run
[10:15:27.790] INFO: test: timing no parameter change
[10:15:27.790] INFO: running: timing
[10:15:27.800] INFO: ######################################################################
[10:15:27.800] INFO: PixTestTiming::doTest()
[10:15:27.820] INFO: ######################################################################
[10:15:27.820] INFO: ----------------------------------------------------------------------
[10:15:27.820] INFO: PixTestTiming::TBMPhaseScan()
[10:15:27.820] INFO: ----------------------------------------------------------------------
[10:19:53.147] INFO: TBM Phase Settings: 248
[10:19:53.147] INFO: 400MHz Phase: 6
[10:19:53.147] INFO: 160MHz Phase: 7
[10:19:53.147] INFO: Functional Phase Area: 5
[10:19:53.157] INFO: Test took 265337 ms.
[10:19:53.157] INFO: PixTestTiming::TBMPhaseScan() done.
[10:19:53.158] INFO: ----------------------------------------------------------------------
[10:19:53.158] INFO: PixTestTiming::ROCDelayScan()
[10:19:53.158] INFO: ----------------------------------------------------------------------
[10:22:00.889] INFO: ROC Delay Settings: 228
[10:22:00.889] INFO: ROC Header-Trailer/Token Delay: 11
[10:22:00.889] INFO: ROC Port 0 Delay: 4
[10:22:00.889] INFO: ROC Port 1 Delay: 4
[10:22:00.889] INFO: Functional ROC Area: 5
[10:22:00.893] INFO: Test took 127736 ms.
[10:22:00.893] INFO: PixTestTiming::ROCDelayScan() done.
[10:22:00.893] INFO: ----------------------------------------------------------------------
[10:22:00.893] INFO: PixTestTiming::TimingTest()
[10:22:00.893] INFO: ----------------------------------------------------------------------
[10:22:17.056] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:22:32.028] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:22:47.002] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:23:01.969] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:23:16.930] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:23:31.895] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:23:46.874] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:01.838] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:16.825] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:31.810] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:32.187] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:24:32.206] INFO: ----------------------------------------------------------------------
[10:24:32.206] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[10:24:32.206] INFO: ----------------------------------------------------------------------
[10:24:32.206] INFO: ----------------------------------------------------------------------
[10:24:32.206] INFO: Read back bit status: 1
[10:24:32.206] INFO: ----------------------------------------------------------------------
[10:24:32.206] INFO: ----------------------------------------------------------------------
[10:24:32.206] INFO: Timings are good!
[10:24:32.206] INFO: ----------------------------------------------------------------------
[10:24:32.206] INFO: Test took 151313 ms.
[10:24:32.206] INFO: PixTestTiming::TimingTest() done.
[10:24:32.206] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0a.dat
[10:24:32.227] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:24:32.228] INFO: PixTestTiming::doTest took 544434 ms.
[10:24:32.228] INFO: PixTestTiming::doTest() done
[10:24:32.228] INFO: Write out TBMPhaseScan_0_V0
[10:24:32.258] INFO: Write out TBMPhaseScan_1_V0
[10:24:32.258] INFO: Write out CombinedTBMPhaseScan_V0
[10:24:32.297] INFO: Write out ROCDelayScan3_V0
[10:24:32.298] INFO: enter test to run
[10:25:01.962] INFO: test: PixelAlive no parameter change
[10:25:01.962] INFO: running: pixelalive
[10:25:01.966] INFO: ----------------------------------------------------------------------
[10:25:01.966] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[10:25:01.967] INFO: ----------------------------------------------------------------------
[10:25:02.288] INFO: Expecting 41600 events.
[10:25:06.240] INFO: 41600 events read in total (3236ms).
[10:25:06.241] INFO: Test took 4271ms.
[10:25:06.247] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:25:06.649] INFO: PixTestAlive::aliveTest() done
[10:25:06.649] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 1 0 0 0 0 2 3 0 0 0
[10:25:06.651] INFO: enter test to run
[10:25:22.954] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:25:22.954] INFO: running: highrate
[10:25:22.954] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:25:23.111] INFO: ----------------------------------------------------------------------
[10:25:23.111] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:25:23.111] INFO: ----------------------------------------------------------------------
[10:25:23.111] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:25:23.111] INFO: edge/corner pixel THR is adjusted
[10:25:23.111] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:25:24.069] INFO: Collecting data for 5 seconds...
[10:25:29.085] INFO: Done with hot pixel readout
[10:25:41.086] INFO: PixTest:: pg_setup set to default.
[10:25:41.087] INFO: 17 hot pixels found in step 0
[10:25:42.081] INFO: Collecting data for 5 seconds...
[10:25:47.097] INFO: Done with hot pixel readout
[10:25:59.094] INFO: PixTest:: pg_setup set to default.
[10:25:59.095] INFO: 18 hot pixels found in step 1
[10:26:00.090] INFO: Collecting data for 5 seconds...
[10:26:05.106] INFO: Done with hot pixel readout
[10:26:17.107] INFO: PixTest:: pg_setup set to default.
[10:26:17.108] INFO: 18 hot pixels found in step 2
[10:26:18.102] INFO: Collecting data for 5 seconds...
[10:26:23.118] INFO: Done with hot pixel readout
[10:26:35.098] INFO: PixTest:: pg_setup set to default.
[10:26:35.099] INFO: 17 hot pixels found in step 3
[10:26:36.093] INFO: Collecting data for 5 seconds...
[10:26:41.108] INFO: Done with hot pixel readout
[10:26:53.116] INFO: PixTest:: pg_setup set to default.
[10:26:53.117] INFO: 13 hot pixels found in step 4
[10:26:54.109] INFO: Collecting data for 5 seconds...
[10:26:59.126] INFO: Done with hot pixel readout
[10:27:11.135] INFO: PixTest:: pg_setup set to default.
[10:27:11.136] INFO: 11 hot pixels found in step 5
[10:27:12.130] INFO: Collecting data for 5 seconds...
[10:27:17.147] INFO: Done with hot pixel readout
[10:27:29.164] INFO: PixTest:: pg_setup set to default.
[10:27:29.165] INFO: 11 hot pixels found in step 6
[10:27:30.159] INFO: Collecting data for 5 seconds...
[10:27:35.176] INFO: Done with hot pixel readout
[10:27:47.188] INFO: PixTest:: pg_setup set to default.
[10:27:47.189] INFO: 12 hot pixels found in step 7
[10:27:48.182] INFO: Collecting data for 5 seconds...
[10:27:53.200] INFO: Done with hot pixel readout
[10:28:05.155] INFO: PixTest:: pg_setup set to default.
[10:28:05.156] INFO: 3 hot pixels found in step 8
[10:28:06.150] INFO: Collecting data for 5 seconds...
[10:28:11.166] INFO: Done with hot pixel readout
[10:28:23.178] INFO: PixTest:: pg_setup set to default.
[10:28:23.179] INFO: 3 hot pixels found in step 9
[10:28:24.174] INFO: Collecting data for 5 seconds...
[10:28:29.190] INFO: Done with hot pixel readout
[10:28:41.191] INFO: PixTest:: pg_setup set to default.
[10:28:41.192] INFO: 9 hot pixels found in step 10
[10:28:42.187] INFO: Collecting data for 5 seconds...
[10:28:47.203] INFO: Done with hot pixel readout
[10:28:59.225] INFO: PixTest:: pg_setup set to default.
[10:28:59.226] INFO: 3 hot pixels found in step 11
[10:29:00.220] INFO: Collecting data for 5 seconds...
[10:29:05.236] INFO: Done with hot pixel readout
[10:29:17.283] INFO: PixTest:: pg_setup set to default.
[10:29:17.284] INFO: 3 hot pixels found in step 12
[10:29:18.278] INFO: Collecting data for 5 seconds...
[10:29:23.294] INFO: Done with hot pixel readout
[10:29:35.357] INFO: PixTest:: pg_setup set to default.
[10:29:35.358] INFO: 3 hot pixels found in step 13
[10:29:36.353] INFO: Collecting data for 5 seconds...
[10:29:41.369] INFO: Done with hot pixel readout
[10:29:53.397] INFO: PixTest:: pg_setup set to default.
[10:29:53.398] INFO: 6 hot pixels found in step 14
[10:29:53.435] INFO: 6 hot pixels could not be trimmed and have been masked.
[10:29:53.439] INFO: PixTest::trimHotPixels() done
[10:29:53.439] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C0.dat
[10:29:53.445] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C1.dat
[10:29:53.451] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C2.dat
[10:29:53.457] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C3.dat
[10:29:53.462] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C4.dat
[10:29:53.468] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C5.dat
[10:29:53.473] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C6.dat
[10:29:53.478] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C7.dat
[10:29:53.484] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C8.dat
[10:29:53.489] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C9.dat
[10:29:53.495] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C10.dat
[10:29:53.500] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C11.dat
[10:29:53.506] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C12.dat
[10:29:53.511] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C13.dat
[10:29:53.517] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C14.dat
[10:29:53.523] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C15.dat
[10:29:53.529] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//defaultMaskFile.dat
[10:29:53.538] INFO: enter test to run
[10:30:43.248] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:30:43.248] INFO: running: highrate
[10:30:43.252] INFO: ----------------------------------------------------------------------
[10:30:43.252] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:30:43.252] INFO: ----------------------------------------------------------------------
[10:30:43.252] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:30:43.252] INFO: edge/corner pixel THR is adjusted
[10:30:43.252] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:30:44.210] INFO: Collecting data for 1 seconds...
[10:30:45.214] INFO: Done with hot pixel readout
[10:30:49.278] INFO: PixTest:: pg_setup set to default.
[10:30:49.279] INFO: 0 hot pixels found in step 0
[10:30:49.284] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:30:49.372] INFO: PixTest::trimHotPixels() done
[10:30:49.372] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C0.dat
[10:30:49.384] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C1.dat
[10:30:49.390] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C2.dat
[10:30:49.396] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C3.dat
[10:30:49.401] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C4.dat
[10:30:49.407] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C5.dat
[10:30:49.412] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C6.dat
[10:30:49.417] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C7.dat
[10:30:49.423] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C8.dat
[10:30:49.428] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C9.dat
[10:30:49.434] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C10.dat
[10:30:49.439] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C11.dat
[10:30:49.444] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C12.dat
[10:30:49.450] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C13.dat
[10:30:49.455] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C14.dat
[10:30:49.461] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//trimParameters35_C15.dat
[10:30:49.466] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-1-01_FPIXTest-17C-FNAL-160426-1157_2016-04-26_11h57m_1461689842/000_FPIXTest_p17//defaultMaskFile.dat
[10:30:49.477] INFO: enter test to run
[10:31:54.103] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:31:54.103] INFO: running: xray
[10:31:54.104] INFO: ----------------------------------------------------------------------
[10:31:54.104] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:31:54.104] INFO: ----------------------------------------------------------------------
[10:31:55.078] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:32:06.553] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[10:32:35.762] INFO: Resuming triggers.
[10:32:47.243] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[10:33:16.614] INFO: Resuming triggers.
[10:33:28.095] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[10:33:57.401] INFO: Resuming triggers.
[10:34:08.880] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[10:34:38.228] INFO: Resuming triggers.
[10:34:49.703] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[10:35:17.900] INFO: Resuming triggers.
[10:35:29.380] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[10:35:58.609] INFO: Resuming triggers.
[10:36:10.086] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[10:36:39.357] INFO: Resuming triggers.
[10:36:50.834] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[10:37:20.202] INFO: Resuming triggers.
[10:37:28.685] INFO: data taking finished, elapsed time: 100 seconds.
[10:37:50.543] INFO: PixTest:: pg_setup set to default.
[10:37:50.546] INFO: PixTestXray::doPhRun() done
[10:37:50.680] INFO: enter test to run
[10:39:02.084] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[10:39:02.084] INFO: running: xray
[10:39:02.085] INFO: ----------------------------------------------------------------------
[10:39:02.085] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:39:02.085] INFO: ----------------------------------------------------------------------
[10:39:03.049] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:39:09.642] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[10:39:39.691] INFO: Resuming triggers.
[10:39:46.286] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[10:40:16.297] INFO: Resuming triggers.
[10:40:22.889] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[10:40:52.930] INFO: Resuming triggers.
[10:40:59.527] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[10:41:29.545] INFO: Resuming triggers.
[10:41:36.140] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[10:42:06.302] INFO: Resuming triggers.
[10:42:12.900] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[10:42:42.924] INFO: Resuming triggers.
[10:42:49.518] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[10:43:19.594] INFO: Resuming triggers.
[10:43:26.190] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[10:43:56.265] INFO: Resuming triggers.
[10:44:02.858] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[10:44:32.852] INFO: Resuming triggers.
[10:44:39.441] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[10:45:09.539] INFO: Resuming triggers.
[10:45:16.132] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[10:45:41.246] INFO: Resuming triggers.
[10:45:47.836] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[10:46:17.881] INFO: Resuming triggers.
[10:46:24.472] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[10:46:54.514] INFO: Resuming triggers.
[10:47:01.102] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[10:47:31.131] INFO: Resuming triggers.
[10:47:37.723] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[10:48:07.745] INFO: Resuming triggers.
[10:48:09.166] INFO: data taking finished, elapsed time: 100 seconds.
[10:48:16.004] INFO: PixTest:: pg_setup set to default.
[10:48:16.007] INFO: PixTestXray::doPhRun() done
[10:48:16.157] INFO: enter test to run
[10:48:52.872] INFO: test: HighRate no parameter change
[10:48:52.872] INFO: running: highrate
[10:48:52.873] INFO: ----------------------------------------------------------------------
[10:48:52.874] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[10:48:52.874] INFO: ----------------------------------------------------------------------
[10:48:53.055] INFO: Expecting 768 events.
[10:48:54.187] INFO: 768 events read in total (417ms).
[10:48:54.188] INFO: Test took 1268ms.
[10:48:54.991] INFO: Expecting 41600 events.
[10:48:58.095] INFO: 41600 events read in total (2577ms).
[10:48:58.096] INFO: Test took 3902ms.
[10:48:58.130] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:48:58.860] INFO: Expecting 41600 events.
[10:49:02.069] INFO: 41600 events read in total (2682ms).
[10:49:02.070] INFO: Test took 3922ms.
[10:49:02.104] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:02.831] INFO: Expecting 41600 events.
[10:49:06.077] INFO: 41600 events read in total (2719ms).
[10:49:06.078] INFO: Test took 3956ms.
[10:49:06.112] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:06.837] INFO: Expecting 41600 events.
[10:49:10.084] INFO: 41600 events read in total (2720ms).
[10:49:10.085] INFO: Test took 3955ms.
[10:49:10.119] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:10.842] INFO: Expecting 41600 events.
[10:49:14.078] INFO: 41600 events read in total (2709ms).
[10:49:14.079] INFO: Test took 3941ms.
[10:49:14.114] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:14.834] INFO: Expecting 41600 events.
[10:49:18.089] INFO: 41600 events read in total (2728ms).
[10:49:18.090] INFO: Test took 3958ms.
[10:49:18.124] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:18.849] INFO: Expecting 41600 events.
[10:49:22.108] INFO: 41600 events read in total (2732ms).
[10:49:22.109] INFO: Test took 3967ms.
[10:49:22.143] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:22.866] INFO: Expecting 41600 events.
[10:49:26.105] INFO: 41600 events read in total (2712ms).
[10:49:26.106] INFO: Test took 3945ms.
[10:49:26.140] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:26.864] INFO: Expecting 41600 events.
[10:49:30.113] INFO: 41600 events read in total (2722ms).
[10:49:30.114] INFO: Test took 3956ms.
[10:49:30.148] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:30.873] INFO: Expecting 41600 events.
[10:49:34.131] INFO: 41600 events read in total (2731ms).
[10:49:34.132] INFO: Test took 3965ms.
[10:49:34.166] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:34.889] INFO: Expecting 41600 events.
[10:49:38.143] INFO: 41600 events read in total (2727ms).
[10:49:38.144] INFO: Test took 3959ms.
[10:49:38.178] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:38.903] INFO: Expecting 41600 events.
[10:49:42.149] INFO: 41600 events read in total (2719ms).
[10:49:42.150] INFO: Test took 3953ms.
[10:49:42.185] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:42.908] INFO: Expecting 41600 events.
[10:49:46.171] INFO: 41600 events read in total (2736ms).
[10:49:46.172] INFO: Test took 3968ms.
[10:49:46.206] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:46.932] INFO: Expecting 41600 events.
[10:49:50.178] INFO: 41600 events read in total (2719ms).
[10:49:50.179] INFO: Test took 3954ms.
[10:49:50.213] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:50.938] INFO: Expecting 41600 events.
[10:49:54.198] INFO: 41600 events read in total (2733ms).
[10:49:54.199] INFO: Test took 3968ms.
[10:49:54.233] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:54.958] INFO: Expecting 41600 events.
[10:49:58.228] INFO: 41600 events read in total (2743ms).
[10:49:58.229] INFO: Test took 3977ms.
[10:49:58.263] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:49:58.987] INFO: Expecting 41600 events.
[10:50:02.203] INFO: 41600 events read in total (2689ms).
[10:50:02.204] INFO: Test took 3923ms.
[10:50:02.238] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:50:02.963] INFO: Expecting 41600 events.
[10:50:06.208] INFO: 41600 events read in total (2718ms).
[10:50:06.209] INFO: Test took 3952ms.
[10:50:06.243] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:50:06.967] INFO: Expecting 41600 events.
[10:50:10.205] INFO: 41600 events read in total (2711ms).
[10:50:10.206] INFO: Test took 3944ms.
[10:50:10.240] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:50:10.965] INFO: Expecting 41600 events.
[10:50:14.088] INFO: 41600 events read in total (2596ms).
[10:50:14.089] INFO: Test took 3830ms.
[10:50:14.123] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:50:14.485] INFO: enter test to run
[10:52:00.678] INFO: test: HighRate no parameter change
[10:52:00.678] INFO: running: highrate
[10:52:00.679] INFO: ----------------------------------------------------------------------
[10:52:00.679] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:52:00.679] INFO: ----------------------------------------------------------------------
[10:52:01.294] INFO: Expecting 208000 events.
[10:52:13.174] INFO: 208000 events read in total (11353ms).
[10:52:13.177] INFO: Test took 12490ms.
[10:52:13.325] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:13.576] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 1 0 0 0 0 2 3 0 0 0
[10:52:13.576] INFO: number of red-efficiency pixels: 91 55 72 121 162 152 146 102 104 113 118 100 86 64 36 26
[10:52:13.576] INFO: number of X-ray hits detected: 70925 46364 69194 113168 117194 116872 120210 86040 81463 92046 93703 76688 83828 51829 23325 25738
[10:52:13.576] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:52:13.576] INFO: number of Vcal hits detected: 207908 207945 207926 207875 207785 207845 207803 207897 207894 207885 207881 207802 207765 207936 207963 207974
[10:52:13.576] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 99.9 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[10:52:13.576] 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 99.9 100.0 100.0 100.0
[10:52:13.576] INFO: X-ray hit rate [MHz/cm2]: 20.8 13.6 20.3 33.2 34.4 34.3 35.2 25.2 23.9 27.0 27.5 22.5 24.6 15.2 6.8 7.5
[10:52:13.576] INFO: PixTestHighRate::doXPixelAlive() done
[10:52:13.624] INFO: PixTest:: pg_setup set to default.
[10:52:13.639] INFO: enter test to run
[10:52:29.582] INFO: test: HighRate no parameter change
[10:52:29.582] INFO: running: highrate
[10:52:29.583] INFO: ----------------------------------------------------------------------
[10:52:29.583] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:52:29.583] INFO: ----------------------------------------------------------------------
[10:52:30.196] INFO: Expecting 208000 events.
[10:52:43.896] INFO: 208000 events read in total (13173ms).
[10:52:43.901] INFO: Test took 14308ms.
[10:52:44.202] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:44.502] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 1 0 0 0 0 2 3 0 0 0
[10:52:44.502] INFO: number of red-efficiency pixels: 276 161 322 416 639 401 490 403 310 291 404 225 336 187 72 68
[10:52:44.502] INFO: number of X-ray hits detected: 148819 97654 144906 239053 246123 245910 253083 181619 171723 194242 196696 163029 177423 109733 50190 53584
[10:52:44.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
[10:52:44.502] INFO: number of Vcal hits detected: 207701 207833 207649 207561 207247 207569 207421 207561 207675 207695 207569 207668 207502 207806 207925 207932
[10:52:44.502] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.8 99.7 99.8 99.8 99.8 99.9 99.9 99.8 99.9 99.8 99.9 100.0 100.0
[10:52:44.503] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.8 99.6 99.8 99.7 99.8 99.8 99.9 99.8 99.8 99.8 99.9 100.0 100.0
[10:52:44.503] INFO: X-ray hit rate [MHz/cm2]: 43.6 28.6 42.5 70.1 72.1 72.1 74.2 53.2 50.3 56.9 57.7 47.8 52.0 32.2 14.7 15.7
[10:52:44.503] INFO: PixTestHighRate::doXPixelAlive() done
[10:52:44.549] INFO: PixTest:: pg_setup set to default.
[10:52:44.565] INFO: enter test to run
[10:52:58.422] INFO: test: HighRate no parameter change
[10:52:58.422] INFO: running: highrate
[10:52:58.423] INFO: ----------------------------------------------------------------------
[10:52:58.423] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:52:58.423] INFO: ----------------------------------------------------------------------
[10:52:59.031] INFO: Expecting 208000 events.
[10:53:14.695] INFO: 208000 events read in total (15137ms).
[10:53:14.704] INFO: Test took 16274ms.
[10:53:15.147] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:53:15.500] INFO: number of dead pixels (per ROC): 0 0 0 0 1 0 1 0 0 0 0 2 3 0 0 0
[10:53:15.500] INFO: number of red-efficiency pixels: 627 336 705 1042 1389 1071 1129 906 730 685 883 480 763 422 113 96
[10:53:15.500] INFO: number of X-ray hits detected: 226704 147760 220173 361098 373072 371632 382675 275334 260794 293046 297794 246227 268162 165901 76263 81841
[10:53:15.500] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:53:15.500] INFO: number of Vcal hits detected: 207234 207611 207065 206694 206132 206662 206561 206818 207170 207226 206936 207369 206962 207505 207885 207903
[10:53:15.500] INFO: Vcal hit fiducial efficiency (%): 99.7 99.8 99.6 99.4 99.2 99.4 99.4 99.5 99.6 99.7 99.5 99.8 99.6 99.8 99.9 100.0
[10:53:15.500] INFO: Vcal hit overall efficiency (%): 99.6 99.8 99.6 99.4 99.1 99.4 99.3 99.4 99.6 99.6 99.5 99.7 99.5 99.8 99.9 100.0
[10:53:15.500] INFO: X-ray hit rate [MHz/cm2]: 66.4 43.3 64.5 105.8 109.4 108.9 112.2 80.7 76.4 85.9 87.3 72.2 78.6 48.6 22.4 24.0
[10:53:15.500] INFO: PixTestHighRate::doXPixelAlive() done
[10:53:15.547] INFO: PixTest:: pg_setup set to default.
[10:53:15.563] INFO: enter test to run
[10:54:17.613] INFO: test: exit no parameter change
[10:54:18.010] QUIET: Connection to board 33 closed.
[10:54:18.011] INFO: pXar: this is the end, my friend