[09:44:49.314] INFO: *** Welcome to pxar ***
[09:44:49.314] INFO: *** Today: 2016/04/11
[09:44:49.799] INFO: *** Version: v1.9.0-796-gef167-dirty
[09:44:49.799] INFO: readRocDacs: /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//dacParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//dacParameters35_C15.dat
[09:44:49.843] INFO: readTbmDacs: /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//tbmParameters_C0a.dat .. /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:44:49.846] INFO: readMaskFile: /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//defaultMaskFile.dat
[09:44:49.851] INFO: readTrimFile: /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C15.dat
[09:44:49.977] INFO: clk: 4
[09:44:49.977] INFO: ctr: 4
[09:44:49.977] INFO: sda: 19
[09:44:49.977] INFO: tin: 9
[09:44:49.977] INFO: level: 15
[09:44:49.977] INFO: triggerdelay: 0
[09:44:49.977] QUIET: Instanciating API for pxar v1.9.0+796~gef16747
[09:44:49.977] INFO: Log level: INFO
[09:44:49.995] QUIET: Connection to board DTB_WREKRL opened.
[09:44:49.999] 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:44:49.002] INFO: RPC call hashes of host and DTB match: 398089610
[09:44:51.538] INFO: DUT info:
[09:44:51.538] INFO: The DUT currently contains the following objects:
[09:44:51.538] INFO: 2 TBM Cores tbm08c (2 ON)
[09:44:51.538] INFO: TBM Core alpha (0): 7 registers set
[09:44:51.538] INFO: TBM Core beta (1): 7 registers set
[09:44:51.538] INFO: 16 ROCs psi46digv21respin (16 ON) with 4160 pixelConfigs
[09:44:51.538] INFO: ROC 0: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.538] INFO: ROC 1: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.538] INFO: ROC 2: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.538] INFO: ROC 3: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.538] INFO: ROC 4: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.538] INFO: ROC 5: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.539] INFO: ROC 6: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.539] INFO: ROC 7: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.539] INFO: ROC 8: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.539] INFO: ROC 9: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.539] INFO: ROC 10: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.539] INFO: ROC 11: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.539] INFO: ROC 12: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.539] INFO: ROC 13: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.539] INFO: ROC 14: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.539] INFO: ROC 15: 19 DACs set, Pixels: 0 masked, 0 active.
[09:44:51.989] INFO: enter 'restricted' command line mode
[09:44:51.989] INFO: enter test to run
[09:45:50.336] INFO: test: timing no parameter change
[09:45:50.336] INFO: running: timing
[09:45:50.364] INFO: ######################################################################
[09:45:50.364] INFO: PixTestTiming::doTest()
[09:45:50.364] INFO: ######################################################################
[09:45:50.364] INFO: ----------------------------------------------------------------------
[09:45:50.364] INFO: PixTestTiming::TBMPhaseScan()
[09:45:50.364] INFO: ----------------------------------------------------------------------
[09:50:19.006] INFO: TBM Phase Settings: 236
[09:50:20.006] INFO: 400MHz Phase: 3
[09:50:20.006] INFO: 160MHz Phase: 7
[09:50:20.006] INFO: Functional Phase Area: 3
[09:50:20.012] INFO: Test took 269648 ms.
[09:50:20.012] INFO: PixTestTiming::TBMPhaseScan() done.
[09:50:20.013] INFO: ----------------------------------------------------------------------
[09:50:20.013] INFO: PixTestTiming::ROCDelayScan()
[09:50:20.013] INFO: ----------------------------------------------------------------------
[09:52:16.652] INFO: ROC Delay Settings: 228
[09:52:16.652] INFO: ROC Header-Trailer/Token Delay: 11
[09:52:16.652] INFO: ROC Port 0 Delay: 4
[09:52:16.653] INFO: ROC Port 1 Delay: 4
[09:52:16.653] INFO: Functional ROC Area: 4
[09:52:16.656] INFO: Test took 116644 ms.
[09:52:16.656] INFO: PixTestTiming::ROCDelayScan() done.
[09:52:16.656] INFO: ----------------------------------------------------------------------
[09:52:16.656] INFO: PixTestTiming::TimingTest()
[09:52:16.656] INFO: ----------------------------------------------------------------------
[09:52:32.828] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:52:47.822] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:53:02.798] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:53:17.806] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:53:32.784] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:53:47.781] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:54:02.768] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:54:17.747] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:54:32.735] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:54:47.724] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:54:48.106] INFO: Fetched DAQ statistics. Counters are being reset now.
[09:54:48.123] INFO: ----------------------------------------------------------------------
[09:54:48.123] INFO: The fraction of properly decoded events is 100.00%: 10000000/10000000
[09:54:48.123] INFO: ----------------------------------------------------------------------
[09:54:48.123] INFO: ----------------------------------------------------------------------
[09:54:48.123] INFO: Read back bit status: 1
[09:54:48.123] INFO: ----------------------------------------------------------------------
[09:54:48.123] INFO: ----------------------------------------------------------------------
[09:54:48.123] INFO: Timings are good!
[09:54:48.123] INFO: ----------------------------------------------------------------------
[09:54:48.123] INFO: Test took 151467 ms.
[09:54:48.123] INFO: PixTestTiming::TimingTest() done.
[09:54:48.145] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//tbmParameters_C0a.dat
[09:54:48.146] INFO: write tbm parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//tbmParameters_C0b.dat
[09:54:48.146] INFO: PixTestTiming::doTest took 537806 ms.
[09:54:48.146] INFO: PixTestTiming::doTest() done
[09:54:48.146] INFO: Write out TBMPhaseScan_0_V0
[09:54:48.180] INFO: Write out TBMPhaseScan_1_V0
[09:54:48.180] INFO: Write out CombinedTBMPhaseScan_V0
[09:54:48.180] INFO: Write out ROCDelayScan3_V0
[09:54:48.181] INFO: enter test to run
[10:08:30.085] INFO: test: PixelAlive no parameter change
[10:08:30.086] INFO: running: pixelalive
[10:08:30.090] INFO: ----------------------------------------------------------------------
[10:08:30.090] 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:08:30.090] INFO: ----------------------------------------------------------------------
[10:08:30.408] INFO: Expecting 41600 events.
[10:08:34.736] INFO: 41600 events read in total (3612ms).
[10:08:34.737] INFO: Test took 4645ms.
[10:08:34.748] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:08:35.144] INFO: PixTestAlive::aliveTest() done
[10:08:35.144] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0
[10:08:35.148] INFO: enter test to run
[10:08:57.829] INFO: test: HighRate setting parameters: ->runsecondshotpixels=5;trimhotpixelthr=200<-
[10:08:57.829] INFO: running: highrate
[10:08:57.830] INFO: readGainPedestalParameters /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//phCalibrationFitErr35_C0.dat .. /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//phCalibrationFitErr35_C15.dat
[10:08:58.103] INFO: ----------------------------------------------------------------------
[10:08:58.103] INFO: PixTest::trimHotPixels() running for 5 seconds with 100 kHz trigger rate
[10:08:58.103] INFO: ----------------------------------------------------------------------
[10:08:58.103] INFO: THR = 200, corresponding to ~ 106.667 MHz/cm2
[10:08:58.103] INFO: edge/corner pixel THR is adjusted
[10:08:58.103] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:08:59.062] INFO: Collecting data for 5 seconds...
[10:09:04.079] INFO: Done with hot pixel readout
[10:09:13.514] INFO: PixTest:: pg_setup set to default.
[10:09:13.515] INFO: 0 hot pixels found in step 0
[10:09:13.530] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:09:13.618] INFO: PixTest::trimHotPixels() done
[10:09:13.631] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C0.dat
[10:09:13.642] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C1.dat
[10:09:13.649] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C2.dat
[10:09:13.656] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C3.dat
[10:09:13.682] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C4.dat
[10:09:13.689] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C5.dat
[10:09:13.696] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C6.dat
[10:09:13.703] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C7.dat
[10:09:13.710] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C8.dat
[10:09:13.717] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C9.dat
[10:09:13.724] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C10.dat
[10:09:13.731] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C11.dat
[10:09:13.738] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C12.dat
[10:09:13.745] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C13.dat
[10:09:13.752] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C14.dat
[10:09:13.759] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C15.dat
[10:09:13.766] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//defaultMaskFile.dat
[10:09:13.775] INFO: enter test to run
[10:11:59.980] INFO: test: HighRate setting parameters: ->runsecondshotpixels=1;trimhotpixelthr=200<-
[10:11:59.980] INFO: running: highrate
[10:11:59.984] INFO: ----------------------------------------------------------------------
[10:11:59.984] INFO: PixTest::trimHotPixels() running for 1 seconds with 100 kHz trigger rate
[10:11:59.984] INFO: ----------------------------------------------------------------------
[10:11:59.985] INFO: THR = 200, corresponding to ~ 533.333 MHz/cm2
[10:11:59.985] INFO: edge/corner pixel THR is adjusted
[10:11:59.985] INFO: PixTestHighRate::trimHotPixels: step 0...
[10:12:00.943] INFO: Collecting data for 1 seconds...
[10:12:01.946] INFO: Done with hot pixel readout
[10:12:05.717] INFO: PixTest:: pg_setup set to default.
[10:12:05.718] INFO: 0 hot pixels found in step 0
[10:12:05.723] INFO: 0 hot pixels could not be trimmed and have been masked.
[10:12:05.822] INFO: PixTest::trimHotPixels() done
[10:12:05.822] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C0.dat
[10:12:05.838] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C1.dat
[10:12:05.845] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C2.dat
[10:12:05.852] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C3.dat
[10:12:05.859] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C4.dat
[10:12:05.866] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C5.dat
[10:12:05.873] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C6.dat
[10:12:05.880] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C7.dat
[10:12:05.887] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C8.dat
[10:12:05.894] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C9.dat
[10:12:05.901] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C10.dat
[10:12:05.908] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C11.dat
[10:12:05.915] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C12.dat
[10:12:05.922] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C13.dat
[10:12:05.929] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C14.dat
[10:12:05.936] INFO: write trim parameters into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//trimParameters35_C15.dat
[10:12:05.943] INFO: write masked pixels into /home/uicpirepix2/ProductionTestResults/M-H-2-17_FPIXTest-17C-FNAL-160223-0857_2016-02-23_08h57m_1456239466/000_FPIXTest_p17//defaultMaskFile.dat
[10:12:05.953] INFO: enter test to run
[10:13:09.083] INFO: test: Xray setting parameters: ->source=DCLowRate<-
[10:13:09.084] INFO: running: xray
[10:13:09.085] INFO: ----------------------------------------------------------------------
[10:13:09.085] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:13:09.085] INFO: ----------------------------------------------------------------------
[10:13:10.063] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:13:22.289] INFO: run duration 12 seconds, buffer almost full (81%), pausing triggers.
[10:13:51.454] INFO: Resuming triggers.
[10:14:03.686] INFO: run duration 24 seconds, buffer almost full (81%), pausing triggers.
[10:14:32.809] INFO: Resuming triggers.
[10:14:45.043] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[10:15:14.184] INFO: Resuming triggers.
[10:15:26.419] INFO: run duration 48 seconds, buffer almost full (81%), pausing triggers.
[10:15:50.279] INFO: Resuming triggers.
[10:16:02.516] INFO: run duration 60 seconds, buffer almost full (81%), pausing triggers.
[10:16:31.702] INFO: Resuming triggers.
[10:16:43.941] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[10:17:13.117] INFO: Resuming triggers.
[10:17:25.361] INFO: run duration 85 seconds, buffer almost full (81%), pausing triggers.
[10:17:54.494] INFO: Resuming triggers.
[10:18:06.737] INFO: run duration 97 seconds, buffer almost full (81%), pausing triggers.
[10:18:35.792] INFO: Resuming triggers.
[10:18:38.234] INFO: data taking finished, elapsed time: 100 seconds.
[10:18:44.336] INFO: PixTest:: pg_setup set to default.
[10:18:44.339] INFO: PixTestXray::doPhRun() done
[10:18:44.481] INFO: enter test to run
[10:21:37.280] INFO: test: Xray setting parameters: ->source=DCHighRate<-
[10:21:37.280] INFO: running: xray
[10:21:37.281] INFO: ----------------------------------------------------------------------
[10:21:37.281] INFO: PixTestXray::doPhRun() fParRunSeconds = 100
[10:21:37.281] INFO: ----------------------------------------------------------------------
[10:21:38.253] INFO: PixTestXray::doPhRun start TriggerLoop with trigger frequency 100 kHz, period 405 and duration 100 seconds, fEventsMax = 10000000
[10:21:45.599] INFO: run duration 7 seconds, buffer almost full (81%), pausing triggers.
[10:22:15.818] INFO: Resuming triggers.
[10:22:23.157] INFO: run duration 14 seconds, buffer almost full (81%), pausing triggers.
[10:22:53.334] INFO: Resuming triggers.
[10:23:00.673] INFO: run duration 21 seconds, buffer almost full (81%), pausing triggers.
[10:23:30.877] INFO: Resuming triggers.
[10:23:38.211] INFO: run duration 29 seconds, buffer almost full (81%), pausing triggers.
[10:24:08.415] INFO: Resuming triggers.
[10:24:15.750] INFO: run duration 36 seconds, buffer almost full (81%), pausing triggers.
[10:24:45.877] INFO: Resuming triggers.
[10:24:53.210] INFO: run duration 43 seconds, buffer almost full (81%), pausing triggers.
[10:25:23.416] INFO: Resuming triggers.
[10:25:30.753] INFO: run duration 51 seconds, buffer almost full (81%), pausing triggers.
[10:25:56.163] INFO: Resuming triggers.
[10:26:03.498] INFO: run duration 58 seconds, buffer almost full (81%), pausing triggers.
[10:26:33.662] INFO: Resuming triggers.
[10:26:40.004] INFO: run duration 65 seconds, buffer almost full (81%), pausing triggers.
[10:27:11.153] INFO: Resuming triggers.
[10:27:18.496] INFO: run duration 73 seconds, buffer almost full (81%), pausing triggers.
[10:27:48.680] INFO: Resuming triggers.
[10:27:56.022] INFO: run duration 80 seconds, buffer almost full (81%), pausing triggers.
[10:28:26.174] INFO: Resuming triggers.
[10:28:33.520] INFO: run duration 87 seconds, buffer almost full (81%), pausing triggers.
[10:29:03.705] INFO: Resuming triggers.
[10:29:11.051] INFO: run duration 95 seconds, buffer almost full (81%), pausing triggers.
[10:29:41.262] INFO: Resuming triggers.
[10:29:46.174] INFO: data taking finished, elapsed time: 100 seconds.
[10:30:06.537] INFO: PixTest:: pg_setup set to default.
[10:30:06.540] INFO: PixTestXray::doPhRun() done
[10:30:06.690] INFO: enter test to run
[10:30:32.636] INFO: test: HighRate no parameter change
[10:30:32.636] INFO: running: highrate
[10:30:32.637] INFO: ----------------------------------------------------------------------
[10:30:32.637] INFO: PixTestHighRate::calDelScan() ntrig = 10, vcal = 200
[10:30:32.637] INFO: ----------------------------------------------------------------------
[10:30:32.780] INFO: Expecting 768 events.
[10:30:33.913] INFO: 768 events read in total (418ms).
[10:30:33.914] INFO: Test took 1269ms.
[10:30:34.717] INFO: Expecting 41600 events.
[10:30:37.687] INFO: 41600 events read in total (2443ms).
[10:30:37.688] INFO: Test took 3765ms.
[10:30:37.715] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:30:38.456] INFO: Expecting 41600 events.
[10:30:41.555] INFO: 41600 events read in total (2572ms).
[10:30:41.556] INFO: Test took 3825ms.
[10:30:41.584] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:30:42.323] INFO: Expecting 41600 events.
[10:30:45.480] INFO: 41600 events read in total (2630ms).
[10:30:45.481] INFO: Test took 3881ms.
[10:30:45.510] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:30:46.245] INFO: Expecting 41600 events.
[10:30:49.437] INFO: 41600 events read in total (2665ms).
[10:30:49.438] INFO: Test took 3912ms.
[10:30:49.466] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:30:50.197] INFO: Expecting 41600 events.
[10:30:53.373] INFO: 41600 events read in total (2649ms).
[10:30:53.374] INFO: Test took 3891ms.
[10:30:53.403] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:30:54.133] INFO: Expecting 41600 events.
[10:30:57.321] INFO: 41600 events read in total (2662ms).
[10:30:57.322] INFO: Test took 3902ms.
[10:30:57.351] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:30:58.086] INFO: Expecting 41600 events.
[10:31:01.269] INFO: 41600 events read in total (2656ms).
[10:31:01.270] INFO: Test took 3904ms.
[10:31:01.299] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:02.031] INFO: Expecting 41600 events.
[10:31:05.219] INFO: 41600 events read in total (2661ms).
[10:31:05.220] INFO: Test took 3906ms.
[10:31:05.248] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:05.984] INFO: Expecting 41600 events.
[10:31:09.170] INFO: 41600 events read in total (2659ms).
[10:31:09.171] INFO: Test took 3906ms.
[10:31:09.199] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:09.934] INFO: Expecting 41600 events.
[10:31:13.114] INFO: 41600 events read in total (2653ms).
[10:31:13.115] INFO: Test took 3899ms.
[10:31:13.144] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:13.874] INFO: Expecting 41600 events.
[10:31:17.072] INFO: 41600 events read in total (2671ms).
[10:31:17.073] INFO: Test took 3913ms.
[10:31:17.102] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:17.833] INFO: Expecting 41600 events.
[10:31:21.012] INFO: 41600 events read in total (2652ms).
[10:31:21.013] INFO: Test took 3894ms.
[10:31:21.041] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:21.777] INFO: Expecting 41600 events.
[10:31:24.971] INFO: 41600 events read in total (2667ms).
[10:31:24.971] INFO: Test took 3913ms.
[10:31:24.000] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:25.733] INFO: Expecting 41600 events.
[10:31:28.907] INFO: 41600 events read in total (2647ms).
[10:31:28.908] INFO: Test took 3891ms.
[10:31:28.936] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:29.669] INFO: Expecting 41600 events.
[10:31:32.858] INFO: 41600 events read in total (2662ms).
[10:31:32.859] INFO: Test took 3908ms.
[10:31:32.888] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:33.625] INFO: Expecting 41600 events.
[10:31:36.803] INFO: 41600 events read in total (2651ms).
[10:31:36.804] INFO: Test took 3900ms.
[10:31:36.834] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:37.568] INFO: Expecting 41600 events.
[10:31:40.751] INFO: 41600 events read in total (2656ms).
[10:31:40.752] INFO: Test took 3903ms.
[10:31:40.780] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:41.514] INFO: Expecting 41600 events.
[10:31:44.702] INFO: 41600 events read in total (2661ms).
[10:31:44.703] INFO: Test took 3907ms.
[10:31:44.731] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:45.467] INFO: Expecting 41600 events.
[10:31:48.623] INFO: 41600 events read in total (2629ms).
[10:31:48.624] INFO: Test took 3877ms.
[10:31:48.653] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:49.388] INFO: Expecting 41600 events.
[10:31:52.436] INFO: 41600 events read in total (2521ms).
[10:31:52.437] INFO: Test took 3767ms.
[10:31:52.465] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:31:52.839] INFO: enter test to run
[10:32:23.715] INFO: test: HighRate no parameter change
[10:32:23.715] INFO: running: highrate
[10:32:23.716] INFO: ----------------------------------------------------------------------
[10:32:23.716] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:32:23.716] INFO: ----------------------------------------------------------------------
[10:32:24.334] INFO: Expecting 208000 events.
[10:32:35.883] INFO: 208000 events read in total (11023ms).
[10:32:35.886] INFO: Test took 12161ms.
[10:32:36.006] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:32:36.248] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0
[10:32:36.248] INFO: number of red-efficiency pixels: 58 40 68 102 122 102 81 72 72 92 102 72 95 54 21 19
[10:32:36.248] INFO: number of X-ray hits detected: 58115 37034 52706 92271 82502 86305 84987 60710 65273 69505 85141 66547 69387 44543 19377 20325
[10:32:36.248] 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:32:36.248] INFO: number of Vcal hits detected: 207939 207959 207932 207880 207877 207897 207919 207926 207830 207905 207896 207927 207902 207946 207977 207981
[10:32:36.248] INFO: Vcal hit fiducial efficiency (%): 100.0 100.0 100.0 99.9 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[10:32:36.249] INFO: Vcal hit overall efficiency (%): 100.0 100.0 100.0 99.9 99.9 100.0 100.0 100.0 99.9 100.0 100.0 100.0 100.0 100.0 100.0 100.0
[10:32:36.249] INFO: X-ray hit rate [MHz/cm2]: 17.0 10.9 15.4 27.0 24.2 25.3 24.9 17.8 19.1 20.4 25.0 19.5 20.3 13.1 5.7 6.0
[10:32:36.249] INFO: PixTestHighRate::doXPixelAlive() done
[10:32:36.295] INFO: PixTest:: pg_setup set to default.
[10:32:36.308] INFO: enter test to run
[10:33:15.051] INFO: test: HighRate no parameter change
[10:33:15.051] INFO: running: highrate
[10:33:15.052] INFO: ----------------------------------------------------------------------
[10:33:15.052] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:33:15.052] INFO: ----------------------------------------------------------------------
[10:33:15.669] INFO: Expecting 208000 events.
[10:33:28.787] INFO: 208000 events read in total (12591ms).
[10:33:28.793] INFO: Test took 13733ms.
[10:33:29.047] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:33:29.335] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0
[10:33:29.335] INFO: number of red-efficiency pixels: 180 97 224 320 355 360 293 194 181 207 314 186 262 180 43 49
[10:33:29.335] INFO: number of X-ray hits detected: 131048 85089 119102 208857 185160 193977 190737 137316 148110 155688 192606 150431 156202 100124 44635 46416
[10:33:29.335] 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:33:29.335] INFO: number of Vcal hits detected: 207813 207898 207756 207624 207631 207622 207696 207798 207716 207774 207670 207802 207724 207813 207956 207950
[10:33:29.335] INFO: Vcal hit fiducial efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.9 99.9 99.9 99.9 100.0 100.0
[10:33:29.335] INFO: Vcal hit overall efficiency (%): 99.9 100.0 99.9 99.8 99.8 99.8 99.9 99.9 99.9 99.9 99.8 99.9 99.9 99.9 100.0 100.0
[10:33:29.335] INFO: X-ray hit rate [MHz/cm2]: 38.4 24.9 34.9 61.2 54.3 56.9 55.9 40.2 43.4 45.6 56.5 44.1 45.8 29.3 13.1 13.6
[10:33:29.335] INFO: PixTestHighRate::doXPixelAlive() done
[10:33:29.382] INFO: PixTest:: pg_setup set to default.
[10:33:29.397] INFO: enter test to run
[10:34:08.818] INFO: test: HighRate no parameter change
[10:34:08.818] INFO: running: highrate
[10:34:08.820] INFO: ----------------------------------------------------------------------
[10:34:08.820] INFO: PixTestHighRate::xPixelAlive() ntrig = 50, vcal = 200
[10:34:08.820] INFO: ----------------------------------------------------------------------
[10:34:09.434] INFO: Expecting 208000 events.
[10:34:24.256] INFO: 208000 events read in total (14295ms).
[10:34:24.262] INFO: Test took 15433ms.
[10:34:24.645] INFO: Fetched DAQ statistics. Counters are being reset now.
[10:34:24.976] INFO: number of dead pixels (per ROC): 0 0 0 0 0 0 0 0 2 0 0 0 0 0 0 0
[10:34:24.976] INFO: number of red-efficiency pixels: 359 189 481 786 763 886 602 478 414 465 739 427 470 394 81 90
[10:34:24.976] INFO: number of X-ray hits detected: 201270 130391 182359 320544 282083 295500 291574 210258 227981 238524 296663 229967 240066 154350 68795 72341
[10:34:24.976] 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:34:24.976] INFO: number of Vcal hits detected: 207594 207790 207427 207037 207122 206974 207320 207470 207454 207480 207154 207541 207486 207545 207918 207907
[10:34:24.976] INFO: Vcal hit fiducial efficiency (%): 99.8 99.9 99.7 99.6 99.6 99.5 99.7 99.8 99.8 99.8 99.6 99.8 99.8 99.8 100.0 100.0
[10:34:24.976] INFO: Vcal hit overall efficiency (%): 99.8 99.9 99.7 99.5 99.6 99.5 99.7 99.7 99.7 99.8 99.6 99.8 99.8 99.8 100.0 100.0
[10:34:24.976] INFO: X-ray hit rate [MHz/cm2]: 59.0 38.2 53.5 94.0 82.7 86.6 85.5 61.6 66.8 69.9 87.0 67.4 70.4 45.2 20.2 21.2
[10:34:24.976] INFO: PixTestHighRate::doXPixelAlive() done
[10:34:25.029] INFO: PixTest:: pg_setup set to default.
[10:34:25.043] INFO: enter test to run
[10:34:28.330] INFO: test: exit no parameter change
[10:34:28.816] QUIET: Connection to board 33 closed.
[10:34:28.818] INFO: pXar: this is the end, my friend