[09:40:25.459] INFO: *** Welcome to pxar ***
[09:40:25.459] INFO: *** Today: 2016/08/25
[09:40:26.372] INFO: *** Version: v1.9.0-818-g96727
[09:40:26.390] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//dacParameters35_C15.dat
[09:40:26.551] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:40:26.551] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//defaultMaskFile.dat
[09:40:26.559] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C15.dat
[09:40:26.679] INFO: clk: 4
[09:40:26.679] INFO: ctr: 4
[09:40:26.679] INFO: sda: 19
[09:40:26.679] INFO: tin: 9
[09:40:26.679] INFO: level: 15
[09:40:26.679] INFO: triggerdelay: 0
[09:40:26.679] QUIET: Instanciating API for pxar v1.9.0+814~g74979a6
[09:40:26.679] INFO: Log level: INFO
[09:40:26.715] QUIET: Connection to board DTB_WREKRL opened.
[09:40:26.718] 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:40:26.721] INFO: RPC call hashes of host and DTB match: 398089610
[09:40:28.255] INFO: DUT info:
[09:40:28.255] INFO: The DUT currently contains the following objects:
[09:40:28.255] INFO: 2 TBM Cores tbm08c (2 ON)
[09:40:28.255] INFO: TBM Core alpha (0): 7 registers set
[09:40:28.255] INFO: TBM Core beta (1): 7 registers set
[09:40:28.255] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[09:40:28.255] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.255] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.255] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.256] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[09:40:28.700] INFO: enter 'restricted' command line mode
[09:40:28.700] INFO: enter test to run
[09:40:33.617] INFO: test: PixelAlive no parameter change
[09:40:33.617] INFO: running: pixelalive
[09:40:33.678] INFO: ----------------------------------------------------------------------
[09:40:33.678] 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:40:33.679] INFO: ----------------------------------------------------------------------
[09:40:34.008] INFO: Expecting 41600 events.
[09:40:38.429] INFO: 41600 events read in total (3703ms).
[09:40:38.597] INFO: Test took 4915ms.
[09:40:38.611] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:40:39.144] INFO: PixTestAlive::aliveTest() done
[09:40:39.144] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 10
[09:40:39.295] INFO: enter test to run
[09:40:45.386] INFO: test: timing no parameter change
[09:40:45.386] INFO: running: timing
[09:40:45.389] INFO: ######################################################################
[09:40:45.389] INFO: PixTestTiming::doTest()
[09:40:45.389] INFO: ######################################################################
[09:40:45.389] INFO: ----------------------------------------------------------------------
[09:40:45.389] INFO: PixTestTiming::TBMPhaseScan()
[09:40:45.389] INFO: ----------------------------------------------------------------------
[09:49:14.510] INFO: TBM Phase Settings: 240
[09:49:14.510] INFO: 400MHz Phase: 4
[09:49:14.510] INFO: 160MHz Phase: 7
[09:49:14.510] INFO: Functional Phase Area: 5
[09:49:14.531] INFO: Test took 509142 ms.
[09:49:14.531] INFO: PixTestTiming::TBMPhaseScan() done.
[09:49:14.531] INFO: ----------------------------------------------------------------------
[09:49:14.531] INFO: PixTestTiming::ROCDelayScan()
[09:49:14.531] INFO: ----------------------------------------------------------------------
[09:54:13.774] INFO: ROC Delay Settings: 220
[09:54:13.774] INFO: ROC Header-Trailer/Token Delay: 11
[09:54:13.774] INFO: ROC Port 0 Delay: 4
[09:54:13.774] INFO: ROC Port 1 Delay: 3
[09:54:13.774] INFO: Functional ROC Area: 4
[09:54:13.777] INFO: Test took 299246 ms.
[09:54:13.777] INFO: PixTestTiming::ROCDelayScan() done.
[09:54:13.778] INFO: ----------------------------------------------------------------------
[09:54:13.778] INFO: PixTestTiming::TimingTest()
[09:54:13.778] INFO: ----------------------------------------------------------------------
[09:54:29.869] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:54:44.837] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:54:59.818] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:55:14.800] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:55:29.731] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:55:44.694] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:55:59.623] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:56:14.537] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:56:29.503] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:56:44.476] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:56:44.854] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:56:44.873] INFO: ----------------------------------------------------------------------
[09:56:44.873] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[09:56:44.873] INFO: ----------------------------------------------------------------------
[09:56:44.873] INFO: ----------------------------------------------------------------------
[09:56:44.873] INFO: Read back bit status: 1
[09:56:44.873] INFO: ----------------------------------------------------------------------
[09:56:44.873] INFO: ----------------------------------------------------------------------
[09:56:44.873] INFO: Timings are good!
[09:56:44.873] INFO: ----------------------------------------------------------------------
[09:56:44.873] INFO: Test took 151096 ms.
[09:56:44.873] INFO: PixTestTiming::TimingTest() done.
[09:56:44.891] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//tbmParameters_C0a.dat
[09:56:44.892] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:56:44.892] INFO: PixTestTiming::doTest took 959506 ms.
[09:56:44.892] INFO: PixTestTiming::doTest() done
[09:56:44.892] INFO: Write out TBMPhaseScan_0_V0
[09:56:44.892] INFO: Write out TBMPhaseScan_1_V0
[09:56:44.893] INFO: Write out CombinedTBMPhaseScan_V0
[09:56:44.918] INFO: Write out ROCDelayScan3_V0
[09:56:44.918] INFO: enter test to run
[09:57:14.251] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[09:57:14.251] INFO: running: highrate
[09:57:14.276] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[09:57:14.575] INFO: ----------------------------------------------------------------------
[09:57:14.575] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[09:57:14.575] INFO: ----------------------------------------------------------------------
[09:57:14.576] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[09:57:14.576] INFO: edge/corner pixel THR is adjusted
[09:57:14.576] INFO: PixTestHighRate::trimHotPixels: step 0...
[09:57:15.535] INFO: Collecting data for 5 seconds...
[09:57:20.551] INFO: Done with hot pixel readout
[09:57:31.981] INFO: PixTest:: pg_setup set to default.

[09:57:31.982] INFO: 1 hot pixels found in step 0
[09:57:32.015] INFO: 1 hot pixels could not be trimmed and have been masked.
[09:57:32.018] INFO: PixTest::trimHotPixels() done
[09:57:32.019] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C0.dat
[09:57:32.024] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C1.dat
[09:57:32.030] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C2.dat
[09:57:32.035] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C3.dat
[09:57:32.040] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C4.dat
[09:57:32.045] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C5.dat
[09:57:32.050] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C6.dat
[09:57:32.056] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C7.dat
[09:57:32.061] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C8.dat
[09:57:32.066] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C9.dat
[09:57:32.071] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C10.dat
[09:57:32.076] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C11.dat
[09:57:32.081] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C12.dat
[09:57:32.087] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C13.dat
[09:57:32.092] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C14.dat
[09:57:32.097] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C15.dat
[09:57:32.103] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//defaultMaskFile.dat
[09:57:32.117] INFO: enter test to run
[09:59:55.794] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[09:59:55.794] INFO: running: highrate
[09:59:55.798] INFO: ----------------------------------------------------------------------
[09:59:55.798] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[09:59:55.798] INFO: ----------------------------------------------------------------------
[09:59:55.798] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[09:59:55.798] INFO: edge/corner pixel THR is adjusted
[09:59:55.798] INFO: PixTestHighRate::trimHotPixels: step 0...
[09:59:56.755] INFO: Collecting data for 1 seconds...
[09:59:57.759] INFO: Done with hot pixel readout
[10:00:01.595] INFO: PixTest:: pg_setup set to default.
[10:00:01.596] INFO: 0 hot pixels found in step 0
[10:00:01.601] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:00:01.697] INFO: PixTest::trimHotPixels() done
[10:00:01.698] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C0.dat
[10:00:01.708] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C1.dat
[10:00:01.713] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C2.dat
[10:00:01.723] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C3.dat
[10:00:01.732] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C4.dat
[10:00:01.737] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C5.dat
[10:00:01.743] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C6.dat
[10:00:01.748] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C7.dat
[10:00:01.753] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C8.dat
[10:00:01.758] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C9.dat
[10:00:01.764] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C10.dat
[10:00:01.769] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C11.dat
[10:00:01.774] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C12.dat
[10:00:01.779] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C13.dat
[10:00:01.785] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C14.dat
[10:00:01.790] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//trimParameters35_C15.dat
[10:00:01.795] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-P-2-24_FPIXTest-17C-FNAL-160817-1311-300V_2016-08-17_13h19m_1471457967/000_FPIXTest_p17//defaultMaskFile.dat
[10:00:01.812] INFO: enter test to run
[10:00:23.793] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:00:23.793] INFO: running: xray
[10:00:23.795] INFO: ----------------------------------------------------------------------
[10:00:23.795] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:00:23.795] INFO: ----------------------------------------------------------------------
[10:00:24.776] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:00:36.562] INFO: run duration 11 seconds, buffer almost full (81%), pausing triggers.
[10:01:05.946] INFO: Resuming triggers.
[10:01:17.732] INFO: run duration 23 seconds, buffer almost full (81%), pausing triggers.
[10:01:46.926] INFO: Resuming triggers.
[10:01:58.715] INFO: run duration 35 seconds, buffer almost full (81%), pausing triggers.
[10:02:27.907] INFO: Resuming triggers.
[10:02:39.697] INFO: run duration 46 seconds, buffer almost full (81%), pausing triggers.
[10:03:09.532] INFO: Resuming triggers.
[10:03:21.323] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[10:03:50.497] INFO: Resuming triggers.
[10:04:02.285] INFO: run duration 70 seconds, buffer almost full (81%), pausing triggers.
[10:04:31.578] INFO: Resuming triggers.
[10:04:43.369] INFO: run duration 82 seconds, buffer almost full (81%), pausing triggers.
[10:05:13.112] INFO: Resuming triggers.
[10:05:24.899] INFO: run duration 93 seconds, buffer almost full (81%), pausing triggers.
[10:05:54.864] INFO: Resuming triggers.
[10:06:00.904] INFO: data taking finished, elapsed time: 100 seconds.
[10:06:16.282] INFO: PixTest:: pg_setup set to default.
[10:06:16.285] INFO: PixTestXray::doPhRun() done
[10:06:16.474] INFO: enter test to run
[10:06:44.167] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[10:06:44.167] INFO: running: xray
[10:06:44.168] INFO: ----------------------------------------------------------------------
[10:06:44.168] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:06:44.168] INFO: ----------------------------------------------------------------------
[10:06:45.131] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:06:52.091] INFO: run duration 6 seconds, buffer almost full (81%), pausing triggers.
[10:07:22.254] INFO: Resuming triggers.
[10:07:29.215] INFO: run duration 13 seconds, buffer almost full (81%), pausing triggers.
[10:07:59.419] INFO: Resuming triggers.
[10:08:06.374] INFO: run duration 20 seconds, buffer almost full (81%), pausing triggers.
[10:08:36.570] INFO: Resuming triggers.
[10:08:43.525] INFO: run duration 27 seconds, buffer almost full (81%), pausing triggers.
[10:09:13.650] INFO: Resuming triggers.
[10:09:20.604] INFO: run duration 34 seconds, buffer almost full (81%), pausing triggers.
[10:09:50.684] INFO: Resuming triggers.
[10:09:57.639] INFO: run duration 41 seconds, buffer almost full (81%), pausing triggers.
[10:10:27.687] INFO: Resuming triggers.
[10:10:34.641] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[10:11:04.825] INFO: Resuming triggers.
[10:11:11.783] INFO: run duration 55 seconds, buffer almost full (81%), pausing triggers.
[10:11:41.860] INFO: Resuming triggers.
[10:11:48.825] INFO: run duration 62 seconds, buffer almost full (81%), pausing triggers.
[10:12:18.880] INFO: Resuming triggers.
[10:12:25.844] INFO: run duration 69 seconds, buffer almost full (81%), pausing triggers.
[10:12:55.772] INFO: Resuming triggers.
[10:13:02.736] INFO: run duration 76 seconds, buffer almost full (81%), pausing triggers.
[10:13:32.903] INFO: Resuming triggers.
[10:13:39.870] INFO: run duration 83 seconds, buffer almost full (81%), pausing triggers.
[10:14:09.948] INFO: Resuming triggers.
[10:14:16.918] INFO: run duration 90 seconds, buffer almost full (81%), pausing triggers.
[10:14:47.026] INFO: Resuming triggers.
[10:14:53.998] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[10:15:25.160] INFO: Resuming triggers.
[10:15:28.029] INFO: data taking finished, elapsed time: 100 seconds.
[10:15:40.720] INFO: PixTest:: pg_setup set to default.
[10:15:40.723] INFO: PixTestXray::doPhRun() done
[10:15:40.874] INFO: enter test to run
[10:16:02.467] INFO: test: HighRate no parameter change
[10:16:02.467] INFO: running: highrate
[10:16:02.468] INFO: ----------------------------------------------------------------------
[10:16:02.468] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[10:16:02.468] INFO: ----------------------------------------------------------------------
[10:16:02.614] INFO: Expecting 768 events.
[10:16:03.750] INFO: 768 events read in total (420ms).
[10:16:03.750] INFO: Test took 1270ms.
[10:16:04.553] INFO: Expecting 41600 events.
[10:16:07.670] INFO: 41600 events read in total (2590ms).
[10:16:07.671] INFO: Test took 3912ms.
[10:16:07.702] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:08.424] INFO: Expecting 41600 events.
[10:16:11.616] INFO: 41600 events read in total (2665ms).
[10:16:11.618] INFO: Test took 3899ms.
[10:16:11.650] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:12.379] INFO: Expecting 41600 events.
[10:16:15.596] INFO: 41600 events read in total (2690ms).
[10:16:15.597] INFO: Test took 3930ms.
[10:16:15.628] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:16.350] INFO: Expecting 41600 events.
[10:16:19.557] INFO: 41600 events read in total (2680ms).
[10:16:19.558] INFO: Test took 3914ms.
[10:16:19.589] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:20.316] INFO: Expecting 41600 events.
[10:16:23.412] INFO: 41600 events read in total (2569ms).
[10:16:23.413] INFO: Test took 3808ms.
[10:16:23.445] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:24.161] INFO: Expecting 41600 events.
[10:16:27.406] INFO: 41600 events read in total (2718ms).
[10:16:27.407] INFO: Test took 3946ms.
[10:16:27.439] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:28.166] INFO: Expecting 41600 events.
[10:16:31.379] INFO: 41600 events read in total (2687ms).
[10:16:31.380] INFO: Test took 3925ms.
[10:16:31.414] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:32.131] INFO: Expecting 41600 events.
[10:16:35.246] INFO: 41600 events read in total (2588ms).
[10:16:35.247] INFO: Test took 3817ms.
[10:16:35.279] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:36.008] INFO: Expecting 41600 events.
[10:16:39.320] INFO: 41600 events read in total (2786ms).
[10:16:39.321] INFO: Test took 4025ms.
[10:16:39.353] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:40.077] INFO: Expecting 41600 events.
[10:16:43.271] INFO: 41600 events read in total (2667ms).
[10:16:43.271] INFO: Test took 3902ms.
[10:16:43.303] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:44.030] INFO: Expecting 41600 events.
[10:16:47.266] INFO: 41600 events read in total (2709ms).
[10:16:47.267] INFO: Test took 3947ms.
[10:16:47.300] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:48.030] INFO: Expecting 41600 events.
[10:16:51.250] INFO: 41600 events read in total (2694ms).
[10:16:51.251] INFO: Test took 3934ms.
[10:16:51.283] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:52.013] INFO: Expecting 41600 events.
[10:16:55.253] INFO: 41600 events read in total (2713ms).
[10:16:55.254] INFO: Test took 3953ms.
[10:16:55.285] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:56.012] INFO: Expecting 41600 events.
[10:16:59.182] INFO: 41600 events read in total (2643ms).
[10:16:59.183] INFO: Test took 3881ms.
[10:16:59.215] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:16:59.941] INFO: Expecting 41600 events.
[10:17:03.084] INFO: 41600 events read in total (2616ms).
[10:17:03.085] INFO: Test took 3854ms.
[10:17:03.117] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:17:03.846] INFO: Expecting 41600 events.
[10:17:07.072] INFO: 41600 events read in total (2699ms).
[10:17:07.073] INFO: Test took 3940ms.
[10:17:07.105] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:17:07.836] INFO: Expecting 41600 events.
[10:17:11.069] INFO: 41600 events read in total (2706ms).
[10:17:11.069] INFO: Test took 3946ms.
[10:17:11.101] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:17:11.823] INFO: Expecting 41600 events.
[10:17:15.069] INFO: 41600 events read in total (2719ms).
[10:17:15.070] INFO: Test took 3951ms.
[10:17:15.102] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:17:15.828] INFO: Expecting 41600 events.
[10:17:19.055] INFO: 41600 events read in total (2700ms).
[10:17:19.055] INFO: Test took 3935ms.
[10:17:19.087] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:17:19.815] INFO: Expecting 41600 events.
[10:17:22.674] INFO: 41600 events read in total (2332ms).
[10:17:22.675] INFO: Test took 3572ms.
[10:17:22.706] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:17:23.069] INFO: enter test to run
[10:17:26.179] INFO: test: HighRate no parameter change
[10:17:26.179] INFO: running: highrate
[10:17:26.192] INFO: ----------------------------------------------------------------------
[10:17:26.192] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:17:26.192] INFO: ----------------------------------------------------------------------
[10:17:26.811] INFO: Expecting 208000 events.
[10:17:38.580] INFO: 208000 events read in total (11242ms).
[10:17:38.582] INFO: Test took 12384ms.
[10:17:38.716] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:17:38.964] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 10
[10:17:38.964] INFO: number of red-efficiency pixels: 85 60 59 105 126 141 124 89 89 93 102 87 94 54 16 36
[10:17:38.964] INFO: number of X-ray hits detected: 60628 37751 57047 91458 100353 103469 104241 75535 67598 87603 85221 71979 74481 42004 17106 18599
[10:17:38.964] 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:17:38.964] INFO: number of Vcal hits detected: 207914 207939 207936 207894 207863 207858 207873 207909 207909 207905 207898 207911 207906 207946 207984 207474
[10:17:38.964] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 100.0 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[10:17:38.964] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 99.7
[10:17:38.964] INFO: X-ray hit rate [MHz/cm2]: 17.8 11.1 16.7 26.8 29.4 30.3 30.6 22.1 19.8 25.7 25.0 21.1 21.8 12.3 5.0 5.5
[10:17:38.964] INFO: PixTestHighRate::doXPixelAlive() done
[10:17:39.010] INFO: PixTest:: pg_setup set to default.
[10:17:39.032] INFO: enter test to run
[10:17:55.930] INFO: test: HighRate no parameter change
[10:17:55.930] INFO: running: highrate
[10:17:55.931] INFO: ----------------------------------------------------------------------
[10:17:55.931] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:17:55.931] INFO: ----------------------------------------------------------------------
[10:17:56.548] INFO: Expecting 208000 events.
[10:18:10.199] INFO: 208000 events read in total (13124ms).
[10:18:10.204] INFO: Test took 14264ms.
[10:18:10.489] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:18:10.789] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 10
[10:18:10.789] INFO: number of red-efficiency pixels: 246 106 216 409 428 548 450 328 263 302 409 279 360 166 55 71
[10:18:10.789] INFO: number of X-ray hits detected: 135805 85604 129661 206216 227856 232221 234768 171982 153700 197351 192527 161931 168956 94377 38695 42596
[10:18:10.789] 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:18:10.789] INFO: number of Vcal hits detected: 207730 207892 207769 207545 207527 207392 207519 207645 207726 207681 207557 207700 207623 207830 207941 207439
[10:18:10.789] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.7 99.8 99.8 99.9 99.9 99.8 99.9 99.8 99.9 100.0 100.0
[10:18:10.789] INFO: Vcal hit overall efficiency (%): 99.9 99.9 99.9 99.8 99.8 99.7 99.8 99.8 99.9 99.8 99.8 99.9 99.8 99.9 100.0 99.7
[10:18:10.789] INFO: X-ray hit rate [MHz/cm2]: 39.8 25.1 38.0 60.4 66.8 68.1 68.8 50.4 45.1 57.8 56.4 47.5 49.5 27.7 11.3 12.5
[10:18:10.789] INFO: PixTestHighRate::doXPixelAlive() done
[10:18:10.836] INFO: PixTest:: pg_setup set to default.
[10:18:10.856] INFO: enter test to run
[10:18:25.986] INFO: test: HighRate no parameter change
[10:18:25.986] INFO: running: highrate
[10:18:25.987] INFO: ----------------------------------------------------------------------
[10:18:25.987] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:18:25.987] INFO: ----------------------------------------------------------------------
[10:18:26.616] INFO: Expecting 208000 events.
[10:18:42.100] INFO: 208000 events read in total (14957ms).
[10:18:42.107] INFO: Test took 16108ms.
[10:18:42.527] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:18:42.871] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 10
[10:18:42.871] INFO: number of red-efficiency pixels: 499 249 427 981 848 1181 904 661 557 596 850 615 673 347 80 72
[10:18:42.871] INFO: number of X-ray hits detected: 198117 123649 187242 299219 330127 336495 339149 248535 222993 286884 278603 234992 243723 137787 56485 61478
[10:18:42.871] 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:18:42.871] INFO: number of Vcal hits detected: 207371 207728 207481 206823 206947 206461 206883 207169 207380 207337 206992 207298 207248 207618 207919 207438
[10:18:42.871] INFO: Vcal hit fiducial efficiency (%): 99.7 99.9 99.8 99.5 99.5 99.3 99.5 99.6 99.7 99.7 99.6 99.7 99.7 99.8 100.0 100.0
[10:18:42.871] INFO: Vcal hit overall efficiency (%): 99.7 99.9 99.8 99.4 99.5 99.3 99.5 99.6 99.7 99.7 99.5 99.7 99.6 99.8 100.0 99.7
[10:18:42.871] INFO: X-ray hit rate [MHz/cm2]: 58.1 36.2 54.9 87.7 96.8 98.6 99.4 72.8 65.4 84.1 81.7 68.9 71.4 40.4 16.6 18.0
[10:18:42.871] INFO: PixTestHighRate::doXPixelAlive() done
[10:18:42.917] INFO: PixTest:: pg_setup set to default.
[10:18:42.932] INFO: enter test to run
[10:18:46.986] INFO: test: exit no parameter change
[10:18:47.393] QUIET: Connection to board 33 closed.
[10:18:47.406] INFO: pXar: this is the end, my friend