diff --git a/scripts/analyze_sub_logs.py b/scripts/analyze_sub_logs.py new file mode 100755 index 0000000..ad8397c --- /dev/null +++ b/scripts/analyze_sub_logs.py @@ -0,0 +1,84 @@ +#!/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) + + 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.debug(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 = 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('-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) + +if __name__ == '__main__': + main() 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_;