[10:30:47.728] INFO: *** Welcome to pxar ***
[10:30:47.728] INFO: *** Today: 2016/04/19
[10:30:47.747] INFO: *** Version: v1.9.0-796-gef167-dirty
[10:30:47.747] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//dacParameters35_C15.dat
[10:30:47.749] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:30:47.749] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//defaultMaskFile.dat
[10:30:47.749] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C15.dat
[10:30:47.825] INFO: clk: 4
[10:30:47.825] INFO: ctr: 4
[10:30:47.825] INFO: sda: 19
[10:30:47.825] INFO: tin: 9
[10:30:47.825] INFO: level: 15
[10:30:47.825] INFO: triggerdelay: 0
[10:30:47.825] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[10:30:47.825] INFO: Log level: INFO
[10:30:47.842] QUIET: Connection to board DTB_WREKRL opened.
[10:30:47.845] INFO: DTB startup information
--- DTB info------------------------------------------
Board id: 33
HW version: DTB1.2
FW version: 4.2
SW version: 4.5
USB id: DTB_WREKRL
MAC address: 40D855118021
Hostname: pixelDTB033
Comment:
------------------------------------------------------
[10:30:47.848] INFO: RPC call hashes of host and DTB match: 398089610
[10:30:49.374] INFO: DUT info:
[10:30:49.374] INFO: The DUT currently contains the following objects:
[10:30:49.374] INFO: 2 TBM Cores tbm08c (2 ON)
[10:30:49.374] INFO: TBM Core alpha (0): 7 registers set
[10:30:49.374] INFO: TBM Core beta (1): 7 registers set
[10:30:49.374] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[10:30:49.374] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.374] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.374] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.374] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.374] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.374] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.374] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.374] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.374] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.375] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.375] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.375] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.375] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.375] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.375] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.375] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[10:30:49.778] INFO: enter 'restricted' command line mode
[10:30:49.778] INFO: enter test to run
[10:30:58.750] INFO: test: timing no parameter change
[10:30:58.750] INFO: running: timing
[10:30:58.776] INFO: ######################################################################
[10:30:58.776] INFO: PixTestTiming::doTest()
[10:30:58.781] INFO: ######################################################################
[10:30:58.781] INFO: ----------------------------------------------------------------------
[10:30:58.781] INFO: PixTestTiming::TBMPhaseScan()
[10:30:58.781] INFO: ----------------------------------------------------------------------
[10:35:26.358] INFO: TBM Phase Settings: 236
[10:35:26.358] INFO: 400MHz Phase: 3
[10:35:26.359] INFO: 160MHz Phase: 7
[10:35:26.359] INFO: Functional Phase Area: 4
[10:35:26.368] INFO: Test took 267587 ms.
[10:35:26.368] INFO: PixTestTiming::TBMPhaseScan() done.
[10:35:26.368] INFO: ----------------------------------------------------------------------
[10:35:26.368] INFO: PixTestTiming::ROCDelayScan()
[10:35:26.368] INFO: ----------------------------------------------------------------------
[10:37:34.278] INFO: ROC Delay Settings: 228
[10:37:34.278] INFO: ROC Header-Trailer/Token Delay: 11
[10:37:34.278] INFO: ROC Port 0 Delay: 4
[10:37:34.278] INFO: ROC Port 1 Delay: 4
[10:37:34.278] INFO: Functional ROC Area: 5
[10:37:34.281] INFO: Test took 127913 ms.
[10:37:34.281] INFO: PixTestTiming::ROCDelayScan() done.
[10:37:34.281] INFO: ----------------------------------------------------------------------
[10:37:34.281] INFO: PixTestTiming::TimingTest()
[10:37:34.281] INFO: ----------------------------------------------------------------------
[10:37:50.440] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:05.424] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:20.398] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:35.372] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:38:50.339] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:39:05.316] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:39:20.301] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:39:35.276] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:39:50.268] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:40:05.255] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:40:05.633] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:40:05.651] INFO: ----------------------------------------------------------------------
[10:40:05.651] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[10:40:05.651] INFO: ----------------------------------------------------------------------
[10:40:05.651] INFO: ----------------------------------------------------------------------
[10:40:05.651] INFO: Read back bit status: 1
[10:40:05.651] INFO: ----------------------------------------------------------------------
[10:40:05.651] INFO: ----------------------------------------------------------------------
[10:40:05.651] INFO: Timings are good!
[10:40:05.651] INFO: ----------------------------------------------------------------------
[10:40:05.651] INFO: Test took 151370 ms.
[10:40:05.651] INFO: PixTestTiming::TimingTest() done.
[10:40:05.658] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//tbmParameters_C0a.dat
[10:40:05.659] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:40:05.659] INFO: PixTestTiming::doTest took 546888 ms.
[10:40:05.659] INFO: PixTestTiming::doTest() done
[10:40:05.659] INFO: Write out TBMPhaseScan_0_V0
[10:40:05.690] INFO: Write out TBMPhaseScan_1_V0
[10:40:05.690] INFO: Write out CombinedTBMPhaseScan_V0
[10:40:05.704] INFO: Write out ROCDelayScan3_V0
[10:40:05.705] INFO: enter test to run
[10:40:40.218] INFO: test: PixelAlive no parameter change
[10:40:40.218] INFO: running: pixelalive
[10:40:40.222] INFO: ----------------------------------------------------------------------
[10:40:40.222] INFO: PixTestAlive::aliveTest() ntrig = 10, vcal = 200 (ctrlreg = 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0)
[10:40:40.222] INFO: ----------------------------------------------------------------------
[10:40:40.545] INFO: Expecting 41600 events.
[10:40:44.873] INFO: 41600 events read in total (3612ms).
[10:40:44.874] INFO: Test took 4648ms.
[10:40:44.880] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:40:45.279] INFO: PixTestAlive::aliveTest() done
[10:40:45.279] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0
[10:40:45.283] INFO: enter test to run
[10:41:13.202] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:41:13.202] INFO: running: highrate
[10:41:13.202] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:41:13.358] INFO: ----------------------------------------------------------------------
[10:41:13.358] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:41:13.358] INFO: ----------------------------------------------------------------------
[10:41:13.358] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:41:13.358] INFO: edge/corner pixel THR is adjusted
[10:41:13.358] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:41:14.317] INFO: Collecting data for 5 seconds...
[10:41:19.333] INFO: Done with hot pixel readout
[10:41:31.324] INFO: PixTest:: pg_setup set to default.
[10:41:31.325] INFO: 0 hot pixels found in step 0
[10:41:31.363] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:41:31.367] INFO: PixTest::trimHotPixels() done
[10:41:31.367] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C0.dat
[10:41:31.372] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C1.dat
[10:41:31.378] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C2.dat
[10:41:31.384] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C3.dat
[10:41:31.390] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C4.dat
[10:41:31.395] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C5.dat
[10:41:31.400] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C6.dat
[10:41:31.405] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C7.dat
[10:41:31.410] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C8.dat
[10:41:31.416] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C9.dat
[10:41:31.421] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C10.dat
[10:41:31.426] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C11.dat
[10:41:31.431] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C12.dat
[10:41:31.436] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C13.dat
[10:41:31.441] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C14.dat
[10:41:31.447] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C15.dat
[10:41:31.452] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//defaultMaskFile.dat
[10:41:31.462] INFO: enter test to run
[10:42:38.769] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:42:38.769] INFO: running: highrate
[10:42:38.773] INFO: ----------------------------------------------------------------------
[10:42:38.773] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:42:38.773] INFO: ----------------------------------------------------------------------
[10:42:38.773] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:42:38.774] INFO: edge/corner pixel THR is adjusted
[10:42:38.774] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:42:39.732] INFO: Collecting data for 1 seconds...
[10:42:40.735] INFO: Done with hot pixel readout
[10:42:44.961] INFO: PixTest:: pg_setup set to default.
[10:42:44.962] INFO: 0 hot pixels found in step 0
[10:42:44.967] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:42:45.046] INFO: PixTest::trimHotPixels() done
[10:42:45.046] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C0.dat
[10:42:45.056] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C1.dat
[10:42:45.061] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C2.dat
[10:42:45.066] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C3.dat
[10:42:45.072] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C4.dat
[10:42:45.077] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C5.dat
[10:42:45.082] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C6.dat
[10:42:45.088] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C7.dat
[10:42:45.093] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C8.dat
[10:42:45.098] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C9.dat
[10:42:45.104] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C10.dat
[10:42:45.109] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C11.dat
[10:42:45.114] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C12.dat
[10:42:45.119] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C13.dat
[10:42:45.125] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C14.dat
[10:42:45.130] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//trimParameters35_C15.dat
[10:42:45.135] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-L-4-42_FPIXTest-17C-FNAL-160414-0854_2016-04-14_08h54m_1460642076/000_FPIXTest_p17//defaultMaskFile.dat
[10:42:45.145] INFO: enter test to run
[10:43:26.473] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:43:26.473] INFO: running: xray
[10:43:26.474] INFO: ----------------------------------------------------------------------
[10:43:26.474] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:43:26.474] INFO: ----------------------------------------------------------------------
[10:43:27.436] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:43:38.156] INFO: run duration 10 seconds, buffer almost full (81%), pausing triggers.
[10:44:02.825] INFO: Resuming triggers.
[10:44:13.548] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[10:44:43.247] INFO: Resuming triggers.
[10:44:53.971] INFO: run duration 32 seconds, buffer almost full (81%), pausing triggers.
[10:45:23.647] INFO: Resuming triggers.
[10:45:34.371] INFO: run duration 42 seconds, buffer almost full (81%), pausing triggers.
[10:46:04.041] INFO: Resuming triggers.
[10:46:14.765] INFO: run duration 53 seconds, buffer almost full (81%), pausing triggers.
[10:46:44.448] INFO: Resuming triggers.
[10:46:55.172] INFO: run duration 64 seconds, buffer almost full (81%), pausing triggers.
[10:47:24.783] INFO: Resuming triggers.
[10:47:35.507] INFO: run duration 74 seconds, buffer almost full (81%), pausing triggers.
[10:48:05.114] INFO: Resuming triggers.
[10:48:15.835] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[10:48:45.326] INFO: Resuming triggers.
[10:48:56.048] INFO: run duration 96 seconds, buffer almost full (81%), pausing triggers.
[10:49:25.749] INFO: Resuming triggers.
[10:49:29.574] INFO: data taking finished, elapsed time: 100 seconds.
[10:49:40.427] INFO: PixTest:: pg_setup set to default.
[10:49:40.431] INFO: PixTestXray::doPhRun() done
[10:49:40.570] INFO: enter test to run
[10:50:06.182] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[10:50:06.182] INFO: running: xray
[10:50:06.183] INFO: ----------------------------------------------------------------------
[10:50:06.183] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:50:06.183] INFO: ----------------------------------------------------------------------
[10:50:07.154] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:50:13.338] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[10:50:43.510] INFO: Resuming triggers.
[10:50:49.695] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[10:51:19.857] INFO: Resuming triggers.
[10:51:26.040] INFO: run duration 18 seconds, buffer almost full (81%), pausing triggers.
[10:51:56.090] INFO: Resuming triggers.
[10:52:02.272] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[10:52:32.367] INFO: Resuming triggers.
[10:52:38.548] INFO: run duration 30 seconds, buffer almost full (81%), pausing triggers.
[10:53:08.782] INFO: Resuming triggers.
[10:53:14.963] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[10:53:45.203] INFO: Resuming triggers.
[10:53:51.385] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[10:54:19.510] INFO: Resuming triggers.
[10:54:25.693] INFO: run duration 49 seconds, buffer almost full (81%), pausing triggers.
[10:54:55.802] INFO: Resuming triggers.
[10:55:01.986] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[10:55:32.089] INFO: Resuming triggers.
[10:55:38.275] INFO: run duration 61 seconds, buffer almost full (81%), pausing triggers.
[10:56:08.459] INFO: Resuming triggers.
[10:56:14.644] INFO: run duration 67 seconds, buffer almost full (81%), pausing triggers.
[10:56:44.996] INFO: Resuming triggers.
[10:56:51.182] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[10:57:21.279] INFO: Resuming triggers.
[10:57:27.465] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[10:57:57.565] INFO: Resuming triggers.
[10:58:03.750] INFO: run duration 86 seconds, buffer almost full (81%), pausing triggers.
[10:58:33.925] INFO: Resuming triggers.
[10:58:40.111] INFO: run duration 92 seconds, buffer almost full (81%), pausing triggers.
[10:59:10.282] INFO: Resuming triggers.
[10:59:16.470] INFO: run duration 98 seconds, buffer almost full (81%), pausing triggers.
[10:59:46.612] INFO: Resuming triggers.
[10:59:47.984] INFO: data taking finished, elapsed time: 100 seconds.
[10:59:55.034] INFO: PixTest:: pg_setup set to default.
[10:59:55.037] INFO: PixTestXray::doPhRun() done
[10:59:55.189] INFO: enter test to run
[11:00:11.425] INFO: test: HighRate no parameter change
[11:00:11.425] INFO: running: highrate
[11:00:11.427] INFO: ----------------------------------------------------------------------
[11:00:11.427] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:00:11.427] INFO: ----------------------------------------------------------------------
[11:00:11.566] INFO: Expecting 768 events.
[11:00:12.700] INFO: 768 events read in total (418ms).
[11:00:12.701] INFO: Test took 1269ms.
[11:00:13.504] INFO: Expecting 41600 events.
[11:00:16.522] INFO: 41600 events read in total (2491ms).
[11:00:16.523] INFO: Test took 3816ms.
[11:00:16.559] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:17.282] INFO: Expecting 41600 events.
[11:00:20.479] INFO: 41600 events read in total (2671ms).
[11:00:20.480] INFO: Test took 3904ms.
[11:00:20.516] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:21.239] INFO: Expecting 41600 events.
[11:00:24.486] INFO: 41600 events read in total (2720ms).
[11:00:24.487] INFO: Test took 3952ms.
[11:00:24.525] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:25.244] INFO: Expecting 41600 events.
[11:00:28.507] INFO: 41600 events read in total (2736ms).
[11:00:28.508] INFO: Test took 3965ms.
[11:00:28.544] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:29.265] INFO: Expecting 41600 events.
[11:00:32.540] INFO: 41600 events read in total (2749ms).
[11:00:32.541] INFO: Test took 3978ms.
[11:00:32.577] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:33.297] INFO: Expecting 41600 events.
[11:00:36.558] INFO: 41600 events read in total (2734ms).
[11:00:36.559] INFO: Test took 3963ms.
[11:00:36.596] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:37.315] INFO: Expecting 41600 events.
[11:00:40.589] INFO: 41600 events read in total (2747ms).
[11:00:40.590] INFO: Test took 3974ms.
[11:00:40.627] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:41.344] INFO: Expecting 41600 events.
[11:00:44.624] INFO: 41600 events read in total (2753ms).
[11:00:44.625] INFO: Test took 3979ms.
[11:00:44.661] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:45.381] INFO: Expecting 41600 events.
[11:00:48.653] INFO: 41600 events read in total (2745ms).
[11:00:48.654] INFO: Test took 3974ms.
[11:00:48.691] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:49.410] INFO: Expecting 41600 events.
[11:00:52.687] INFO: 41600 events read in total (2750ms).
[11:00:52.688] INFO: Test took 3978ms.
[11:00:52.724] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:53.445] INFO: Expecting 41600 events.
[11:00:56.729] INFO: 41600 events read in total (2757ms).
[11:00:56.730] INFO: Test took 3986ms.
[11:00:56.767] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:00:57.485] INFO: Expecting 41600 events.
[11:01:00.762] INFO: 41600 events read in total (2750ms).
[11:01:00.763] INFO: Test took 3977ms.
[11:01:00.801] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:01.517] INFO: Expecting 41600 events.
[11:01:04.795] INFO: 41600 events read in total (2751ms).
[11:01:04.796] INFO: Test took 3975ms.
[11:01:04.834] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:05.552] INFO: Expecting 41600 events.
[11:01:08.837] INFO: 41600 events read in total (2758ms).
[11:01:08.838] INFO: Test took 3985ms.
[11:01:08.875] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:09.592] INFO: Expecting 41600 events.
[11:01:12.872] INFO: 41600 events read in total (2753ms).
[11:01:12.873] INFO: Test took 3979ms.
[11:01:12.910] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:13.631] INFO: Expecting 41600 events.
[11:01:16.902] INFO: 41600 events read in total (2745ms).
[11:01:16.903] INFO: Test took 3972ms.
[11:01:16.940] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:17.657] INFO: Expecting 41600 events.
[11:01:20.932] INFO: 41600 events read in total (2748ms).
[11:01:20.933] INFO: Test took 3973ms.
[11:01:20.970] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:21.687] INFO: Expecting 41600 events.
[11:01:24.969] INFO: 41600 events read in total (2756ms).
[11:01:24.970] INFO: Test took 3980ms.
[11:01:25.007] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:25.728] INFO: Expecting 41600 events.
[11:01:28.988] INFO: 41600 events read in total (2733ms).
[11:01:28.989] INFO: Test took 3962ms.
[11:01:29.025] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:29.743] INFO: Expecting 41600 events.
[11:01:32.922] INFO: 41600 events read in total (2652ms).
[11:01:32.923] INFO: Test took 3879ms.
[11:01:32.959] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:33.316] INFO: enter test to run
[11:01:35.177] INFO: test: HighRate no parameter change
[11:01:35.177] INFO: running: highrate
[11:01:35.178] INFO: ----------------------------------------------------------------------
[11:01:35.178] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:01:35.178] INFO: ----------------------------------------------------------------------
[11:01:35.795] INFO: Expecting 208000 events.
[11:01:47.841] INFO: 208000 events read in total (11519ms).
[11:01:47.845] INFO: Test took 12658ms.
[11:01:48.003] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:01:48.260] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0
[11:01:48.260] INFO: number of red-efficiency pixels: 97 63 92 166 164 148 197 123 139 160 124 95 117 130 32 38
[11:01:48.260] INFO: number of X-ray hits detected: 62527 46299 74000 115596 124508 123709 128666 92662 91249 118491 109137 95304 100559 57942 23125 26326
[11:01:48.260] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:01:48.260] INFO: number of Vcal hits detected: 207898 207937 207908 207782 207835 207844 207798 207873 207861 207838 207872 207904 207882 207855 207968 207962
[11:01:48.260] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0 99.9 100.0 100.0
[11:01:48.260] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 100.0
[11:01:48.260] INFO: X-ray hit rate [MHz/cm2]: 18.3 13.6 21.7 33.9 36.5 36.3 37.7 27.2 26.7 34.7 32.0 27.9 29.5 17.0 6.8 7.7
[11:01:48.260] INFO: PixTestHighRate::doXPixelAlive() done
[11:01:48.309] INFO: PixTest:: pg_setup set to default.
[11:01:48.321] INFO: enter test to run
[11:02:04.041] INFO: test: HighRate no parameter change
[11:02:04.041] INFO: running: highrate
[11:02:04.042] INFO: ----------------------------------------------------------------------
[11:02:04.042] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:02:04.042] INFO: ----------------------------------------------------------------------
[11:02:04.655] INFO: Expecting 208000 events.
[11:02:18.752] INFO: 208000 events read in total (13570ms).
[11:02:18.758] INFO: Test took 14708ms.
[11:02:19.086] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:02:19.410] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0
[11:02:19.410] INFO: number of red-efficiency pixels: 201 151 368 596 496 638 731 453 384 527 375 323 341 345 68 76
[11:02:19.410] INFO: number of X-ray hits detected: 132985 97535 156227 245526 263219 260971 270809 195643 192841 250497 229649 200938 213063 122481 49181 55901
[11:02:19.410] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:02:19.410] INFO: number of Vcal hits detected: 207793 207844 207581 207287 207455 207286 207160 207489 207584 207428 207593 207660 207641 207593 207932 207922
[11:02:19.410] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.8 99.7 99.8 99.7 99.6 99.8 99.8 99.8 99.8 99.9 99.8 99.8 100.0 100.0
[11:02:19.410] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.8 99.7 99.7 99.7 99.6 99.8 99.8 99.7 99.8 99.8 99.8 99.8 100.0 100.0
[11:02:19.410] INFO: X-ray hit rate [MHz/cm2]: 39.0 28.6 45.8 72.0 77.2 76.5 79.4 57.3 56.5 73.4 67.3 58.9 62.5 35.9 14.4 16.4
[11:02:19.410] INFO: PixTestHighRate::doXPixelAlive() done
[11:02:19.455] INFO: PixTest:: pg_setup set to default.
[11:02:19.472] INFO: enter test to run
[11:02:34.352] INFO: test: HighRate no parameter change
[11:02:34.353] INFO: running: highrate
[11:02:34.354] INFO: ----------------------------------------------------------------------
[11:02:34.354] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:02:34.354] INFO: ----------------------------------------------------------------------
[11:02:34.968] INFO: Expecting 208000 events.
[11:02:51.225] INFO: 208000 events read in total (15731ms).
[11:02:51.233] INFO: Test took 16871ms.
[11:02:51.740] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:02:52.108] INFO: number of dead pixels (per ROC): 0 0 0 1 0 0 0 0 0 0 0 0 0 0 0 0
[11:02:52.108] INFO: number of red-efficiency pixels: 443 307 768 1329 1152 1470 1663 1056 837 1110 838 690 758 637 125 131
[11:02:52.108] INFO: number of X-ray hits detected: 197936 145968 232489 363486 391626 387397 404407 294030 287862 374129 343144 299209 317726 182868 73650 84210
[11:02:52.108] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:02:52.108] INFO: number of Vcal hits detected: 207506 207666 206920 206212 206546 205966 205581 206533 206965 206577 207031 207187 207106 207137 207872 207868
[11:02:52.108] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.5 99.2 99.4 99.1 99.0 99.4 99.6 99.4 99.6 99.7 99.6 99.6 99.9 99.9
[11:02:52.108] INFO: Vcal hit overall efficiency (%): 99.8 99.8 99.5 99.1 99.3 99.0 98.8 99.3 99.5 99.3 99.5 99.6 99.6 99.6 99.9 99.9
[11:02:52.108] INFO: X-ray hit rate [MHz/cm2]: 58.0 42.8 68.1 106.5 114.8 113.5 118.5 86.2 84.4 109.7 100.6 87.7 93.1 53.6 21.6 24.7
[11:02:52.108] INFO: PixTestHighRate::doXPixelAlive() done
[11:02:52.158] INFO: PixTest:: pg_setup set to default.
[11:02:52.174] INFO: enter test to run
[11:02:55.040] INFO: test: exit no parameter change
[11:02:55.508] QUIET: Connection to board 33 closed.
[11:02:55.510] INFO: pXar: this is the end, my friend