From d02ad3f9ef826ef4dbdb9f663a4d47252ed9f305 Mon Sep 17 00:00:00 2001 From: Tim Evens Date: Sat, 6 Sep 2025 07:07:52 -0700 Subject: [PATCH 1/3] Add analyzer script for subscribe logs --- src/qperf_sub.cc | 15 +++++++++++---- 1 file changed, 11 insertions(+), 4 deletions(-) diff --git a/src/qperf_sub.cc b/src/qperf_sub.cc index 77f2420..03fd35e 100644 --- a/src/qperf_sub.cc +++ b/src/qperf_sub.cc @@ -234,9 +234,14 @@ namespace qperf { SPDLOG_INFO(" min {}", min_object_arrival_delta_); SPDLOG_INFO(" max {}", max_object_arrival_delta_); SPDLOG_INFO(" avg {:04.3f}", avg_object_arrival_delta_); + SPDLOG_INFO(" over_multiplier {}", + static_cast(avg_object_arrival_delta_ / (perf_config_.transmit_interval * 10000))); SPDLOG_INFO("--------------------------------------------"); - // id,test_name,total_time,total_transmit_time,total_objects,total_bytes,sent_object,sent_bytes,min_bitrate,max_bitrate,avg_bitrate,min_time,maxtime,avg_time,min_arrival,max_arrival,avg_arrival - SPDLOG_INFO("OR COMPLETE, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}", + + // id,test_name,total_time,total_transmit_time,total_objects,total_bytes,sent_object,sent_bytes,min_bitrate, + // max_bitrate,avg_bitrate,min_time,maxtime,avg_time,min_arrival,max_arrival,avg_arrival, + // delta_objects,arrival_over_multiplier + SPDLOG_INFO("OR COMPLETE, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}, {}", test_identifier_, perf_config_.test_name, total_time, @@ -253,12 +258,14 @@ namespace qperf { avg_object_time_delta_, min_object_arrival_delta_, max_object_arrival_delta_, - avg_object_arrival_delta_); + avg_object_arrival_delta_, + test_complete.test_metrics.total_published_objects - total_objects_, + static_cast(avg_object_arrival_delta_ / (perf_config_.transmit_interval * 10000))); terminate_ = true; return; } else { SPDLOG_WARN( - "OR, {}, {} - unkown data identifier {}", test_identifier_, perf_config_.test_name, (int)test_mode_); + "OR, {}, {} - unknown data identifier {}", test_identifier_, perf_config_.test_name, (int)test_mode_); } last_local_now_ = local_now_; From 16ce5621a3b22a4d906b4f04c4a00e99be4d0fcb Mon Sep 17 00:00:00 2001 From: Tim Evens Date: Sat, 6 Sep 2025 07:15:15 -0700 Subject: [PATCH 2/3] Add analyzer script --- scripts/analyze_sub_logs.py | 60 +++++++++++++++++++++++++++++++++++++ 1 file changed, 60 insertions(+) create mode 100755 scripts/analyze_sub_logs.py diff --git a/scripts/analyze_sub_logs.py b/scripts/analyze_sub_logs.py new file mode 100755 index 0000000..f19689f --- /dev/null +++ b/scripts/analyze_sub_logs.py @@ -0,0 +1,60 @@ +#!/usr/bin/env python3 +# ----------------------------------------------------------------------------------------- +# Simple program to analyze the qperf subscriber result log files. +# +# Requirements: +# pip3 install click +# ----------------------------------------------------------------------------------------- + +import logging +import click +import time +import traceback +import os + +logging.basicConfig(format='%(asctime)s | %(levelname)-8s | %(name)s[%(lineno)s] %(threadName)s | %(message)s', + level=logging.INFO) +LOG = logging.getLogger("analyze_sub_logs") + +PATH = "./" + + +def process_sub_logs_path(path): + directory = os.fsencode(path) + + for file in os.listdir(directory): + filename = os.fsdecode(file) + if filename.startswith("t_") and filename.endswith("logs.txt"): + # print(os.path.join(directory, filename)) + file = os.path.join(path, filename) + LOG.info(f"Processing file: {file}") + + with open(file, "r") as f: + for line in f.readlines(): + if "OR COMPLETE, " in line: + csv = line.split("OR COMPLETE, ", maxsplit=1)[1].split(", ") + + if len(csv) >= 19: + track_id = csv[0] + test_name = csv[1] + delta_objects = csv[17] + over_multiplier = csv[18].strip() + LOG.info(f"id: {track_id} track name: '{test_name}' delta_objects: {delta_objects} over multiplier: {over_multiplier}") + else: + LOG.info(f"Skipping line csv length: {len(csv)}, expected 19") + else: + continue + + +@click.command(context_settings=dict(help_option_names=['-h', '--help'], max_content_width=200)) +@click.option('-p', '--path', 'path', + help="Directory/path of where the qperf log files are located", metavar='', default=PATH) +#@click.option('-b', '--bool', 'bool', default=False, +# is_flag=True, help="Bool value") +def main(path): + LOG.info(f"Loop through all qperf log files in directory {path}") + + process_sub_logs_path(path) + +if __name__ == '__main__': + main() From 91693b84eda676db94e5d911e72427ca9c6ffb2e Mon Sep 17 00:00:00 2001 From: Tim Evens Date: Sun, 7 Sep 2025 12:14:57 -0700 Subject: [PATCH 3/3] Add analysis of files --- scripts/analyze_sub_logs.py | 40 +++++++++++++++++++++++++++++-------- 1 file changed, 32 insertions(+), 8 deletions(-) diff --git a/scripts/analyze_sub_logs.py b/scripts/analyze_sub_logs.py index f19689f..ad8397c 100755 --- a/scripts/analyze_sub_logs.py +++ b/scripts/analyze_sub_logs.py @@ -22,12 +22,15 @@ def process_sub_logs_path(path): directory = os.fsencode(path) + num_delayed = 0 + num_lost_objects = 0 + for file in os.listdir(directory): filename = os.fsdecode(file) if filename.startswith("t_") and filename.endswith("logs.txt"): # print(os.path.join(directory, filename)) file = os.path.join(path, filename) - LOG.info(f"Processing file: {file}") + LOG.debug(f"Processing file: {file}") with open(file, "r") as f: for line in f.readlines(): @@ -37,22 +40,43 @@ def process_sub_logs_path(path): if len(csv) >= 19: track_id = csv[0] test_name = csv[1] - delta_objects = csv[17] - over_multiplier = csv[18].strip() - LOG.info(f"id: {track_id} track name: '{test_name}' delta_objects: {delta_objects} over multiplier: {over_multiplier}") + delta_objects = int(csv[17]) + over_multiplier = int(csv[18].strip()) + + if over_multiplier > 1 or delta_objects != 0: + if over_multiplier > 1: + num_delayed += 1 + if delta_objects != 0: + num_lost_objects += 1 + + LOG.info(f"id: {track_id} track name: '{test_name}' delta_objects: {delta_objects} over multiplier: {over_multiplier}") + else: + LOG.debug(f"id: {track_id} track name: '{test_name}' delta_objects: {delta_objects} over multiplier: {over_multiplier}") else: LOG.info(f"Skipping line csv length: {len(csv)}, expected 19") else: continue + # End of for loop through all files + if num_delayed > 0: + LOG.warning(f"ANALYSIS: {num_delayed} subscriber tracks were delayed 2 or more times the expected interval") + if num_lost_objects: + LOG.warning(f"ANALYSIS: {num_lost_objects} subscriber tracks had lost objects") + + if num_delayed == 0 and num_lost_objects == 0: + LOG.info("ANALYSIS: No issues found") @click.command(context_settings=dict(help_option_names=['-h', '--help'], max_content_width=200)) @click.option('-p', '--path', 'path', help="Directory/path of where the qperf log files are located", metavar='', default=PATH) -#@click.option('-b', '--bool', 'bool', default=False, -# is_flag=True, help="Bool value") -def main(path): - LOG.info(f"Loop through all qperf log files in directory {path}") +@click.option('-d', '--debug', 'debug', + help="Enable debug logging", + is_flag=True, default=False) +def main(path, debug): + if debug: + LOG.setLevel(logging.DEBUG) + + LOG.info(f"Reading all qperf subscriber log files in directory {path}") process_sub_logs_path(path)