[13:14:22.187] INFO: *** Welcome to pxar ***
[13:14:22.187] INFO: *** Today: 2016/10/14
[13:14:23.068] INFO: *** Version: v1.9.0-818-g96727
[13:14:23.068] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//dacParameters35_C15.dat
[13:14:23.089] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:14:23.089] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//defaultMaskFile.dat
[13:14:23.093] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C15.dat
[13:14:23.219] INFO: clk: 4
[13:14:23.219] INFO: ctr: 4
[13:14:23.219] INFO: sda: 19
[13:14:23.219] INFO: tin: 9
[13:14:23.219] INFO: level: 15
[13:14:23.219] INFO: triggerdelay: 0
[13:14:23.219] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[13:14:23.219] INFO: Log level: INFO
[13:14:23.260] QUIET: Connection to board DTB_WREKRL opened.
[13:14:23.263] 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:14:23.266] INFO: RPC call hashes of host and DTB match: 398089610
[13:14:24.796] INFO: DUT info:
[13:14:24.796] INFO: The DUT currently contains the following objects:
[13:14:24.797] INFO: 2 TBM Cores tbm08c (2 ON)
[13:14:24.807] INFO: TBM Core alpha (0): 7 registers set
[13:14:24.807] INFO: TBM Core beta (1): 7 registers set
[13:14:24.807] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[13:14:24.807] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.807] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.807] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.807] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.807] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.807] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.807] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.807] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.807] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.807] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.807] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.808] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.808] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.808] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.808] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:24.808] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[13:14:25.234] INFO: enter 'restricted' command line mode
[13:14:25.234] INFO: enter test to run
[13:14:57.870] INFO: test: PixelAlive no parameter change
[13:14:57.870] INFO: running: pixelalive
[13:14:57.879] INFO: ----------------------------------------------------------------------
[13:14:57.879] 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:14:57.880] INFO: ----------------------------------------------------------------------
[13:14:58.195] INFO: Expecting 41600 events.
[13:15:02.509] INFO: 41600 events read in total (3595ms).
[13:15:02.674] INFO: Test took 4792ms.
[13:15:02.683] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:15:03.006] INFO: PixTestAlive::aliveTest() done
[13:15:03.006] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 2 0 0 0 0 0 0 0 0 0
[13:15:03.043] INFO: enter test to run
[13:15:10.438] INFO: test: timing no parameter change
[13:15:10.438] INFO: running: timing
[13:15:10.442] INFO: ######################################################################
[13:15:10.442] INFO: PixTestTiming::doTest()
[13:15:10.442] INFO: ######################################################################
[13:15:10.442] INFO: ----------------------------------------------------------------------
[13:15:10.442] INFO: PixTestTiming::TBMPhaseScan()
[13:15:10.442] INFO: ----------------------------------------------------------------------
[13:19:49.471] INFO: TBM Phase Settings: 208
[13:19:49.471] INFO: 400MHz Phase: 4
[13:19:49.471] INFO: 160MHz Phase: 6
[13:19:49.471] INFO: Functional Phase Area: 4
[13:19:49.476] INFO: Test took 279034 ms.
[13:19:49.476] INFO: PixTestTiming::TBMPhaseScan() done.
[13:19:49.476] INFO: ----------------------------------------------------------------------
[13:19:49.476] INFO: PixTestTiming::ROCDelayScan()
[13:19:49.476] INFO: ----------------------------------------------------------------------
[13:21:44.097] INFO: ROC Delay Settings: 219
[13:21:44.097] INFO: ROC Header-Trailer/Token Delay: 11
[13:21:44.097] INFO: ROC Port 0 Delay: 3
[13:21:44.097] INFO: ROC Port 1 Delay: 3
[13:21:44.097] INFO: Functional ROC Area: 4
[13:21:44.101] INFO: Test took 114625 ms.
[13:21:44.101] INFO: PixTestTiming::ROCDelayScan() done.
[13:21:44.101] INFO: ----------------------------------------------------------------------
[13:21:44.101] INFO: PixTestTiming::TimingTest()
[13:21:44.101] INFO: ----------------------------------------------------------------------
[13:22:00.471] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:15.562] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:30.658] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:22:45.911] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:23:01.102] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:23:16.459] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:23:31.587] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:23:46.640] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:24:01.650] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:24:16.637] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:24:17.014] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:24:17.031] INFO: ----------------------------------------------------------------------
[13:24:17.031] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[13:24:17.031] INFO: ----------------------------------------------------------------------
[13:24:17.031] INFO: ----------------------------------------------------------------------
[13:24:17.031] INFO: Read back bit status: 1
[13:24:17.031] INFO: ----------------------------------------------------------------------
[13:24:17.031] INFO: ----------------------------------------------------------------------
[13:24:17.031] INFO: Timings are good!
[13:24:17.031] INFO: ----------------------------------------------------------------------
[13:24:17.031] INFO: Test took 152930 ms.
[13:24:17.031] INFO: PixTestTiming::TimingTest() done.
[13:24:17.068] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//tbmParameters_C0a.dat
[13:24:17.068] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//tbmParameters_C0b.dat
[13:24:17.068] INFO: PixTestTiming::doTest took 546629 ms.
[13:24:17.068] INFO: PixTestTiming::doTest() done
[13:24:17.068] INFO: Write out TBMPhaseScan_0_V0
[13:24:17.069] INFO: Write out TBMPhaseScan_1_V0
[13:24:17.069] INFO: Write out CombinedTBMPhaseScan_V0
[13:24:17.089] INFO: Write out ROCDelayScan3_V0
[13:24:17.090] INFO: enter test to run
[13:25:05.379] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[13:25:05.379] INFO: running: highrate
[13:25:05.392] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[13:25:05.641] INFO: ----------------------------------------------------------------------
[13:25:05.641] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[13:25:05.641] INFO: ----------------------------------------------------------------------
[13:25:05.641] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[13:25:05.641] INFO: edge/corner pixel THR is adjusted
[13:25:05.641] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:25:06.628] INFO: Collecting data for 5 seconds...
[13:25:11.646] INFO: Done with hot pixel readout
[13:25:23.592] INFO: PixTest:: pg_setup set to default.
[13:25:23.593] INFO: 33 hot pixels found in step 0
[13:25:24.586] INFO: Collecting data for 5 seconds...
[13:25:29.602] INFO: Done with hot pixel readout
[13:25:41.434] INFO: PixTest:: pg_setup set to default.


[13:25:41.435] INFO: 43 hot pixels found in step 1
[13:25:42.429] INFO: Collecting data for 5 seconds...
[13:25:47.446] INFO: Done with hot pixel readout
[13:25:59.341] INFO: PixTest:: pg_setup set to default.

[13:25:59.342] INFO: 37 hot pixels found in step 2
[13:26:00.337] INFO: Collecting data for 5 seconds...
[13:26:05.354] INFO: Done with hot pixel readout
[13:26:17.185] INFO: PixTest:: pg_setup set to default.
[13:26:17.186] INFO: 36 hot pixels found in step 3
[13:26:18.180] INFO: Collecting data for 5 seconds...
[13:26:23.197] INFO: Done with hot pixel readout
[13:26:35.121] INFO: PixTest:: pg_setup set to default.
[13:26:35.122] INFO: 36 hot pixels found in step 4
[13:26:36.116] INFO: Collecting data for 5 seconds...
[13:26:41.132] INFO: Done with hot pixel readout
[13:26:52.959] INFO: PixTest:: pg_setup set to default.


[13:26:52.960] INFO: 41 hot pixels found in step 5
[13:26:53.955] INFO: Collecting data for 5 seconds...
[13:26:58.971] INFO: Done with hot pixel readout
[13:27:10.848] INFO: PixTest:: pg_setup set to default.




[13:27:10.849] INFO: 34 hot pixels found in step 6
[13:27:11.844] INFO: Collecting data for 5 seconds...
[13:27:16.860] INFO: Done with hot pixel readout
[13:27:28.861] INFO: PixTest:: pg_setup set to default.





[13:27:28.862] INFO: 30 hot pixels found in step 7
[13:27:29.856] INFO: Collecting data for 5 seconds...
[13:27:34.872] INFO: Done with hot pixel readout
[13:27:46.443] INFO: PixTest:: pg_setup set to default.












[13:27:46.444] INFO: 31 hot pixels found in step 8
[13:27:47.438] INFO: Collecting data for 5 seconds...
[13:27:52.455] INFO: Done with hot pixel readout
[13:28:04.407] INFO: PixTest:: pg_setup set to default.










[13:28:04.408] INFO: 24 hot pixels found in step 9
[13:28:05.403] INFO: Collecting data for 5 seconds...
[13:28:10.420] INFO: Done with hot pixel readout
[13:28:22.264] INFO: PixTest:: pg_setup set to default.












[13:28:22.265] INFO: 24 hot pixels found in step 10
[13:28:23.259] INFO: Collecting data for 5 seconds...
[13:28:28.275] INFO: Done with hot pixel readout
[13:28:40.211] INFO: PixTest:: pg_setup set to default.












[13:28:40.212] INFO: 24 hot pixels found in step 11
[13:28:41.207] INFO: Collecting data for 5 seconds...
[13:28:46.224] INFO: Done with hot pixel readout
[13:28:58.106] INFO: PixTest:: pg_setup set to default.











[13:28:58.107] INFO: 23 hot pixels found in step 12
[13:28:59.100] INFO: Collecting data for 5 seconds...
[13:29:04.117] INFO: Done with hot pixel readout
[13:29:16.060] INFO: PixTest:: pg_setup set to default.













[13:29:16.061] INFO: 23 hot pixels found in step 13
[13:29:17.056] INFO: Collecting data for 5 seconds...
[13:29:22.073] INFO: Done with hot pixel readout
[13:29:33.938] INFO: PixTest:: pg_setup set to default.












[13:29:33.939] INFO: 25 hot pixels found in step 14
[13:29:33.977] INFO: 25 hot pixels could not be trimmed and have been masked.
[13:29:33.981] INFO: PixTest::trimHotPixels() done
[13:29:33.986] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C0.dat
[13:29:33.996] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C1.dat
[13:29:33.002] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C2.dat
[13:29:34.007] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C3.dat
[13:29:34.013] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C4.dat
[13:29:34.018] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C5.dat
[13:29:34.023] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C6.dat
[13:29:34.029] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C7.dat
[13:29:34.034] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C8.dat
[13:29:34.040] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C9.dat
[13:29:34.045] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C10.dat
[13:29:34.050] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C11.dat
[13:29:34.056] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C12.dat
[13:29:34.061] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C13.dat
[13:29:34.067] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C14.dat
[13:29:34.072] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C15.dat
[13:29:34.077] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//defaultMaskFile.dat
[13:29:34.094] INFO: enter test to run
[13:30:14.201] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[13:30:14.201] INFO: running: highrate
[13:30:14.205] INFO: ----------------------------------------------------------------------
[13:30:14.205] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[13:30:14.205] INFO: ----------------------------------------------------------------------
[13:30:14.205] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[13:30:14.205] INFO: edge/corner pixel THR is adjusted
[13:30:14.205] INFO: PixTestHighRate::trimHotPixels: step 0...
[13:30:15.164] INFO: Collecting data for 1 seconds...
[13:30:16.167] INFO: Done with hot pixel readout
[13:30:20.235] INFO: PixTest:: pg_setup set to default.
[13:30:20.236] INFO: 0 hot pixels found in step 0
[13:30:20.241] INFO: 0 hot pixels could not be trimmed and have been masked.
[13:30:20.332] INFO: PixTest::trimHotPixels() done
[13:30:20.332] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C0.dat
[13:30:20.344] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C1.dat
[13:30:20.355] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C2.dat
[13:30:20.360] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C3.dat
[13:30:20.366] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C4.dat
[13:30:20.371] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C5.dat
[13:30:20.376] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C6.dat
[13:30:20.382] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C7.dat
[13:30:20.387] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C8.dat
[13:30:20.392] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C9.dat
[13:30:20.398] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C10.dat
[13:30:20.403] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C11.dat
[13:30:20.408] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C12.dat
[13:30:20.414] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C13.dat
[13:30:20.419] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C14.dat
[13:30:20.424] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//trimParameters35_C15.dat
[13:30:20.430] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-Q-2-21_FPIXTest-17C-FNAL-160930-1319-150V_2016-09-30_13h19m_1475259569/000_FPIXTest_p17//defaultMaskFile.dat
[13:30:20.439] INFO: enter test to run
[13:31:08.712] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:31:08.712] INFO: running: xray
[13:31:08.714] INFO: ----------------------------------------------------------------------
[13:31:08.714] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:31:08.714] INFO: ----------------------------------------------------------------------
[13:31:09.677] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:31:20.858] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[13:31:50.508] INFO: Resuming triggers.
[13:32:01.691] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[13:32:31.768] INFO: Resuming triggers.
[13:32:42.944] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[13:33:12.743] INFO: Resuming triggers.
[13:33:23.923] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[13:33:53.836] INFO: Resuming triggers.
[13:34:05.013] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[13:34:35.076] INFO: Resuming triggers.
[13:34:46.271] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[13:35:16.491] INFO: Resuming triggers.
[13:35:27.669] INFO: run duration 77 seconds, buffer almost full (81%), pausing triggers.
[13:35:58.145] INFO: Resuming triggers.
[13:36:09.326] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[13:36:39.914] INFO: Resuming triggers.
[13:36:50.840] INFO: data taking finished, elapsed time: 100 seconds.
[13:37:20.953] INFO: PixTest:: pg_setup set to default.
[13:37:20.956] INFO: PixTestXray::doPhRun() done
[13:37:21.343] INFO: enter test to run
[13:37:42.549] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[13:37:42.550] INFO: running: xray
[13:37:42.551] INFO: ----------------------------------------------------------------------
[13:37:42.551] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:37:42.551] INFO: ----------------------------------------------------------------------
[13:37:43.521] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:37:50.083] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[13:38:22.218] INFO: Resuming triggers.
[13:38:28.786] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[13:38:59.148] INFO: Resuming triggers.
[13:39:05.716] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[13:39:36.047] INFO: Resuming triggers.
[13:39:42.610] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[13:40:12.833] INFO: Resuming triggers.
[13:40:19.396] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[13:40:49.490] INFO: Resuming triggers.
[13:40:56.052] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[13:41:26.437] INFO: Resuming triggers.
[13:41:32.996] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[13:42:04.026] INFO: Resuming triggers.
[13:42:10.587] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[13:42:40.900] INFO: Resuming triggers.
[13:42:47.462] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[13:43:17.504] INFO: Resuming triggers.
[13:43:24.067] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[13:43:54.139] INFO: Resuming triggers.
[13:44:00.703] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[13:44:30.612] INFO: Resuming triggers.
[13:44:37.170] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[13:45:07.157] INFO: Resuming triggers.
[13:45:13.715] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[13:45:43.974] INFO: Resuming triggers.
[13:45:50.533] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[13:46:21.518] INFO: Resuming triggers.
[13:46:28.075] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[13:46:58.799] INFO: Resuming triggers.
[13:47:00.710] INFO: data taking finished, elapsed time: 100 seconds.
[13:47:10.169] INFO: PixTest:: pg_setup set to default.
[13:47:10.172] INFO: PixTestXray::doPhRun() done
[13:47:10.329] INFO: enter test to run
[13:48:35.420] INFO: test: HighRate no parameter change
[13:48:35.420] INFO: running: highrate
[13:48:35.437] INFO: ----------------------------------------------------------------------
[13:48:35.437] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:48:35.437] INFO: ----------------------------------------------------------------------
[13:48:35.594] INFO: Expecting 768 events.
[13:48:36.739] INFO: 768 events read in total (430ms).
[13:48:36.739] INFO: Test took 1279ms.
[13:48:37.542] INFO: Expecting 41600 events.
[13:48:40.717] INFO: 41600 events read in total (2648ms).
[13:48:40.718] INFO: Test took 3932ms.
[13:48:40.753] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:48:41.480] INFO: Expecting 41600 events.
[13:48:44.690] INFO: 41600 events read in total (2683ms).
[13:48:44.691] INFO: Test took 3887ms.
[13:48:44.727] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:48:45.448] INFO: Expecting 41600 events.
[13:48:48.733] INFO: 41600 events read in total (2758ms).
[13:48:48.734] INFO: Test took 3989ms.
[13:48:48.771] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:48:49.489] INFO: Expecting 41600 events.
[13:48:52.757] INFO: 41600 events read in total (2741ms).
[13:48:52.758] INFO: Test took 3969ms.
[13:48:52.803] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:48:53.508] INFO: Expecting 41600 events.
[13:48:56.780] INFO: 41600 events read in total (2745ms).
[13:48:56.781] INFO: Test took 3955ms.
[13:48:56.816] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:48:57.530] INFO: Expecting 41600 events.
[13:49:00.830] INFO: 41600 events read in total (2773ms).
[13:49:00.832] INFO: Test took 3998ms.
[13:49:00.870] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:01.584] INFO: Expecting 41600 events.
[13:49:04.882] INFO: 41600 events read in total (2771ms).
[13:49:04.883] INFO: Test took 3995ms.
[13:49:04.919] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:05.634] INFO: Expecting 41600 events.
[13:49:08.847] INFO: 41600 events read in total (2686ms).
[13:49:08.848] INFO: Test took 3911ms.
[13:49:08.884] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:09.606] INFO: Expecting 41600 events.
[13:49:12.853] INFO: 41600 events read in total (2721ms).
[13:49:12.855] INFO: Test took 3953ms.
[13:49:12.890] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:13.609] INFO: Expecting 41600 events.
[13:49:16.861] INFO: 41600 events read in total (2725ms).
[13:49:16.862] INFO: Test took 3953ms.
[13:49:16.898] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:17.617] INFO: Expecting 41600 events.
[13:49:20.868] INFO: 41600 events read in total (2725ms).
[13:49:20.869] INFO: Test took 3953ms.
[13:49:20.906] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:21.626] INFO: Expecting 41600 events.
[13:49:24.937] INFO: 41600 events read in total (2784ms).
[13:49:24.938] INFO: Test took 4014ms.
[13:49:24.974] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:25.693] INFO: Expecting 41600 events.
[13:49:28.945] INFO: 41600 events read in total (2725ms).
[13:49:28.946] INFO: Test took 3954ms.
[13:49:28.983] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:29.702] INFO: Expecting 41600 events.
[13:49:32.978] INFO: 41600 events read in total (2749ms).
[13:49:32.979] INFO: Test took 3978ms.
[13:49:33.017] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:33.733] INFO: Expecting 41600 events.
[13:49:37.019] INFO: 41600 events read in total (2760ms).
[13:49:37.020] INFO: Test took 3984ms.
[13:49:37.055] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:37.772] INFO: Expecting 41600 events.
[13:49:41.046] INFO: 41600 events read in total (2747ms).
[13:49:41.047] INFO: Test took 3974ms.
[13:49:41.083] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:41.796] INFO: Expecting 41600 events.
[13:49:45.076] INFO: 41600 events read in total (2753ms).
[13:49:45.077] INFO: Test took 3976ms.
[13:49:45.114] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:45.832] INFO: Expecting 41600 events.
[13:49:49.057] INFO: 41600 events read in total (2698ms).
[13:49:49.058] INFO: Test took 3924ms.
[13:49:49.094] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:49.813] INFO: Expecting 41600 events.
[13:49:53.155] INFO: 41600 events read in total (2816ms).
[13:49:53.156] INFO: Test took 4043ms.
[13:49:53.192] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:53.902] INFO: Expecting 41600 events.
[13:49:57.072] INFO: 41600 events read in total (2644ms).
[13:49:57.073] INFO: Test took 3863ms.
[13:49:57.109] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:49:57.466] INFO: enter test to run
[13:50:31.592] INFO: test: HighRate no parameter change
[13:50:31.592] INFO: running: highrate
[13:50:31.593] INFO: ----------------------------------------------------------------------
[13:50:31.593] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:50:31.594] INFO: ----------------------------------------------------------------------
[13:50:32.217] INFO: Expecting 208000 events.
[13:50:44.441] INFO: 208000 events read in total (11697ms).
[13:50:44.444] INFO: Test took 12842ms.
[13:50:44.600] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:50:44.857] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 2 0 0 0 0 0 0 0 0 0
[13:50:44.870] INFO: number of red-efficiency pixels: 93 45 107 136 175 189 154 110 71 119 127 74 99 66 32 29
[13:50:44.870] INFO: number of X-ray hits detected: 74814 47069 72903 112064 122516 124313 122030 91109 73474 98069 95067 79999 84655 50569 22968 25358
[13:50:44.870] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:50:44.870] INFO: number of Vcal hits detected: 207904 207955 207889 207864 207820 207755 207741 207888 207927 207879 207872 207924 207900 207933 207968 207971
[13:50:44.870] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[13:50:44.870] INFO: Vcal hit overall efficiency (%): 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[13:50:44.870] INFO: X-ray hit rate [MHz/cm2]: 21.9 13.8 21.4 32.8 35.9 36.4 35.8 26.7 21.5 28.7 27.9 23.4 24.8 14.8 6.7 7.4
[13:50:44.870] INFO: PixTestHighRate::doXPixelAlive() done
[13:50:44.917] INFO: PixTest:: pg_setup set to default.
[13:50:44.932] INFO: enter test to run
[13:51:09.784] INFO: test: HighRate no parameter change
[13:51:09.784] INFO: running: highrate
[13:51:09.785] INFO: ----------------------------------------------------------------------
[13:51:09.785] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:51:09.785] INFO: ----------------------------------------------------------------------
[13:51:10.406] INFO: Expecting 208000 events.
[13:51:24.538] INFO: 208000 events read in total (13605ms).
[13:51:24.543] INFO: Test took 14748ms.
[13:51:24.842] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:51:25.148] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 2 0 0 0 0 0 0 0 0 0
[13:51:25.148] INFO: number of red-efficiency pixels: 331 133 337 474 472 619 586 299 203 407 382 233 307 174 59 65
[13:51:25.148] INFO: number of X-ray hits detected: 152060 97184 148652 230830 251563 254230 249768 186818 150836 201425 195878 163677 174323 102717 47445 51882
[13:51:25.148] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:51:25.148] INFO: number of Vcal hits detected: 207635 207860 207619 207487 207464 207271 207243 207683 207794 207559 207589 207758 207669 207817 207939 207934
[13:51:25.148] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.8 99.8 99.7 99.7 99.9 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[13:51:25.148] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.8 99.7 99.6 99.6 99.8 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[13:51:25.148] INFO: X-ray hit rate [MHz/cm2]: 44.6 28.5 43.6 67.7 73.7 74.5 73.2 54.8 44.2 59.0 57.4 48.0 51.1 30.1 13.9 15.2
[13:51:25.148] INFO: PixTestHighRate::doXPixelAlive() done
[13:51:25.194] INFO: PixTest:: pg_setup set to default.
[13:51:25.207] INFO: enter test to run
[13:51:45.592] INFO: test: HighRate no parameter change
[13:51:45.592] INFO: running: highrate
[13:51:45.593] INFO: ----------------------------------------------------------------------
[13:51:45.593] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:51:45.593] INFO: ----------------------------------------------------------------------
[13:51:46.210] INFO: Expecting 208000 events.
[13:52:02.157] INFO: 208000 events read in total (15420ms).
[13:52:02.165] INFO: Test took 16563ms.
[13:52:02.617] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:52:02.980] INFO: number of dead pixels (per ROC): 0 0 0 0 0 1 2 0 0 0 0 0 0 0 0 0
[13:52:02.980] INFO: number of red-efficiency pixels: 658 228 753 1151 1105 1568 1348 701 404 956 894 483 708 386 86 88
[13:52:02.980] INFO: number of X-ray hits detected: 230571 146983 227602 348911 382786 386276 379292 285082 230075 306539 296913 249562 266213 156907 72578 80054
[13:52:02.980] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[13:52:02.980] INFO: number of Vcal hits detected: 207060 207749 206965 206525 206603 205763 206111 207107 207561 206859 206918 207478 207195 207555 207909 207911
[13:52:02.980] INFO: Vcal hit fiducial efficiency (%): 99.6 99.9 99.6 99.4 99.4 99.0 99.2 99.6 99.8 99.5 99.5 99.8 99.6 99.8 100.0 100.0
[13:52:02.980] INFO: Vcal hit overall efficiency (%): 99.5 99.9 99.5 99.3 99.3 98.9 99.1 99.6 99.8 99.5 99.5 99.7 99.6 99.8 100.0 100.0
[13:52:02.980] INFO: X-ray hit rate [MHz/cm2]: 67.6 43.1 66.7 102.3 112.2 113.2 111.2 83.6 67.4 89.8 87.0 73.1 78.0 46.0 21.3 23.5
[13:52:02.980] INFO: PixTestHighRate::doXPixelAlive() done
[13:52:03.027] INFO: PixTest:: pg_setup set to default.
[13:52:03.037] INFO: enter test to run
[13:52:16.863] INFO: test: exit no parameter change
[13:52:17.852] QUIET: Connection to board 33 closed.
[13:52:18.197] INFO: pXar: this is the end, my friend