From 8114b42d988a7ae2aaa51fbf55c50333471a7d34 Mon Sep 17 00:00:00 2001 From: Kris Date: Wed, 20 Nov 2024 16:33:48 +0800 Subject: [PATCH 1/7] add schedlatsys script --- bin/schedlatsys | 127 ++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 127 insertions(+) create mode 100755 bin/schedlatsys diff --git a/bin/schedlatsys b/bin/schedlatsys new file mode 100755 index 0000000..2cb3d88 --- /dev/null +++ b/bin/schedlatsys @@ -0,0 +1,127 @@ +#!/usr/bin/env python3 + +# Copyright 2020 Tanel Poder +# Copyright 2024 Kristian Rados +# Licensed under the Apache License, Version 2.0 + +from datetime import datetime +import time, re, subprocess, argparse + +NANOSECONDS_PER_SEC = 1_000_000_000 +NANOSECONDS_PER_USEC = 1_000 +HELP = """ +%CPU = mean %time spent running tasks on the CPU +%LAT = mean %time spent waiting in the run queue (scheduler latency) by all tasks, normalized by num tasks +%SLP = 100 - (%CPU + %LAT) +""" + + +def main(args): + print(HELP) + print("%s| RUNQ LAT µs" % (" " * 42)) + print( + "%-20s %6s %6s %6s | %7s %6s" + % ("TIMESTAMP", "%CPU", "%LAT", "%SLP", str(args.interval) + "-sec", "boot") + ) + + count = 0 + rqlat_us_sum = 0 + try: + while not args.count or count < args.count: + with open("/proc/schedstat", "r") as f: + t1 = time.time() + (cpu_ns1, lat_ns1, slices1) = parse_schedstat(f.read()) + + time.sleep(args.interval) + f.seek(0) + + t2 = time.time() + (cpu_ns2, lat_ns2, slices2) = parse_schedstat(f.read()) + + cpu = (cpu_ns2 - cpu_ns1) / (t2 - t1) / NANOSECONDS_PER_SEC * 100 + + ps = subprocess.Popen(("ps", "-e", "--no-headers"), stdout=subprocess.PIPE) + num_tasks = subprocess.check_output(["wc", "-l"], stdin=ps.stdout) + + rqlat_all = lat_ns2 - lat_ns1 + rqlat_norm = rqlat_all / int(num_tasks) + rqlat = rqlat_norm / (t2 - t1) / NANOSECONDS_PER_SEC * 100 + + rqlat_us = (lat_ns2 - lat_ns1) / (slices2 - slices1) / NANOSECONDS_PER_USEC + rqlat_us_boot = lat_ns2 / slices2 / NANOSECONDS_PER_USEC + + rqlat_us_sum += rqlat_us + count += 1 + + debug_str = ( + "" + if not args.verbose + else f" ({(rqlat_norm) / 1_000_000:.6f} ms avg wait time in {t2 - t1:.6f} s " + f"normalized by num tasks, i.e. {rqlat_all / 1_000_000:.6f} / {int(num_tasks)})" + ) + print( + "%-20s %6.2f %6.2f %6.2f | %7.2f %6.2f%s" + % ( + datetime.fromtimestamp(t2).strftime("%Y-%m-%d %H:%M:%S"), + cpu, + rqlat, + 100 - (cpu + rqlat), + rqlat_us, + rqlat_us_boot, + debug_str, + ) + ) + except KeyboardInterrupt: + print() + + print("Mean RUNQ LAT: %.2f µs" % (rqlat_us_sum / count)) + + +def parse_schedstat(text): + cpus = re.findall( + "cpu(?:\d+) (?:\d+ ){6}(?P\d+) (?P\d+) (?P\d+)", text + ) + + cpu_ns, wait_ns, slices = 0, 0, 0 + for cpu in cpus: + cpu_ns += int(cpu[0]) + wait_ns += int(cpu[1]) + slices += int(cpu[2]) + + cpu_ns /= len(cpus) + # Mean time all tasks spent waiting on the run queue across all CPUs + wait_ns /= len(cpus) + slices /= len(cpus) + + return cpu_ns, wait_ns, slices + + +def get_args() -> argparse.Namespace: + parser = argparse.ArgumentParser() + parser.add_argument( + "-i", + "--interval", + type=int, + default=1, + help="how long to sleep in seconds before measuring /proc/schedstat", + ) + parser.add_argument( + "-c", + "--count", + type=int, + default=None, + help="number of intervals to track before stopping", + ) + parser.add_argument( + "-v", + "--verbose", + action="store_true", + help="display info regarding the calculation of %%LAT", + ) + + args = parser.parse_args() + return args + + +if __name__ == "__main__": + main(get_args()) From b136fb64694ae1ffe76bdc24c76ff3dd104ea69d Mon Sep 17 00:00:00 2001 From: Kris Date: Fri, 6 Dec 2024 12:04:26 +0800 Subject: [PATCH 2/7] schedlatsys python2 compatibility --- bin/schedlatsys | 46 +++++++++++++++++++++++++--------------------- 1 file changed, 25 insertions(+), 21 deletions(-) diff --git a/bin/schedlatsys b/bin/schedlatsys index 2cb3d88..f19e7e6 100755 --- a/bin/schedlatsys +++ b/bin/schedlatsys @@ -1,4 +1,4 @@ -#!/usr/bin/env python3 +#!/usr/bin/env python # Copyright 2020 Tanel Poder # Copyright 2024 Kristian Rados @@ -7,10 +7,9 @@ from datetime import datetime import time, re, subprocess, argparse -NANOSECONDS_PER_SEC = 1_000_000_000 -NANOSECONDS_PER_USEC = 1_000 -HELP = """ -%CPU = mean %time spent running tasks on the CPU +NANOSECONDS_PER_SEC = 1000000000 +NANOSECONDS_PER_USEC = 1000 +HELP = """%CPU = mean %time spent running tasks on the CPU %LAT = mean %time spent waiting in the run queue (scheduler latency) by all tasks, normalized by num tasks %SLP = 100 - (%CPU + %LAT) """ @@ -18,14 +17,14 @@ HELP = """ def main(args): print(HELP) - print("%s| RUNQ LAT µs" % (" " * 42)) + print(u"%s| RUNQ LAT \u00B5s" % (" " * 42)) print( "%-20s %6s %6s %6s | %7s %6s" % ("TIMESTAMP", "%CPU", "%LAT", "%SLP", str(args.interval) + "-sec", "boot") ) count = 0 - rqlat_us_sum = 0 + lat_us_sum = 0 try: while not args.count or count < args.count: with open("/proc/schedstat", "r") as f: @@ -43,38 +42,43 @@ def main(args): ps = subprocess.Popen(("ps", "-e", "--no-headers"), stdout=subprocess.PIPE) num_tasks = subprocess.check_output(["wc", "-l"], stdin=ps.stdout) - rqlat_all = lat_ns2 - lat_ns1 - rqlat_norm = rqlat_all / int(num_tasks) - rqlat = rqlat_norm / (t2 - t1) / NANOSECONDS_PER_SEC * 100 + lat_all = lat_ns2 - lat_ns1 + lat_norm = lat_all / int(num_tasks) + lat = lat_norm / (t2 - t1) / NANOSECONDS_PER_SEC * 100 - rqlat_us = (lat_ns2 - lat_ns1) / (slices2 - slices1) / NANOSECONDS_PER_USEC - rqlat_us_boot = lat_ns2 / slices2 / NANOSECONDS_PER_USEC + lat_us = (lat_ns2 - lat_ns1) / (slices2 - slices1) / NANOSECONDS_PER_USEC + lat_us_boot = lat_ns2 / slices2 / NANOSECONDS_PER_USEC - rqlat_us_sum += rqlat_us + lat_us_sum += lat_us count += 1 debug_str = ( "" if not args.verbose - else f" ({(rqlat_norm) / 1_000_000:.6f} ms avg wait time in {t2 - t1:.6f} s " - f"normalized by num tasks, i.e. {rqlat_all / 1_000_000:.6f} / {int(num_tasks)})" + else " (%.6f ms avg wait time in %.6f s normalized by num tasks, i.e. %.6f / %d)" + % ( + (lat_norm) / 1000000, + t2 - t1, + lat_all / 1000000, + int(num_tasks), + ) ) print( "%-20s %6.2f %6.2f %6.2f | %7.2f %6.2f%s" % ( datetime.fromtimestamp(t2).strftime("%Y-%m-%d %H:%M:%S"), cpu, - rqlat, - 100 - (cpu + rqlat), - rqlat_us, - rqlat_us_boot, + lat, + 100 - (cpu + lat), + lat_us, + lat_us_boot, debug_str, ) ) except KeyboardInterrupt: print() - print("Mean RUNQ LAT: %.2f µs" % (rqlat_us_sum / count)) + print(u"Mean RUNQ LAT: %.2f \u00B5s" % (lat_us_sum / count)) def parse_schedstat(text): @@ -96,7 +100,7 @@ def parse_schedstat(text): return cpu_ns, wait_ns, slices -def get_args() -> argparse.Namespace: +def get_args(): parser = argparse.ArgumentParser() parser.add_argument( "-i", From 975e4676f61b5d61d91c42e5e2778bac018ae51f Mon Sep 17 00:00:00 2001 From: Kris Date: Fri, 6 Dec 2024 12:05:42 +0800 Subject: [PATCH 3/7] schedlat readability --- CHANGELOG.md | 2 +- bin/schedlat | 36 +++++++++++++++++++----------------- bin/syscallargs | 2 -- 3 files changed, 20 insertions(+), 20 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f6a9eec..543da41 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -64,7 +64,7 @@ * pSnapper can now run on RHEL5 equivalents (2.6.18 kernel), however with separately installed python26 or later, as I haven't "downgraded" pSnapper's python code to work with python 2.4 (yet) - you could install python 2.6 or 2.7 manually in your own directory or use the EPEL package: (yum install epel-release ; yum install python26 ) - you will also need to uncomment the 2nd line in psn script (use #!/usr/bin/env/python26 instead of python) - - note that 2.6.18 kernel doesnt provide syscall,file name and kstack sampling (but wchan is available) + - note that 2.6.18 kernel doesnt provide syscall, file name and kstack sampling (but wchan is available) diff --git a/bin/schedlat b/bin/schedlat index 9f4f1aa..0fe8c4c 100755 --- a/bin/schedlat +++ b/bin/schedlat @@ -4,7 +4,7 @@ # Licensed under the Apache License, Version 2.0 (the "License") # # Name: schedlat.py (v0.2) -# Purpose: display % of time a process spent in CPU runqueue +# Purpose: display % of time a process spent in CPU runqueue # (scheduling latency) # Usage: ./schedlat.py PID # @@ -18,28 +18,30 @@ from __future__ import print_function from datetime import datetime import time, sys +NANOSECONDS_PER_SEC = 1000000000 + + if len(sys.argv) != 2 or sys.argv[1] == '-h': - print("usage: " + sys.argv[0] + " PID") - exit(1) + print("usage: " + sys.argv[0] + " PID") + exit(1) pid=sys.argv[1] with open('/proc/' + pid + '/comm', 'r') as f: - print("SchedLat by Tanel Poder [https://0x.tools]\n\nPID=" + pid + " COMM=" + f.read()) + print("SchedLat by Tanel Poder [https://0x.tools]\n\nPID=" + pid + " COMM=" + f.read()) print("%-20s %6s %6s %6s" % ("TIMESTAMP", "%CPU", "%LAT", "%SLP")) while True: - with open('/proc/' + pid + '/schedstat' , 'r') as f: - t1=time.time() - (cpu_ns1, lat_ns1, dontcare) = f.read().split() - time.sleep(1) - f.seek(0) - t2=time.time() - (cpu_ns2, lat_ns2, dontcare) = f.read().split() - - cpu=(int(cpu_ns2)-int(cpu_ns1))/(t2-t1)/10000000 - lat=(int(lat_ns2)-int(lat_ns1))/(t2-t1)/10000000 - - print("%-20s %6.1f %6.1f %6.1f" % (datetime.fromtimestamp(t2).strftime("%Y-%m-%d %H:%M:%S"), cpu, lat, 100-(cpu+lat))) - + with open('/proc/' + pid + '/schedstat' , 'r') as f: + t1=time.time() + (cpu_ns1, lat_ns1, slices1) = f.read().split() + time.sleep(1) + f.seek(0) + t2=time.time() + (cpu_ns2, lat_ns2, slices2) = f.read().split() + + cpu=(int(cpu_ns2)-int(cpu_ns1))/(t2-t1)/NANOSECONDS_PER_SEC*100 + lat=(int(lat_ns2)-int(lat_ns1))/(t2-t1)/NANOSECONDS_PER_SEC*100 + + print("%-20s %6.1f %6.1f %6.1f" % (datetime.fromtimestamp(t2).strftime("%Y-%m-%d %H:%M:%S"), cpu, lat, 100-(cpu+lat))) diff --git a/bin/syscallargs b/bin/syscallargs index 41c5827..d32e97f 100755 --- a/bin/syscallargs +++ b/bin/syscallargs @@ -130,5 +130,3 @@ def main(): if __name__ == "__main__": main() - - From 8a365b651109a869dce23b5226da0308b6082afe Mon Sep 17 00:00:00 2001 From: Kris Date: Fri, 6 Dec 2024 12:26:55 +0800 Subject: [PATCH 4/7] =?UTF-8?q?add=20=C2=B5s=20latency=20to=20schedlat?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- bin/schedlat | 15 ++++++++++++--- bin/schedlatsys | 4 +++- 2 files changed, 15 insertions(+), 4 deletions(-) diff --git a/bin/schedlat b/bin/schedlat index 0fe8c4c..1fd0ff3 100755 --- a/bin/schedlat +++ b/bin/schedlat @@ -19,6 +19,7 @@ from datetime import datetime import time, sys NANOSECONDS_PER_SEC = 1000000000 +NANOSECONDS_PER_USEC = 1000 if len(sys.argv) != 2 or sys.argv[1] == '-h': @@ -30,18 +31,26 @@ pid=sys.argv[1] with open('/proc/' + pid + '/comm', 'r') as f: print("SchedLat by Tanel Poder [https://0x.tools]\n\nPID=" + pid + " COMM=" + f.read()) -print("%-20s %6s %6s %6s" % ("TIMESTAMP", "%CPU", "%LAT", "%SLP")) +print(u"%s| RUNQ LAT \u00B5s" % (" " * 42)) +print("%-20s %6s %6s %6s | %7s %6s" % ("TIMESTAMP", "%CPU", "%LAT", "%SLP", "1-sec", "boot")) while True: with open('/proc/' + pid + '/schedstat' , 'r') as f: t1=time.time() (cpu_ns1, lat_ns1, slices1) = f.read().split() + lat_ns1, slices1 = int(lat_ns1), int(slices1) + time.sleep(1) f.seek(0) + t2=time.time() (cpu_ns2, lat_ns2, slices2) = f.read().split() + lat_ns2, slices2 = int(lat_ns2), int(slices2) cpu=(int(cpu_ns2)-int(cpu_ns1))/(t2-t1)/NANOSECONDS_PER_SEC*100 - lat=(int(lat_ns2)-int(lat_ns1))/(t2-t1)/NANOSECONDS_PER_SEC*100 + lat=(lat_ns2-lat_ns1)/(t2-t1)/NANOSECONDS_PER_SEC*100 + + lat_us = (lat_ns2 - lat_ns1) / (slices2 - slices1) / NANOSECONDS_PER_USEC + lat_us_boot = lat_ns2 / slices2 / NANOSECONDS_PER_USEC - print("%-20s %6.1f %6.1f %6.1f" % (datetime.fromtimestamp(t2).strftime("%Y-%m-%d %H:%M:%S"), cpu, lat, 100-(cpu+lat))) + print("%-20s %6.1f %6.1f %6.1f | %7.2f %6.2f" % (datetime.fromtimestamp(t2).strftime("%Y-%m-%d %H:%M:%S"), cpu, lat, 100 - (cpu + lat), lat_us, lat_us_boot)) diff --git a/bin/schedlatsys b/bin/schedlatsys index f19e7e6..803ea41 100755 --- a/bin/schedlatsys +++ b/bin/schedlatsys @@ -9,7 +9,9 @@ import time, re, subprocess, argparse NANOSECONDS_PER_SEC = 1000000000 NANOSECONDS_PER_USEC = 1000 -HELP = """%CPU = mean %time spent running tasks on the CPU +HELP = """SchedLatSys by Kristian Rados and Tanel Poder [https://0x.tools] + +%CPU = mean %time spent running tasks on the CPU %LAT = mean %time spent waiting in the run queue (scheduler latency) by all tasks, normalized by num tasks %SLP = 100 - (%CPU + %LAT) """ From 1627bfe57ad1d1dc1a600c1b5f50a34011c07d26 Mon Sep 17 00:00:00 2001 From: Kris Date: Fri, 6 Dec 2024 12:31:25 +0800 Subject: [PATCH 5/7] schedlat readability --- bin/schedlat | 52 ++++++++++++++++++++++++++++++++++++---------------- 1 file changed, 36 insertions(+), 16 deletions(-) diff --git a/bin/schedlat b/bin/schedlat index 1fd0ff3..3c2bbba 100755 --- a/bin/schedlat +++ b/bin/schedlat @@ -26,7 +26,7 @@ if len(sys.argv) != 2 or sys.argv[1] == '-h': print("usage: " + sys.argv[0] + " PID") exit(1) -pid=sys.argv[1] +pid = sys.argv[1] with open('/proc/' + pid + '/comm', 'r') as f: print("SchedLat by Tanel Poder [https://0x.tools]\n\nPID=" + pid + " COMM=" + f.read()) @@ -34,23 +34,43 @@ with open('/proc/' + pid + '/comm', 'r') as f: print(u"%s| RUNQ LAT \u00B5s" % (" " * 42)) print("%-20s %6s %6s %6s | %7s %6s" % ("TIMESTAMP", "%CPU", "%LAT", "%SLP", "1-sec", "boot")) -while True: - with open('/proc/' + pid + '/schedstat' , 'r') as f: - t1=time.time() - (cpu_ns1, lat_ns1, slices1) = f.read().split() - lat_ns1, slices1 = int(lat_ns1), int(slices1) +count = 0 +lat_us_sum = 0 +try: + while True: + with open('/proc/' + pid + '/schedstat' , 'r') as f: + t1 = time.time() + (cpu_ns1, lat_ns1, slices1) = f.read().split() + lat_ns1, slices1 = int(lat_ns1), int(slices1) - time.sleep(1) - f.seek(0) + time.sleep(1) + f.seek(0) - t2=time.time() - (cpu_ns2, lat_ns2, slices2) = f.read().split() - lat_ns2, slices2 = int(lat_ns2), int(slices2) + t2 = time.time() + (cpu_ns2, lat_ns2, slices2) = f.read().split() + lat_ns2, slices2 = int(lat_ns2), int(slices2) - cpu=(int(cpu_ns2)-int(cpu_ns1))/(t2-t1)/NANOSECONDS_PER_SEC*100 - lat=(lat_ns2-lat_ns1)/(t2-t1)/NANOSECONDS_PER_SEC*100 + cpu = (int(cpu_ns2) - int(cpu_ns1)) / (t2 - t1) / NANOSECONDS_PER_SEC * 100 + lat = (lat_ns2 - lat_ns1) / (t2 - t1) / NANOSECONDS_PER_SEC * 100 - lat_us = (lat_ns2 - lat_ns1) / (slices2 - slices1) / NANOSECONDS_PER_USEC - lat_us_boot = lat_ns2 / slices2 / NANOSECONDS_PER_USEC + lat_us = (lat_ns2 - lat_ns1) / (slices2 - slices1) / NANOSECONDS_PER_USEC + lat_us_boot = lat_ns2 / slices2 / NANOSECONDS_PER_USEC - print("%-20s %6.1f %6.1f %6.1f | %7.2f %6.2f" % (datetime.fromtimestamp(t2).strftime("%Y-%m-%d %H:%M:%S"), cpu, lat, 100 - (cpu + lat), lat_us, lat_us_boot)) + lat_us_sum += lat_us + count += 1 + + print( + "%-20s %6.1f %6.1f %6.1f | %7.2f %6.2f" + % ( + datetime.fromtimestamp(t2).strftime("%Y-%m-%d %H:%M:%S"), + cpu, + lat, + 100 - (cpu + lat), + lat_us, + lat_us_boot, + ) + ) +except KeyboardInterrupt: + print() + +print(u"Mean RUNQ LAT: %.2f \u00B5s" % (lat_us_sum / count)) From 6106f212c2f3ce924ac6c8fadf5311b695a6db3b Mon Sep 17 00:00:00 2001 From: Kris Date: Fri, 6 Dec 2024 13:09:58 +0800 Subject: [PATCH 6/7] schedlat comment addressing issue #14 https://github.com/tanelpoder/0xtools/issues/14#issuecomment-2495267186 --- bin/schedlat | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/bin/schedlat b/bin/schedlat index 3c2bbba..e8a69ad 100755 --- a/bin/schedlat +++ b/bin/schedlat @@ -4,8 +4,8 @@ # Licensed under the Apache License, Version 2.0 (the "License") # # Name: schedlat.py (v0.2) -# Purpose: display % of time a process spent in CPU runqueue -# (scheduling latency) +# Purpose: display % of time a process (thread group leader, i.e. excluding child threads) spent +# in CPU runqueue (scheduling latency) # Usage: ./schedlat.py PID # # %CPU shows % of time the task spent on CPU From 4893e5a2c13c593532c9ed3859e1a64f4420fef6 Mon Sep 17 00:00:00 2001 From: Kris Date: Fri, 6 Dec 2024 13:26:55 +0800 Subject: [PATCH 7/7] use /proc/PID/task/TID instead of /proc/PID Simple fix for issue #14 --- bin/schedlat | 17 ++++++++++------- 1 file changed, 10 insertions(+), 7 deletions(-) diff --git a/bin/schedlat b/bin/schedlat index e8a69ad..3ba8625 100755 --- a/bin/schedlat +++ b/bin/schedlat @@ -4,9 +4,11 @@ # Licensed under the Apache License, Version 2.0 (the "License") # # Name: schedlat.py (v0.2) -# Purpose: display % of time a process (thread group leader, i.e. excluding child threads) spent -# in CPU runqueue (scheduling latency) -# Usage: ./schedlat.py PID +# Purpose: display % of time a thread spent in CPU runqueue +# (scheduling latency) +# Usage: ./schedlat.py PID TID +# +# For the main process thread, i.e. the thread group leader, TID = PID # # %CPU shows % of time the task spent on CPU # %LAT shows % of time the task spent trying to get onto CPU (in runqueue) @@ -22,14 +24,15 @@ NANOSECONDS_PER_SEC = 1000000000 NANOSECONDS_PER_USEC = 1000 -if len(sys.argv) != 2 or sys.argv[1] == '-h': - print("usage: " + sys.argv[0] + " PID") +if len(sys.argv) != 3 or sys.argv[1] == '-h': + print("usage: " + sys.argv[0] + " PID TID") exit(1) pid = sys.argv[1] +tid = sys.argv[2] with open('/proc/' + pid + '/comm', 'r') as f: - print("SchedLat by Tanel Poder [https://0x.tools]\n\nPID=" + pid + " COMM=" + f.read()) + print("SchedLat by Tanel Poder [https://0x.tools]\n\nTID=%s PID=%s COMM=%s" % (tid, pid, f.read())) print(u"%s| RUNQ LAT \u00B5s" % (" " * 42)) print("%-20s %6s %6s %6s | %7s %6s" % ("TIMESTAMP", "%CPU", "%LAT", "%SLP", "1-sec", "boot")) @@ -38,7 +41,7 @@ count = 0 lat_us_sum = 0 try: while True: - with open('/proc/' + pid + '/schedstat' , 'r') as f: + with open('/proc/' + pid + '/task/' + tid + '/schedstat', 'r') as f: t1 = time.time() (cpu_ns1, lat_ns1, slices1) = f.read().split() lat_ns1, slices1 = int(lat_ns1), int(slices1)