[12:53:58.756] INFO: *** Welcome to pxar ***
[12:53:58.756] INFO: *** Today: 2016/04/21
[12:53:58.775] INFO: *** Version: v1.9.0-796-gef167-dirty
[12:53:58.775] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//dacParameters35_C15.dat
[12:53:58.777] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//tbmParameters_C0b.dat
[12:53:58.777] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//defaultMaskFile.dat
[12:53:58.777] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C15.dat
[12:53:58.852] INFO: clk: 4
[12:53:58.853] INFO: ctr: 4
[12:53:58.853] INFO: sda: 19
[12:53:58.853] INFO: tin: 9
[12:53:58.853] INFO: level: 15
[12:53:58.853] INFO: triggerdelay: 0
[12:53:58.853] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[12:53:58.853] INFO: Log level: INFO
[12:53:58.870] QUIET: Connection to board DTB_WREK4U opened.
[12:53:58.874] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 32
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREK4U
MAC address: 40D855118020
Hostname: pixelDTB032
Comment:
------------------------------------------------------
[12:53:58.877] INFO: RPC call hashes of host and DTB match: 398089610
[12:54:00.405] INFO: DUT info:
[12:54:00.405] INFO: The DUT currently contains the following objects:
[12:54:00.405] INFO: 2 TBM Cores tbm08c (2 ON)
[12:54:00.405] INFO: TBM Core alpha (0): 7 registers set
[12:54:00.405] INFO: TBM Core beta (1): 7 registers set
[12:54:00.405] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[12:54:00.405] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.405] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[12:54:00.809] INFO: enter 'restricted' command line mode
[12:54:00.809] INFO: enter test to run
[12:54:06.310] INFO: test: PixelAlive no parameter change
[12:54:06.310] INFO: running: pixelalive
[12:54:06.320] INFO: ----------------------------------------------------------------------
[12:54:06.320] 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:54:06.320] INFO: ----------------------------------------------------------------------
[12:54:06.645] INFO: Expecting 41600 events.
[12:54:10.993] INFO: 41600 events read in total (3629ms).
[12:54:11.154] INFO: Test took 4832ms.
[12:54:11.167] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:54:11.428] INFO: PixTestAlive::aliveTest() done
[12:54:11.428] INFO: number of dead pixels (per ROC): 0 0 2 1 0 0 0 0 1 0 0 0 0 0 0 0
[12:54:11.463] INFO: enter test to run
[12:55:00.910] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[12:55:00.910] INFO: running: highrate
[12:55:00.910] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[12:55:01.062] INFO: ----------------------------------------------------------------------
[12:55:01.062] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[12:55:01.062] INFO: ----------------------------------------------------------------------
[12:55:01.062] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[12:55:01.062] INFO: edge/corner pixel THR is adjusted
[12:55:01.062] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:55:02.021] INFO: Collecting data for 5 seconds...
[12:55:07.038] INFO: Done with hot pixel readout
[12:55:18.828] INFO: PixTest:: pg_setup set to default.
[12:55:18.829] INFO: 13 hot pixels found in step 0
[12:55:19.818] INFO: Collecting data for 5 seconds...
[12:55:24.835] INFO: Done with hot pixel readout
[12:55:36.719] INFO: PixTest:: pg_setup set to default.
[12:55:36.720] INFO: 15 hot pixels found in step 1
[12:55:37.715] INFO: Collecting data for 5 seconds...
[12:55:42.730] INFO: Done with hot pixel readout
[12:55:54.630] INFO: PixTest:: pg_setup set to default.
[12:55:54.631] INFO: 9 hot pixels found in step 2
[12:55:55.625] INFO: Collecting data for 5 seconds...
[12:56:00.641] INFO: Done with hot pixel readout
[12:56:12.548] INFO: PixTest:: pg_setup set to default.
[12:56:12.549] INFO: 9 hot pixels found in step 3
[12:56:13.543] INFO: Collecting data for 5 seconds...
[12:56:18.559] INFO: Done with hot pixel readout
[12:56:30.475] INFO: PixTest:: pg_setup set to default.
[12:56:30.476] INFO: 9 hot pixels found in step 4
[12:56:31.470] INFO: Collecting data for 5 seconds...
[12:56:36.486] INFO: Done with hot pixel readout
[12:56:48.438] INFO: PixTest:: pg_setup set to default.
[12:56:48.439] INFO: 10 hot pixels found in step 5
[12:56:49.433] INFO: Collecting data for 5 seconds...
[12:56:54.450] INFO: Done with hot pixel readout
[12:57:06.428] INFO: PixTest:: pg_setup set to default.
[12:57:06.428] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:57:06.429] INFO: 12 hot pixels found in step 6
[12:57:07.423] INFO: Collecting data for 5 seconds...
[12:57:12.439] INFO: Done with hot pixel readout
[12:57:24.366] INFO: PixTest:: pg_setup set to default.
[12:57:24.366] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:57:24.366] INFO: 6 hot pixels found in step 7
[12:57:25.360] INFO: Collecting data for 5 seconds...
[12:57:30.377] INFO: Done with hot pixel readout
[12:57:42.293] INFO: PixTest:: pg_setup set to default.
[12:57:42.293] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:57:42.294] INFO: 5 hot pixels found in step 8
[12:57:43.287] INFO: Collecting data for 5 seconds...
[12:57:48.303] INFO: Done with hot pixel readout
[12:58:00.225] INFO: PixTest:: pg_setup set to default.
[12:58:00.225] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:58:00.226] INFO: 6 hot pixels found in step 9
[12:58:01.219] INFO: Collecting data for 5 seconds...
[12:58:06.236] INFO: Done with hot pixel readout
[12:58:18.196] INFO: PixTest:: pg_setup set to default.
[12:58:18.196] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:58:18.197] INFO: 4 hot pixels found in step 10
[12:58:19.191] INFO: Collecting data for 5 seconds...
[12:58:24.207] INFO: Done with hot pixel readout
[12:58:36.126] INFO: PixTest:: pg_setup set to default.
[12:58:36.127] INFO: 1 hot pixels found in step 11
[12:58:37.121] INFO: Collecting data for 5 seconds...
[12:58:42.137] INFO: Done with hot pixel readout
[12:58:53.995] INFO: PixTest:: pg_setup set to default.
[12:58:53.995] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:58:53.996] INFO: 3 hot pixels found in step 12
[12:58:54.989] INFO: Collecting data for 5 seconds...
[12:59:00.006] INFO: Done with hot pixel readout
[12:59:11.899] INFO: PixTest:: pg_setup set to default.
[12:59:11.899] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:59:11.899] WARNING: => trimBits already at highest possible threshold, 'real' hot pixel found
[12:59:11.900] INFO: 5 hot pixels found in step 13
[12:59:12.894] INFO: Collecting data for 5 seconds...
[12:59:17.910] INFO: Done with hot pixel readout
[12:59:29.877] INFO: PixTest:: pg_setup set to default.
[12:59:29.878] INFO: 2 hot pixels found in step 14
[12:59:29.915] INFO: 2 hot pixels could not be trimmed and have been masked.
[12:59:29.919] INFO: PixTest::trimHotPixels() done
[12:59:29.919] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C0.dat
[12:59:29.925] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C1.dat
[12:59:29.931] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C2.dat
[12:59:29.937] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C3.dat
[12:59:29.942] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C4.dat
[12:59:29.947] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C5.dat
[12:59:29.952] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C6.dat
[12:59:29.957] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C7.dat
[12:59:29.963] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C8.dat
[12:59:29.968] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C9.dat
[12:59:29.973] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C10.dat
[12:59:29.978] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C11.dat
[12:59:29.983] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C12.dat
[12:59:29.989] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C13.dat
[12:59:29.994] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C14.dat
[12:59:29.999] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C15.dat
[12:59:30.004] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//defaultMaskFile.dat
[12:59:30.015] INFO: enter test to run
[12:59:53.555] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[12:59:53.555] INFO: running: highrate
[12:59:53.560] INFO: ----------------------------------------------------------------------
[12:59:53.560] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[12:59:53.560] INFO: ----------------------------------------------------------------------
[12:59:53.560] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[12:59:53.560] INFO: edge/corner pixel THR is adjusted
[12:59:53.560] INFO: PixTestHighRate::trimHotPixels: step 0...
[12:59:54.519] INFO: Collecting data for 1 seconds...
[12:59:55.522] INFO: Done with hot pixel readout
[12:59:59.899] INFO: PixTest:: pg_setup set to default.
[12:59:59.900] INFO: 0 hot pixels found in step 0
[12:59:59.905] INFO: 0 hot pixels could not be trimmed and have been masked.
[12:59:59.983] INFO: PixTest::trimHotPixels() done
[12:59:59.983] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C0.dat
[12:59:59.994] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C1.dat
[12:59:59.000] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C2.dat
[13:00:00.005] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C3.dat
[13:00:00.010] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C4.dat
[13:00:00.016] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C5.dat
[13:00:00.021] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C6.dat
[13:00:00.026] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C7.dat
[13:00:00.031] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C8.dat
[13:00:00.037] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C9.dat
[13:00:00.042] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C10.dat
[13:00:00.047] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C11.dat
[13:00:00.053] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C12.dat
[13:00:00.058] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C13.dat
[13:00:00.063] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C14.dat
[13:00:00.068] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//trimParameters35_C15.dat
[13:00:00.073] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-M-3-02_FPIXTest-17C-FNAL-160418-0847_2016-04-18_08h47m_1460987273/000_FPIXTest_p17//defaultMaskFile.dat
[13:00:00.084] INFO: enter test to run
[13:00:20.755] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[13:00:20.755] INFO: running: xray
[13:00:20.756] INFO: ----------------------------------------------------------------------
[13:00:20.756] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:00:20.756] INFO: ----------------------------------------------------------------------
[13:00:21.720] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:00:32.952] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[13:01:02.359] INFO: Resuming triggers.
[13:01:13.594] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[13:01:43.131] INFO: Resuming triggers.
[13:01:54.362] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[13:02:23.853] INFO: Resuming triggers.
[13:02:35.085] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[13:03:04.477] INFO: Resuming triggers.
[13:03:15.707] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[13:03:45.183] INFO: Resuming triggers.
[13:03:56.417] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[13:04:25.355] INFO: Resuming triggers.
[13:04:36.585] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[13:05:05.977] INFO: Resuming triggers.
[13:05:17.211] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[13:05:46.731] INFO: Resuming triggers.
[13:05:57.186] INFO: data taking finished, elapsed time: 100 seconds.
[13:06:24.707] INFO: PixTest:: pg_setup set to default.
[13:06:24.710] INFO: PixTestXray::doPhRun() done
[13:06:24.897] INFO: enter test to run
[13:06:47.321] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[13:06:47.321] INFO: running: xray
[13:06:47.322] INFO: ----------------------------------------------------------------------
[13:06:47.322] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[13:06:47.322] INFO: ----------------------------------------------------------------------
[13:06:48.286] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[13:06:54.326] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[13:07:24.409] INFO: Resuming triggers.
[13:07:30.454] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[13:08:00.515] INFO: Resuming triggers.
[13:08:06.556] INFO: run duration 18 seconds, buffer almost full (81%), pausing triggers.
[13:08:36.522] INFO: Resuming triggers.
[13:08:42.564] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[13:09:12.612] INFO: Resuming triggers.
[13:09:18.651] INFO: run duration 30 seconds, buffer almost full (81%), pausing triggers.
[13:09:48.656] INFO: Resuming triggers.
[13:09:54.698] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[13:10:24.816] INFO: Resuming triggers.
[13:10:30.854] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[13:11:00.896] INFO: Resuming triggers.
[13:11:06.933] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[13:11:36.973] INFO: Resuming triggers.
[13:11:43.012] INFO: run duration 54 seconds, buffer almost full (81%), pausing triggers.
[13:12:13.114] INFO: Resuming triggers.
[13:12:19.153] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[13:12:49.235] INFO: Resuming triggers.
[13:12:55.277] INFO: run duration 66 seconds, buffer almost full (81%), pausing triggers.
[13:13:25.317] INFO: Resuming triggers.
[13:13:31.354] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[13:14:01.460] INFO: Resuming triggers.
[13:14:07.502] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[13:14:36.413] INFO: Resuming triggers.
[13:14:42.455] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[13:15:12.410] INFO: Resuming triggers.
[13:15:18.451] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[13:15:48.622] INFO: Resuming triggers.
[13:15:54.661] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[13:16:24.800] INFO: Resuming triggers.
[13:16:28.473] INFO: data taking finished, elapsed time: 100 seconds.
[13:16:47.086] INFO: PixTest:: pg_setup set to default.
[13:16:47.089] INFO: PixTestXray::doPhRun() done
[13:16:47.240] INFO: enter test to run
[13:17:03.548] INFO: test: HighRate no parameter change
[13:17:03.548] INFO: running: highrate
[13:17:03.570] INFO: ----------------------------------------------------------------------
[13:17:03.570] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[13:17:03.570] INFO: ----------------------------------------------------------------------
[13:17:03.735] INFO: Expecting 768 events.
[13:17:04.867] INFO: 768 events read in total (416ms).
[13:17:04.868] INFO: Test took 1268ms.
[13:17:05.671] INFO: Expecting 41600 events.
[13:17:08.794] INFO: 41600 events read in total (2596ms).
[13:17:08.795] INFO: Test took 3918ms.
[13:17:08.831] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:09.553] INFO: Expecting 41600 events.
[13:17:12.783] INFO: 41600 events read in total (2703ms).
[13:17:12.784] INFO: Test took 3933ms.
[13:17:12.819] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:13.542] INFO: Expecting 41600 events.
[13:17:16.805] INFO: 41600 events read in total (2736ms).
[13:17:16.806] INFO: Test took 3969ms.
[13:17:16.842] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:17.564] INFO: Expecting 41600 events.
[13:17:20.848] INFO: 41600 events read in total (2757ms).
[13:17:20.849] INFO: Test took 3987ms.
[13:17:20.886] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:21.605] INFO: Expecting 41600 events.
[13:17:24.881] INFO: 41600 events read in total (2749ms).
[13:17:24.882] INFO: Test took 3977ms.
[13:17:24.918] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:25.638] INFO: Expecting 41600 events.
[13:17:28.924] INFO: 41600 events read in total (2759ms).
[13:17:28.925] INFO: Test took 3988ms.
[13:17:28.961] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:29.679] INFO: Expecting 41600 events.
[13:17:32.971] INFO: 41600 events read in total (2765ms).
[13:17:32.972] INFO: Test took 3990ms.
[13:17:33.008] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:33.729] INFO: Expecting 41600 events.
[13:17:37.027] INFO: 41600 events read in total (2771ms).
[13:17:37.028] INFO: Test took 4000ms.
[13:17:37.064] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:37.785] INFO: Expecting 41600 events.
[13:17:41.083] INFO: 41600 events read in total (2771ms).
[13:17:41.084] INFO: Test took 4000ms.
[13:17:41.121] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:41.842] INFO: Expecting 41600 events.
[13:17:45.138] INFO: 41600 events read in total (2769ms).
[13:17:45.139] INFO: Test took 3998ms.
[13:17:45.175] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:45.896] INFO: Expecting 41600 events.
[13:17:49.161] INFO: 41600 events read in total (2738ms).
[13:17:49.162] INFO: Test took 3967ms.
[13:17:49.199] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:49.920] INFO: Expecting 41600 events.
[13:17:53.204] INFO: 41600 events read in total (2757ms).
[13:17:53.205] INFO: Test took 3984ms.
[13:17:53.240] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:53.963] INFO: Expecting 41600 events.
[13:17:57.255] INFO: 41600 events read in total (2765ms).
[13:17:57.256] INFO: Test took 3995ms.
[13:17:57.292] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:17:58.009] INFO: Expecting 41600 events.
[13:18:01.305] INFO: 41600 events read in total (2769ms).
[13:18:01.306] INFO: Test took 3994ms.
[13:18:01.343] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:18:02.065] INFO: Expecting 41600 events.
[13:18:05.358] INFO: 41600 events read in total (2766ms).
[13:18:05.360] INFO: Test took 3997ms.
[13:18:05.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:18:06.113] INFO: Expecting 41600 events.
[13:18:09.404] INFO: 41600 events read in total (2764ms).
[13:18:09.405] INFO: Test took 3990ms.
[13:18:09.441] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:18:10.164] INFO: Expecting 41600 events.
[13:18:13.449] INFO: 41600 events read in total (2758ms).
[13:18:13.450] INFO: Test took 3989ms.
[13:18:13.486] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:18:14.208] INFO: Expecting 41600 events.
[13:18:17.491] INFO: 41600 events read in total (2756ms).
[13:18:17.492] INFO: Test took 3985ms.
[13:18:17.528] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:18:18.249] INFO: Expecting 41600 events.
[13:18:21.511] INFO: 41600 events read in total (2735ms).
[13:18:21.512] INFO: Test took 3964ms.
[13:18:21.547] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:18:22.269] INFO: Expecting 41600 events.
[13:18:25.393] INFO: 41600 events read in total (2597ms).
[13:18:25.394] INFO: Test took 3826ms.
[13:18:25.429] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:18:25.782] INFO: enter test to run
[13:18:52.851] INFO: test: HighRate no parameter change
[13:18:52.851] INFO: running: highrate
[13:18:52.852] INFO: ----------------------------------------------------------------------
[13:18:52.852] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:18:52.852] INFO: ----------------------------------------------------------------------
[13:18:53.462] INFO: Expecting 208000 events.
[13:19:05.465] INFO: 208000 events read in total (11476ms).
[13:19:05.468] INFO: Test took 12608ms.
[13:19:05.623] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:19:05.879] INFO: number of dead pixels (per ROC): 0 0 1 1 0 0 0 0 1 0 0 0 0 0 0 0
[13:19:05.879] INFO: number of red-efficiency pixels: 109 50 97 167 147 170 166 107 112 137 158 130 140 64 34 41
[13:19:05.879] INFO: number of X-ray hits detected: 71036 46758 74731 114524 118731 121578 115820 86861 89625 106049 104574 89697 99120 57735 24463 29628
[13:19:05.879] 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:19:05.879] INFO: number of Vcal hits detected: 207889 207949 207852 207777 207848 207827 207831 207893 207834 207857 207838 207869 207857 207936 207966 207959
[13:19:05.880] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[13:19:05.880] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[13:19:05.880] INFO: X-ray hit rate [MHz/cm2]: 20.8 13.7 21.9 33.6 34.8 35.6 33.9 25.5 26.3 31.1 30.7 26.3 29.1 16.9 7.2 8.7
[13:19:05.880] INFO: PixTestHighRate::doXPixelAlive() done
[13:19:05.925] INFO: PixTest:: pg_setup set to default.
[13:19:05.937] INFO: enter test to run
[13:19:18.955] INFO: test: HighRate no parameter change
[13:19:18.955] INFO: running: highrate
[13:19:18.956] INFO: ----------------------------------------------------------------------
[13:19:18.956] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:19:18.956] INFO: ----------------------------------------------------------------------
[13:19:19.572] INFO: Expecting 208000 events.
[13:19:33.696] INFO: 208000 events read in total (13597ms).
[13:19:33.702] INFO: Test took 14737ms.
[13:19:34.032] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:19:34.344] INFO: number of dead pixels (per ROC): 0 0 1 1 0 0 0 0 1 0 0 0 0 0 0 0
[13:19:34.344] INFO: number of red-efficiency pixels: 288 141 392 635 522 705 624 343 332 411 530 418 426 199 67 85
[13:19:34.344] INFO: number of X-ray hits detected: 154719 101929 161200 250890 260541 264652 251538 190591 195488 234087 229724 196100 216208 126478 54435 64531
[13:19:34.344] 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:19:34.344] INFO: number of Vcal hits detected: 207691 207853 207509 207237 207440 207206 207309 207630 207604 207558 207404 207553 207541 207795 207932 207915
[13:19:34.344] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.8 99.6 99.7 99.8 99.8 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[13:19:34.344] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.6 99.7 99.6 99.7 99.8 99.8 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[13:19:34.344] INFO: X-ray hit rate [MHz/cm2]: 45.3 29.9 47.2 73.5 76.4 77.6 73.7 55.9 57.3 68.6 67.3 57.5 63.4 37.1 16.0 18.9
[13:19:34.344] INFO: PixTestHighRate::doXPixelAlive() done
[13:19:34.392] INFO: PixTest:: pg_setup set to default.
[13:19:34.411] INFO: enter test to run
[13:19:53.099] INFO: test: HighRate no parameter change
[13:19:53.099] INFO: running: highrate
[13:19:53.100] INFO: ----------------------------------------------------------------------
[13:19:53.100] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[13:19:53.100] INFO: ----------------------------------------------------------------------
[13:19:53.719] INFO: Expecting 208000 events.
[13:20:10.404] INFO: 208000 events read in total (16158ms).
[13:20:10.413] INFO: Test took 17304ms.
[13:20:10.948] INFO: Fetched DAQ statistics. Counters are being reset now.
[13:20:11.325] INFO: number of dead pixels (per ROC): 0 0 1 1 0 0 0 0 1 0 0 0 0 0 0 0
[13:20:11.325] INFO: number of red-efficiency pixels: 731 326 938 1633 1210 1818 1583 793 710 1066 1302 1014 978 491 138 162
[13:20:11.325] INFO: number of X-ray hits detected: 244595 160710 254268 395678 411919 417552 399511 301877 310429 368726 362537 310504 341528 201004 85746 101794
[13:20:11.325] 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:20:11.325] INFO: number of Vcal hits detected: 207049 207638 206524 205644 206414 205267 205796 206999 207137 206685 206334 206677 206812 207419 207851 207833
[13:20:11.325] INFO: Vcal hit fiducial efficiency (%): 99.6 99.8 99.4 99.0 99.3 98.8 99.0 99.6 99.6 99.4 99.3 99.4 99.5 99.7 99.9 99.9
[13:20:11.325] INFO: Vcal hit overall efficiency (%): 99.5 99.8 99.3 98.9 99.2 98.7 98.9 99.5 99.6 99.4 99.2 99.4 99.4 99.7 99.9 99.9
[13:20:11.325] INFO: X-ray hit rate [MHz/cm2]: 71.7 47.1 74.5 116.0 120.7 122.4 117.1 88.5 91.0 108.1 106.3 91.0 100.1 58.9 25.1 29.8
[13:20:11.325] INFO: PixTestHighRate::doXPixelAlive() done
[13:20:11.371] INFO: PixTest:: pg_setup set to default.
[13:20:11.387] INFO: enter test to run
[13:20:13.810] INFO: test: exit no parameter change
[13:20:14.166] QUIET: Connection to board 32 closed.
[13:20:14.168] INFO: pXar: this is the end, my friend