[11:41:25.386] INFO: *** Welcome to pxar ***
[11:41:25.386] INFO: *** Today: 2016/04/11
[11:41:25.405] INFO: *** Version: v1.9.0-796-gef167-dirty
[11:41:25.405] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//dacParameters35_C15.dat
[11:41:25.432] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:41:25.432] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//defaultMaskFile.dat
[11:41:25.438] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C15.dat
[11:41:25.533] INFO: clk: 4
[11:41:25.533] INFO: ctr: 4
[11:41:25.533] INFO: sda: 19
[11:41:25.533] INFO: tin: 9
[11:41:25.533] INFO: level: 15
[11:41:25.533] INFO: triggerdelay: 0
[11:41:25.533] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[11:41:25.533] INFO: Log level: INFO
[11:41:25.552] QUIET: Connection to board DTB_WREKRL opened.
[11:41:25.556] 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:
------------------------------------------------------
[11:41:25.559] INFO: RPC call hashes of host and DTB match: 398089610
[11:41:27.088] INFO: DUT info:
[11:41:27.088] INFO: The DUT currently contains the following objects:
[11:41:27.088] INFO: 2 TBM Cores tbm08c (2 ON)
[11:41:27.088] INFO: TBM Core alpha (0): 7 registers set
[11:41:27.089] INFO: TBM Core beta (1): 7 registers set
[11:41:27.089] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[11:41:27.089] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.089] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[11:41:27.493] INFO: enter 'restricted' command line mode
[11:41:27.493] INFO: enter test to run
[11:41:45.381] INFO: test: timing no parameter change
[11:41:45.381] INFO: running: timing
[11:41:45.390] INFO: ######################################################################
[11:41:45.390] INFO: PixTestTiming::doTest()
[11:41:45.390] INFO: ######################################################################
[11:41:45.390] INFO: ----------------------------------------------------------------------
[11:41:45.390] INFO: PixTestTiming::TBMPhaseScan()
[11:41:45.390] INFO: ----------------------------------------------------------------------
[11:48:54.230] INFO: TBM Phase Settings: 224
[11:48:54.230] INFO: 400MHz Phase: 0
[11:48:54.230] INFO: 160MHz Phase: 7
[11:48:54.230] INFO: Functional Phase Area: 3
[11:48:54.233] INFO: Test took 428843 ms.
[11:48:54.233] INFO: PixTestTiming::TBMPhaseScan() done.
[11:48:54.234] INFO: ----------------------------------------------------------------------
[11:48:54.234] INFO: PixTestTiming::ROCDelayScan()
[11:48:54.234] INFO: ----------------------------------------------------------------------
[11:51:06.665] INFO: ROC Delay Settings: 228
[11:51:06.665] INFO: ROC Header-Trailer/Token Delay: 11
[11:51:06.665] INFO: ROC Port 0 Delay: 4
[11:51:06.665] INFO: ROC Port 1 Delay: 4
[11:51:06.665] INFO: Functional ROC Area: 5
[11:51:06.668] INFO: Test took 132435 ms.
[11:51:06.668] INFO: PixTestTiming::ROCDelayScan() done.
[11:51:06.669] INFO: ----------------------------------------------------------------------
[11:51:06.669] INFO: PixTestTiming::TimingTest()
[11:51:06.669] INFO: ----------------------------------------------------------------------
[11:51:22.818] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:37.823] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:51:52.789] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:52:07.772] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:52:22.736] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:52:37.704] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:52:52.691] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:53:07.668] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:53:22.646] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:53:37.640] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:53:38.018] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:53:38.035] INFO: ----------------------------------------------------------------------
[11:53:38.035] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[11:53:38.035] INFO: ----------------------------------------------------------------------
[11:53:38.035] INFO: ----------------------------------------------------------------------
[11:53:38.035] INFO: Read back bit status: 1
[11:53:38.035] INFO: ----------------------------------------------------------------------
[11:53:38.035] INFO: ----------------------------------------------------------------------
[11:53:38.035] INFO: Timings are good!
[11:53:38.035] INFO: ----------------------------------------------------------------------
[11:53:38.035] INFO: Test took 151366 ms.
[11:53:38.035] INFO: PixTestTiming::TimingTest() done.
[11:53:38.035] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//tbmParameters_C0a.dat
[11:53:38.035] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//tbmParameters_C0b.dat
[11:53:38.035] INFO: PixTestTiming::doTest took 712650 ms.
[11:53:38.035] INFO: PixTestTiming::doTest() done
[11:53:38.035] INFO: Write out TBMPhaseScan_0_V0
[11:53:38.061] INFO: Write out TBMPhaseScan_1_V0
[11:53:38.061] INFO: Write out CombinedTBMPhaseScan_V0
[11:53:38.062] INFO: Write out ROCDelayScan3_V0
[11:53:38.062] INFO: enter test to run
[11:55:36.054] INFO: test: PixelAlive no parameter change
[11:55:36.055] INFO: running: pixelalive
[11:55:36.059] INFO: ----------------------------------------------------------------------
[11:55:36.059] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[11:55:36.059] INFO: ----------------------------------------------------------------------
[11:55:36.381] INFO: Expecting 41600 events.
[11:55:40.699] INFO: 41600 events read in total (3602ms).
[11:55:40.700] INFO: Test took 4638ms.
[11:55:40.706] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:55:41.104] INFO: PixTestAlive::aliveTest() done
[11:55:41.105] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 3 0
[11:55:41.108] INFO: enter test to run
[11:56:09.966] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[11:56:09.966] INFO: running: highrate
[11:56:09.967] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[11:56:10.166] INFO: ----------------------------------------------------------------------
[11:56:10.166] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[11:56:10.166] INFO: ----------------------------------------------------------------------
[11:56:10.166] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[11:56:10.166] INFO: edge/corner pixel THR is adjusted
[11:56:10.166] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:56:11.125] INFO: Collecting data for 5 seconds...
[11:56:16.141] INFO: Done with hot pixel readout
[11:56:26.700] INFO: PixTest:: pg_setup set to default.
[11:56:26.701] INFO: 0 hot pixels found in step 0
[11:56:26.723] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:56:26.753] INFO: PixTest::trimHotPixels() done
[11:56:26.754] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C0.dat
[11:56:26.765] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C1.dat
[11:56:26.771] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C2.dat
[11:56:26.776] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C3.dat
[11:56:26.781] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C4.dat
[11:56:26.787] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C5.dat
[11:56:26.792] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C6.dat
[11:56:26.797] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C7.dat
[11:56:26.802] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C8.dat
[11:56:26.808] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C9.dat
[11:56:26.813] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C10.dat
[11:56:26.818] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C11.dat
[11:56:26.824] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C12.dat
[11:56:26.829] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C13.dat
[11:56:26.834] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C14.dat
[11:56:26.840] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C15.dat
[11:56:26.845] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//defaultMaskFile.dat
[11:56:26.855] INFO: enter test to run
[11:56:52.998] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[11:56:52.998] INFO: running: highrate
[11:56:52.002] INFO: ----------------------------------------------------------------------
[11:56:52.002] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[11:56:52.002] INFO: ----------------------------------------------------------------------
[11:56:52.002] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[11:56:52.003] INFO: edge/corner pixel THR is adjusted
[11:56:52.003] INFO: PixTestHighRate::trimHotPixels: step 0...
[11:56:53.960] INFO: Collecting data for 1 seconds...
[11:56:54.963] INFO: Done with hot pixel readout
[11:56:58.429] INFO: PixTest:: pg_setup set to default.
[11:56:58.430] INFO: 0 hot pixels found in step 0
[11:56:58.437] INFO: 0 hot pixels could not be trimmed and have been masked.
[11:56:58.548] INFO: PixTest::trimHotPixels() done
[11:56:58.548] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C0.dat
[11:56:58.556] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C1.dat
[11:56:58.562] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C2.dat
[11:56:58.567] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C3.dat
[11:56:58.572] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C4.dat
[11:56:58.577] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C5.dat
[11:56:58.583] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C6.dat
[11:56:58.588] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C7.dat
[11:56:58.593] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C8.dat
[11:56:58.598] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C9.dat
[11:56:58.603] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C10.dat
[11:56:58.609] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C11.dat
[11:56:58.614] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C12.dat
[11:56:58.619] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C13.dat
[11:56:58.624] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C14.dat
[11:56:58.630] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//trimParameters35_C15.dat
[11:56:58.635] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-B-7-10_FPIXTest-17C-FNAL-160125-1011_2016-01-25_10h11m_1453738317/000_FPIXTest_p17//defaultMaskFile.dat
[11:56:58.649] INFO: enter test to run
[11:57:18.094] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[11:57:18.094] INFO: running: xray
[11:57:18.095] INFO: ----------------------------------------------------------------------
[11:57:18.095] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:57:18.095] INFO: ----------------------------------------------------------------------
[11:57:19.058] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:57:31.381] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[11:58:00.560] INFO: Resuming triggers.
[11:58:12.885] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[11:58:42.054] INFO: Resuming triggers.
[11:58:54.376] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[11:59:23.490] INFO: Resuming triggers.
[11:59:35.810] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[12:00:05.038] INFO: Resuming triggers.
[12:00:17.356] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[12:00:46.556] INFO: Resuming triggers.
[12:00:58.867] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[12:01:28.024] INFO: Resuming triggers.
[12:01:40.331] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[12:02:09.503] INFO: Resuming triggers.
[12:02:21.809] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[12:02:50.001] INFO: Resuming triggers.
[12:02:52.791] INFO: data taking finished, elapsed time: 100 seconds.
[12:02:57.425] INFO: PixTest:: pg_setup set to default.
[12:02:57.428] INFO: PixTestXray::doPhRun() done
[12:02:57.561] INFO: enter test to run
[12:03:42.731] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[12:03:42.731] INFO: running: xray
[12:03:42.732] INFO: ----------------------------------------------------------------------
[12:03:42.732] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[12:03:42.732] INFO: ----------------------------------------------------------------------
[12:03:43.696] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[12:03:51.673] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[12:04:21.729] INFO: Resuming triggers.
[12:04:29.708] INFO: run duration 15 seconds, buffer almost full (81%), pausing triggers.
[12:04:59.773] INFO: Resuming triggers.
[12:05:07.757] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[12:05:37.790] INFO: Resuming triggers.
[12:05:45.771] INFO: run duration 31 seconds, buffer almost full (81%), pausing triggers.
[12:06:15.902] INFO: Resuming triggers.
[12:06:23.892] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[12:06:52.079] INFO: Resuming triggers.
[12:07:00.070] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[12:07:30.205] INFO: Resuming triggers.
[12:07:38.195] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[12:08:08.352] INFO: Resuming triggers.
[12:08:16.350] INFO: run duration 63 seconds, buffer almost full (81%), pausing triggers.
[12:08:46.392] INFO: Resuming triggers.
[12:08:54.393] INFO: run duration 71 seconds, buffer almost full (81%), pausing triggers.
[12:09:24.464] INFO: Resuming triggers.
[12:09:32.465] INFO: run duration 79 seconds, buffer almost full (81%), pausing triggers.
[12:10:02.615] INFO: Resuming triggers.
[12:10:10.617] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[12:10:40.750] INFO: Resuming triggers.
[12:10:48.753] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[12:11:18.863] INFO: Resuming triggers.
[12:11:23.280] INFO: data taking finished, elapsed time: 100 seconds.
[12:11:40.144] INFO: PixTest:: pg_setup set to default.
[12:11:40.147] INFO: PixTestXray::doPhRun() done
[12:11:40.293] INFO: enter test to run
[12:13:54.334] INFO: test: HighRate no parameter change
[12:13:54.334] INFO: running: highrate
[12:13:54.335] INFO: ----------------------------------------------------------------------
[12:13:54.335] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[12:13:54.335] INFO: ----------------------------------------------------------------------
[12:13:54.477] INFO: Expecting 768 events.
[12:13:55.611] INFO: 768 events read in total (418ms).
[12:13:55.612] INFO: Test took 1269ms.
[12:13:56.415] INFO: Expecting 41600 events.
[12:13:59.393] INFO: 41600 events read in total (2451ms).
[12:13:59.394] INFO: Test took 3775ms.
[12:13:59.422] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:00.161] INFO: Expecting 41600 events.
[12:14:03.290] INFO: 41600 events read in total (2602ms).
[12:14:03.290] INFO: Test took 3852ms.
[12:14:03.320] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:04.055] INFO: Expecting 41600 events.
[12:14:07.237] INFO: 41600 events read in total (2655ms).
[12:14:07.238] INFO: Test took 3901ms.
[12:14:07.269] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:07.001] INFO: Expecting 41600 events.
[12:14:11.206] INFO: 41600 events read in total (2679ms).
[12:14:11.207] INFO: Test took 3922ms.
[12:14:11.237] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:11.966] INFO: Expecting 41600 events.
[12:14:15.156] INFO: 41600 events read in total (2663ms).
[12:14:15.157] INFO: Test took 3903ms.
[12:14:15.187] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:15.917] INFO: Expecting 41600 events.
[12:14:19.129] INFO: 41600 events read in total (2685ms).
[12:14:19.130] INFO: Test took 3925ms.
[12:14:19.160] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:19.891] INFO: Expecting 41600 events.
[12:14:23.099] INFO: 41600 events read in total (2681ms).
[12:14:23.100] INFO: Test took 3923ms.
[12:14:23.130] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:23.859] INFO: Expecting 41600 events.
[12:14:27.051] INFO: 41600 events read in total (2665ms).
[12:14:27.052] INFO: Test took 3905ms.
[12:14:27.090] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:27.815] INFO: Expecting 41600 events.
[12:14:31.020] INFO: 41600 events read in total (2678ms).
[12:14:31.021] INFO: Test took 3914ms.
[12:14:31.051] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:31.778] INFO: Expecting 41600 events.
[12:14:34.991] INFO: 41600 events read in total (2686ms).
[12:14:34.992] INFO: Test took 3925ms.
[12:14:35.022] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:35.753] INFO: Expecting 41600 events.
[12:14:38.965] INFO: 41600 events read in total (2686ms).
[12:14:38.966] INFO: Test took 3927ms.
[12:14:38.997] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:39.728] INFO: Expecting 41600 events.
[12:14:42.936] INFO: 41600 events read in total (2682ms).
[12:14:42.937] INFO: Test took 3923ms.
[12:14:42.967] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:43.698] INFO: Expecting 41600 events.
[12:14:46.918] INFO: 41600 events read in total (2693ms).
[12:14:46.919] INFO: Test took 3936ms.
[12:14:46.949] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:47.676] INFO: Expecting 41600 events.
[12:14:50.892] INFO: 41600 events read in total (2689ms).
[12:14:50.893] INFO: Test took 3927ms.
[12:14:50.924] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:51.652] INFO: Expecting 41600 events.
[12:14:54.856] INFO: 41600 events read in total (2677ms).
[12:14:54.857] INFO: Test took 3915ms.
[12:14:54.887] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:55.621] INFO: Expecting 41600 events.
[12:14:58.814] INFO: 41600 events read in total (2667ms).
[12:14:58.815] INFO: Test took 3910ms.
[12:14:58.845] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:14:59.578] INFO: Expecting 41600 events.
[12:15:02.774] INFO: 41600 events read in total (2669ms).
[12:15:02.775] INFO: Test took 3913ms.
[12:15:02.805] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:03.538] INFO: Expecting 41600 events.
[12:15:06.732] INFO: 41600 events read in total (2667ms).
[12:15:06.733] INFO: Test took 3911ms.
[12:15:06.763] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:07.495] INFO: Expecting 41600 events.
[12:15:10.657] INFO: 41600 events read in total (2635ms).
[12:15:10.658] INFO: Test took 3878ms.
[12:15:10.688] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:11.422] INFO: Expecting 41600 events.
[12:15:14.458] INFO: 41600 events read in total (2509ms).
[12:15:14.459] INFO: Test took 3755ms.
[12:15:14.487] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:15:14.860] INFO: enter test to run
[12:18:43.692] INFO: test: HighRate no parameter change
[12:18:43.692] INFO: running: highrate
[12:18:43.693] INFO: ----------------------------------------------------------------------
[12:18:43.693] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:18:43.693] INFO: ----------------------------------------------------------------------
[12:18:44.313] INFO: Expecting 208000 events.
[12:18:55.965] INFO: 208000 events read in total (11125ms).
[12:18:55.968] INFO: Test took 12267ms.
[12:18:56.092] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:18:56.337] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 3 0
[12:18:56.337] INFO: number of red-efficiency pixels: 89 54 81 125 112 114 86 93 86 107 111 76 86 34 32 31
[12:18:56.337] INFO: number of X-ray hits detected: 69620 43033 62169 92486 88872 99486 86567 73232 75718 92319 70352 60671 72184 36738 22795 24258
[12:18:56.337] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:18:56.337] INFO: number of Vcal hits detected: 207910 207945 207915 207871 207885 207886 207912 207906 207911 207890 207887 207922 207913 207965 207821 207969
[12:18:56.337] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[12:18:56.337] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 99.9 99.9 100.0 100.0 100.0 99.9 100.0
[12:18:56.337] INFO: X-ray hit rate [MHz/cm2]: 20.4 12.6 18.2 27.1 26.0 29.2 25.4 21.5 22.2 27.1 20.6 17.8 21.2 10.8 6.7 7.1
[12:18:56.338] INFO: PixTestHighRate::doXPixelAlive() done
[12:18:56.387] INFO: PixTest:: pg_setup set to default.
[12:18:56.404] INFO: enter test to run
[12:19:20.156] INFO: test: HighRate no parameter change
[12:19:20.156] INFO: running: highrate
[12:19:20.157] INFO: ----------------------------------------------------------------------
[12:19:20.157] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:19:20.157] INFO: ----------------------------------------------------------------------
[12:19:20.774] INFO: Expecting 208000 events.
[12:19:33.590] INFO: 208000 events read in total (12289ms).
[12:19:33.594] INFO: Test took 13428ms.
[12:19:33.822] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:19:34.100] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 3 0
[12:19:34.100] INFO: number of red-efficiency pixels: 219 131 224 309 224 366 291 195 243 299 250 190 204 85 43 47
[12:19:34.100] INFO: number of X-ray hits detected: 131754 81772 117646 174268 167103 185863 163043 138716 144129 173714 133403 114600 137185 70243 43606 46210
[12:19:34.100] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:19:34.100] INFO: number of Vcal hits detected: 207771 207865 207762 207672 207769 207608 207697 207797 207750 207690 207733 207804 207792 207913 207810 207953
[12:19:34.100] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.9 99.9 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[12:19:34.100] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.9 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 100.0
[12:19:34.100] INFO: X-ray hit rate [MHz/cm2]: 38.6 24.0 34.5 51.1 49.0 54.5 47.8 40.7 42.2 50.9 39.1 33.6 40.2 20.6 12.8 13.5
[12:19:34.100] INFO: PixTestHighRate::doXPixelAlive() done
[12:19:34.155] INFO: PixTest:: pg_setup set to default.
[12:19:34.171] INFO: enter test to run
[12:19:51.020] INFO: test: HighRate no parameter change
[12:19:51.020] INFO: running: highrate
[12:19:51.021] INFO: ----------------------------------------------------------------------
[12:19:51.021] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[12:19:51.021] INFO: ----------------------------------------------------------------------
[12:19:51.638] INFO: Expecting 208000 events.
[12:20:05.694] INFO: 208000 events read in total (13529ms).
[12:20:05.699] INFO: Test took 14667ms.
[12:20:06.022] INFO: Fetched DAQ statistics. Counters are being reset now.
[12:20:06.333] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 3 0
[12:20:06.333] INFO: number of red-efficiency pixels: 403 185 387 596 405 714 515 350 444 611 434 303 375 171 69 84
[12:20:06.333] INFO: number of X-ray hits detected: 189551 116549 167494 247315 237031 264019 231716 196849 205838 247964 191310 164384 195459 100219 61758 66835
[12:20:06.333] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[12:20:06.333] INFO: number of Vcal hits detected: 207554 207807 207565 207354 207562 207206 207441 207618 207511 207342 207521 207672 207604 207815 207781 207912
[12:20:06.333] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.8 99.7 99.8 99.6 99.7 99.8 99.8 99.7 99.8 99.9 99.8 99.9 100.0 100.0
[12:20:06.333] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.8 99.7 99.8 99.6 99.7 99.8 99.8 99.7 99.8 99.8 99.8 99.9 99.9 100.0
[12:20:06.333] INFO: X-ray hit rate [MHz/cm2]: 55.6 34.2 49.1 72.5 69.5 77.4 67.9 57.7 60.3 72.7 56.1 48.2 57.3 29.4 18.1 19.6
[12:20:06.333] INFO: PixTestHighRate::doXPixelAlive() done
[12:20:06.379] INFO: PixTest:: pg_setup set to default.
[12:20:06.399] INFO: enter test to run
[12:20:09.387] INFO: test: exit no parameter change
[12:20:09.795] QUIET: Connection to board 33 closed.
[12:20:09.797] INFO: pXar: this is the end, my friend