[10:54:13.151] INFO: *** Welcome to pxar ***
[10:54:13.151] INFO: *** Today: 2016/05/09
[10:54:13.553] INFO: *** Version: v1.9.0-796-gef167-dirty
[10:54:13.553] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//dacParameters35_C15.dat
[10:54:13.611] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:54:13.611] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//defaultMaskFile.dat
[10:54:13.614] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C15.dat
[10:54:13.753] INFO: clk: 4
[10:54:13.753] INFO: ctr: 4
[10:54:13.753] INFO: sda: 19
[10:54:13.753] INFO: tin: 9
[10:54:13.753] INFO: level: 15
[10:54:13.753] INFO: triggerdelay: 0
[10:54:13.753] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[10:54:13.753] INFO: Log level: INFO
[10:54:13.771] QUIET: Connection to board DTB_WREKRL opened.
[10:54:13.774] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[10:54:13.777] INFO: RPC call hashes of host and DTB match: 398089610
[10:54:15.322] INFO: DUT info:
[10:54:15.322] INFO: The DUT currently contains the following objects:
[10:54:15.322] INFO: 2 TBM Cores tbm08c (2 ON)
[10:54:15.336] INFO: TBM Core alpha (0): 7 registers set
[10:54:15.336] INFO: TBM Core beta (1): 7 registers set
[10:54:15.336] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[10:54:15.336] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.336] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[10:54:15.774] INFO: enter 'restricted' command line mode
[10:54:15.774] INFO: enter test to run
[10:54:19.550] INFO: test: PixelAlive no parameter change
[10:54:19.550] INFO: running: pixelalive
[10:54:19.600] INFO: ----------------------------------------------------------------------
[10:54:19.600] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[10:54:19.600] INFO: ----------------------------------------------------------------------
[10:54:19.916] INFO: Expecting 41600 events.
[10:54:24.244] INFO: 41600 events read in total (3610ms).
[10:54:24.414] INFO: Test took 4810ms.
[10:54:24.424] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:54:24.704] INFO: PixTestAlive::aliveTest() done
[10:54:24.704] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 5 0 0 0 0 0 0 0 1 0
[10:54:24.740] INFO: enter test to run
[10:54:51.110] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:54:51.110] INFO: running: highrate
[10:54:51.110] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:54:51.339] INFO: ----------------------------------------------------------------------
[10:54:51.339] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:54:51.339] INFO: ----------------------------------------------------------------------
[10:54:51.339] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:54:51.339] INFO: edge/corner pixel THR is adjusted
[10:54:51.339] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:54:52.317] INFO: Collecting data for 5 seconds...
[10:54:57.334] INFO: Done with hot pixel readout
[10:55:08.964] INFO: PixTest:: pg_setup set to default.
[10:55:08.965] INFO: 8 hot pixels found in step 0
[10:55:09.956] INFO: Collecting data for 5 seconds...
[10:55:14.973] INFO: Done with hot pixel readout
[10:55:26.533] INFO: PixTest:: pg_setup set to default.
[10:55:26.534] INFO: 5 hot pixels found in step 1
[10:55:27.529] INFO: Collecting data for 5 seconds...
[10:55:32.545] INFO: Done with hot pixel readout
[10:55:44.179] INFO: PixTest:: pg_setup set to default.
[10:55:44.180] INFO: 5 hot pixels found in step 2
[10:55:45.172] INFO: Collecting data for 5 seconds...
[10:55:50.189] INFO: Done with hot pixel readout
[10:56:01.871] INFO: PixTest:: pg_setup set to default.
[10:56:01.873] INFO: 3 hot pixels found in step 3
[10:56:02.869] INFO: Collecting data for 5 seconds...
[10:56:07.888] INFO: Done with hot pixel readout
[10:56:19.112] INFO: PixTest:: pg_setup set to default.
[10:56:19.113] INFO: 0 hot pixels found in step 4
[10:56:19.150] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:56:19.154] INFO: PixTest::trimHotPixels() done
[10:56:19.154] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C0.dat
[10:56:19.159] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C1.dat
[10:56:19.165] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C2.dat
[10:56:19.171] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C3.dat
[10:56:19.190] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C4.dat
[10:56:19.197] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C5.dat
[10:56:19.202] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C6.dat
[10:56:19.208] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C7.dat
[10:56:19.213] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C8.dat
[10:56:19.219] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C9.dat
[10:56:19.224] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C10.dat
[10:56:19.229] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C11.dat
[10:56:19.235] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C12.dat
[10:56:19.240] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C13.dat
[10:56:19.245] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C14.dat
[10:56:19.251] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C15.dat
[10:56:19.256] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//defaultMaskFile.dat
[10:56:19.266] INFO: enter test to run
[10:56:44.989] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:56:44.989] INFO: running: highrate
[10:56:44.993] INFO: ----------------------------------------------------------------------
[10:56:44.993] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:56:44.993] INFO: ----------------------------------------------------------------------
[10:56:44.993] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:56:44.993] INFO: edge/corner pixel THR is adjusted
[10:56:44.993] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:56:45.950] INFO: Collecting data for 1 seconds...
[10:56:46.954] INFO: Done with hot pixel readout
[10:56:50.797] INFO: PixTest:: pg_setup set to default.
[10:56:50.798] INFO: 1 hot pixels found in step 0
[10:56:51.829] INFO: Collecting data for 1 seconds...
[10:56:52.833] INFO: Done with hot pixel readout
[10:56:56.837] INFO: PixTest:: pg_setup set to default.
[10:56:56.838] INFO: 1 hot pixels found in step 1
[10:56:57.888] INFO: Collecting data for 1 seconds...
[10:56:58.892] INFO: Done with hot pixel readout
[10:57:02.918] INFO: PixTest:: pg_setup set to default.
[10:57:02.919] INFO: 1 hot pixels found in step 2
[10:57:03.970] INFO: Collecting data for 1 seconds...
[10:57:04.973] INFO: Done with hot pixel readout
[10:57:08.964] INFO: PixTest:: pg_setup set to default.
[10:57:08.965] INFO: 1 hot pixels found in step 3
[10:57:10.010] INFO: Collecting data for 1 seconds...
[10:57:11.014] INFO: Done with hot pixel readout
[10:57:15.033] INFO: PixTest:: pg_setup set to default.
[10:57:15.034] INFO: 0 hot pixels found in step 4
[10:57:15.039] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:57:15.130] INFO: PixTest::trimHotPixels() done
[10:57:15.130] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C0.dat
[10:57:15.142] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C1.dat
[10:57:15.149] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C2.dat
[10:57:15.155] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C3.dat
[10:57:15.160] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C4.dat
[10:57:15.165] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C5.dat
[10:57:15.170] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C6.dat
[10:57:15.175] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C7.dat
[10:57:15.181] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C8.dat
[10:57:15.186] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C9.dat
[10:57:15.191] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C10.dat
[10:57:15.196] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C11.dat
[10:57:15.202] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C12.dat
[10:57:15.207] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C13.dat
[10:57:15.212] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C14.dat
[10:57:15.217] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//trimParameters35_C15.dat
[10:57:15.223] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-3-28_FPIXTest-17C-FNAL-160503-1259_2016-05-03_12h59m_1462298381/000_FPIXTest_p17//defaultMaskFile.dat
[10:57:15.232] INFO: enter test to run
[10:57:38.877] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:57:38.877] INFO: running: xray
[10:57:38.878] INFO: ----------------------------------------------------------------------
[10:57:38.878] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:57:38.878] INFO: ----------------------------------------------------------------------
[10:57:39.841] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:57:51.404] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[10:58:20.584] INFO: Resuming triggers.
[10:58:32.149] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[10:59:01.399] INFO: Resuming triggers.
[10:59:12.963] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[10:59:41.724] INFO: Resuming triggers.
[10:59:53.277] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:00:22.658] INFO: Resuming triggers.
[11:00:34.212] INFO: run duration 57 seconds, buffer almost full (81%), pausing triggers.
[11:01:03.585] INFO: Resuming triggers.
[11:01:15.151] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[11:01:44.553] INFO: Resuming triggers.
[11:01:56.120] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:02:25.458] INFO: Resuming triggers.
[11:02:37.020] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[11:03:06.350] INFO: Resuming triggers.
[11:03:14.208] INFO: data taking finished, elapsed time: 100 seconds.
[11:03:34.302] INFO: PixTest:: pg_setup set to default.
[11:03:34.305] INFO: PixTestXray::doPhRun() done
[11:03:34.442] INFO: enter test to run
[11:03:58.146] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:03:58.146] INFO: running: xray
[11:03:58.147] INFO: ----------------------------------------------------------------------
[11:03:58.147] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:03:58.147] INFO: ----------------------------------------------------------------------
[11:03:59.111] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:04:05.845] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:04:36.032] INFO: Resuming triggers.
[11:04:42.766] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[11:05:12.869] INFO: Resuming triggers.
[11:05:19.601] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[11:05:49.700] INFO: Resuming triggers.
[11:05:56.434] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[11:06:26.503] INFO: Resuming triggers.
[11:06:33.237] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[11:07:03.227] INFO: Resuming triggers.
[11:07:09.958] INFO: run duration 40 seconds, buffer almost full (81%), pausing triggers.
[11:07:41.010] INFO: Resuming triggers.
[11:07:47.739] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[11:08:17.432] INFO: Resuming triggers.
[11:08:24.160] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[11:08:55.287] INFO: Resuming triggers.
[11:09:02.017] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[11:09:33.304] INFO: Resuming triggers.
[11:09:40.032] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[11:10:10.696] INFO: Resuming triggers.
[11:10:17.426] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[11:10:47.566] INFO: Resuming triggers.
[11:10:54.296] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[11:11:24.446] INFO: Resuming triggers.
[11:11:31.178] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[11:12:01.327] INFO: Resuming triggers.
[11:12:08.057] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[11:12:38.213] INFO: Resuming triggers.
[11:12:44.327] INFO: data taking finished, elapsed time: 100 seconds.
[11:13:11.993] INFO: PixTest:: pg_setup set to default.
[11:13:11.997] INFO: PixTestXray::doPhRun() done
[11:13:12.147] INFO: enter test to run
[11:14:28.221] INFO: test: HighRate no parameter change
[11:14:28.221] INFO: running: highrate
[11:14:28.222] INFO: ----------------------------------------------------------------------
[11:14:28.222] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:14:28.222] INFO: ----------------------------------------------------------------------
[11:14:28.364] INFO: Expecting 768 events.
[11:14:29.511] INFO: 768 events read in total (432ms).
[11:14:29.511] INFO: Test took 1281ms.
[11:14:30.314] INFO: Expecting 41600 events.
[11:14:33.415] INFO: 41600 events read in total (2574ms).
[11:14:33.416] INFO: Test took 3897ms.
[11:14:33.448] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:34.178] INFO: Expecting 41600 events.
[11:14:37.377] INFO: 41600 events read in total (2673ms).
[11:14:37.378] INFO: Test took 3912ms.
[11:14:37.412] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:38.136] INFO: Expecting 41600 events.
[11:14:41.362] INFO: 41600 events read in total (2699ms).
[11:14:41.363] INFO: Test took 3933ms.
[11:14:41.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:42.121] INFO: Expecting 41600 events.
[11:14:45.350] INFO: 41600 events read in total (2702ms).
[11:14:45.351] INFO: Test took 3937ms.
[11:14:45.384] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:46.111] INFO: Expecting 41600 events.
[11:14:49.342] INFO: 41600 events read in total (2704ms).
[11:14:49.343] INFO: Test took 3941ms.
[11:14:49.377] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:50.102] INFO: Expecting 41600 events.
[11:14:53.341] INFO: 41600 events read in total (2712ms).
[11:14:53.342] INFO: Test took 3947ms.
[11:14:53.375] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:54.101] INFO: Expecting 41600 events.
[11:14:57.348] INFO: 41600 events read in total (2720ms).
[11:14:57.349] INFO: Test took 3957ms.
[11:14:57.382] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:58.108] INFO: Expecting 41600 events.
[11:15:01.346] INFO: 41600 events read in total (2711ms).
[11:15:01.347] INFO: Test took 3947ms.
[11:15:01.380] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:02.107] INFO: Expecting 41600 events.
[11:15:05.338] INFO: 41600 events read in total (2704ms).
[11:15:05.339] INFO: Test took 3941ms.
[11:15:05.372] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:06.098] INFO: Expecting 41600 events.
[11:15:09.338] INFO: 41600 events read in total (2713ms).
[11:15:09.339] INFO: Test took 3948ms.
[11:15:09.372] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:10.100] INFO: Expecting 41600 events.
[11:15:13.333] INFO: 41600 events read in total (2707ms).
[11:15:13.334] INFO: Test took 3945ms.
[11:15:13.367] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:14.094] INFO: Expecting 41600 events.
[11:15:17.316] INFO: 41600 events read in total (2695ms).
[11:15:17.317] INFO: Test took 3932ms.
[11:15:17.350] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:18.078] INFO: Expecting 41600 events.
[11:15:21.321] INFO: 41600 events read in total (2716ms).
[11:15:21.322] INFO: Test took 3953ms.
[11:15:21.354] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:22.077] INFO: Expecting 41600 events.
[11:15:25.307] INFO: 41600 events read in total (2703ms).
[11:15:25.308] INFO: Test took 3936ms.
[11:15:25.342] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:26.067] INFO: Expecting 41600 events.
[11:15:29.303] INFO: 41600 events read in total (2709ms).
[11:15:29.304] INFO: Test took 3944ms.
[11:15:29.338] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:30.064] INFO: Expecting 41600 events.
[11:15:33.321] INFO: 41600 events read in total (2730ms).
[11:15:33.322] INFO: Test took 3967ms.
[11:15:33.356] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:34.078] INFO: Expecting 41600 events.
[11:15:37.321] INFO: 41600 events read in total (2716ms).
[11:15:37.322] INFO: Test took 3947ms.
[11:15:37.355] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:38.082] INFO: Expecting 41600 events.
[11:15:41.325] INFO: 41600 events read in total (2717ms).
[11:15:41.326] INFO: Test took 3953ms.
[11:15:41.359] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:42.083] INFO: Expecting 41600 events.
[11:15:45.276] INFO: 41600 events read in total (2666ms).
[11:15:45.277] INFO: Test took 3899ms.
[11:15:45.310] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:46.038] INFO: Expecting 41600 events.
[11:15:49.087] INFO: 41600 events read in total (2522ms).
[11:15:49.088] INFO: Test took 3760ms.
[11:15:49.120] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:49.486] INFO: enter test to run
[11:16:24.836] INFO: test: HighRate no parameter change
[11:16:24.836] INFO: running: highrate
[11:16:24.837] INFO: ----------------------------------------------------------------------
[11:16:24.837] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:16:24.837] INFO: ----------------------------------------------------------------------
[11:16:25.457] INFO: Expecting 208000 events.
[11:16:37.262] INFO: 208000 events read in total (11278ms).
[11:16:37.265] INFO: Test took 12420ms.
[11:16:37.405] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:16:37.655] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 6 0 0 0 0 0 0 0 1 0
[11:16:37.655] INFO: number of red-efficiency pixels: 99 46 94 1896 129 139 148 64 99 76 116 95 94 40 18 19
[11:16:37.655] INFO: number of X-ray hits detected: 63345 42770 64956 107400 109572 113351 115338 76362 78547 86215 90534 76497 81045 47986 20845 22788
[11:16:37.655] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:16:37.655] INFO: number of Vcal hits detected: 207900 207953 207905 206037 207870 207857 207556 207935 207898 207923 207884 207904 207903 207960 207933 207981
[11:16:37.655] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.1 99.9 99.9 99.9 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[11:16:37.655] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.1 99.9 99.9 99.8 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[11:16:37.655] INFO: X-ray hit rate [MHz/cm2]: 18.6 12.5 19.0 31.5 32.1 33.2 33.8 22.4 23.0 25.3 26.5 22.4 23.8 14.1 6.1 6.7
[11:16:37.655] INFO: PixTestHighRate::doXPixelAlive() done
[11:16:37.704] INFO: PixTest:: pg_setup set to default.
[11:16:37.718] INFO: enter test to run
[11:16:53.708] INFO: test: HighRate no parameter change
[11:16:53.708] INFO: running: highrate
[11:16:53.709] INFO: ----------------------------------------------------------------------
[11:16:53.709] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:16:53.710] INFO: ----------------------------------------------------------------------
[11:16:54.323] INFO: Expecting 208000 events.
[11:17:07.906] INFO: 208000 events read in total (13056ms).
[11:17:07.911] INFO: Test took 14192ms.
[11:17:08.202] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:08.500] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 6 0 0 0 0 0 0 0 1 0
[11:17:08.500] INFO: number of red-efficiency pixels: 239 136 278 1031 410 427 453 270 230 268 395 250 274 146 54 41
[11:17:08.500] INFO: number of X-ray hits detected: 135788 90862 140503 226866 234255 243193 247223 164039 168782 185359 192746 164356 172432 102546 44614 48885
[11:17:08.500] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:17:08.500] INFO: number of Vcal hits detected: 207742 207859 207700 206859 207556 207545 207218 207702 207762 207715 207587 207735 207718 207845 207895 207959
[11:17:08.500] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.5 99.8 99.8 99.8 99.9 99.9 99.9 99.8 99.9 99.9 99.9 100.0 100.0
[11:17:08.500] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.5 99.8 99.8 99.6 99.9 99.9 99.9 99.8 99.9 99.9 99.9 99.9 100.0
[11:17:08.500] INFO: X-ray hit rate [MHz/cm2]: 39.8 26.6 41.2 66.5 68.7 71.3 72.5 48.1 49.5 54.3 56.5 48.2 50.5 30.1 13.1 14.3
[11:17:08.500] INFO: PixTestHighRate::doXPixelAlive() done
[11:17:08.546] INFO: PixTest:: pg_setup set to default.
[11:17:08.561] INFO: enter test to run
[11:17:41.228] INFO: test: HighRate no parameter change
[11:17:41.228] INFO: running: highrate
[11:17:41.229] INFO: ----------------------------------------------------------------------
[11:17:41.229] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:17:41.229] INFO: ----------------------------------------------------------------------
[11:17:41.849] INFO: Expecting 208000 events.
[11:17:57.294] INFO: 208000 events read in total (14918ms).
[11:17:57.301] INFO: Test took 16064ms.
[11:17:57.742] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:58.088] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 6 0 0 0 0 0 0 0 1 0
[11:17:58.088] INFO: number of red-efficiency pixels: 464 268 617 1298 895 965 1058 636 519 610 910 594 623 321 81 84
[11:17:58.088] INFO: number of X-ray hits detected: 206027 137902 212546 341303 354876 366393 372353 247594 255022 280927 293883 247852 261159 155656 68171 74337
[11:17:58.088] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:17:58.088] INFO: number of Vcal hits detected: 207443 207717 207189 206326 206911 206811 206404 207227 207440 207331 206940 207311 207301 207653 207867 207915
[11:17:58.088] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.3 99.5 99.5 99.4 99.7 99.7 99.7 99.5 99.7 99.7 99.8 100.0 100.0
[11:17:58.088] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.6 99.2 99.5 99.4 99.2 99.6 99.7 99.7 99.5 99.7 99.7 99.8 99.9 100.0
[11:17:58.088] INFO: X-ray hit rate [MHz/cm2]: 60.4 40.4 62.3 100.0 104.0 107.4 109.1 72.6 74.7 82.3 86.1 72.6 76.5 45.6 20.0 21.8
[11:17:58.088] INFO: PixTestHighRate::doXPixelAlive() done
[11:17:58.134] INFO: PixTest:: pg_setup set to default.
[11:17:58.148] INFO: enter test to run
[11:18:12.859] INFO: test: exit no parameter change
[11:18:13.237] QUIET: Connection to board 33 closed.
[11:18:13.238] INFO: pXar: this is the end, my friend