From 71f2ff3611622c19151a832bd9105260410504c5 Mon Sep 17 00:00:00 2001 From: Pete Peterson Date: Wed, 27 Dec 2023 09:26:21 -0500 Subject: [PATCH 01/15] Add badge for pre-commit --- README.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/README.md b/README.md index ad4306a..a015127 100644 --- a/README.md +++ b/README.md @@ -49,3 +49,5 @@ You can interact with a demo profile [here](http://www.nbi.dk/~nvaytet/SNSPowder ## Contact Neil Vaytet, European Spallation Source + +[![pre-commit.ci status](https://results.pre-commit.ci/badge/github/mantidproject/mantid-profiler/main.svg)](https://results.pre-commit.ci/latest/github/mantidproject/mantid-profiler/main) From c9739a3cfcd50b36d056321205bdde3c20c55700 Mon Sep 17 00:00:00 2001 From: Pete Peterson Date: Wed, 27 Dec 2023 09:53:35 -0500 Subject: [PATCH 02/15] Terminate process being watched when script is interupted --- psrecord.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/psrecord.py b/psrecord.py index 01dc6f0..18794ce 100644 --- a/psrecord.py +++ b/psrecord.py @@ -172,7 +172,8 @@ def monitor(pid, logfile=None, interval=None): time.sleep(interval) except KeyboardInterrupt: # pragma: no cover - pass + print(f"killing process being monitored [PID={pr.pid}]:", " ".join(pr.cmdline())) + pr.kill() if logfile: f.close() From a4c15a0bcae235a8a331877557157b9b0ed75043 Mon Sep 17 00:00:00 2001 From: Pete Peterson Date: Wed, 27 Dec 2023 11:40:28 -0500 Subject: [PATCH 03/15] Add type hints and explicit exceptions --- psrecord.py | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/psrecord.py b/psrecord.py index 18794ce..eb24788 100644 --- a/psrecord.py +++ b/psrecord.py @@ -31,6 +31,7 @@ ############################################################################### import time +from typing import Optional # returns percentage for system + user time @@ -84,11 +85,15 @@ def update_children(old_children, new_children): # old children - dict, new_chi old_children.update(updct) -def monitor(pid, logfile=None, interval=None): +def monitor(pid: int, logfile: str, interval: Optional[float]): # We import psutil here so that the module can be imported even if psutil # is not present (for example if accessing the version) import psutil + # change None to reasonable default + if interval is None: + interval = 0.0 + pr = psutil.Process(pid) # Record start time @@ -140,7 +145,7 @@ def monitor(pid, logfile=None, interval=None): current_cpu = get_percent(pr) current_mem = get_memory(pr) current_threads = get_threads(pr) - except Exception: # noqa: BLE001 + except (psutil.NoSuchProcess, psutil.AccessDenied): break current_mem_real = current_mem.rss / 1024.0**2 current_mem_virtual = current_mem.vms / 1024.0**2 @@ -152,7 +157,7 @@ def monitor(pid, logfile=None, interval=None): current_cpu += get_percent(child) current_mem = get_memory(child) current_threads.extend(get_threads(child)) - except Exception: # noqa: BLE001 + except (psutil.NoSuchProcess, psutil.AccessDenied): continue current_mem_real += current_mem.rss / 1024.0**2 current_mem_virtual += current_mem.vms / 1024.0**2 @@ -168,7 +173,7 @@ def monitor(pid, logfile=None, interval=None): ) f.flush() - if interval is not None: + if interval > 0.0: time.sleep(interval) except KeyboardInterrupt: # pragma: no cover From 834ea6073bad4e11ee0cbff5b178b1ae76215b32 Mon Sep 17 00:00:00 2001 From: Pete Peterson Date: Wed, 27 Dec 2023 12:02:01 -0500 Subject: [PATCH 04/15] Refactor functionality into utility module --- psrecord.py | 18 +++++++----------- time_util.py | 12 ++++++++++++ 2 files changed, 19 insertions(+), 11 deletions(-) create mode 100644 time_util.py diff --git a/psrecord.py b/psrecord.py index eb24788..23bc2f0 100644 --- a/psrecord.py +++ b/psrecord.py @@ -30,9 +30,11 @@ # ############################################################################### -import time +from time import sleep from typing import Optional +from time_util import get_current_time, get_start_time + # returns percentage for system + user time def get_percent(process): @@ -97,11 +99,8 @@ def monitor(pid: int, logfile: str, interval: Optional[float]): pr = psutil.Process(pid) # Record start time - starting_point = time.time() - try: - start_time = time.perf_counter() - except AttributeError: - start_time = time.time() + starting_point = get_start_time() + start_time = get_current_time() f = open(logfile, "w") f.write( @@ -123,10 +122,7 @@ def monitor(pid: int, logfile: str, interval: Optional[float]): # Start main event loop while True: # Find current time - try: - current_time = time.perf_counter() - except AttributeError: - current_time = time.time() + current_time = get_current_time() try: pr_status = pr.status() @@ -174,7 +170,7 @@ def monitor(pid: int, logfile: str, interval: Optional[float]): f.flush() if interval > 0.0: - time.sleep(interval) + sleep(interval) except KeyboardInterrupt: # pragma: no cover print(f"killing process being monitored [PID={pr.pid}]:", " ".join(pr.cmdline())) diff --git a/time_util.py b/time_util.py new file mode 100644 index 0000000..1e23409 --- /dev/null +++ b/time_util.py @@ -0,0 +1,12 @@ +import time + + +def get_start_time() -> float: + return time.time() + + +def get_current_time() -> float: + try: + return time.perf_counter() + except AttributeError: + return time.time() From e3eed1b135ac1caa33ff988f88f69f31f07f432a Mon Sep 17 00:00:00 2001 From: Pete Peterson Date: Wed, 27 Dec 2023 12:08:31 -0500 Subject: [PATCH 05/15] Add log file for disk usage --- diskrecord.py | 72 ++++++++++++++++++++++++++++++++++++++++++++++ mantid-profiler.py | 26 +++++++++++++---- 2 files changed, 93 insertions(+), 5 deletions(-) create mode 100644 diskrecord.py diff --git a/diskrecord.py b/diskrecord.py new file mode 100644 index 0000000..35afeed --- /dev/null +++ b/diskrecord.py @@ -0,0 +1,72 @@ +from time import sleep +from typing import Optional + +import psutil + +from time_util import get_current_time, get_start_time + + +def monitor(pid: int, logfile: str, interval: Optional[float]): + """Monitor the disk usage of the supplied process id + The interval defaults to ??? if not supplied""" # TODO + # change None to reasonable default + if interval is None: + interval = 0.1 # TODO + + process = psutil.Process(pid) + + # Record start time + starting_point = get_start_time() + start_time = get_current_time() + + disk_before = process.io_counters() + + with open(logfile, "w") as handle: + # add header + handle.write( + "# {0:12s} {1:12s} {2:12s} {3:12s} {4}\n".format( + "Elapsed time".center(12), + "ReadChars (per sec)".center(12), + "WriteChars (per sec)".center(12), + "ReadBytes (per sec)".center(12), + "WriteBytes (per sec)".center(12), + ) + ) + handle.write("START_TIME: {}\n".format(starting_point)) + + # main event loop + try: + while True: + try: + # update information + current_time = get_current_time() + disk_after = process.io_counters() + + # calculate amount per second + read_char_per_sec = (disk_after.read_chars - disk_before.read_chars) / interval + write_char_per_sec = (disk_after.write_chars - disk_before.write_chars) / interval + + read_byte_per_sec = (disk_after.read_bytes - disk_before.read_bytes) / interval + write_byte_per_sec = (disk_after.write_bytes - disk_before.write_bytes) / interval + + # write information to the log file + handle.write( + "{0:12.6f} {1:12.3f} {2:12.3f} {3:12.3f} {4}\n".format( + current_time - start_time + starting_point, + read_char_per_sec, + write_char_per_sec, + read_byte_per_sec, + write_byte_per_sec, + ) + ) + + # copy over information to new previous + disk_before = disk_after + except (psutil.NoSuchProcess, psutil.AccessDenied): + break # all done + + if interval > 0.0: + sleep(interval) + except KeyboardInterrupt: # pragma: no cover + print(f"killing process being monitored [PID={process.pid}]:", " ".join(process.cmdline())) + process.kill() diff --git a/mantid-profiler.py b/mantid-profiler.py index 5319fb3..6c5ed6c 100644 --- a/mantid-profiler.py +++ b/mantid-profiler.py @@ -18,11 +18,13 @@ import argparse import copy import sys +from threading import Thread import numpy as np import algorithm_tree as at -import psrecord +from diskrecord import monitor as diskmonitor +from psrecord import monitor as cpumonitor # Parse the logfile outputted by psrecord @@ -301,7 +303,7 @@ def htmlProfile( def main(): parser = argparse.ArgumentParser(description="Profile a Mantid workflow") - parser.add_argument("pid", type=str, help="the process id") + parser.add_argument("pid", type=int, help="the process id") parser.add_argument("--outfile", type=str, default="profile.html", help="name of output html file") @@ -313,6 +315,10 @@ def main(): "--logfile", type=str, default="mantidprofile.txt", help="name of output file containing process monitor data" ) + parser.add_argument( + "--diskfile", type=str, default="mantiddisk.txt", help="name of output file containing process disk usage data" + ) + parser.add_argument( "--interval", type=float, @@ -330,9 +336,19 @@ def main(): args = parser.parse_args() - # Launch the process monitor and wait for it to return - print("Attaching to process " + args.pid) - psrecord.monitor(int(args.pid), logfile=args.logfile, interval=args.interval) + print(f"Attaching to process {args.pid}") + + # start the disk monitor in a separate thread + diskthread = Thread( + target=diskmonitor, args=(args.pid,), kwargs={"logfile": args.diskfile, "interval": args.interval} + ) + diskthread.start() + + # cpu mointor in main thread to prevent early exit + cpumonitor(int(args.pid), logfile=args.logfile, interval=args.interval) + + # wait for disk monitor to finish + diskthread.join() # Read in algorithm timing log and build tree try: From 0a13fbb5b7ddbe433be4e41795cfecdbc2bfa7a5 Mon Sep 17 00:00:00 2001 From: Pete Peterson Date: Wed, 27 Dec 2023 14:53:38 -0500 Subject: [PATCH 06/15] Move parsing function closer to writer --- psrecord.py | 60 +++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 60 insertions(+) diff --git a/psrecord.py b/psrecord.py index 23bc2f0..1ce3177 100644 --- a/psrecord.py +++ b/psrecord.py @@ -30,9 +30,13 @@ # ############################################################################### +import copy +from pathlib import Path from time import sleep from typing import Optional +import numpy as np + from time_util import get_current_time, get_start_time @@ -178,3 +182,59 @@ def monitor(pid: int, logfile: str, interval: Optional[float]): if logfile: f.close() + + +# Parse the logfile outputted by psrecord +def parse_log(filename: Path, cleanup: bool = True): + rows = [] + dct1 = {} # starts out uninitialzed + dct2 = {} + start_time = 0.0 + with open(filename, "r") as f: + for line in f: + if "#" in line: + continue + if "START_TIME:" in line: + start_time = float(line.split()[1]) + continue + line = line.replace("[", "") + line = line.replace("]", "") + line = line.replace("(", "") + line = line.replace(")", "") + line = line.replace(",", "") + line = line.replace("pthread", "") + line = line.replace("id=", "") + line = line.replace("user_time=", "") + line = line.replace("system_time=", "") + row = [] + lst = line.split() + for i in range(4): + row.append(float(lst[i])) + i = 4 + dct1 = copy.deepcopy(dct2) + dct2.clear() + while i < len(lst): + idx = int(lst[i]) + i += 1 + ut = float(lst[i]) + i += 1 + st = float(lst[i]) + i += 1 + dct2.update({idx: [ut, st]}) + count = 0 + for key, val in dct2.items(): + if key not in dct1.keys(): + count += 1 + continue + elem = dct1[key] + if val[0] != elem[0] or val[1] != elem[1]: + count += 1 + row.append(count) + row.append(len(dct2)) + rows.append(row) + # remove the file + if cleanup and filename.exists(): + filename.unlink() + + # return results + return start_time, np.array(rows) From 69282906cd7712461b0fa71a79a1387636f5a46f Mon Sep 17 00:00:00 2001 From: Pete Peterson Date: Wed, 27 Dec 2023 14:54:11 -0500 Subject: [PATCH 07/15] Add option to cleanup file --- algorithm_tree.py | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/algorithm_tree.py b/algorithm_tree.py index 8b18506..55099ea 100644 --- a/algorithm_tree.py +++ b/algorithm_tree.py @@ -17,6 +17,7 @@ import copy import re +from pathlib import Path class Node: @@ -137,7 +138,7 @@ def parseLine(line): return {"thread_id": res.group(1), "name": res.group(2), "start": int(res.group(3)), "finish": int(res.group(4))} -def fromFile(fileName): +def fromFile(fileName: Path, cleanup: bool = True): res = [] header = "" with open(fileName) as inp: @@ -146,6 +147,10 @@ def fromFile(fileName): header = line.strip("\n") continue res.append(parseLine(line)) + + if cleanup and fileName.exists(): + fileName.unlink() + return header, res From bccb871f4c474f13b4669cb550b24b0a8d01ee01 Mon Sep 17 00:00:00 2001 From: Pete Peterson Date: Wed, 27 Dec 2023 14:57:36 -0500 Subject: [PATCH 08/15] Refactor code for generating traces --- mantid-profiler.py | 151 ++++++++++++++------------------------------- 1 file changed, 48 insertions(+), 103 deletions(-) diff --git a/mantid-profiler.py b/mantid-profiler.py index 6c5ed6c..93d46c6 100644 --- a/mantid-profiler.py +++ b/mantid-profiler.py @@ -16,8 +16,8 @@ import argparse -import copy import sys +from pathlib import Path from threading import Thread import numpy as np @@ -25,57 +25,7 @@ import algorithm_tree as at from diskrecord import monitor as diskmonitor from psrecord import monitor as cpumonitor - - -# Parse the logfile outputted by psrecord -def parse_cpu_log(filename): - rows = [] - dct1 = {} - dct2 = {} - start_time = 0.0 - with open(filename, "r") as f: - for line in f: - if "#" in line: - continue - if "START_TIME:" in line: - start_time = float(line.split()[1]) - continue - line = line.replace("[", "") - line = line.replace("]", "") - line = line.replace("(", "") - line = line.replace(")", "") - line = line.replace(",", "") - line = line.replace("pthread", "") - line = line.replace("id=", "") - line = line.replace("user_time=", "") - line = line.replace("system_time=", "") - row = [] - lst = line.split() - for i in range(4): - row.append(float(lst[i])) - i = 4 - dct1 = copy.deepcopy(dct2) - dct2.clear() - while i < len(lst): - idx = int(lst[i]) - i += 1 - ut = float(lst[i]) - i += 1 - st = float(lst[i]) - i += 1 - dct2.update({idx: [ut, st]}) - count = 0 - for key, val in dct2.items(): - if key not in dct1.keys(): - count += 1 - continue - elem = dct1[key] - if val[0] != elem[0] or val[1] != elem[1]: - count += 1 - row.append(count) - row.append(len(dct2)) - rows.append(row) - return start_time, np.array(rows) +from psrecord import parse_log as parse_cpu_log # Convert string to RGB color @@ -167,9 +117,35 @@ def treeNodeToHtml(node, lmax, sync_time, header, count, tot_time): return outputString +def writeArray(stream, array): + stream.write("[") + stream.write(",".join([str(value) for value in array])) + stream.write("],\n") + + +def writeTrace(stream, x_axis, y_axis, x_name: str, y_name: str, label: str): + stream.write(" x: ") + writeArray(stream, x_axis) + stream.write(" y: ") + writeArray(stream, y_axis) + + stream.write(" xaxis: '{}',\n".format(x_name)) + stream.write(" yaxis: '{}',\n".format(y_name)) + stream.write(" type: 'scatter',\n") + stream.write(" name:'{}',\n".format(label)) + + # Generate HTML interactive plot with Plotly library def htmlProfile( - filename=None, x=None, data=None, records=None, fill_factor=0, nthreads=0, lmax=0, sync_time=0, header=None + filename=None, + cpu_x=None, + cpu_data=None, + algm_records=None, + fill_factor=0, + nthreads=0, + lmax=0, + sync_time=0, + header=None, ): htmlFile = open(filename, "w") htmlFile.write("\n") @@ -178,57 +154,27 @@ def htmlProfile( htmlFile.write("\n") htmlFile.write('
\n') htmlFile.write("