From 7f639c103b2fcb9432fd7af91add82029ae7de85 Mon Sep 17 00:00:00 2001 From: Kunshan Wang Date: Thu, 18 Sep 2025 14:28:04 +0800 Subject: [PATCH 1/3] Warn the user about stroboscopic effect If the user chooses an even number for the `-e` option of `capture.py`, it may get misleading results if the GCs alternate between two different behaviors, such as nursery GC and full-heap GC. We now warn the user if the value of `-e` is an even number. --- tools/tracing/timeline/README.md | 13 +++++++++---- tools/tracing/timeline/capture.py | 14 +++++++++++--- 2 files changed, 20 insertions(+), 7 deletions(-) diff --git a/tools/tracing/timeline/README.md b/tools/tracing/timeline/README.md index 16ad553c2c..8e6f75d6f7 100644 --- a/tools/tracing/timeline/README.md +++ b/tools/tracing/timeline/README.md @@ -19,16 +19,21 @@ Suite. Run the following command with a **normal** user (*not* as `root` or using `sudo`): ```shell -./capture.py -e 50 -m /path/to/libmmtk_openjdk.so --no-root-nodes +./capture.py -e 47 -m /path/to/libmmtk_openjdk.so --no-root-nodes ``` -`-e 50` means we only capture one GC in every 50 GCs because otherwise it will have to print too +`-e 47` means we only capture one GC in every 47 GCs because otherwise it will have to print too much log. (Note: Printing in bpftrace is done via a fixed-size user/kernel space buffer, therefore excessive printing will overrun the buffer and cause events to be dropped. The `-e` option helps reducing the volume of log, thereby reducing the likelihood of buffer overrun and the time for post-processing. If one single GC still produces too much log and overruns the buffer, the user should consider setting the `BPFTRACE_PERF_RB_PAGES` environment variable. See the man page of -`bpftrace`.) +`bpftrace`.) We choose a large prime number, such as 47, because some GCs may exhibit periodic +behaviors under certain workloads. For example, generational GCs may alternate between nursery and +full-heap GC. If we capture every 50th GC, we will only observe even or odd GCs. This is an +instance of [stroboscopic effect]. + +[stroboscopic effect]: https://en.wikipedia.org/wiki/Stroboscopic_effect `--no-root-nodes` skips the `process_root_nodes` USDT which does not exist in `libmmtk_openjdk.so`. @@ -86,7 +91,7 @@ This means things are working properly. Now re-run `./capture.py` again, but pi file. ``` -./capture.py -m /path/to/libmmtk_openjdk.so --no-root-nodes > mybenchmark.log +./capture.py -e 47 -m /path/to/libmmtk_openjdk.so --no-root-nodes > mybenchmark.log ``` Type the root password if prompted. diff --git a/tools/tracing/timeline/capture.py b/tools/tracing/timeline/capture.py index 9ca3803d1a..9e18f82752 100755 --- a/tools/tracing/timeline/capture.py +++ b/tools/tracing/timeline/capture.py @@ -54,6 +54,9 @@ def delete_lines_between(lines, begin, end): raise Exception(f"Cannot find {begin} and {end} in the script. {begin_index} {end_index}") del lines[begin_index:end_index + 1] +def eprint(*args, **kwargs): + print(*args, **kwargs, file=sys.stderr) + def main(): args = get_args() here = Path(__file__).parent.resolve() @@ -84,7 +87,7 @@ def main(): MMTK=mmtk_bin, TMP_FILE=tmp.name) if args.print_script: - print(content) + eprint(content) tmp.write(content) tmp.flush() @@ -94,9 +97,14 @@ def main(): command_line = ["sudo", args.bpftrace] + extra_options + ["--unsafe", tmp.name] + if args.every % 2 == 0: + eprint(f"""\ +WARNING! The value of the --every option is {args.every} which is an even number. +You may observe misleading results due to stroboscopic effect. See README.md""") + if args.dry_run: - print("Dry run. Command to execute:") - print(" ".join(f"'{c}'" for c in command_line)) + eprint("Dry run. Command to execute:") + eprint(" ".join(f"'{c}'" for c in command_line)) # tempfile will be deleted at the end of `with`. else: # We use execvp to replace the current process instead of creating From 6e6eba5731280f41a0a4cb96fd19b4ac88df9004 Mon Sep 17 00:00:00 2001 From: Kunshan Wang Date: Mon, 22 Sep 2025 14:26:38 +0800 Subject: [PATCH 2/3] stroboscopic -> aliasing --- tools/tracing/timeline/README.md | 4 ++-- tools/tracing/timeline/capture.py | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/tools/tracing/timeline/README.md b/tools/tracing/timeline/README.md index 8e6f75d6f7..ac559dd067 100644 --- a/tools/tracing/timeline/README.md +++ b/tools/tracing/timeline/README.md @@ -31,9 +31,9 @@ should consider setting the `BPFTRACE_PERF_RB_PAGES` environment variable. See `bpftrace`.) We choose a large prime number, such as 47, because some GCs may exhibit periodic behaviors under certain workloads. For example, generational GCs may alternate between nursery and full-heap GC. If we capture every 50th GC, we will only observe even or odd GCs. This is an -instance of [stroboscopic effect]. +instance of [aliasing effect]. -[stroboscopic effect]: https://en.wikipedia.org/wiki/Stroboscopic_effect +[aliasing effect]: https://en.wikipedia.org/wiki/Aliasing `--no-root-nodes` skips the `process_root_nodes` USDT which does not exist in `libmmtk_openjdk.so`. diff --git a/tools/tracing/timeline/capture.py b/tools/tracing/timeline/capture.py index 9e18f82752..0a56ab050e 100755 --- a/tools/tracing/timeline/capture.py +++ b/tools/tracing/timeline/capture.py @@ -100,7 +100,7 @@ def main(): if args.every % 2 == 0: eprint(f"""\ WARNING! The value of the --every option is {args.every} which is an even number. -You may observe misleading results due to stroboscopic effect. See README.md""") +You may observe misleading results due to aliasing effect. See README.md""") if args.dry_run: eprint("Dry run. Command to execute:") From ea30eea6ddefdcf9883293d1e1e76b9df00c313d Mon Sep 17 00:00:00 2001 From: Kunshan Wang Date: Mon, 22 Sep 2025 14:30:10 +0800 Subject: [PATCH 3/3] More detailed description --- tools/tracing/timeline/README.md | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/tools/tracing/timeline/README.md b/tools/tracing/timeline/README.md index ac559dd067..3b8c9fa97a 100644 --- a/tools/tracing/timeline/README.md +++ b/tools/tracing/timeline/README.md @@ -30,8 +30,10 @@ post-processing. If one single GC still produces too much log and overruns the should consider setting the `BPFTRACE_PERF_RB_PAGES` environment variable. See the man page of `bpftrace`.) We choose a large prime number, such as 47, because some GCs may exhibit periodic behaviors under certain workloads. For example, generational GCs may alternate between nursery and -full-heap GC. If we capture every 50th GC, we will only observe even or odd GCs. This is an -instance of [aliasing effect]. +full-heap GC, making every odd GC a nursey GC, and every even GC a full-heap GC. If we capture +every 50th GC, we will only observe even or odd GCs because 50 is an even number, and it will give +us an illusion of "all GCs are nursery GC" or "all GCs are full-heap GC". This is an instance of +[aliasing effect]. [aliasing effect]: https://en.wikipedia.org/wiki/Aliasing