[10:42:50.414] INFO: *** Welcome to pxar ***
[10:42:50.414] INFO: *** Today: 2016/04/11
[10:42:50.435] INFO: *** Version: v1.9.0-796-gef167-dirty
[10:42:50.435] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//dacParameters35_C15.dat
[10:42:50.436] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:42:50.436] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//defaultMaskFile.dat
[10:42:50.436] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C15.dat
[10:42:50.560] INFO: clk: 4
[10:42:50.560] INFO: ctr: 4
[10:42:50.560] INFO: sda: 19
[10:42:50.560] INFO: tin: 9
[10:42:50.560] INFO: level: 15
[10:42:50.560] INFO: triggerdelay: 0
[10:42:50.560] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[10:42:50.560] INFO: Log level: INFO
[10:42:50.578] QUIET: Connection to board DTB_WREKRL opened.
[10:42:50.581] 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:42:50.584] INFO: RPC call hashes of host and DTB match: 398089610
[10:42:52.112] INFO: DUT info:
[10:42:52.113] INFO: The DUT currently contains the following objects:
[10:42:52.113] INFO: 2 TBM Cores tbm08c (2 ON)
[10:42:52.113] INFO: TBM Core alpha (0): 7 registers set
[10:42:52.113] INFO: TBM Core beta (1): 7 registers set
[10:42:52.113] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[10:42:52.113] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.113] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[10:42:52.516] INFO: enter 'restricted' command line mode
[10:42:52.516] INFO: enter test to run
[10:42:57.854] INFO: test: timing no parameter change
[10:42:57.854] INFO: running: timing
[10:42:57.863] INFO: ######################################################################
[10:42:57.864] INFO: PixTestTiming::doTest()
[10:42:57.864] INFO: ######################################################################
[10:42:57.864] INFO: ----------------------------------------------------------------------
[10:42:57.864] INFO: PixTestTiming::TBMPhaseScan()
[10:42:57.864] INFO: ----------------------------------------------------------------------
[10:48:29.488] INFO: TBM Phase Settings: 236
[10:48:29.489] INFO: 400MHz Phase: 3
[10:48:29.489] INFO: 160MHz Phase: 7
[10:48:29.489] INFO: Functional Phase Area: 3
[10:48:29.492] INFO: Test took 331628 ms.
[10:48:29.492] INFO: PixTestTiming::TBMPhaseScan() done.
[10:48:29.492] INFO: ----------------------------------------------------------------------
[10:48:29.492] INFO: PixTestTiming::ROCDelayScan()
[10:48:29.492] INFO: ----------------------------------------------------------------------
[10:50:32.915] INFO: ROC Delay Settings: 227
[10:50:32.915] INFO: ROC Header-Trailer/Token Delay: 11
[10:50:32.915] INFO: ROC Port 0 Delay: 3
[10:50:32.915] INFO: ROC Port 1 Delay: 4
[10:50:32.915] INFO: Functional ROC Area: 4
[10:50:32.918] INFO: Test took 123426 ms.
[10:50:32.918] INFO: PixTestTiming::ROCDelayScan() done.
[10:50:32.918] INFO: ----------------------------------------------------------------------
[10:50:32.919] INFO: PixTestTiming::TimingTest()
[10:50:32.919] INFO: ----------------------------------------------------------------------
[10:50:49.065] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:04.030] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:18.992] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:33.959] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:51:48.908] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:03.896] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:18.911] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:33.900] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:52:48.865] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:53:03.853] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:53:04.236] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:53:04.254] INFO: ----------------------------------------------------------------------
[10:53:04.254] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[10:53:04.254] INFO: ----------------------------------------------------------------------
[10:53:04.254] INFO: ----------------------------------------------------------------------
[10:53:04.254] INFO: Read back bit status: 1
[10:53:04.254] INFO: ----------------------------------------------------------------------
[10:53:04.254] INFO: ----------------------------------------------------------------------
[10:53:04.254] INFO: Timings are good!
[10:53:04.254] INFO: ----------------------------------------------------------------------
[10:53:04.254] INFO: Test took 151336 ms.
[10:53:04.254] INFO: PixTestTiming::TimingTest() done.
[10:53:04.254] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//tbmParameters_C0a.dat
[10:53:04.254] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//tbmParameters_C0b.dat
[10:53:04.254] INFO: PixTestTiming::doTest took 606395 ms.
[10:53:04.254] INFO: PixTestTiming::doTest() done
[10:53:04.255] INFO: Write out TBMPhaseScan_0_V0
[10:53:04.280] INFO: Write out TBMPhaseScan_1_V0
[10:53:04.280] INFO: Write out CombinedTBMPhaseScan_V0
[10:53:04.281] INFO: Write out ROCDelayScan3_V0
[10:53:04.282] INFO: enter test to run
[10:53:12.690] INFO: test: PixelAlive no parameter change
[10:53:12.690] INFO: running: pixelalive
[10:53:12.694] INFO: ----------------------------------------------------------------------
[10:53:12.694] 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:53:12.694] INFO: ----------------------------------------------------------------------
[10:53:13.017] INFO: Expecting 41600 events.
[10:53:17.336] INFO: 41600 events read in total (3603ms).
[10:53:17.337] INFO: Test took 4639ms.
[10:53:17.343] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:53:17.740] INFO: PixTestAlive::aliveTest() done
[10:53:17.740] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[10:53:17.744] INFO: enter test to run
[10:55:17.769] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:55:17.769] INFO: running: highrate
[10:55:17.769] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:55:17.002] INFO: ----------------------------------------------------------------------
[10:55:17.002] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:55:17.002] INFO: ----------------------------------------------------------------------
[10:55:17.002] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:55:17.002] INFO: edge/corner pixel THR is adjusted
[10:55:17.002] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:55:18.960] INFO: Collecting data for 5 seconds...
[10:55:23.977] INFO: Done with hot pixel readout
[10:55:35.551] INFO: PixTest:: pg_setup set to default.

[10:55:35.552] INFO: 1 hot pixels found in step 0
[10:55:35.587] INFO: 1 hot pixels could not be trimmed and have been masked.
[10:55:35.591] INFO: PixTest::trimHotPixels() done
[10:55:35.609] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C0.dat
[10:55:35.622] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C1.dat
[10:55:35.636] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C2.dat
[10:55:35.643] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C3.dat
[10:55:35.651] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C4.dat
[10:55:35.658] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C5.dat
[10:55:35.665] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C6.dat
[10:55:35.672] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C7.dat
[10:55:35.679] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C8.dat
[10:55:35.686] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C9.dat
[10:55:35.693] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C10.dat
[10:55:35.700] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C11.dat
[10:55:35.707] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C12.dat
[10:55:35.714] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C13.dat
[10:55:35.721] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C14.dat
[10:55:35.728] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C15.dat
[10:55:35.747] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//defaultMaskFile.dat
[10:55:35.757] INFO: enter test to run
[10:56:01.737] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:56:01.737] INFO: running: highrate
[10:56:01.741] INFO: ----------------------------------------------------------------------
[10:56:01.741] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:56:01.741] INFO: ----------------------------------------------------------------------
[10:56:01.741] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:56:01.741] INFO: edge/corner pixel THR is adjusted
[10:56:01.741] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:56:02.698] INFO: Collecting data for 1 seconds...
[10:56:03.700] INFO: Done with hot pixel readout
[10:56:06.699] INFO: PixTest:: pg_setup set to default.
[10:56:06.700] INFO: 0 hot pixels found in step 0
[10:56:06.705] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:56:06.802] INFO: PixTest::trimHotPixels() done
[10:56:06.802] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C0.dat
[10:56:06.809] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C1.dat
[10:56:06.817] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C2.dat
[10:56:06.824] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C3.dat
[10:56:06.831] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C4.dat
[10:56:06.838] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C5.dat
[10:56:06.845] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C6.dat
[10:56:06.852] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C7.dat
[10:56:06.859] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C8.dat
[10:56:06.866] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C9.dat
[10:56:06.873] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C10.dat
[10:56:06.880] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C11.dat
[10:56:06.887] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C12.dat
[10:56:06.894] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C13.dat
[10:56:06.902] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C14.dat
[10:56:06.909] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//trimParameters35_C15.dat
[10:56:06.916] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-I-4-28_FPIXTest-17C-FNAL-160308-0940_2016-03-08_09h40m_1457451633/000_FPIXTest_p17//defaultMaskFile.dat
[10:56:06.925] INFO: enter test to run
[10:56:27.368] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:56:27.368] INFO: running: xray
[10:56:27.370] INFO: ----------------------------------------------------------------------
[10:56:27.370] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:56:27.370] INFO: ----------------------------------------------------------------------
[10:56:28.334] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:56:40.204] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[10:57:09.512] INFO: Resuming triggers.
[10:57:21.380] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[10:57:50.758] INFO: Resuming triggers.
[10:58:02.624] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[10:58:31.834] INFO: Resuming triggers.
[10:58:43.704] INFO: run duration 47 seconds, buffer almost full (81%), pausing triggers.
[10:59:12.954] INFO: Resuming triggers.
[10:59:24.823] INFO: run duration 59 seconds, buffer almost full (81%), pausing triggers.
[10:59:54.057] INFO: Resuming triggers.
[11:00:05.930] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[11:00:35.228] INFO: Resuming triggers.
[11:00:47.103] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[11:01:16.371] INFO: Resuming triggers.
[11:01:28.247] INFO: run duration 94 seconds, buffer almost full (81%), pausing triggers.
[11:01:57.413] INFO: Resuming triggers.
[11:02:02.771] INFO: data taking finished, elapsed time: 100 seconds.
[11:02:16.379] INFO: PixTest:: pg_setup set to default.
[11:02:16.382] INFO: PixTestXray::doPhRun() done
[11:02:16.517] INFO: enter test to run
[11:03:55.085] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[11:03:55.085] INFO: running: xray
[11:03:55.086] INFO: ----------------------------------------------------------------------
[11:03:55.086] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[11:03:55.086] INFO: ----------------------------------------------------------------------
[11:03:56.050] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[11:04:03.054] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[11:04:33.198] INFO: Resuming triggers.
[11:04:40.203] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[11:05:10.378] INFO: Resuming triggers.
[11:05:17.379] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[11:05:47.595] INFO: Resuming triggers.
[11:05:54.594] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[11:06:21.262] INFO: Resuming triggers.
[11:06:28.257] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[11:06:58.473] INFO: Resuming triggers.
[11:07:05.465] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[11:07:35.621] INFO: Resuming triggers.
[11:07:42.602] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[11:08:12.791] INFO: Resuming triggers.
[11:08:19.771] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[11:08:50.023] INFO: Resuming triggers.
[11:08:56.999] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[11:09:27.150] INFO: Resuming triggers.
[11:09:34.125] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[11:10:04.263] INFO: Resuming triggers.
[11:10:11.239] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[11:10:41.463] INFO: Resuming triggers.
[11:10:48.438] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[11:11:18.628] INFO: Resuming triggers.
[11:11:25.604] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[11:11:55.837] INFO: Resuming triggers.
[11:12:02.816] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[11:12:32.925] INFO: Resuming triggers.
[11:12:35.439] INFO: data taking finished, elapsed time: 100 seconds.
[11:12:46.582] INFO: PixTest:: pg_setup set to default.
[11:12:46.585] INFO: PixTestXray::doPhRun() done
[11:12:46.735] INFO: enter test to run
[11:13:15.569] INFO: test: HighRate no parameter change
[11:13:15.569] INFO: running: highrate
[11:13:15.570] INFO: ----------------------------------------------------------------------
[11:13:15.570] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[11:13:15.571] INFO: ----------------------------------------------------------------------
[11:13:15.712] INFO: Expecting 768 events.
[11:13:16.846] INFO: 768 events read in total (418ms).
[11:13:16.847] INFO: Test took 1269ms.
[11:13:17.649] INFO: Expecting 41600 events.
[11:13:20.702] INFO: 41600 events read in total (2526ms).
[11:13:20.703] INFO: Test took 3848ms.
[11:13:20.760] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:21.465] INFO: Expecting 41600 events.
[11:13:24.640] INFO: 41600 events read in total (2648ms).
[11:13:24.641] INFO: Test took 3863ms.
[11:13:24.677] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:25.401] INFO: Expecting 41600 events.
[11:13:28.635] INFO: 41600 events read in total (2707ms).
[11:13:28.636] INFO: Test took 3941ms.
[11:13:28.672] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:29.392] INFO: Expecting 41600 events.
[11:13:32.635] INFO: 41600 events read in total (2716ms).
[11:13:32.636] INFO: Test took 3947ms.
[11:13:32.672] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:33.393] INFO: Expecting 41600 events.
[11:13:36.644] INFO: 41600 events read in total (2724ms).
[11:13:36.645] INFO: Test took 3953ms.
[11:13:36.680] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:37.403] INFO: Expecting 41600 events.
[11:13:40.671] INFO: 41600 events read in total (2741ms).
[11:13:40.672] INFO: Test took 3972ms.
[11:13:40.708] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:41.427] INFO: Expecting 41600 events.
[11:13:44.679] INFO: 41600 events read in total (2725ms).
[11:13:44.680] INFO: Test took 3953ms.
[11:13:44.716] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:45.435] INFO: Expecting 41600 events.
[11:13:48.701] INFO: 41600 events read in total (2739ms).
[11:13:48.702] INFO: Test took 3967ms.
[11:13:48.737] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:49.458] INFO: Expecting 41600 events.
[11:13:52.698] INFO: 41600 events read in total (2714ms).
[11:13:52.699] INFO: Test took 3942ms.
[11:13:52.734] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:53.457] INFO: Expecting 41600 events.
[11:13:56.683] INFO: 41600 events read in total (2700ms).
[11:13:56.684] INFO: Test took 3930ms.
[11:13:56.719] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:13:57.442] INFO: Expecting 41600 events.
[11:14:00.704] INFO: 41600 events read in total (2735ms).
[11:14:00.705] INFO: Test took 3967ms.
[11:14:00.741] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:01.464] INFO: Expecting 41600 events.
[11:14:04.726] INFO: 41600 events read in total (2735ms).
[11:14:04.727] INFO: Test took 3966ms.
[11:14:04.763] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:05.484] INFO: Expecting 41600 events.
[11:14:08.739] INFO: 41600 events read in total (2728ms).
[11:14:08.740] INFO: Test took 3957ms.
[11:14:08.777] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:09.494] INFO: Expecting 41600 events.
[11:14:12.759] INFO: 41600 events read in total (2738ms).
[11:14:12.760] INFO: Test took 3964ms.
[11:14:12.796] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:13.515] INFO: Expecting 41600 events.
[11:14:16.768] INFO: 41600 events read in total (2726ms).
[11:14:16.769] INFO: Test took 3954ms.
[11:14:16.805] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:17.525] INFO: Expecting 41600 events.
[11:14:20.777] INFO: 41600 events read in total (2725ms).
[11:14:20.778] INFO: Test took 3954ms.
[11:14:20.813] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:21.537] INFO: Expecting 41600 events.
[11:14:24.788] INFO: 41600 events read in total (2725ms).
[11:14:24.789] INFO: Test took 3956ms.
[11:14:24.825] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:25.549] INFO: Expecting 41600 events.
[11:14:28.806] INFO: 41600 events read in total (2730ms).
[11:14:28.807] INFO: Test took 3964ms.
[11:14:28.843] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:29.565] INFO: Expecting 41600 events.
[11:14:32.773] INFO: 41600 events read in total (2681ms).
[11:14:32.774] INFO: Test took 3913ms.
[11:14:32.810] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:33.528] INFO: Expecting 41600 events.
[11:14:36.571] INFO: 41600 events read in total (2516ms).
[11:14:36.572] INFO: Test took 3742ms.
[11:14:36.606] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:14:36.967] INFO: enter test to run
[11:15:01.888] INFO: test: HighRate no parameter change
[11:15:01.888] INFO: running: highrate
[11:15:01.890] INFO: ----------------------------------------------------------------------
[11:15:01.890] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:15:01.890] INFO: ----------------------------------------------------------------------
[11:15:02.505] INFO: Expecting 208000 events.
[11:15:14.480] INFO: 208000 events read in total (11448ms).
[11:15:14.483] INFO: Test took 12585ms.
[11:15:14.638] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:15:14.891] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[11:15:14.891] INFO: number of red-efficiency pixels: 75 47 99 134 155 142 118 115 94 148 154 107 121 52 28 30
[11:15:14.891] INFO: number of X-ray hits detected: 68153 43257 71356 107022 109876 111750 120830 85303 80949 116878 120139 90604 91039 53981 25954 31636
[11:15:14.891] 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:15:14.891] INFO: number of Vcal hits detected: 207923 207951 207900 207862 207844 207856 207880 207881 207902 207848 207844 207892 207879 207948 207971 207970
[11:15:14.891] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 100.0 99.9 100.0 100.0 100.0
[11:15:14.891] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 99.9 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0
[11:15:14.891] INFO: X-ray hit rate [MHz/cm2]: 20.0 12.7 20.9 31.4 32.2 32.8 35.4 25.0 23.7 34.3 35.2 26.6 26.7 15.8 7.6 9.3
[11:15:14.891] INFO: PixTestHighRate::doXPixelAlive() done
[11:15:14.938] INFO: PixTest:: pg_setup set to default.
[11:15:14.950] INFO: enter test to run
[11:16:26.167] INFO: test: HighRate no parameter change
[11:16:26.167] INFO: running: highrate
[11:16:26.168] INFO: ----------------------------------------------------------------------
[11:16:26.168] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:16:26.168] INFO: ----------------------------------------------------------------------
[11:16:26.776] INFO: Expecting 208000 events.
[11:16:40.213] INFO: 208000 events read in total (12911ms).
[11:16:40.218] INFO: Test took 14043ms.
[11:16:40.496] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:16:40.791] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[11:16:40.791] INFO: number of red-efficiency pixels: 203 113 272 331 394 405 365 317 261 398 454 226 284 159 64 67
[11:16:40.791] INFO: number of X-ray hits detected: 127408 80737 134640 198530 205501 207292 224414 159784 151361 217093 223337 168175 169442 101056 48298 60349
[11:16:40.791] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:16:40.791] INFO: number of Vcal hits detected: 207791 207877 207706 207648 207563 207564 207606 207663 207730 207571 207509 207763 207700 207833 207935 207930
[11:16:40.791] INFO: Vcal hit fiducial efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[11:16:40.791] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.8 99.8 99.8 99.9 99.8 99.8 99.9 99.9 99.9 100.0 100.0
[11:16:40.791] INFO: X-ray hit rate [MHz/cm2]: 37.3 23.7 39.5 58.2 60.2 60.8 65.8 46.8 44.4 63.6 65.5 49.3 49.7 29.6 14.2 17.7
[11:16:40.791] INFO: PixTestHighRate::doXPixelAlive() done
[11:16:40.839] INFO: PixTest:: pg_setup set to default.
[11:16:40.855] INFO: enter test to run
[11:17:07.623] INFO: test: HighRate no parameter change
[11:17:07.623] INFO: running: highrate
[11:17:07.625] INFO: ----------------------------------------------------------------------
[11:17:07.625] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[11:17:07.625] INFO: ----------------------------------------------------------------------
[11:17:08.241] INFO: Expecting 208000 events.
[11:17:23.340] INFO: 208000 events read in total (14572ms).
[11:17:23.347] INFO: Test took 15714ms.
[11:17:23.761] INFO: Fetched DAQ statistics. Counters are being reset now.
[11:17:24.098] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
[11:17:24.098] INFO: number of red-efficiency pixels: 397 166 581 540 887 879 816 623 513 973 937 449 601 351 106 112
[11:17:24.098] INFO: number of X-ray hits detected: 185872 117935 195680 289419 297890 301815 325938 233792 220093 315911 325437 244905 247700 146381 70681 88010
[11:17:24.098] INFO: number of triggers sent (total per ROC): 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000 208000
[11:17:24.098] INFO: number of Vcal hits detected: 207569 207820 207291 207392 206974 206986 207033 207291 207443 206843 206872 207511 207330 207614 207892 207886
[11:17:24.098] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.7 99.5 99.5 99.6 99.7 99.7 99.5 99.5 99.8 99.7 99.8 99.9 99.9
[11:17:24.098] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.7 99.5 99.5 99.5 99.7 99.7 99.4 99.5 99.8 99.7 99.8 99.9 99.9
[11:17:24.098] INFO: X-ray hit rate [MHz/cm2]: 54.5 34.6 57.4 84.8 87.3 88.5 95.5 68.5 64.5 92.6 95.4 71.8 72.6 42.9 20.7 25.8
[11:17:24.098] INFO: PixTestHighRate::doXPixelAlive() done
[11:17:24.144] INFO: PixTest:: pg_setup set to default.
[11:17:24.163] INFO: enter test to run
[11:17:28.895] INFO: test: exit no parameter change
[11:17:29.289] QUIET: Connection to board 33 closed.
[11:17:29.290] INFO: pXar: this is the end, my friend