From 6e2eedb0ffeea22928032e59f34889f6df076043 Mon Sep 17 00:00:00 2001 From: Manuel Bucher Date: Wed, 3 Jan 2024 15:52:43 +0100 Subject: [PATCH 1/5] Add script to plot neqo's MOZ_LOG output from the congestion controller This script can visualize MOZ_LOGs * 'HTTP/3 upload speed' in `about:logging` * log modules: `timestamp,neqo_transport::*:3` Using the directory `performance-test` from https://github.com/mozilla/neqo/pull/1529 Moving the script from https://github.com/mb/scripts/blob/5a72b00cda615a9ea940f0f93efeacb422807ec0/visualize/mozlog-neqo-cwnd.py Example output: https://bugzilla.mozilla.org/show_bug.cgi?id=1852924#c36 --- test/mozlog-neqo-cwnd.py | 143 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 143 insertions(+) create mode 100755 test/mozlog-neqo-cwnd.py diff --git a/test/mozlog-neqo-cwnd.py b/test/mozlog-neqo-cwnd.py new file mode 100755 index 0000000000..5a937cb46a --- /dev/null +++ b/test/mozlog-neqo-cwnd.py @@ -0,0 +1,143 @@ +#!/usr/bin/env python3 + +# Licensed under the Apache License, Version 2.0 or the MIT license +# , at your +# option. This file may not be copied, modified, or distributed +# except according to those terms. + +# Author: Manuel Bucher +# Date: 2023-11-02 + +import matplotlib.pyplot as plt +import re +import sys +from collections import defaultdict +from datetime import datetime + +#2023-11-02 13:32:28.450290 UTC - [Parent 31525: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] packet_sent this=0x7f84d3d31100, pn=111, ps=36 +#2023-11-02 13:32:28.477635 UTC - [Parent 31525: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] packet_acked this=0x7f84d3d31100, pn=111, ps=36, ignored=0, lost=0 +#2023-11-02 13:55:02.954829 UTC - [Parent 41203: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] packet_lost this=0x7f2864efcc80, pn=308694, ps=1337 +PATTERN = r" ([a-z_]+) this=0x([0-9a-f]+), pn=(\d+), ps=(\d+)" +events = re.compile(PATTERN) + +#2023-11-02 13:32:28.477655 UTC - [Parent 31525: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] on_packets_acked this=0x7f84d3d31100, limited=1, bytes_in_flight=0, cwnd=13370, state=SlowStart, new_acked=36 +PATTERN = r" on_packets_acked this=0x([0-9a-f]+), limited=(\d+), bytes_in_flight=(\d+), cwnd=(\d+), state=([a-zA-Z]+), new_acked=(\d+)" +acked = re.compile(PATTERN) +#2023-11-02 13:55:02.954909 UTC - [Parent 41203: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] on_packets_lost this=0x7f2864efcc80, bytes_in_flight=690883, cwnd=1520187, state=RecoveryStart +PATTERN = r" on_packet_lost this=0x([0-9a-f]+), bytes_in_flight=(\d+), cwnd=(\d+), state=([a-zA-Z]+)" +lost = re.compile(PATTERN) + +def get_time(line): + # allow garbage data before timestamp + timestamp = line.split(" UTC", 1)[0].split(' ') + timestamp = timestamp[-2] + " " + timestamp[-1] + return datetime.strptime(timestamp, "%Y-%m-%d %H:%M:%S.%f") + +def main(): + if len(sys.argv) < 2: + print("usage:", sys.argv[0], "LOG_FILE") + return + + data = defaultdict(lambda: { + "time": [], + "cwnd": [], + "bif": [], + "bif_limited": [], + "bif_limited_time": [], + "last_bytes_in_flight": 0, + "last_state": ("SlowStart", 0), + + # event occurences + "p": {}, # pn -> y-axis (bytes in flight after packet sent) + "ps": defaultdict(lambda: defaultdict(lambda: [])), # x/y coords of packet_sent/_acked/_lost + }) + + for line in open(sys.argv[1]): + if (result := acked.search(line)) is not None: + this = result.group(1) + now = get_time(line) + data[this]["time"].append(now) + data[this]["limited"] = bool(int(result.group(2))) + data[this]["last_bytes_in_flight"] = int(result.group(3)) + data[this]["bif"].append(data[this]["last_bytes_in_flight"]) + data[this]["cwnd"].append(int(result.group(4))) + state = result.group(5) + data[this]["last_state"] = (state, now) + data[this]["new_acked"] = result.group(6) + if data[this]["limited"]: + data[this]["bif_limited"].append(data[this]["last_bytes_in_flight"]) + data[this]["bif_limited_time"].append(now) + elif (result := events.search(line)) is not None: + this = result.group(2) + now = get_time(line) + event = result.group(1) + pn = int(result.group(3)) + packet_size = int(result.group(4)) + if event == "packet_sent" or event == "packet_acked" or event == "packet_lost": + if event == 'packet_sent': + data[this]["last_bytes_in_flight"] += packet_size + data[this]["p"][pn] = data[this]["last_bytes_in_flight"] + if data[this]["last_state"][0] == 'RecoveryStart': + data[this]["last_state"] = ('CongestionAvoidance', now) + if data[this]["last_state"] == 'PersistentCongestion': + data[this]["last_state"] = ('SlowStart', now) + # only remember events for packets where we sent the packet + if pn in data[this]["p"]: + data[this]["ps"][event]["time"].append(now) + data[this]["ps"][event]["bif"].append(data[this]["p"][pn]) + data[this]["ps"][event]["pn"].append(pn) + elif (result := lost.search(line)) is not None: + this = result.group(1) + now = get_time(line) + data[this]["time"].append(now) + data[this]["last_bytes_in_flight"] = int(result.group(3)) + data[this]["bif"].append(data[this]["last_bytes_in_flight"]) + data[this]["cwnd"].append(int(result.group(4))) + state = result.group(5) + data[this]["last_state"] = (state, now) + + output = "" + output_num = 0 + for el in data: + if len(data[el]["time"]) > output_num: + output_num = len(data[el]["time"]) + output = el + fig, axs = plt.subplots(2, 1) + + # add plots + graph_pn(axs[0], data[output]) + graph_cwnd(axs[1], data[output]) + + # configure graph + axs[0].set_title(sys.argv[1].split('/')[-1]) + for ax in axs: + ax.grid() + ax.legend() + plt.show() + +COLORS = { + 'packet_sent': 'black', + 'packet_lost': 'red', + 'packet_acked': 'green', +} + +# plot pn graph +def graph_pn(ax, output_data): + for event in ['packet_sent', 'packet_acked', 'packet_lost']: + ax.scatter(output_data["ps"][event]["time"], output_data["ps"][event]["pn"], label=event, s=10, color=COLORS[event]) + ax.set_xlabel('time in s') + ax.set_ylabel('packet_number') + +# plot cwnd graph +def graph_cwnd(ax, output_data): + ax.plot(output_data["time"], output_data["cwnd"], label='cwnd') + ax.plot(output_data["time"], output_data["bif"], '.-', label='bytes in flight') + ax.plot(output_data["bif_limited_time"], output_data["bif_limited"], 's', label='app_limited') + for event in ['packet_sent', 'packet_lost']: + ax.scatter(output_data["ps"][event]["time"], output_data["ps"][event]["bif"], label=event, s=10, color=COLORS[event]) + ax.set_xlabel('time in s') + ax.set_ylabel('bytes') + +if __name__ == '__main__': + main() From d4d7b9e7bfd8ed96eb556afe475447fa1d856380 Mon Sep 17 00:00:00 2001 From: Manuel Bucher Date: Wed, 17 Jan 2024 18:37:22 +0100 Subject: [PATCH 2/5] Add state color to background of diagrams --- test/mozlog-neqo-cwnd.py | 39 ++++++++++++++++++++++++++++++++++++++- 1 file changed, 38 insertions(+), 1 deletion(-) diff --git a/test/mozlog-neqo-cwnd.py b/test/mozlog-neqo-cwnd.py index 5a937cb46a..d1783fdd48 100755 --- a/test/mozlog-neqo-cwnd.py +++ b/test/mozlog-neqo-cwnd.py @@ -48,6 +48,10 @@ def main(): "last_bytes_in_flight": 0, "last_state": ("SlowStart", 0), + # color background depending on state + "bg_state": [], + "bg_time": [], + # event occurences "p": {}, # pn -> y-axis (bytes in flight after packet sent) "ps": defaultdict(lambda: defaultdict(lambda: [])), # x/y coords of packet_sent/_acked/_lost @@ -63,6 +67,9 @@ def main(): data[this]["bif"].append(data[this]["last_bytes_in_flight"]) data[this]["cwnd"].append(int(result.group(4))) state = result.group(5) + if data[this]["last_state"][0] != state: + data[this]["bg_state"].append(state) + data[this]["bg_time"].append(now) data[this]["last_state"] = (state, now) data[this]["new_acked"] = result.group(6) if data[this]["limited"]: @@ -79,8 +86,12 @@ def main(): data[this]["last_bytes_in_flight"] += packet_size data[this]["p"][pn] = data[this]["last_bytes_in_flight"] if data[this]["last_state"][0] == 'RecoveryStart': + data[this]["bg_state"].append('CongestionAvoidance') + data[this]["bg_time"].append(now) data[this]["last_state"] = ('CongestionAvoidance', now) if data[this]["last_state"] == 'PersistentCongestion': + data[this]["bg_state"].append('SlowStart') + data[this]["bg_time"].append(now) data[this]["last_state"] = ('SlowStart', now) # only remember events for packets where we sent the packet if pn in data[this]["p"]: @@ -95,6 +106,9 @@ def main(): data[this]["bif"].append(data[this]["last_bytes_in_flight"]) data[this]["cwnd"].append(int(result.group(4))) state = result.group(5) + if data[this]["last_state"][0] != state: + data[this]["bg_state"].append(state) + data[this]["bg_time"].append(now) data[this]["last_state"] = (state, now) output = "" @@ -105,14 +119,18 @@ def main(): output = el fig, axs = plt.subplots(2, 1) + data[output]['bg_time'].append(data[output]['time'][-1]) + for ax in axs: + color_background(ax, data[output]['bg_time'], data[output]['bg_state']) + # add plots graph_pn(axs[0], data[output]) graph_cwnd(axs[1], data[output]) + # configure graph axs[0].set_title(sys.argv[1].split('/')[-1]) for ax in axs: - ax.grid() ax.legend() plt.show() @@ -139,5 +157,24 @@ def graph_cwnd(ax, output_data): ax.set_xlabel('time in s') ax.set_ylabel('bytes') +def color_background(ax, time, states): + # change background depending on congestion controller state + state_colors = { + "SlowStart": "green", + "CongestionAvoidance": "blue", + "RecoveryStart": "gray", + "Recovery": "orange", + "PersistentCongestion": "purple", + } + legend = set() + for (time_from, time_to, state) in zip(time[:-1], time[1:], states): + color = state_colors[state] + if state in legend: + ax.axvspan(time_from, time_to, facecolor=color, alpha=0.3) + else: + legend.add(state) + ax.axvspan(time_from, time_to, facecolor=color, alpha=0.3, label=state) + + if __name__ == '__main__': main() From 8d42ebc9372a2491746569ff359b284a9e18ec67 Mon Sep 17 00:00:00 2001 From: Manuel Bucher Date: Wed, 7 Feb 2024 14:48:19 +0100 Subject: [PATCH 3/5] Fix 'on_packets_lost' line not being parsed --- test/mozlog-neqo-cwnd.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/test/mozlog-neqo-cwnd.py b/test/mozlog-neqo-cwnd.py index d1783fdd48..70b06580e6 100755 --- a/test/mozlog-neqo-cwnd.py +++ b/test/mozlog-neqo-cwnd.py @@ -25,7 +25,7 @@ PATTERN = r" on_packets_acked this=0x([0-9a-f]+), limited=(\d+), bytes_in_flight=(\d+), cwnd=(\d+), state=([a-zA-Z]+), new_acked=(\d+)" acked = re.compile(PATTERN) #2023-11-02 13:55:02.954909 UTC - [Parent 41203: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] on_packets_lost this=0x7f2864efcc80, bytes_in_flight=690883, cwnd=1520187, state=RecoveryStart -PATTERN = r" on_packet_lost this=0x([0-9a-f]+), bytes_in_flight=(\d+), cwnd=(\d+), state=([a-zA-Z]+)" +PATTERN = r" on_packets_lost this=0x([0-9a-f]+), bytes_in_flight=(\d+), cwnd=(\d+), state=([a-zA-Z]+)" lost = re.compile(PATTERN) def get_time(line): @@ -102,10 +102,10 @@ def main(): this = result.group(1) now = get_time(line) data[this]["time"].append(now) - data[this]["last_bytes_in_flight"] = int(result.group(3)) + data[this]["last_bytes_in_flight"] = int(result.group(2)) data[this]["bif"].append(data[this]["last_bytes_in_flight"]) - data[this]["cwnd"].append(int(result.group(4))) - state = result.group(5) + data[this]["cwnd"].append(int(result.group(3))) + state = result.group(4) if data[this]["last_state"][0] != state: data[this]["bg_state"].append(state) data[this]["bg_time"].append(now) From e5b088551dd82b6c7c4f68c3c321f32362ac425f Mon Sep 17 00:00:00 2001 From: Manuel Bucher Date: Wed, 7 Feb 2024 14:49:48 +0100 Subject: [PATCH 4/5] Apply formatting from black --- test/mozlog-neqo-cwnd.py | 132 ++++++++++++++++++++++++--------------- 1 file changed, 80 insertions(+), 52 deletions(-) diff --git a/test/mozlog-neqo-cwnd.py b/test/mozlog-neqo-cwnd.py index 70b06580e6..f40c3d5606 100755 --- a/test/mozlog-neqo-cwnd.py +++ b/test/mozlog-neqo-cwnd.py @@ -15,47 +15,51 @@ from collections import defaultdict from datetime import datetime -#2023-11-02 13:32:28.450290 UTC - [Parent 31525: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] packet_sent this=0x7f84d3d31100, pn=111, ps=36 -#2023-11-02 13:32:28.477635 UTC - [Parent 31525: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] packet_acked this=0x7f84d3d31100, pn=111, ps=36, ignored=0, lost=0 -#2023-11-02 13:55:02.954829 UTC - [Parent 41203: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] packet_lost this=0x7f2864efcc80, pn=308694, ps=1337 +# 2023-11-02 13:32:28.450290 UTC - [Parent 31525: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] packet_sent this=0x7f84d3d31100, pn=111, ps=36 +# 2023-11-02 13:32:28.477635 UTC - [Parent 31525: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] packet_acked this=0x7f84d3d31100, pn=111, ps=36, ignored=0, lost=0 +# 2023-11-02 13:55:02.954829 UTC - [Parent 41203: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] packet_lost this=0x7f2864efcc80, pn=308694, ps=1337 PATTERN = r" ([a-z_]+) this=0x([0-9a-f]+), pn=(\d+), ps=(\d+)" events = re.compile(PATTERN) -#2023-11-02 13:32:28.477655 UTC - [Parent 31525: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] on_packets_acked this=0x7f84d3d31100, limited=1, bytes_in_flight=0, cwnd=13370, state=SlowStart, new_acked=36 +# 2023-11-02 13:32:28.477655 UTC - [Parent 31525: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] on_packets_acked this=0x7f84d3d31100, limited=1, bytes_in_flight=0, cwnd=13370, state=SlowStart, new_acked=36 PATTERN = r" on_packets_acked this=0x([0-9a-f]+), limited=(\d+), bytes_in_flight=(\d+), cwnd=(\d+), state=([a-zA-Z]+), new_acked=(\d+)" acked = re.compile(PATTERN) -#2023-11-02 13:55:02.954909 UTC - [Parent 41203: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] on_packets_lost this=0x7f2864efcc80, bytes_in_flight=690883, cwnd=1520187, state=RecoveryStart +# 2023-11-02 13:55:02.954909 UTC - [Parent 41203: Socket Thread]: I/neqo_transport::* [neqo_transport::cc::classic_cc] on_packets_lost this=0x7f2864efcc80, bytes_in_flight=690883, cwnd=1520187, state=RecoveryStart PATTERN = r" on_packets_lost this=0x([0-9a-f]+), bytes_in_flight=(\d+), cwnd=(\d+), state=([a-zA-Z]+)" lost = re.compile(PATTERN) + def get_time(line): # allow garbage data before timestamp - timestamp = line.split(" UTC", 1)[0].split(' ') + timestamp = line.split(" UTC", 1)[0].split(" ") timestamp = timestamp[-2] + " " + timestamp[-1] return datetime.strptime(timestamp, "%Y-%m-%d %H:%M:%S.%f") + def main(): if len(sys.argv) < 2: print("usage:", sys.argv[0], "LOG_FILE") return - data = defaultdict(lambda: { - "time": [], - "cwnd": [], - "bif": [], - "bif_limited": [], - "bif_limited_time": [], - "last_bytes_in_flight": 0, - "last_state": ("SlowStart", 0), - - # color background depending on state - "bg_state": [], - "bg_time": [], - - # event occurences - "p": {}, # pn -> y-axis (bytes in flight after packet sent) - "ps": defaultdict(lambda: defaultdict(lambda: [])), # x/y coords of packet_sent/_acked/_lost - }) + data = defaultdict( + lambda: { + "time": [], + "cwnd": [], + "bif": [], + "bif_limited": [], + "bif_limited_time": [], + "last_bytes_in_flight": 0, + "last_state": ("SlowStart", 0), + # color background depending on state + "bg_state": [], + "bg_time": [], + # event occurences + "p": {}, # pn -> y-axis (bytes in flight after packet sent) + "ps": defaultdict( + lambda: defaultdict(lambda: []) + ), # x/y coords of packet_sent/_acked/_lost + } + ) for line in open(sys.argv[1]): if (result := acked.search(line)) is not None: @@ -81,18 +85,22 @@ def main(): event = result.group(1) pn = int(result.group(3)) packet_size = int(result.group(4)) - if event == "packet_sent" or event == "packet_acked" or event == "packet_lost": - if event == 'packet_sent': + if ( + event == "packet_sent" + or event == "packet_acked" + or event == "packet_lost" + ): + if event == "packet_sent": data[this]["last_bytes_in_flight"] += packet_size data[this]["p"][pn] = data[this]["last_bytes_in_flight"] - if data[this]["last_state"][0] == 'RecoveryStart': - data[this]["bg_state"].append('CongestionAvoidance') + if data[this]["last_state"][0] == "RecoveryStart": + data[this]["bg_state"].append("CongestionAvoidance") data[this]["bg_time"].append(now) - data[this]["last_state"] = ('CongestionAvoidance', now) - if data[this]["last_state"] == 'PersistentCongestion': - data[this]["bg_state"].append('SlowStart') + data[this]["last_state"] = ("CongestionAvoidance", now) + if data[this]["last_state"] == "PersistentCongestion": + data[this]["bg_state"].append("SlowStart") data[this]["bg_time"].append(now) - data[this]["last_state"] = ('SlowStart', now) + data[this]["last_state"] = ("SlowStart", now) # only remember events for packets where we sent the packet if pn in data[this]["p"]: data[this]["ps"][event]["time"].append(now) @@ -119,43 +127,63 @@ def main(): output = el fig, axs = plt.subplots(2, 1) - data[output]['bg_time'].append(data[output]['time'][-1]) + data[output]["bg_time"].append(data[output]["time"][-1]) for ax in axs: - color_background(ax, data[output]['bg_time'], data[output]['bg_state']) + color_background(ax, data[output]["bg_time"], data[output]["bg_state"]) # add plots graph_pn(axs[0], data[output]) graph_cwnd(axs[1], data[output]) - # configure graph - axs[0].set_title(sys.argv[1].split('/')[-1]) + axs[0].set_title(sys.argv[1].split("/")[-1]) for ax in axs: ax.legend() plt.show() + COLORS = { - 'packet_sent': 'black', - 'packet_lost': 'red', - 'packet_acked': 'green', + "packet_sent": "black", + "packet_lost": "red", + "packet_acked": "green", } - + + # plot pn graph def graph_pn(ax, output_data): - for event in ['packet_sent', 'packet_acked', 'packet_lost']: - ax.scatter(output_data["ps"][event]["time"], output_data["ps"][event]["pn"], label=event, s=10, color=COLORS[event]) - ax.set_xlabel('time in s') - ax.set_ylabel('packet_number') + for event in ["packet_sent", "packet_acked", "packet_lost"]: + ax.scatter( + output_data["ps"][event]["time"], + output_data["ps"][event]["pn"], + label=event, + s=10, + color=COLORS[event], + ) + ax.set_xlabel("time in s") + ax.set_ylabel("packet_number") + # plot cwnd graph def graph_cwnd(ax, output_data): - ax.plot(output_data["time"], output_data["cwnd"], label='cwnd') - ax.plot(output_data["time"], output_data["bif"], '.-', label='bytes in flight') - ax.plot(output_data["bif_limited_time"], output_data["bif_limited"], 's', label='app_limited') - for event in ['packet_sent', 'packet_lost']: - ax.scatter(output_data["ps"][event]["time"], output_data["ps"][event]["bif"], label=event, s=10, color=COLORS[event]) - ax.set_xlabel('time in s') - ax.set_ylabel('bytes') + ax.plot(output_data["time"], output_data["cwnd"], label="cwnd") + ax.plot(output_data["time"], output_data["bif"], ".-", label="bytes in flight") + ax.plot( + output_data["bif_limited_time"], + output_data["bif_limited"], + "s", + label="app_limited", + ) + for event in ["packet_sent", "packet_lost"]: + ax.scatter( + output_data["ps"][event]["time"], + output_data["ps"][event]["bif"], + label=event, + s=10, + color=COLORS[event], + ) + ax.set_xlabel("time in s") + ax.set_ylabel("bytes") + def color_background(ax, time, states): # change background depending on congestion controller state @@ -167,7 +195,7 @@ def color_background(ax, time, states): "PersistentCongestion": "purple", } legend = set() - for (time_from, time_to, state) in zip(time[:-1], time[1:], states): + for time_from, time_to, state in zip(time[:-1], time[1:], states): color = state_colors[state] if state in legend: ax.axvspan(time_from, time_to, facecolor=color, alpha=0.3) @@ -176,5 +204,5 @@ def color_background(ax, time, states): ax.axvspan(time_from, time_to, facecolor=color, alpha=0.3, label=state) -if __name__ == '__main__': +if __name__ == "__main__": main() From 2ff069ee317d8f5abc2860d7338e6268e21bb2ec Mon Sep 17 00:00:00 2001 From: Manuel Bucher Date: Wed, 7 Feb 2024 17:14:19 +0100 Subject: [PATCH 5/5] Mention mozlog-neqo-cwnd.py with example call in README.md --- test/README.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/test/README.md b/test/README.md index ca1bc0684f..38acb7a90f 100644 --- a/test/README.md +++ b/test/README.md @@ -31,3 +31,5 @@ The `upload_test.sh` script automates testing network conditions for `neqo-clien 3. **Automated Test Execution**: The script sets up network conditions and runs `neqo-client` and `neqo-server` tests. 4. **Cleanup**: At the end, it resets network conditions and stops the server. +## Visualize log file +Run `./mozlog-neqo-cwnd.py upload.log` to view the logs with matplotlib and python.