[09:47:30.819] INFO: *** Welcome to pxar ***
[09:47:30.819] INFO: *** Today: 2016/04/15
[09:47:30.838] INFO: *** Version: v1.9.0-796-gef167-dirty
[09:47:30.838] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//dacParameters35_C15.dat
[09:47:30.839] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:47:30.839] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//defaultMaskFile.dat
[09:47:30.839] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C15.dat
[09:47:30.908] INFO: clk: 4
[09:47:30.909] INFO: ctr: 4
[09:47:30.909] INFO: sda: 19
[09:47:30.909] INFO: tin: 9
[09:47:30.909] INFO: level: 15
[09:47:30.909] INFO: triggerdelay: 0
[09:47:30.909] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[09:47:30.909] INFO: Log level: INFO
[09:47:30.927] QUIET: Connection to board DTB_WREKRL opened.
[09:47:30.930] 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:
------------------------------------------------------
[09:47:30.933] INFO: RPC call hashes of host and DTB match: 398089610
[09:47:32.463] INFO: DUT info:
[09:47:32.463] INFO: The DUT currently contains the following objects:
[09:47:32.463] INFO: 2 TBM Cores tbm08c (2 ON)
[09:47:32.463] INFO: TBM Core alpha (0): 7 registers set
[09:47:32.463] INFO: TBM Core beta (1): 7 registers set
[09:47:32.464] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[09:47:32.464] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.464] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[09:47:32.867] INFO: enter 'restricted' command line mode
[09:47:32.868] INFO: enter test to run
[09:47:38.660] INFO: test: timing no parameter change
[09:47:38.660] INFO: running: timing
[09:47:38.690] INFO: ######################################################################
[09:47:38.690] INFO: PixTestTiming::doTest()
[09:47:38.693] INFO: ######################################################################
[09:47:38.694] INFO: ----------------------------------------------------------------------
[09:47:38.694] INFO: PixTestTiming::TBMPhaseScan()
[09:47:38.694] INFO: ----------------------------------------------------------------------
[09:53:47.905] INFO: TBM Phase Settings: 240
[09:53:47.905] INFO: 400MHz Phase: 4
[09:53:47.905] INFO: 160MHz Phase: 7
[09:53:47.905] INFO: Functional Phase Area: 4
[09:53:47.929] INFO: Test took 369236 ms.
[09:53:47.929] INFO: PixTestTiming::TBMPhaseScan() done.
[09:53:47.929] INFO: ----------------------------------------------------------------------
[09:53:47.929] INFO: PixTestTiming::ROCDelayScan()
[09:53:47.929] INFO: ----------------------------------------------------------------------
[09:57:02.564] INFO: ROC Delay Settings: 228
[09:57:02.564] INFO: ROC Header-Trailer/Token Delay: 11
[09:57:02.564] INFO: ROC Port 0 Delay: 4
[09:57:02.564] INFO: ROC Port 1 Delay: 4
[09:57:02.564] INFO: Functional ROC Area: 5
[09:57:02.567] INFO: Test took 194638 ms.
[09:57:02.567] INFO: PixTestTiming::ROCDelayScan() done.
[09:57:02.567] INFO: ----------------------------------------------------------------------
[09:57:02.567] INFO: PixTestTiming::TimingTest()
[09:57:02.567] INFO: ----------------------------------------------------------------------
[09:57:18.723] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:57:33.683] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:57:48.645] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:03.621] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:18.610] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:33.542] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:58:48.491] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:03.429] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:18.347] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:33.032] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:33.417] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:33.436] INFO: ----------------------------------------------------------------------
[09:59:33.436] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[09:59:33.436] INFO: ----------------------------------------------------------------------
[09:59:33.436] INFO: ----------------------------------------------------------------------
[09:59:33.436] INFO: Read back bit status: 1
[09:59:33.436] INFO: ----------------------------------------------------------------------
[09:59:33.436] INFO: ----------------------------------------------------------------------
[09:59:33.436] INFO: Timings are good!
[09:59:33.436] INFO: ----------------------------------------------------------------------
[09:59:33.436] INFO: Test took 150869 ms.
[09:59:33.436] INFO: PixTestTiming::TimingTest() done.
[09:59:33.452] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//tbmParameters_C0a.dat
[09:59:33.452] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:59:33.452] INFO: PixTestTiming::doTest took 714767 ms.
[09:59:33.452] INFO: PixTestTiming::doTest() done
[09:59:33.452] INFO: Write out TBMPhaseScan_0_V0
[09:59:33.478] INFO: Write out TBMPhaseScan_1_V0
[09:59:33.478] INFO: Write out CombinedTBMPhaseScan_V0
[09:59:33.498] INFO: Write out ROCDelayScan3_V0
[09:59:33.498] INFO: enter test to run
[09:59:48.223] INFO: test: PixelAlive no parameter change
[09:59:48.223] INFO: running: pixelalive
[09:59:48.227] INFO: ----------------------------------------------------------------------
[09:59:48.227] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[09:59:48.227] INFO: ----------------------------------------------------------------------
[09:59:48.541] INFO: Expecting 41600 events.
[09:59:52.866] INFO: 41600 events read in total (3609ms).
[09:59:52.867] INFO: Test took 4638ms.
[09:59:52.873] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:59:53.273] INFO: PixTestAlive::aliveTest() done
[09:59:53.273] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[09:59:53.277] INFO: enter test to run
[10:00:21.446] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:00:21.447] INFO: running: highrate
[10:00:21.447] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:00:21.601] INFO: ----------------------------------------------------------------------
[10:00:21.601] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:00:21.601] INFO: ----------------------------------------------------------------------
[10:00:21.601] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:00:21.601] INFO: edge/corner pixel THR is adjusted
[10:00:21.601] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:00:22.559] INFO: Collecting data for 5 seconds...
[10:00:27.575] INFO: Done with hot pixel readout
[10:00:39.398] INFO: PixTest:: pg_setup set to default.
[10:00:39.399] INFO: 0 hot pixels found in step 0
[10:00:39.437] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:00:39.440] INFO: PixTest::trimHotPixels() done
[10:00:39.440] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C0.dat
[10:00:39.446] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C1.dat
[10:00:39.451] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C2.dat
[10:00:39.457] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C3.dat
[10:00:39.462] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C4.dat
[10:00:39.467] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C5.dat
[10:00:39.472] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C6.dat
[10:00:39.477] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C7.dat
[10:00:39.483] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C8.dat
[10:00:39.488] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C9.dat
[10:00:39.493] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C10.dat
[10:00:39.498] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C11.dat
[10:00:39.503] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C12.dat
[10:00:39.509] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C13.dat
[10:00:39.514] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C14.dat
[10:00:39.519] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C15.dat
[10:00:39.524] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//defaultMaskFile.dat
[10:00:39.534] INFO: enter test to run
[10:00:57.590] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:00:57.590] INFO: running: highrate
[10:00:57.595] INFO: ----------------------------------------------------------------------
[10:00:57.595] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:00:57.595] INFO: ----------------------------------------------------------------------
[10:00:57.595] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:00:57.595] INFO: edge/corner pixel THR is adjusted
[10:00:57.595] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:00:58.552] INFO: Collecting data for 1 seconds...
[10:00:59.556] INFO: Done with hot pixel readout
[10:01:03.621] INFO: PixTest:: pg_setup set to default.
[10:01:03.622] INFO: 0 hot pixels found in step 0
[10:01:03.627] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:01:03.720] INFO: PixTest::trimHotPixels() done
[10:01:03.720] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C0.dat
[10:01:03.728] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C1.dat
[10:01:03.734] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C2.dat
[10:01:03.739] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C3.dat
[10:01:03.744] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C4.dat
[10:01:03.749] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C5.dat
[10:01:03.755] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C6.dat
[10:01:03.760] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C7.dat
[10:01:03.765] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C8.dat
[10:01:03.770] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C9.dat
[10:01:03.775] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C10.dat
[10:01:03.781] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C11.dat
[10:01:03.786] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C12.dat
[10:01:03.791] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C13.dat
[10:01:03.796] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C14.dat
[10:01:03.802] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//trimParameters35_C15.dat
[10:01:03.807] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-4-41_FPIXTest-17C-FNAL-160408-0921_2016-04-08_09h21m_1460125289/000_FPIXTest_p17//defaultMaskFile.dat
[10:01:03.817] INFO: enter test to run
[10:01:48.238] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:01:48.238] INFO: running: xray
[10:01:48.239] INFO: ----------------------------------------------------------------------
[10:01:48.239] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:01:48.239] INFO: ----------------------------------------------------------------------
[10:01:49.202] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:02:00.479] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[10:02:30.122] INFO: Resuming triggers.
[10:02:41.395] INFO: run duration 22 seconds, buffer almost full (81%), pausing triggers.
[10:03:10.849] INFO: Resuming triggers.
[10:03:22.121] INFO: run duration 33 seconds, buffer almost full (81%), pausing triggers.
[10:03:51.703] INFO: Resuming triggers.
[10:04:02.978] INFO: run duration 44 seconds, buffer almost full (81%), pausing triggers.
[10:04:32.418] INFO: Resuming triggers.
[10:04:43.696] INFO: run duration 56 seconds, buffer almost full (81%), pausing triggers.
[10:05:09.079] INFO: Resuming triggers.
[10:05:20.353] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[10:05:49.734] INFO: Resuming triggers.
[10:06:01.008] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[10:06:30.542] INFO: Resuming triggers.
[10:06:41.820] INFO: run duration 89 seconds, buffer almost full (81%), pausing triggers.
[10:07:11.368] INFO: Resuming triggers.
[10:07:21.486] INFO: data taking finished, elapsed time: 100 seconds.
[10:07:48.054] INFO: PixTest:: pg_setup set to default.
[10:07:48.057] INFO: PixTestXray::doPhRun() done
[10:07:48.192] INFO: enter test to run
[10:08:27.243] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[10:08:27.243] INFO: running: xray
[10:08:27.244] INFO: ----------------------------------------------------------------------
[10:08:27.244] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:08:27.244] INFO: ----------------------------------------------------------------------
[10:08:28.223] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:08:34.799] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[10:09:04.918] INFO: Resuming triggers.
[10:09:11.493] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[10:09:41.636] INFO: Resuming triggers.
[10:09:48.210] INFO: run duration 19 seconds, buffer almost full (81%), pausing triggers.
[10:10:18.322] INFO: Resuming triggers.
[10:10:24.897] INFO: run duration 26 seconds, buffer almost full (81%), pausing triggers.
[10:10:54.975] INFO: Resuming triggers.
[10:11:01.546] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[10:11:31.662] INFO: Resuming triggers.
[10:11:38.235] INFO: run duration 39 seconds, buffer almost full (81%), pausing triggers.
[10:12:08.805] INFO: Resuming triggers.
[10:12:15.378] INFO: run duration 45 seconds, buffer almost full (81%), pausing triggers.
[10:12:45.607] INFO: Resuming triggers.
[10:12:52.181] INFO: run duration 52 seconds, buffer almost full (81%), pausing triggers.
[10:13:22.292] INFO: Resuming triggers.
[10:13:28.864] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[10:13:59.020] INFO: Resuming triggers.
[10:14:05.591] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[10:14:35.724] INFO: Resuming triggers.
[10:14:42.296] INFO: run duration 72 seconds, buffer almost full (81%), pausing triggers.
[10:15:07.956] INFO: Resuming triggers.
[10:15:14.528] INFO: run duration 78 seconds, buffer almost full (81%), pausing triggers.
[10:15:44.668] INFO: Resuming triggers.
[10:15:51.242] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[10:16:21.307] INFO: Resuming triggers.
[10:16:27.882] INFO: run duration 91 seconds, buffer almost full (81%), pausing triggers.
[10:16:58.072] INFO: Resuming triggers.
[10:17:04.645] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[10:17:34.766] INFO: Resuming triggers.
[10:17:36.496] INFO: data taking finished, elapsed time: 100 seconds.
[10:17:44.772] INFO: PixTest:: pg_setup set to default.
[10:17:44.775] INFO: PixTestXray::doPhRun() done
[10:17:44.925] INFO: enter test to run
[10:18:36.135] INFO: test: HighRate no parameter change
[10:18:36.135] INFO: running: highrate
[10:18:36.158] INFO: ----------------------------------------------------------------------
[10:18:36.158] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[10:18:36.158] INFO: ----------------------------------------------------------------------
[10:18:36.313] INFO: Expecting 768 events.
[10:18:37.447] INFO: 768 events read in total (418ms).
[10:18:37.448] INFO: Test took 1269ms.
[10:18:38.251] INFO: Expecting 41600 events.
[10:18:41.366] INFO: 41600 events read in total (2588ms).
[10:18:41.367] INFO: Test took 3912ms.
[10:18:41.402] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:18:42.128] INFO: Expecting 41600 events.
[10:18:45.352] INFO: 41600 events read in total (2697ms).
[10:18:45.353] INFO: Test took 3933ms.
[10:18:45.388] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:18:46.107] INFO: Expecting 41600 events.
[10:18:49.362] INFO: 41600 events read in total (2728ms).
[10:18:49.363] INFO: Test took 3956ms.
[10:18:49.399] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:18:50.120] INFO: Expecting 41600 events.
[10:18:53.372] INFO: 41600 events read in total (2725ms).
[10:18:53.373] INFO: Test took 3957ms.
[10:18:53.408] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:18:54.131] INFO: Expecting 41600 events.
[10:18:57.376] INFO: 41600 events read in total (2718ms).
[10:18:57.377] INFO: Test took 3950ms.
[10:18:57.412] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:18:58.131] INFO: Expecting 41600 events.
[10:19:01.398] INFO: 41600 events read in total (2740ms).
[10:19:01.399] INFO: Test took 3968ms.
[10:19:01.435] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:02.155] INFO: Expecting 41600 events.
[10:19:05.415] INFO: 41600 events read in total (2733ms).
[10:19:05.416] INFO: Test took 3962ms.
[10:19:05.452] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:06.170] INFO: Expecting 41600 events.
[10:19:09.425] INFO: 41600 events read in total (2728ms).
[10:19:09.426] INFO: Test took 3955ms.
[10:19:09.462] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:10.181] INFO: Expecting 41600 events.
[10:19:13.446] INFO: 41600 events read in total (2738ms).
[10:19:13.447] INFO: Test took 3966ms.
[10:19:13.483] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:14.206] INFO: Expecting 41600 events.
[10:19:17.454] INFO: 41600 events read in total (2722ms).
[10:19:17.455] INFO: Test took 3953ms.
[10:19:17.490] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:18.212] INFO: Expecting 41600 events.
[10:19:21.483] INFO: 41600 events read in total (2744ms).
[10:19:21.484] INFO: Test took 3974ms.
[10:19:21.520] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:22.238] INFO: Expecting 41600 events.
[10:19:25.503] INFO: 41600 events read in total (2738ms).
[10:19:25.504] INFO: Test took 3966ms.
[10:19:25.539] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:26.257] INFO: Expecting 41600 events.
[10:19:29.515] INFO: 41600 events read in total (2731ms).
[10:19:29.516] INFO: Test took 3959ms.
[10:19:29.552] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:30.273] INFO: Expecting 41600 events.
[10:19:33.532] INFO: 41600 events read in total (2732ms).
[10:19:33.534] INFO: Test took 3964ms.
[10:19:33.576] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:34.289] INFO: Expecting 41600 events.
[10:19:37.544] INFO: 41600 events read in total (2728ms).
[10:19:37.545] INFO: Test took 3949ms.
[10:19:37.581] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:38.302] INFO: Expecting 41600 events.
[10:19:41.564] INFO: 41600 events read in total (2735ms).
[10:19:41.564] INFO: Test took 3965ms.
[10:19:41.600] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:42.323] INFO: Expecting 41600 events.
[10:19:45.590] INFO: 41600 events read in total (2740ms).
[10:19:45.591] INFO: Test took 3973ms.
[10:19:45.626] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:46.345] INFO: Expecting 41600 events.
[10:19:49.605] INFO: 41600 events read in total (2734ms).
[10:19:49.606] INFO: Test took 3961ms.
[10:19:49.641] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:50.364] INFO: Expecting 41600 events.
[10:19:53.609] INFO: 41600 events read in total (2718ms).
[10:19:53.610] INFO: Test took 3949ms.
[10:19:53.646] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:54.368] INFO: Expecting 41600 events.
[10:19:57.469] INFO: 41600 events read in total (2574ms).
[10:19:57.470] INFO: Test took 3805ms.
[10:19:57.505] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:19:57.866] INFO: enter test to run
[10:20:07.038] INFO: test: HighRate no parameter change
[10:20:07.038] INFO: running: highrate
[10:20:07.039] INFO: ----------------------------------------------------------------------
[10:20:07.039] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:20:07.039] INFO: ----------------------------------------------------------------------
[10:20:07.647] INFO: Expecting 208000 events.
[10:20:19.584] INFO: 208000 events read in total (11410ms).
[10:20:19.588] INFO: Test took 12543ms.
[10:20:19.743] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:20:19.998] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[10:20:19.998] INFO: number of red-efficiency pixels: 102 64 66 150 163 166 141 87 115 131 135 109 98 60 27 30
[10:20:19.998] INFO: number of X-ray hits detected: 69621 48973 72158 111086 120191 125649 122992 87157 79236 104167 100133 88752 93279 56579 23951 27679
[10:20:19.998] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:20:19.998] INFO: number of Vcal hits detected: 207897 207935 207933 207841 207835 207829 207856 207913 207883 207860 207813 207888 207900 207940 207966 207970
[10:20:19.998] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0
[10:20:19.998] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0
[10:20:19.998] INFO: X-ray hit rate [MHz/cm2]: 20.4 14.4 21.2 32.6 35.2 36.8 36.0 25.5 23.2 30.5 29.3 26.0 27.3 16.6 7.0 8.1
[10:20:19.998] INFO: PixTestHighRate::doXPixelAlive() done
[10:20:20.049] INFO: PixTest:: pg_setup set to default.
[10:20:20.061] INFO: enter test to run
[10:20:52.061] INFO: test: HighRate no parameter change
[10:20:52.061] INFO: running: highrate
[10:20:52.062] INFO: ----------------------------------------------------------------------
[10:20:52.062] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:20:52.062] INFO: ----------------------------------------------------------------------
[10:20:52.678] INFO: Expecting 208000 events.
[10:21:06.465] INFO: 208000 events read in total (13260ms).
[10:21:06.470] INFO: Test took 14400ms.
[10:21:06.773] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:21:07.079] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[10:21:07.079] INFO: number of red-efficiency pixels: 224 162 248 515 624 470 507 300 256 459 398 279 305 223 42 58
[10:21:07.079] INFO: number of X-ray hits detected: 141185 98514 145604 224230 244829 253818 248908 175890 160195 210696 203819 180115 190303 114143 48239 55595
[10:21:07.079] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:21:07.079] INFO: number of Vcal hits detected: 207765 207827 207735 207433 207321 207481 207443 207678 207730 207507 207523 207702 207679 207762 207958 207942
[10:21:07.079] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.7 99.8 99.8 99.9 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[10:21:07.079] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.7 99.7 99.8 99.7 99.8 99.9 99.8 99.8 99.9 99.8 99.9 100.0 100.0
[10:21:07.079] INFO: X-ray hit rate [MHz/cm2]: 41.4 28.9 42.7 65.7 71.8 74.4 73.0 51.6 47.0 61.8 59.7 52.8 55.8 33.5 14.1 16.3
[10:21:07.079] INFO: PixTestHighRate::doXPixelAlive() done
[10:21:07.125] INFO: PixTest:: pg_setup set to default.
[10:21:07.138] INFO: enter test to run
[10:21:18.885] INFO: test: HighRate no parameter change
[10:21:18.885] INFO: running: highrate
[10:21:18.886] INFO: ----------------------------------------------------------------------
[10:21:18.886] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:21:18.886] INFO: ----------------------------------------------------------------------
[10:21:19.501] INFO: Expecting 208000 events.
[10:21:35.235] INFO: 208000 events read in total (15207ms).
[10:21:35.243] INFO: Test took 16349ms.
[10:21:35.706] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:21:36.059] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 1 0 0 0 0 0
[10:21:36.059] INFO: number of red-efficiency pixels: 498 338 510 1118 1388 1023 1152 682 583 1002 976 619 706 406 96 128
[10:21:36.059] INFO: number of X-ray hits detected: 209889 148336 218347 333454 365721 379219 371295 263809 239580 315094 304374 270687 283956 171030 71958 83623
[10:21:36.059] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[10:21:36.059] INFO: number of Vcal hits detected: 207427 207628 207377 206601 206143 206723 206523 207196 207323 206792 206781 207277 207186 207526 207899 207870
[10:21:36.059] INFO: Vcal hit fiducial efficiency (%): 99.8 99.8 99.7 99.4 99.2 99.4 99.4 99.6 99.7 99.5 99.5 99.7 99.6 99.8 100.0 99.9
[10:21:36.059] INFO: Vcal hit overall efficiency (%): 99.7 99.8 99.7 99.3 99.1 99.4 99.3 99.6 99.7 99.4 99.4 99.7 99.6 99.8 100.0 99.9
[10:21:36.059] INFO: X-ray hit rate [MHz/cm2]: 61.5 43.5 64.0 97.7 107.2 111.2 108.8 77.3 70.2 92.4 89.2 79.3 83.2 50.1 21.1 24.5
[10:21:36.059] INFO: PixTestHighRate::doXPixelAlive() done
[10:21:36.108] INFO: PixTest:: pg_setup set to default.
[10:21:36.121] INFO: enter test to run
[10:21:38.157] INFO: test: exit no parameter change
[10:21:38.602] QUIET: Connection to board 33 closed.
[10:21:38.612] INFO: pXar: this is the end, my friend