diff --git a/RNS/Reticulum.py b/RNS/Reticulum.py index 94924ee9..0804c567 100755 --- a/RNS/Reticulum.py +++ b/RNS/Reticulum.py @@ -1327,6 +1327,7 @@ class Reticulum: except Exception as e: RNS.log("An error ocurred while handling RPC call from local client: "+str(e), RNS.LOG_ERROR) + RNS.trace_exception(e) def get_rpc_client(self): return multiprocessing.connection.Client(self.rpc_addr, family=self.rpc_type, authkey=self.rpc_key) diff --git a/RNS/__init__.py b/RNS/__init__.py index e4356502..8c56abe3 100755 --- a/RNS/__init__.py +++ b/RNS/__init__.py @@ -35,6 +35,8 @@ import time import datetime import random import threading +import math +import bisect from collections import deque from threading import Lock, Condition @@ -329,7 +331,7 @@ def prettytime(time, verbose=False, compact=False): if not neg: return tstr else: return f"-{tstr}" -def prettyshorttime(time, verbose=False, compact=False): +def prettyshorttime(time, verbose=False, compact=False, tight=False): neg = False time = time*1e6 if time < 0: @@ -365,8 +367,8 @@ def prettyshorttime(time, verbose=False, compact=False): for c in components: i += 1 if i == 1: pass - elif i < len(components): tstr += ", " - elif i == len(components): tstr += " and " + elif i < len(components): tstr += ", " if not tight else " " + elif i == len(components): tstr += " and " if not tight else " " tstr += c @@ -403,20 +405,25 @@ class Profiler: profilers = {} tags = {} + # Samples per tag per thread + MAX_CAPTURES = 10000 + @staticmethod - def get_profiler(tag=None, super_tag=None): + def get_profiler(tag=None, super_tag=None, max_captures=None): if tag in Profiler.profilers: return Profiler.profilers[tag] else: - profiler = Profiler(tag, super_tag) + if max_captures is None: max_captures = Profiler.MAX_CAPTURES + profiler = Profiler(tag, super_tag, max_captures) Profiler.profilers[tag] = profiler return profiler - def __init__(self, tag=None, super_tag=None): + def __init__(self, tag=None, super_tag=None, max_captures=None): self.paused = False self.pause_time = 0 self.pause_started = None self.tag = tag self.super_tag = super_tag + self.max_captures = max_captures if max_captures is not None else Profiler.MAX_CAPTURES if self.super_tag in Profiler.profilers: self.super_profiler = Profiler.profilers[self.super_tag] @@ -436,7 +443,7 @@ class Profiler: thread_ident = threading.get_ident() if not tag in Profiler.tags: Profiler.tags[tag] = {"threads": {}, "super": super_tag} if not thread_ident in Profiler.tags[tag]["threads"]: - Profiler.tags[tag]["threads"][thread_ident] = {"current_start": None, "captures": []} + Profiler.tags[tag]["threads"][thread_ident] = {"current_start": None, "captures": deque(maxlen=self.max_captures)} Profiler.tags[tag]["threads"][thread_ident]["current_start"] = time.perf_counter() self.resume_super() @@ -452,7 +459,7 @@ class Profiler: if Profiler.tags[tag]["threads"][thread_ident]["current_start"] != None: begin = Profiler.tags[tag]["threads"][thread_ident]["current_start"] Profiler.tags[tag]["threads"][thread_ident]["current_start"] = None - Profiler.tags[tag]["threads"][thread_ident]["captures"].append(end-begin) + Profiler.tags[tag]["threads"][thread_ident]["captures"].append((begin, end-begin)) if not Profiler._ran: Profiler._ran = True self.resume_super() @@ -474,55 +481,104 @@ class Profiler: @staticmethod def results(): - from statistics import mean, median, stdev results = {} - + + def find_window_start(captures, start_time, hi=None): + hi = len(captures) if hi is None else hi + idx = bisect.bisect_left(captures, start_time, hi=hi, key=lambda c: c[0]) + return idx if len(captures) - idx > 1 else None + + # Fast one-pass calculation of summary statistics + def calc_stats(captures, start=0, end=None, key=lambda c: c): + if end is None: end = len(captures) + count = end - start + + if count <= 0: return None + elif count == 1: + return { "mean": key(captures[start]), + "median": key(captures[start]), + "min": key(captures[start]), + "max": key(captures[start]), + "stdev": None } + + med_even = count % 2 == 0 + med_idx = start + (count // 2 if med_even else (count - 1) // 2) + if med_even: c_median = key(captures[med_idx]) + else: c_median = (key(captures[med_idx]) + key(captures[med_idx+1])) / 2 + + c_mean = 0; c_min = key(captures[start]); c_max = key(captures[start]); ck = 0; ck2 = 0 + for idx in range(start, end): + c = key(captures[idx]) + c_mean += c + if c < c_min: c_min = c + if c > c_max: c_max = c + ck += c - c_median + ck2 += (c - c_median) ** 2 + c_mean /= count + c_std = math.sqrt((ck2 - (ck ** 2)/count) / (count - 1)) + + return { "mean": c_mean, "median": c_median, "min": c_min, "max": c_max, "stdev": c_std } + + now = time.perf_counter() for tag in sorted(Profiler.tags): tag_captures = [] tag_entry = Profiler.tags[tag] - + for thread_ident in tag_entry["threads"]: thread_entry = tag_entry["threads"][thread_ident] thread_captures = thread_entry["captures"] - sample_count = len(thread_captures) - - if sample_count > 1: - thread_results = { "count": sample_count, - "mean": mean(thread_captures), - "median": median(thread_captures), - "stdev": stdev(thread_captures) } - - elif sample_count == 1: - thread_results = { "count": sample_count, - "mean": mean(thread_captures), - "median": median(thread_captures), - "stdev": None } + + #sample_count = len(thread_captures) + #if sample_count > 1: + # thread_results = { "count": sample_count, + # "mean": mean(thread_captures), + # "median": median(thread_captures), + # "stdev": stdev(thread_captures) } + #elif sample_count == 1: + # thread_results = { "count": sample_count, + # "mean": mean(thread_captures), + # "median": median(thread_captures), + # "stdev": None } tag_captures.extend(thread_captures) + tag_captures.sort(key=lambda c: c[0]) - sample_count = len(tag_captures) - if sample_count > 1: - tag_results = { "name": tag, - "super": tag_entry["super"], - "count": len(tag_captures), - "mean": mean(tag_captures), - "median": median(tag_captures), - "stdev": stdev(tag_captures) } - - elif sample_count == 1: - tag_results = { "name": tag, - "super": tag_entry["super"], - "count": len(tag_captures), - "mean": mean(tag_captures), - "median": median(tag_captures), - "stdev": None } + tag_results = None + if len(tag_captures): + captures_1m = None; captures_5m = None; captures_30m = None; captures_60m = None + stats_1m = None; stats_5m = None; stats_30m = None; stats_60m = None - results[tag] = tag_results + captures_1m = find_window_start(tag_captures, now - 1*60) + if captures_1m: captures_5m = find_window_start(tag_captures, now - 5*60, hi=captures_1m) + if captures_5m: captures_30m = find_window_start(tag_captures, now - 30*60, hi=captures_5m) + if captures_30m: captures_60m = find_window_start(tag_captures, now - 60*60, hi=captures_30m) + + stats_all = calc_stats(tag_captures, 0, key=lambda c: c[1]) + if captures_1m: stats_1m = calc_stats(tag_captures, captures_1m, key=lambda c: c[1]) + if captures_5m: stats_5m = calc_stats(tag_captures, captures_5m, key=lambda c: c[1]) + if captures_30m: stats_30m = calc_stats(tag_captures, captures_30m, key=lambda c: c[1]) + if captures_60m: stats_60m = calc_stats(tag_captures, captures_60m, key=lambda c: c[1]) + + tag_results = { "name": tag, + "super": tag_entry["super"], + "count": len(tag_captures), + "threads": len(tag_entry["threads"]), + "stats_all": stats_all, + "stats_1m": stats_1m, + "stats_5m": stats_5m, + "stats_30m": stats_30m, + "stats_60m": stats_60m } + + results[tag] = tag_results return results @staticmethod def format_results(results): + def pst(time): + if time is not None: return prettyshorttime(time, tight=True) + else: return "-----" + def print_results_recursive(tag, results, level=0): results_str = print_tag_results(tag, level+1) + "\n" @@ -533,18 +589,24 @@ class Profiler: return results_str - def print_tag_results(tag, level): ind = " "*level - name = tag["name"]; count = tag["count"] - mean = tag["mean"]; median = tag["median"]; stdev = tag["stdev"] + name = tag["name"]; count = tag["count"]; threads = tag["threads"] + stats_all = tag["stats_all"]; stats_1m = tag["stats_1m"]; stats_5m = tag["stats_5m"]; stats_30m = tag["stats_30m"]; stats_60m = tag["stats_60m"] results_str = f" {ind}{name}\n" - results_str += f" {ind} Samples : {count}\n" - if stdev != None: - results_str += f" {ind} Mean : {prettyshorttime(mean)}\n" - results_str += f" {ind} Median : {prettyshorttime(median)}\n" - results_str += f" {ind} St.dev. : {prettyshorttime(stdev)}\n" - results_str += f" {ind} Total : {prettyshorttime(mean*count)}\n" + results_str += f" {ind} Samples : {count} from {threads} thread{'s' if threads > 1 else ''}\n" + if stats_all != None: + results_str += f" {ind} Total : {pst(stats_all["mean"]*count)}\n" + results_str += f" {ind} {'Mean':^15} | {'Median':^15} | {'Min':^15} | {'Max':^15} | {'St. dev':^15}\n" + results_str += f" {ind} Stats : ({pst(stats_all["mean"]):^15} | {pst(stats_all["median"]):^15} | {pst(stats_all["min"]):^15} | {pst(stats_all["max"]):^15} | {pst(stats_all["stdev"]):^15})\n" + if stats_1m != None: + results_str += f" {ind} 1m : ({pst(stats_1m["mean"]):^15} | {pst(stats_1m["median"]):^15} | {pst(stats_1m["min"]):^15} | {pst(stats_1m["max"]):^15} | {pst(stats_1m["stdev"]):^15})\n" + if stats_5m != None: + results_str += f" {ind} 5m : ({pst(stats_5m["mean"]):^15} | {pst(stats_5m["median"]):^15} | {pst(stats_5m["min"]):^15} | {pst(stats_5m["max"]):^15} | {pst(stats_5m["stdev"]):^15})\n" + if stats_30m != None: + results_str += f" {ind} 30m : ({pst(stats_30m["mean"]):^15} | {pst(stats_30m["median"]):^15} | {pst(stats_30m["min"]):^15} | {pst(stats_30m["max"]):^15} | {pst(stats_30m["stdev"]):^15})\n" + if stats_60m != None: + results_str += f" {ind} 60m : ({pst(stats_60m["mean"]):^15} | {pst(stats_60m["median"]):^15} | {pst(stats_60m["min"]):^15} | {pst(stats_60m["max"]):^15} | {pst(stats_60m["stdev"]):^15})\n" return results_str results_str = ""