[16:14:02.141] INFO: *** Welcome to pxar ***
[16:14:02.141] INFO: *** Today: 2016/06/06
[16:14:02.162] INFO: *** Version: v1.9.0-814-g7497
[16:14:02.162] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//dacParameters35_C15.dat
[16:14:02.163] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:14:02.163] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//defaultMaskFile.dat
[16:14:02.163] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C15.dat
[16:14:02.233] INFO: clk: 4
[16:14:02.233] INFO: ctr: 4
[16:14:02.233] INFO: sda: 19
[16:14:02.234] INFO: tin: 9
[16:14:02.234] INFO: level: 15
[16:14:02.234] INFO: triggerdelay: 0
[16:14:02.234] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[16:14:02.234] INFO: Log level: INFO
[16:14:02.251] QUIET: Connection to board DTB_WREK4U opened.
[16:14:02.255] 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:
------------------------------------------------------
[16:14:02.258] INFO: RPC call hashes of host and DTB match: 398089610
[16:14:03.787] INFO: DUT info:
[16:14:03.787] INFO: The DUT currently contains the following objects:
[16:14:03.787] INFO: 2 TBM Cores tbm08c (2 ON)
[16:14:03.787] INFO: TBM Core alpha (0): 7 registers set
[16:14:03.787] INFO: TBM Core beta (1): 7 registers set
[16:14:03.787] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[16:14:03.787] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.787] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.787] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.787] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:03.788] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[16:14:04.191] INFO: enter 'restricted' command line mode
[16:14:04.191] INFO: enter test to run
[16:14:05.367] INFO: test: timing no parameter change
[16:14:05.368] INFO: running: timing
[16:14:05.376] INFO: ######################################################################
[16:14:05.376] INFO: PixTestTiming::doTest()
[16:14:05.376] INFO: ######################################################################
[16:14:05.377] INFO: ----------------------------------------------------------------------
[16:14:05.377] INFO: PixTestTiming::TBMPhaseScan()
[16:14:05.377] INFO: ----------------------------------------------------------------------
[16:19:36.027] INFO: TBM Phase Settings: 192
[16:19:36.028] INFO: 400MHz Phase: 0
[16:19:36.028] INFO: 160MHz Phase: 6
[16:19:36.028] INFO: Functional Phase Area: 4
[16:19:36.031] INFO: Test took 330654 ms.
[16:19:36.031] INFO: PixTestTiming::TBMPhaseScan() done.
[16:19:36.031] INFO: ----------------------------------------------------------------------
[16:19:36.031] INFO: PixTestTiming::ROCDelayScan()
[16:19:36.031] INFO: ----------------------------------------------------------------------
[16:21:45.145] INFO: ROC Delay Settings: 227
[16:21:45.145] INFO: ROC Header-Trailer/Token Delay: 11
[16:21:45.145] INFO: ROC Port 0 Delay: 3
[16:21:45.145] INFO: ROC Port 1 Delay: 4
[16:21:45.145] INFO: Functional ROC Area: 5
[16:21:45.148] INFO: Test took 129117 ms.
[16:21:45.148] INFO: PixTestTiming::ROCDelayScan() done.
[16:21:45.149] INFO: ----------------------------------------------------------------------
[16:21:45.149] INFO: PixTestTiming::TimingTest()
[16:21:45.149] INFO: ----------------------------------------------------------------------
[16:22:01.525] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:22:16.674] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:22:31.673] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:22:46.643] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:23:01.637] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:23:16.610] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:23:31.583] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:23:46.562] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:01.534] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:16.467] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:16.849] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:24:16.867] INFO: ----------------------------------------------------------------------
[16:24:16.867] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[16:24:16.867] INFO: ----------------------------------------------------------------------
[16:24:16.867] INFO: ----------------------------------------------------------------------
[16:24:16.867] INFO: Read back bit status: 1
[16:24:16.867] INFO: ----------------------------------------------------------------------
[16:24:16.867] INFO: ----------------------------------------------------------------------
[16:24:16.867] INFO: Timings are good!
[16:24:16.867] INFO: ----------------------------------------------------------------------
[16:24:16.867] INFO: Test took 151719 ms.
[16:24:16.867] INFO: PixTestTiming::TimingTest() done.
[16:24:16.875] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//tbmParameters_C0a.dat
[16:24:16.875] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//tbmParameters_C0b.dat
[16:24:16.875] INFO: PixTestTiming::doTest took 611503 ms.
[16:24:16.875] INFO: PixTestTiming::doTest() done
[16:24:16.875] INFO: Write out TBMPhaseScan_0_V0
[16:24:16.911] INFO: Write out TBMPhaseScan_1_V0
[16:24:16.911] INFO: Write out CombinedTBMPhaseScan_V0
[16:24:16.912] INFO: Write out ROCDelayScan3_V0
[16:24:16.912] INFO: enter test to run
[16:25:02.995] INFO: test: PixelAlive no parameter change
[16:25:02.995] INFO: running: pixelalive
[16:25:02.999] INFO: ----------------------------------------------------------------------
[16:25:02.999] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[16:25:02.999] INFO: ----------------------------------------------------------------------
[16:25:03.317] INFO: Expecting 41600 events.
[16:25:07.632] INFO: 41600 events read in total (3600ms).
[16:25:07.632] INFO: Test took 4629ms.
[16:25:07.639] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:25:08.037] INFO: PixTestAlive::aliveTest() done
[16:25:08.037] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 2 0 1 0 2 0 0 0 0
[16:25:08.041] INFO: enter test to run
[16:26:21.762] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[16:26:21.762] INFO: running: highrate
[16:26:21.763] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[16:26:21.922] INFO: ----------------------------------------------------------------------
[16:26:21.922] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[16:26:21.922] INFO: ----------------------------------------------------------------------
[16:26:21.922] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[16:26:21.922] INFO: edge/corner pixel THR is adjusted
[16:26:21.922] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:26:22.879] INFO: Collecting data for 5 seconds...
[16:26:27.899] INFO: Done with hot pixel readout
[16:26:39.465] INFO: PixTest:: pg_setup set to default.
[16:26:39.466] INFO: 3 hot pixels found in step 0
[16:26:40.455] INFO: Collecting data for 5 seconds...
[16:26:45.471] INFO: Done with hot pixel readout
[16:26:56.800] INFO: PixTest:: pg_setup set to default.
[16:26:56.801] INFO: 0 hot pixels found in step 1
[16:26:56.834] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:26:56.837] INFO: PixTest::trimHotPixels() done
[16:26:56.837] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C0.dat
[16:26:56.843] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C1.dat
[16:26:56.850] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C2.dat
[16:26:56.855] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C3.dat
[16:26:56.861] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C4.dat
[16:26:56.866] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C5.dat
[16:26:56.872] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C6.dat
[16:26:56.877] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C7.dat
[16:26:56.883] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C8.dat
[16:26:56.888] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C9.dat
[16:26:56.894] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C10.dat
[16:26:56.899] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C11.dat
[16:26:56.904] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C12.dat
[16:26:56.910] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C13.dat
[16:26:56.915] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C14.dat
[16:26:56.920] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C15.dat
[16:26:56.926] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//defaultMaskFile.dat
[16:26:56.935] INFO: enter test to run
[16:27:59.234] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[16:27:59.234] INFO: running: highrate
[16:27:59.238] INFO: ----------------------------------------------------------------------
[16:27:59.238] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[16:27:59.238] INFO: ----------------------------------------------------------------------
[16:27:59.238] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[16:27:59.238] INFO: edge/corner pixel THR is adjusted
[16:27:59.238] INFO: PixTestHighRate::trimHotPixels: step 0...
[16:28:00.196] INFO: Collecting data for 1 seconds...
[16:28:01.200] INFO: Done with hot pixel readout
[16:28:04.867] INFO: PixTest:: pg_setup set to default.
[16:28:04.868] INFO: 0 hot pixels found in step 0
[16:28:04.875] INFO: 0 hot pixels could not be trimmed and have been masked.
[16:28:04.973] INFO: PixTest::trimHotPixels() done
[16:28:04.973] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C0.dat
[16:28:04.981] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C1.dat
[16:28:04.986] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C2.dat
[16:28:04.992] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C3.dat
[16:28:04.997] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C4.dat
[16:28:05.002] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C5.dat
[16:28:05.008] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C6.dat
[16:28:05.013] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C7.dat
[16:28:05.018] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C8.dat
[16:28:05.024] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C9.dat
[16:28:05.029] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C10.dat
[16:28:05.034] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C11.dat
[16:28:05.040] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C12.dat
[16:28:05.045] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C13.dat
[16:28:05.050] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C14.dat
[16:28:05.056] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//trimParameters35_C15.dat
[16:28:05.061] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-N-3-01_FPIXTest-17C-FNAL-160601-0922_2016-06-01_09h23m_1464790980/000_FPIXTest_p17//defaultMaskFile.dat
[16:28:05.074] INFO: enter test to run
[16:29:16.745] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[16:29:16.745] INFO: running: xray
[16:29:16.746] INFO: ----------------------------------------------------------------------
[16:29:16.746] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:29:16.746] INFO: ----------------------------------------------------------------------
[16:29:17.710] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:29:29.875] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[16:29:59.248] INFO: Resuming triggers.
[16:30:11.410] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[16:30:40.691] INFO: Resuming triggers.
[16:30:52.856] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[16:31:22.126] INFO: Resuming triggers.
[16:31:34.290] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[16:32:04.010] INFO: Resuming triggers.
[16:32:16.174] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[16:32:45.784] INFO: Resuming triggers.
[16:32:57.946] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[16:33:28.038] INFO: Resuming triggers.
[16:33:40.201] INFO: run duration 84 seconds, buffer almost full (81%), pausing triggers.
[16:34:09.681] INFO: Resuming triggers.
[16:34:21.844] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[16:34:51.044] INFO: Resuming triggers.
[16:34:54.080] INFO: data taking finished, elapsed time: 100 seconds.
[16:35:01.783] INFO: PixTest:: pg_setup set to default.
[16:35:01.786] INFO: PixTestXray::doPhRun() done
[16:35:01.919] INFO: enter test to run
[16:36:07.238] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[16:36:07.238] INFO: running: xray
[16:36:07.239] INFO: ----------------------------------------------------------------------
[16:36:07.239] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[16:36:07.239] INFO: ----------------------------------------------------------------------
[16:36:08.211] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[16:36:15.683] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[16:36:46.386] INFO: Resuming triggers.
[16:36:53.865] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[16:37:25.167] INFO: Resuming triggers.
[16:37:32.639] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[16:38:02.778] INFO: Resuming triggers.
[16:38:10.253] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[16:38:40.339] INFO: Resuming triggers.
[16:38:47.811] INFO: run duration 37 seconds, buffer almost full (81%), pausing triggers.
[16:39:17.938] INFO: Resuming triggers.
[16:39:25.412] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[16:39:55.586] INFO: Resuming triggers.
[16:40:03.057] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[16:40:33.068] INFO: Resuming triggers.
[16:40:40.536] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[16:41:10.674] INFO: Resuming triggers.
[16:41:18.145] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[16:41:48.212] INFO: Resuming triggers.
[16:41:55.682] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[16:42:25.796] INFO: Resuming triggers.
[16:42:33.264] INFO: run duration 81 seconds, buffer almost full (81%), pausing triggers.
[16:43:03.882] INFO: Resuming triggers.
[16:43:11.354] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[16:43:41.813] INFO: Resuming triggers.
[16:43:49.280] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[16:44:20.134] INFO: Resuming triggers.
[16:44:23.339] INFO: data taking finished, elapsed time: 100 seconds.
[16:44:36.850] INFO: PixTest:: pg_setup set to default.
[16:44:36.853] INFO: PixTestXray::doPhRun() done
[16:44:37.005] INFO: enter test to run
[16:46:40.593] INFO: test: HighRate no parameter change
[16:46:40.593] INFO: running: highrate
[16:46:40.605] INFO: ----------------------------------------------------------------------
[16:46:40.606] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[16:46:40.606] INFO: ----------------------------------------------------------------------
[16:46:40.761] INFO: Expecting 768 events.
[16:46:41.895] INFO: 768 events read in total (418ms).
[16:46:41.896] INFO: Test took 1269ms.
[16:46:42.699] INFO: Expecting 41600 events.
[16:46:45.782] INFO: 41600 events read in total (2556ms).
[16:46:45.783] INFO: Test took 3879ms.
[16:46:45.813] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:46:46.547] INFO: Expecting 41600 events.
[16:46:49.732] INFO: 41600 events read in total (2658ms).
[16:46:49.733] INFO: Test took 3903ms.
[16:46:49.764] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:46:50.494] INFO: Expecting 41600 events.
[16:46:53.656] INFO: 41600 events read in total (2635ms).
[16:46:53.657] INFO: Test took 3877ms.
[16:46:53.688] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:46:54.416] INFO: Expecting 41600 events.
[16:46:57.595] INFO: 41600 events read in total (2652ms).
[16:46:57.596] INFO: Test took 3891ms.
[16:46:57.627] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:46:58.360] INFO: Expecting 41600 events.
[16:47:01.555] INFO: 41600 events read in total (2668ms).
[16:47:01.556] INFO: Test took 3912ms.
[16:47:01.587] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:02.318] INFO: Expecting 41600 events.
[16:47:05.499] INFO: 41600 events read in total (2654ms).
[16:47:05.499] INFO: Test took 3895ms.
[16:47:05.530] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:06.258] INFO: Expecting 41600 events.
[16:47:09.472] INFO: 41600 events read in total (2687ms).
[16:47:09.473] INFO: Test took 3926ms.
[16:47:09.504] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:10.232] INFO: Expecting 41600 events.
[16:47:13.436] INFO: 41600 events read in total (2677ms).
[16:47:13.437] INFO: Test took 3916ms.
[16:47:13.467] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:14.201] INFO: Expecting 41600 events.
[16:47:17.402] INFO: 41600 events read in total (2675ms).
[16:47:17.403] INFO: Test took 3918ms.
[16:47:17.434] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:18.161] INFO: Expecting 41600 events.
[16:47:21.364] INFO: 41600 events read in total (2676ms).
[16:47:21.365] INFO: Test took 3915ms.
[16:47:21.396] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:22.126] INFO: Expecting 41600 events.
[16:47:25.328] INFO: 41600 events read in total (2675ms).
[16:47:25.329] INFO: Test took 3917ms.
[16:47:25.360] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:26.092] INFO: Expecting 41600 events.
[16:47:29.296] INFO: 41600 events read in total (2677ms).
[16:47:29.297] INFO: Test took 3920ms.
[16:47:29.328] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:30.057] INFO: Expecting 41600 events.
[16:47:33.371] INFO: 41600 events read in total (2787ms).
[16:47:33.372] INFO: Test took 4028ms.
[16:47:33.403] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:34.122] INFO: Expecting 41600 events.
[16:47:37.379] INFO: 41600 events read in total (2730ms).
[16:47:37.380] INFO: Test took 3960ms.
[16:47:37.411] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:38.135] INFO: Expecting 41600 events.
[16:47:41.417] INFO: 41600 events read in total (2755ms).
[16:47:41.418] INFO: Test took 3990ms.
[16:47:41.450] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:42.176] INFO: Expecting 41600 events.
[16:47:45.408] INFO: 41600 events read in total (2705ms).
[16:47:45.408] INFO: Test took 3942ms.
[16:47:45.440] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:46.168] INFO: Expecting 41600 events.
[16:47:49.455] INFO: 41600 events read in total (2761ms).
[16:47:49.456] INFO: Test took 3999ms.
[16:47:49.488] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:50.212] INFO: Expecting 41600 events.
[16:47:53.426] INFO: 41600 events read in total (2687ms).
[16:47:53.427] INFO: Test took 3922ms.
[16:47:53.459] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:54.182] INFO: Expecting 41600 events.
[16:47:57.352] INFO: 41600 events read in total (2643ms).
[16:47:57.353] INFO: Test took 3876ms.
[16:47:57.385] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:47:58.112] INFO: Expecting 41600 events.
[16:48:01.094] INFO: 41600 events read in total (2455ms).
[16:48:01.095] INFO: Test took 3692ms.
[16:48:01.126] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:48:01.495] INFO: enter test to run
[16:50:07.848] INFO: test: HighRate no parameter change
[16:50:07.848] INFO: running: highrate
[16:50:07.849] INFO: ----------------------------------------------------------------------
[16:50:07.849] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:50:07.849] INFO: ----------------------------------------------------------------------
[16:50:08.463] INFO: Expecting 208000 events.
[16:50:20.135] INFO: 208000 events read in total (11145ms).
[16:50:20.137] INFO: Test took 12279ms.
[16:50:20.267] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:50:20.514] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 2 0 1 0 2 0 0 0 0
[16:50:20.514] INFO: number of red-efficiency pixels: 58 57 74 95 108 150 102 91 76 94 110 85 77 59 20 17
[16:50:20.514] INFO: number of X-ray hits detected: 53256 38210 61122 97223 96504 104134 101375 74937 69644 81158 87939 76334 76067 46265 19407 24065
[16:50:20.514] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:50:20.514] INFO: number of Vcal hits detected: 207942 207943 207923 207904 207891 207848 207897 207804 207924 207856 207888 207817 207922 207941 207980 207982
[16:50:20.514] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0
[16:50:20.514] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 100.0 99.9 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0
[16:50:20.514] INFO: X-ray hit rate [MHz/cm2]: 15.6 11.2 17.9 28.5 28.3 30.5 29.7 22.0 20.4 23.8 25.8 22.4 22.3 13.6 5.7 7.1
[16:50:20.514] INFO: PixTestHighRate::doXPixelAlive() done
[16:50:20.559] INFO: PixTest:: pg_setup set to default.
[16:50:20.570] INFO: enter test to run
[16:53:20.070] INFO: test: HighRate no parameter change
[16:53:20.070] INFO: running: highrate
[16:53:20.072] INFO: ----------------------------------------------------------------------
[16:53:20.072] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:53:20.072] INFO: ----------------------------------------------------------------------
[16:53:20.688] INFO: Expecting 208000 events.
[16:53:33.737] INFO: 208000 events read in total (12522ms).
[16:53:33.742] INFO: Test took 13662ms.
[16:53:33.988] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:53:34.273] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 2 0 1 0 2 0 0 0 0
[16:53:34.273] INFO: number of red-efficiency pixels: 147 101 224 306 330 423 302 242 166 230 316 206 187 132 52 57
[16:53:34.273] INFO: number of X-ray hits detected: 105105 75266 120377 192355 189757 205182 198578 147876 137766 158792 173106 149746 149279 91803 38884 47855
[16:53:34.273] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:53:34.273] INFO: number of Vcal hits detected: 207850 207897 207762 207680 207651 207546 207686 207634 207832 207709 207668 207689 207808 207863 207946 207942
[16:53:34.273] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.9 99.9 99.8 99.9 99.9 99.9 99.9 99.8 99.9 99.9 99.9 100.0 100.0
[16:53:34.273] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.8 99.8 99.8 99.9 99.9 99.8 99.9 99.9 99.9 100.0 100.0
[16:53:34.273] INFO: X-ray hit rate [MHz/cm2]: 30.8 22.1 35.3 56.4 55.6 60.1 58.2 43.3 40.4 46.5 50.7 43.9 43.8 26.9 11.4 14.0
[16:53:34.274] INFO: PixTestHighRate::doXPixelAlive() done
[16:53:34.322] INFO: PixTest:: pg_setup set to default.
[16:53:34.341] INFO: enter test to run
[16:54:08.182] INFO: test: HighRate no parameter change
[16:54:08.182] INFO: running: highrate
[16:54:08.183] INFO: ----------------------------------------------------------------------
[16:54:08.183] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[16:54:08.183] INFO: ----------------------------------------------------------------------
[16:54:08.798] INFO: Expecting 208000 events.
[16:54:23.484] INFO: 208000 events read in total (14159ms).
[16:54:23.490] INFO: Test took 15298ms.
[16:54:23.858] INFO: Fetched DAQ statistics. Counters are being reset now.
[16:54:24.184] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 2 0 1 0 2 0 0 0 0
[16:54:24.184] INFO: number of red-efficiency pixels: 285 168 443 635 730 881 653 516 314 442 647 351 376 275 63 90
[16:54:24.184] INFO: number of X-ray hits detected: 153292 109655 176202 278893 274875 298310 288278 215633 200615 233049 251909 217307 217081 133560 56662 69688
[16:54:24.184] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[16:54:24.184] INFO: number of Vcal hits detected: 207685 207825 207475 207290 207152 206958 207265 207294 207668 207467 207263 207524 207594 207706 207936 207908
[16:54:24.184] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.6 99.5 99.7 99.7 99.9 99.8 99.7 99.8 99.8 99.9 100.0 100.0
[16:54:24.184] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.7 99.6 99.5 99.6 99.7 99.8 99.7 99.6 99.8 99.8 99.9 100.0 100.0
[16:54:24.184] INFO: X-ray hit rate [MHz/cm2]: 44.9 32.1 51.6 81.7 80.6 87.4 84.5 63.2 58.8 68.3 73.8 63.7 63.6 39.1 16.6 20.4
[16:54:24.184] INFO: PixTestHighRate::doXPixelAlive() done
[16:54:24.229] INFO: PixTest:: pg_setup set to default.
[16:54:24.243] INFO: enter test to run
[16:54:30.390] INFO: test: exit no parameter change
[16:54:30.778] QUIET: Connection to board 32 closed.
[16:54:30.779] INFO: pXar: this is the end, my friend