[12:05:11.278] INFO: *** Welcome to pxar ***
[12:05:11.278] INFO: *** Today: 2016/06/30
[12:05:11.773] INFO: *** Version: v1.9.0-814-g7497
[12:05:11.773] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//dacParameters35_C15.dat
[12:05:11.815] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:05:11.816] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//defaultMaskFile.dat
[12:05:11.819] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C15.dat
[12:05:11.941] INFO: clk: 4
[12:05:11.941] INFO: ctr: 4
[12:05:11.941] INFO: sda: 19
[12:05:11.941] INFO: tin: 9
[12:05:11.941] INFO: level: 15
[12:05:11.941] INFO: triggerdelay: 0
[12:05:11.941] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[12:05:11.941] INFO: Log level: INFO
[12:05:11.959] QUIET: Connection to board DTB_WREKRL opened.
[12:05:11.963] 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:
------------------------------------------------------
[12:05:11.965] INFO: RPC call hashes of host and DTB match: 398089610
[12:05:13.499] INFO: DUT info:
[12:05:13.499] INFO: The DUT currently contains the following objects:
[12:05:13.499] INFO: 2 TBM Cores tbm08c (2 ON)
[12:05:13.499] INFO: TBM Core alpha (0): 7 registers set
[12:05:13.499] INFO: TBM Core beta (1): 7 registers set
[12:05:13.499] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:05:13.499] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.499] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.499] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.499] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.499] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.499] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.500] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.500] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.500] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.500] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.500] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.500] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.500] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.500] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.500] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.500] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:05:13.904] INFO: enter 'restricted' command line mode
[12:05:13.904] INFO: enter test to run
[12:05:19.533] INFO: test: PixelAlive no parameter change
[12:05:19.533] INFO: running: pixelalive
[12:05:19.542] INFO: ----------------------------------------------------------------------
[12:05:19.542] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[12:05:19.542] INFO: ----------------------------------------------------------------------
[12:05:19.859] INFO: Expecting 41600 events.
[12:05:24.198] INFO: 41600 events read in total (3621ms).
[12:05:24.366] INFO: Test took 4822ms.
[12:05:24.377] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:05:24.639] INFO: PixTestAlive::aliveTest() done
[12:05:24.639] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 3 3 0 0 0 0 0 0 0 1
[12:05:24.670] INFO: enter test to run
[12:05:51.389] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:05:51.389] INFO: running: highrate
[12:05:51.389] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:05:51.659] INFO: ----------------------------------------------------------------------
[12:05:51.659] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:05:51.659] INFO: ----------------------------------------------------------------------
[12:05:51.659] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:05:51.660] INFO: edge/corner pixel THR is adjusted
[12:05:51.660] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:05:52.618] INFO: Collecting data for 5 seconds...
[12:05:57.635] INFO: Done with hot pixel readout
[12:06:09.677] INFO: PixTest:: pg_setup set to default.
[12:06:09.678] INFO: 9 hot pixels found in step 0
[12:06:10.702] INFO: Collecting data for 5 seconds...
[12:06:15.720] INFO: Done with hot pixel readout
[12:06:27.893] INFO: PixTest:: pg_setup set to default.
[12:06:27.894] INFO: 13 hot pixels found in step 1
[12:06:28.891] INFO: Collecting data for 5 seconds...
[12:06:33.907] INFO: Done with hot pixel readout
[12:06:46.081] INFO: PixTest:: pg_setup set to default.
[12:06:46.082] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:06:46.082] INFO: 13 hot pixels found in step 2
[12:06:47.077] INFO: Collecting data for 5 seconds...
[12:06:52.095] INFO: Done with hot pixel readout
[12:07:04.374] INFO: PixTest:: pg_setup set to default.
[12:07:04.375] INFO: 15 hot pixels found in step 3
[12:07:05.370] INFO: Collecting data for 5 seconds...
[12:07:10.387] INFO: Done with hot pixel readout
[12:07:22.586] INFO: PixTest:: pg_setup set to default.
[12:07:22.587] INFO: 11 hot pixels found in step 4
[12:07:23.590] INFO: Collecting data for 5 seconds...
[12:07:28.607] INFO: Done with hot pixel readout
[12:07:40.648] INFO: PixTest:: pg_setup set to default.
[12:07:40.649] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:07:40.649] INFO: 6 hot pixels found in step 5
[12:07:41.645] INFO: Collecting data for 5 seconds...
[12:07:46.662] INFO: Done with hot pixel readout
[12:07:58.604] INFO: PixTest:: pg_setup set to default.
[12:07:58.605] INFO: 7 hot pixels found in step 6
[12:07:59.602] INFO: Collecting data for 5 seconds...
[12:08:04.618] INFO: Done with hot pixel readout
[12:08:16.536] INFO: PixTest:: pg_setup set to default.
[12:08:16.537] INFO: 11 hot pixels found in step 7
[12:08:17.533] INFO: Collecting data for 5 seconds...
[12:08:22.550] INFO: Done with hot pixel readout
[12:08:34.567] INFO: PixTest:: pg_setup set to default.
[12:08:34.567] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:08:34.567] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:08:34.567] INFO: 10 hot pixels found in step 8
[12:08:35.564] INFO: Collecting data for 5 seconds...
[12:08:40.580] INFO: Done with hot pixel readout
[12:08:52.710] INFO: PixTest:: pg_setup set to default.
[12:08:52.710] INFO: 5 hot pixels found in step 9
[12:08:53.707] INFO: Collecting data for 5 seconds...
[12:08:58.723] INFO: Done with hot pixel readout
[12:09:10.952] INFO: PixTest:: pg_setup set to default.
[12:09:10.952] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:09:10.953] INFO: 12 hot pixels found in step 10
[12:09:11.949] INFO: Collecting data for 5 seconds...
[12:09:16.967] INFO: Done with hot pixel readout
[12:09:29.104] INFO: PixTest:: pg_setup set to default.
[12:09:29.105] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:09:29.105] INFO: 8 hot pixels found in step 11
[12:09:30.102] INFO: Collecting data for 5 seconds...
[12:09:35.120] INFO: Done with hot pixel readout
[12:09:47.053] INFO: PixTest:: pg_setup set to default.
[12:09:47.054] INFO: 2 hot pixels found in step 12
[12:09:48.050] INFO: Collecting data for 5 seconds...
[12:09:53.068] INFO: Done with hot pixel readout
[12:10:04.775] INFO: PixTest:: pg_setup set to default.
[12:10:04.776] INFO: 15 hot pixels found in step 13
[12:10:05.772] INFO: Collecting data for 5 seconds...
[12:10:10.789] INFO: Done with hot pixel readout
[12:10:22.606] INFO: PixTest:: pg_setup set to default.
[12:10:22.607] INFO: 8 hot pixels found in step 14
[12:10:22.647] INFO: 8 hot pixels could not be trimmed and have been masked.
[12:10:22.650] INFO: PixTest::trimHotPixels() done
[12:10:22.651] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C0.dat
[12:10:22.658] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C1.dat
[12:10:22.665] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C2.dat
[12:10:22.672] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C3.dat
[12:10:22.679] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C4.dat
[12:10:22.685] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C5.dat
[12:10:22.691] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C6.dat
[12:10:22.698] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C7.dat
[12:10:22.704] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C8.dat
[12:10:22.710] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C9.dat
[12:10:22.715] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C10.dat
[12:10:22.721] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C11.dat
[12:10:22.726] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C12.dat
[12:10:22.731] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C13.dat
[12:10:22.737] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C14.dat
[12:10:22.742] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C15.dat
[12:10:22.748] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//defaultMaskFile.dat
[12:10:22.762] INFO: enter test to run
[12:10:55.195] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:10:55.195] INFO: running: highrate
[12:10:55.199] INFO: ----------------------------------------------------------------------
[12:10:55.200] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:10:55.200] INFO: ----------------------------------------------------------------------
[12:10:55.200] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:10:55.200] INFO: edge/corner pixel THR is adjusted
[12:10:55.200] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:10:56.157] INFO: Collecting data for 1 seconds...
[12:10:57.161] INFO: Done with hot pixel readout
[12:11:01.247] INFO: PixTest:: pg_setup set to default.
[12:11:01.248] INFO: 0 hot pixels found in step 0
[12:11:01.253] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:11:01.335] INFO: PixTest::trimHotPixels() done
[12:11:01.335] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C0.dat
[12:11:01.344] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C1.dat
[12:11:01.351] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C2.dat
[12:11:01.356] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C3.dat
[12:11:01.361] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C4.dat
[12:11:01.366] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C5.dat
[12:11:01.372] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C6.dat
[12:11:01.377] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C7.dat
[12:11:01.382] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C8.dat
[12:11:01.387] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C9.dat
[12:11:01.392] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C10.dat
[12:11:01.398] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C11.dat
[12:11:01.403] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C12.dat
[12:11:01.409] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C13.dat
[12:11:01.414] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C14.dat
[12:11:01.420] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//trimParameters35_C15.dat
[12:11:01.427] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-1-32_FPIXTest-17C-FNAL-160622-1238_2016-06-22_12h39m_1466617145/000_FPIXTest_p17//defaultMaskFile.dat
[12:11:01.438] INFO: enter test to run
[12:11:29.602] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[12:11:29.603] INFO: running: xray
[12:11:29.604] INFO: ----------------------------------------------------------------------
[12:11:29.604] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:11:29.604] INFO: ----------------------------------------------------------------------
[12:11:30.567] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:11:41.584] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[12:12:11.823] INFO: Resuming triggers.
[12:12:22.843] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[12:12:52.763] INFO: Resuming triggers.
[12:13:03.781] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[12:13:33.491] INFO: Resuming triggers.
[12:13:44.509] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[12:14:14.046] INFO: Resuming triggers.
[12:14:25.060] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[12:14:54.620] INFO: Resuming triggers.
[12:15:05.634] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[12:15:35.329] INFO: Resuming triggers.
[12:15:46.343] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[12:16:15.725] INFO: Resuming triggers.
[12:16:26.744] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[12:16:56.332] INFO: Resuming triggers.
[12:17:07.351] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[12:17:37.122] INFO: Resuming triggers.
[12:17:38.315] INFO: data taking finished, elapsed time: 100 seconds.
[12:17:41.928] INFO: PixTest:: pg_setup set to default.
[12:17:41.931] INFO: PixTestXray::doPhRun() done
[12:17:42.070] INFO: enter test to run
[12:18:12.360] INFO: test: [D[BXray setting parameters: ->source=DCHighRate<-
[12:18:12.360] INFO: running: [d[bxray
[12:18:12.384] INFO: command ->[d[bxray<- not known, ignored
[12:18:12.384] INFO: enter test to run
[12:18:50.367] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:18:50.368] INFO: running: xray
[12:18:50.369] INFO: ----------------------------------------------------------------------
[12:18:50.369] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:18:50.369] INFO: ----------------------------------------------------------------------
[12:18:51.336] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:18:57.624] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[12:19:27.879] INFO: Resuming triggers.
[12:19:34.172] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[12:20:04.503] INFO: Resuming triggers.
[12:20:10.791] INFO: run duration 18 seconds, buffer almost full (81%), pausing triggers.
[12:20:41.040] INFO: Resuming triggers.
[12:20:47.334] INFO: run duration 25 seconds, buffer almost full (81%), pausing triggers.
[12:21:18.459] INFO: Resuming triggers.
[12:21:24.752] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[12:21:56.124] INFO: Resuming triggers.
[12:22:02.418] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[12:22:33.373] INFO: Resuming triggers.
[12:22:39.663] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[12:23:11.416] INFO: Resuming triggers.
[12:23:17.706] INFO: run duration 50 seconds, buffer almost full (81%), pausing triggers.
[12:23:49.447] INFO: Resuming triggers.
[12:23:55.738] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[12:24:27.294] INFO: Resuming triggers.
[12:24:33.583] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[12:25:03.765] INFO: Resuming triggers.
[12:25:10.051] INFO: run duration 68 seconds, buffer almost full (81%), pausing triggers.
[12:25:40.344] INFO: Resuming triggers.
[12:25:46.631] INFO: run duration 75 seconds, buffer almost full (81%), pausing triggers.
[12:26:16.825] INFO: Resuming triggers.
[12:26:23.113] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[12:26:53.447] INFO: Resuming triggers.
[12:26:59.732] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[12:27:29.940] INFO: Resuming triggers.
[12:27:36.226] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[12:28:06.421] INFO: Resuming triggers.
[12:28:12.424] INFO: data taking finished, elapsed time: 100 seconds.
[12:28:41.483] INFO: PixTest:: pg_setup set to default.
[12:28:41.486] INFO: PixTestXray::doPhRun() done
[12:28:41.639] INFO: enter test to run
[12:29:29.339] INFO: test: HighRate no parameter change
[12:29:29.339] INFO: running: highrate
[12:29:29.357] INFO: ----------------------------------------------------------------------
[12:29:29.357] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:29:29.357] INFO: ----------------------------------------------------------------------
[12:29:29.513] INFO: Expecting 768 events.
[12:29:30.647] INFO: 768 events read in total (419ms).
[12:29:30.647] INFO: Test took 1269ms.
[12:29:31.451] INFO: Expecting 41600 events.
[12:29:34.556] INFO: 41600 events read in total (2579ms).
[12:29:34.557] INFO: Test took 3850ms.
[12:29:34.593] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:35.314] INFO: Expecting 41600 events.
[12:29:38.554] INFO: 41600 events read in total (2713ms).
[12:29:38.555] INFO: Test took 3945ms.
[12:29:38.593] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:39.304] INFO: Expecting 41600 events.
[12:29:42.589] INFO: 41600 events read in total (2758ms).
[12:29:42.590] INFO: Test took 3977ms.
[12:29:42.627] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:43.343] INFO: Expecting 41600 events.
[12:29:46.613] INFO: 41600 events read in total (2743ms).
[12:29:46.614] INFO: Test took 3968ms.
[12:29:46.652] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:47.371] INFO: Expecting 41600 events.
[12:29:50.633] INFO: 41600 events read in total (2735ms).
[12:29:50.634] INFO: Test took 3962ms.
[12:29:50.671] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:51.391] INFO: Expecting 41600 events.
[12:29:54.672] INFO: 41600 events read in total (2754ms).
[12:29:54.673] INFO: Test took 3983ms.
[12:29:54.711] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:55.425] INFO: Expecting 41600 events.
[12:29:58.719] INFO: 41600 events read in total (2767ms).
[12:29:58.720] INFO: Test took 3991ms.
[12:29:58.758] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:29:59.475] INFO: Expecting 41600 events.
[12:30:02.753] INFO: 41600 events read in total (2751ms).
[12:30:02.754] INFO: Test took 3978ms.
[12:30:02.792] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:03.510] INFO: Expecting 41600 events.
[12:30:06.797] INFO: 41600 events read in total (2760ms).
[12:30:06.798] INFO: Test took 3988ms.
[12:30:06.836] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:07.554] INFO: Expecting 41600 events.
[12:30:10.840] INFO: 41600 events read in total (2760ms).
[12:30:10.841] INFO: Test took 3986ms.
[12:30:10.878] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:11.596] INFO: Expecting 41600 events.
[12:30:14.881] INFO: 41600 events read in total (2758ms).
[12:30:14.882] INFO: Test took 3986ms.
[12:30:14.919] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:15.635] INFO: Expecting 41600 events.
[12:30:18.928] INFO: 41600 events read in total (2766ms).
[12:30:18.929] INFO: Test took 3990ms.
[12:30:18.967] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:19.683] INFO: Expecting 41600 events.
[12:30:22.972] INFO: 41600 events read in total (2763ms).
[12:30:22.973] INFO: Test took 3987ms.
[12:30:23.011] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:23.730] INFO: Expecting 41600 events.
[12:30:27.014] INFO: 41600 events read in total (2757ms).
[12:30:27.015] INFO: Test took 3984ms.
[12:30:27.052] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:27.770] INFO: Expecting 41600 events.
[12:30:31.033] INFO: 41600 events read in total (2736ms).
[12:30:31.034] INFO: Test took 3963ms.
[12:30:31.071] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:31.786] INFO: Expecting 41600 events.
[12:30:35.069] INFO: 41600 events read in total (2756ms).
[12:30:35.070] INFO: Test took 3980ms.
[12:30:35.107] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:35.826] INFO: Expecting 41600 events.
[12:30:39.116] INFO: 41600 events read in total (2763ms).
[12:30:39.117] INFO: Test took 3991ms.
[12:30:39.154] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:39.871] INFO: Expecting 41600 events.
[12:30:43.155] INFO: 41600 events read in total (2757ms).
[12:30:43.156] INFO: Test took 3982ms.
[12:30:43.193] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:43.911] INFO: Expecting 41600 events.
[12:30:47.209] INFO: 41600 events read in total (2771ms).
[12:30:47.210] INFO: Test took 3997ms.
[12:30:47.247] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:47.961] INFO: Expecting 41600 events.
[12:30:51.106] INFO: 41600 events read in total (2619ms).
[12:30:51.107] INFO: Test took 3842ms.
[12:30:51.144] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:30:51.495] INFO: enter test to run
[12:31:03.035] INFO: test: HighRate no parameter change
[12:31:03.035] INFO: running: highrate
[12:31:03.036] INFO: ----------------------------------------------------------------------
[12:31:03.036] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:31:03.036] INFO: ----------------------------------------------------------------------
[12:31:03.657] INFO: Expecting 208000 events.
[12:31:15.771] INFO: 208000 events read in total (11588ms).
[12:31:15.775] INFO: Test took 12730ms.
[12:31:15.933] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:31:16.192] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 3 3 0 0 0 0 0 0 0 1
[12:31:16.192] INFO: number of red-efficiency pixels: 72 38 92 145 152 158 173 107 107 128 167 146 113 68 35 26
[12:31:16.193] INFO: number of X-ray hits detected: 65796 45319 72951 116053 123440 131168 126803 91442 89706 115171 112594 100420 103799 61184 23869 28577
[12:31:16.193] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:31:16.193] INFO: number of Vcal hits detected: 207927 207962 207906 207852 207848 207837 207676 207746 207889 207870 207825 207852 207886 207931 207964 207925
[12:31:16.193] INFO: Vcal hit fiducial 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
[12:31:16.193] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.8 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[12:31:16.193] INFO: X-ray hit rate [MHz/cm2]: 19.3 13.3 21.4 34.0 36.2 38.4 37.2 26.8 26.3 33.8 33.0 29.4 30.4 17.9 7.0 8.4
[12:31:16.193] INFO: PixTestHighRate::doXPixelAlive() done
[12:31:16.244] INFO: PixTest:: pg_setup set to default.
[12:31:16.255] INFO: enter test to run
[12:32:18.554] INFO: test: HighRate no parameter change
[12:32:18.554] INFO: running: highrate
[12:32:18.555] INFO: ----------------------------------------------------------------------
[12:32:18.555] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:32:18.555] INFO: ----------------------------------------------------------------------
[12:32:19.173] INFO: Expecting 208000 events.
[12:32:33.158] INFO: 208000 events read in total (13458ms).
[12:32:33.164] INFO: Test took 14600ms.
[12:32:33.482] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:32:33.792] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 3 3 0 0 0 0 0 0 0 1
[12:32:33.792] INFO: number of red-efficiency pixels: 176 108 293 560 482 657 499 398 276 398 476 408 335 203 56 56
[12:32:33.792] INFO: number of X-ray hits detected: 133071 92011 147135 234416 249948 264345 256199 185116 182884 232246 227810 202705 208792 124244 48145 58016
[12:32:33.792] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:32:33.792] INFO: number of Vcal hits detected: 207821 207890 207677 207383 207484 207257 207296 207404 207709 207562 207488 207548 207641 207787 207942 207894
[12:32:33.792] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.7 99.8 99.7 99.8 99.8 99.9 99.8 99.8 99.8 99.8 99.9 100.0 100.0
[12:32:33.792] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.8 99.6 99.7 99.7 99.9 99.8 99.8 99.8 99.8 99.9 100.0 99.9
[12:32:33.792] INFO: X-ray hit rate [MHz/cm2]: 39.0 27.0 43.1 68.7 73.3 77.5 75.1 54.3 53.6 68.1 66.8 59.4 61.2 36.4 14.1 17.0
[12:32:33.792] INFO: PixTestHighRate::doXPixelAlive() done
[12:32:33.845] INFO: PixTest:: pg_setup set to default.
[12:32:33.859] INFO: enter test to run
[12:33:13.322] INFO: test: HighRate no parameter change
[12:33:13.322] INFO: running: highrate
[12:33:13.323] INFO: ----------------------------------------------------------------------
[12:33:13.323] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:33:13.323] INFO: ----------------------------------------------------------------------
[12:33:13.947] INFO: Expecting 208000 events.
[12:33:30.289] INFO: 208000 events read in total (15815ms).
[12:33:30.297] INFO: Test took 16963ms.
[12:33:30.805] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:33:31.173] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 3 3 0 0 0 0 0 0 0 1
[12:33:31.173] INFO: number of red-efficiency pixels: 411 216 660 1271 1125 1615 1291 954 621 934 1188 1003 859 405 93 107
[12:33:31.173] INFO: number of X-ray hits detected: 200659 139900 223066 353774 378524 397969 387810 278922 276910 352130 343490 306752 316391 189153 73280 87866
[12:33:31.173] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:33:31.173] INFO: number of Vcal hits detected: 207526 207763 207120 206324 206614 205683 206138 206566 207310 206900 206486 206728 206978 207522 207905 207842
[12:33:31.173] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.6 99.3 99.4 99.0 99.3 99.4 99.7 99.5 99.3 99.5 99.6 99.8 100.0 100.0
[12:33:31.173] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.6 99.2 99.3 98.9 99.1 99.3 99.7 99.5 99.3 99.4 99.5 99.8 100.0 99.9
[12:33:31.173] INFO: X-ray hit rate [MHz/cm2]: 58.8 41.0 65.4 103.7 110.9 116.6 113.7 81.8 81.2 103.2 100.7 89.9 92.7 55.4 21.5 25.8
[12:33:31.173] INFO: PixTestHighRate::doXPixelAlive() done
[12:33:31.217] INFO: PixTest:: pg_setup set to default.
[12:33:31.236] INFO: enter test to run
[12:34:29.089] INFO: test: exit no parameter change
[12:34:29.359] QUIET: Connection to board 33 closed.
[12:34:29.368] INFO: pXar: this is the end, my friend