DRIVERS-3620: OpenTelemetry overhead benchmark suite

driver-benchmarks/build.gradle.kts

@@ -36,8 +36,20 @@ sourceSets {
 
 dependencies {
     api(project(":driver-sync"))
+    api(project(":driver-reactive-streams"))
     api(project(":mongodb-crypt"))
 
+    // OpenTelemetry overhead suite (com.mongodb.benchmark.benchmarks.otel): the harness, not the driver,
+    // installs the OpenTelemetry SDK and sampler, as required by the OpenTelemetry spec's Benchmarking section.
+    implementation(platform(libs.micrometer.observation.bom))
+    implementation(libs.micrometer.observation)
+    implementation(platform(libs.micrometer.tracing.integration.test.bom))
+    implementation(libs.micrometer.tracing.bridge.otel)
+    implementation(platform(libs.opentelemetry.bom))
+    implementation(libs.opentelemetry.sdk.trace)
+    implementation(platform(libs.project.reactor.bom))
+    implementation(libs.project.reactor.core)
+
     implementation(platform(libs.netty.bom))
     implementation(libs.bundles.netty)
 
@@ -62,6 +74,17 @@ tasks.register<JavaExec>("runNetty") {
     jvmArgs = application.applicationDefaultJvmArgs.toList()
 }
 
+tasks.register<JavaExec>("runOtel") {
+    group = "benchmark"
+    description = "Run the OpenTelemetry overhead suite (DRIVERS-3620) for one tracing configuration."
+    mainClass.set("com.mongodb.benchmark.benchmarks.otel.OtelBenchmarkSuite")
+    classpath = sourceSets["main"].runtimeClasspath
+    jvmArgs = application.applicationDefaultJvmArgs.toList() +
+        (System.getProperty("org.mongodb.benchmarks.jvmArgs")?.split(" ")?.filter { it.isNotBlank() } ?: emptyList())
+    systemProperties(System.getProperties().filterKeys { it.toString().startsWith("org.mongodb.benchmarks.") }
+        .mapKeys { it.key.toString() })
+}
+
 tasks.withType<Javadoc>().configureEach {
     enabled = false
 }

driver-benchmarks/otel-bench.py

@@ -0,0 +1,170 @@
+#!/usr/bin/env python3
+"""Run the OpenTelemetry overhead benchmark (DRIVERS-3620) for the Java driver.
+
+Each configuration runs in its own JVM via ``:driver-benchmarks:runOtel``. The whole set of
+configurations is run REPS times, interleaved, with the order rotated by one position each
+repetition, as the OpenTelemetry spec's Benchmarking section requires. The ``pre-otel``
+configuration runs the same tasks from a worktree checked out at the commit before tracing
+support was added (the spec's one-time comparison of the default configuration).
+
+Usage:
+  otel-bench.py --data DIR --out DIR [--reps 5] [--pre-otel-worktree PATH]
+                [--configs off,api-only,sdk-ratio,sdk-always,pre-otel]
+                [--iterations 100] [--min-time 60] [--report-only]
+"""
+import argparse
+import json
+import os
+import statistics
+import subprocess
+import sys
+import time
+from collections import deque
+from pathlib import Path
+
+ROOT = Path(__file__).resolve().parent.parent
+TASKS = [("sync", "Small doc insertOne"), ("sync", "Find one by ID"),
+         ("async", "Small doc insertOne"), ("async", "Find one by ID")]
+ALL = ["off", "api-only", "sdk-ratio", "sdk-always", "pre-otel"]
+METRICS = ["megabytes_per_sec", "wall_us_per_op", "cpu_us_per_op", "gc_us_per_op", "cpu_ex_gc_us_per_op"]
+
+
+def run_one(config, rep, args):
+    out = args.out / f"{config}-rep{rep:02d}.json"
+    log = out.with_suffix(".log")
+    if out.exists() and args.resume:
+        return out
+    cwd = args.pre_otel_worktree if config == "pre-otel" else ROOT
+    cmd = ["./gradlew", "-q", ":driver-benchmarks:runOtel",
+           f"-Dorg.mongodb.benchmarks.data={args.data}/",
+           f"-Dorg.mongodb.benchmarks.output={out}",
+           f"-Dorg.mongodb.benchmarks.otel.config={config}",
+           f"-Dorg.mongodb.benchmarks.otel.iterations={args.iterations}",
+           f"-Dorg.mongodb.benchmarks.otel.minTimeSeconds={args.min_time}"]
+    if config == "pre-otel":
+        cmd += ["-x", ":mongodb-crypt:downloadJava", "-x", ":mongodb-crypt:unzipJava"]
+    env = {k: v for k, v in os.environ.items() if not k.startswith("OTEL_")}
+    start = time.monotonic()
+    with open(log, "w") as fh:
+        proc = subprocess.run(cmd, cwd=cwd, env=env, stdout=fh, stderr=subprocess.STDOUT)
+    if proc.returncode != 0:
+        print(f"FAILED {config} rep {rep}: see {log}", file=sys.stderr)
+        print(log.read_text()[-3000:], file=sys.stderr)
+        sys.exit(1)
+    print(f"  {config:<10} rep {rep} done in {time.monotonic() - start:.0f}s", flush=True)
+    return out
+
+
+def load(args, configs):
+    samples = {}  # (config, api, task) -> metric -> [values]
+    for f in sorted(args.out.glob("*-rep*.json")):
+        config = f.name.rsplit("-rep", 1)[0]
+        if config not in configs:
+            continue
+        for r in json.loads(f.read_text())["results"]:
+            d = samples.setdefault((config, r["api"], r["test_name"]), {m: [] for m in METRICS})
+            for m in METRICS:
+                d[m].append(r[m])
+    return samples
+
+
+def med(xs):
+    return statistics.median(xs) if xs else float("nan")
+
+
+def report(args, configs):
+    samples = load(args, configs)
+    reps = max((len(v["megabytes_per_sec"]) for v in samples.values()), default=0)
+    lines = [f"# Java driver OpenTelemetry overhead (DRIVERS-3620), {reps} repetitions, medians\n"]
+    lines.append("## Throughput (median MB/s; loss vs `off`)\n")
+    lines.append("| API | Task | " + " | ".join(c for c in configs) + " |")
+    lines.append("|---|---|" + "---|" * len(configs))
+    for api, task in TASKS:
+        base = med(samples.get(("off", api, task), {}).get("megabytes_per_sec", []))
+        cells = []
+        for c in configs:
+            v = med(samples.get((c, api, task), {}).get("megabytes_per_sec", []))
+            if c == "off":
+                cells.append(f"{v:.3f} (baseline)")
+            else:
+                loss = (1 - v / base) * 100 if base == base else float("nan")
+                cells.append(f"{v:.3f} ({loss:+.1f}%)")
+        lines.append(f"| {api} | {task} | " + " | ".join(cells) + " |")
+    lines.append("\nA negative loss means the configuration measured faster than `off`. "
+                 "For `pre-otel` the percentage is the cost of the `off` configuration relative to the pre-tracing commit.\n")
+
+    lines.append("## CPU time per operation, excluding GC (median µs/op; delta vs `off`)\n")
+    lines.append("| API | Task | " + " | ".join(configs) + " |")
+    lines.append("|---|---|" + "---|" * len(configs))
+    for api, task in TASKS:
+        base = med(samples.get(("off", api, task), {}).get("cpu_ex_gc_us_per_op", []))
+        cells = []
+        for c in configs:
+            v = med(samples.get((c, api, task), {}).get("cpu_ex_gc_us_per_op", []))
+            if c == "off":
+                cells.append(f"{v:.1f} (baseline)")
+            else:
+                cells.append(f"{v:.1f} ({v - base:+.1f}, {(v / base - 1) * 100:+.1f}%)")
+        lines.append(f"| {api} | {task} | " + " | ".join(cells) + " |")
+
+    lines.append("\n## Wall time per operation (median µs/op)\n")
+    lines.append("| API | Task | " + " | ".join(configs) + " |")
+    lines.append("|---|---|" + "---|" * len(configs))
+    for api, task in TASKS:
+        cells = [f"{med(samples.get((c, api, task), {}).get('wall_us_per_op', [])):.1f}" for c in configs]
+        lines.append(f"| {api} | {task} | " + " | ".join(cells) + " |")
+
+    lines.append("\n## Throughput spread across repetitions (min–max MB/s)\n")
+    lines.append("| API | Task | " + " | ".join(configs) + " |")
+    lines.append("|---|---|" + "---|" * len(configs))
+    for api, task in TASKS:
+        cells = []
+        for c in configs:
+            xs = samples.get((c, api, task), {}).get("megabytes_per_sec", [])
+            cells.append(f"{min(xs):.3f}–{max(xs):.3f}" if xs else "n/a")
+        lines.append(f"| {api} | {task} | " + " | ".join(cells) + " |")
+
+    text = "\n".join(lines) + "\n"
+    (args.out / "REPORT.md").write_text(text)
+    summary = {f"{c}/{api}/{task}": {m: {"median": med(v[m]), "values": v[m]} for m in METRICS}
+               for (c, api, task), v in samples.items()}
+    (args.out / "summary.json").write_text(json.dumps(summary, indent=2))
+    return text
+
+
+def main():
+    ap = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter)
+    ap.add_argument("--data", type=Path, required=True)
+    ap.add_argument("--out", type=Path, required=True)
+    ap.add_argument("--reps", type=int, default=5)
+    ap.add_argument("--configs", default=",".join(ALL))
+    ap.add_argument("--pre-otel-worktree", type=Path)
+    ap.add_argument("--iterations", type=int, default=100)
+    ap.add_argument("--min-time", type=int, default=60)
+    ap.add_argument("--resume", action="store_true", help="skip repetitions whose result file exists")
+    ap.add_argument("--report-only", action="store_true")
+    args = ap.parse_args()
+    args.data = args.data.resolve()
+    args.out = args.out.resolve()
+    args.out.mkdir(parents=True, exist_ok=True)
+    configs = [c.strip() for c in args.configs.split(",") if c.strip()]
+    if "off" not in configs:
+        sys.exit("'off' is required as the baseline")
+    if "pre-otel" in configs and not args.pre_otel_worktree and not args.report_only:
+        sys.exit("--pre-otel-worktree is required for the pre-otel configuration")
+    if not args.report_only:
+        started = time.monotonic()
+        for rep in range(1, args.reps + 1):
+            order = deque(configs)
+            order.rotate(-(rep - 1))
+            print(f"rep {rep}/{args.reps}: order {list(order)}", flush=True)
+            for c in order:
+                run_one(c, rep, args)
+            print(report(args, configs), flush=True)
+        print(f"total {time.monotonic() - started:.0f}s")
+    else:
+        print(report(args, configs))
+
+
+if __name__ == "__main__":
+    main()

driver-benchmarks/otel-compare-langs.py

@@ -0,0 +1,78 @@
+#!/usr/bin/env python3
+"""Place the Java OTel overhead numbers beside the Python and Ruby figures posted on
+mongodb/specifications#1986, on the spec's common metrics: throughput loss vs `off`
+and added CPU µs/op vs `off`. Usage: otel-compare-langs.py <results-dir>"""
+import json
+import sys
+from pathlib import Path
+
+# Published on PR 1986 / linked driver PRs. Python: PR 3102 description (sync, 16-core x86_64, MongoDB 8.0.4, CPython 3.9).
+# Ruby: PR 3108 description (Evergreen, Ruby 4.0.1+YJIT), sdk-ratio = "sdk-parent-1pct".
+OTHERS = {
+    "Python (sync)": {
+        ("Small doc insertOne", "api-only"): (10.2, 25), ("Small doc insertOne", "sdk-ratio"): (19.1, 53),
+        ("Small doc insertOne", "sdk-always"): (36.0, 130),
+        ("Find one by ID", "api-only"): (8.0, 24), ("Find one by ID", "sdk-ratio"): (16.3, 56),
+        ("Find one by ID", "sdk-always"): (31.6, 133),
+        "pre": {"Small doc insertOne": 1.8, "Find one by ID": 0.8},
+    },
+    "Python (async)": {
+        ("Small doc insertOne", "api-only"): (6.1, 26), ("Small doc insertOne", "sdk-ratio"): (11.3, 51),
+        ("Small doc insertOne", "sdk-always"): (24.4, 131),
+        ("Find one by ID", "api-only"): (4.5, 22), ("Find one by ID", "sdk-ratio"): (9.6, 50),
+        ("Find one by ID", "sdk-always"): (21.7, 130),
+        "pre": {"Small doc insertOne": -0.8, "Find one by ID": 0.6},
+    },
+    "Ruby": {
+        ("Small doc insertOne", "api-only"): (2.71, 7.30), ("Small doc insertOne", "sdk-ratio"): (8.06, 20.50),
+        ("Small doc insertOne", "sdk-always"): (11.22, 29.60),
+        ("Find one by ID", "api-only"): (5.35, 10.81), ("Find one by ID", "sdk-ratio"): (5.97, 19.36),
+        ("Find one by ID", "sdk-always"): (7.66, 26.90),
+        "pre": None,
+    },
+}
+
+
+def main(results_dir):
+    summary = json.loads((Path(results_dir) / "summary.json").read_text())
+
+    def med(cfg, api, task, metric):
+        return summary[f"{cfg}/{api}/{task}"][metric]["median"]
+
+    java = {}
+    for api in ("sync", "async"):
+        d = {}
+        for task in ("Small doc insertOne", "Find one by ID"):
+            base_mb = med("off", api, task, "megabytes_per_sec")
+            base_cpu = med("off", api, task, "cpu_ex_gc_us_per_op")
+            for cfg in ("api-only", "sdk-ratio", "sdk-always"):
+                d[(task, cfg)] = ((1 - med(cfg, api, task, "megabytes_per_sec") / base_mb) * 100,
+                                  med(cfg, api, task, "cpu_ex_gc_us_per_op") - base_cpu)
+            key = f"pre-otel/{api}/{task}"
+            d.setdefault("pre", {})
+            if key in summary:
+                d["pre"][task] = (1 - base_mb / summary[key]["megabytes_per_sec"]["median"]) * 100
+        java[f"Java ({api})"] = d
+
+    langs = {**java, **OTHERS}
+    out = ["## Cross-language comparison (throughput loss vs `off` / added CPU µs per op vs `off`)\n"]
+    for task in ("Small doc insertOne", "Find one by ID"):
+        out.append(f"### {task}\n")
+        out.append("| Driver | api-only | sdk-ratio (1%) | sdk-always | `off` vs pre-OTel commit |")
+        out.append("|---|---|---|---|---|")
+        for name, d in langs.items():
+            cells = [f"{d[(task, c)][0]:+.1f}% / +{d[(task, c)][1]:.0f} µs" for c in ("api-only", "sdk-ratio", "sdk-always")]
+            pre = d.get("pre")
+            cells.append(f"{pre[task]:+.1f}%" if pre and task in pre else "n/a")
+            out.append(f"| {name} | " + " | ".join(cells) + " |")
+        out.append("")
+    out.append("Java CPU is process CPU time excluding GC; Python is process CPU time; Ruby is CPU excluding GC. "
+               "Hosts differ (Java: Apple M4 Max, MongoDB 8.2.6, Temurin 17; Python: 16-core x86_64, MongoDB 8.0.4; "
+               "Ruby: Evergreen), so compare relative overhead, not absolute µs.")
+    text = "\n".join(out) + "\n"
+    (Path(results_dir) / "CROSS_LANGUAGE.md").write_text(text)
+    print(text)
+
+
+if __name__ == "__main__":
+    main(sys.argv[1])

driver-benchmarks/otel-compare-runs.py

@@ -0,0 +1,64 @@
+#!/usr/bin/env python3
+"""Compare two otel-bench.py result directories (before/after an optimisation).
+Usage: otel-compare-runs.py <before-dir> <after-dir> [<out.md>]"""
+import json
+import sys
+from pathlib import Path
+
+TASKS = [("sync", "Small doc insertOne"), ("sync", "Find one by ID"),
+         ("async", "Small doc insertOne"), ("async", "Find one by ID")]
+CONFIGS = ["off", "api-only", "sdk-ratio", "sdk-always"]
+
+
+def load(d):
+    return json.loads((Path(d) / "summary.json").read_text())
+
+
+def med(s, cfg, api, task, metric):
+    return s[f"{cfg}/{api}/{task}"][metric]["median"]
+
+
+def main(before, after, out=None):
+    b, a = load(before), load(after)
+    lines = ["# Java OTel overhead: before vs after optimisation\n",
+             f"Before: `{before}`  After: `{after}`. Medians of 5 repetitions each. "
+             "Loss = throughput lost vs that run's own `off`; CPU = process CPU per op excluding GC.\n"]
+    lines.append("## Overhead vs `off` (loss % / added CPU µs per op)\n")
+    lines.append("| API | Task | Config | Before | After | Δ loss (pts) | Δ CPU (µs) |")
+    lines.append("|---|---|---|---|---|---|---|")
+    for api, task in TASKS:
+        bb_mb, ab_mb = med(b, "off", api, task, "megabytes_per_sec"), med(a, "off", api, task, "megabytes_per_sec")
+        bb_cpu, ab_cpu = med(b, "off", api, task, "cpu_ex_gc_us_per_op"), med(a, "off", api, task, "cpu_ex_gc_us_per_op")
+        for cfg in CONFIGS[1:]:
+            bl = (1 - med(b, cfg, api, task, "megabytes_per_sec") / bb_mb) * 100
+            al = (1 - med(a, cfg, api, task, "megabytes_per_sec") / ab_mb) * 100
+            bc = med(b, cfg, api, task, "cpu_ex_gc_us_per_op") - bb_cpu
+            ac = med(a, cfg, api, task, "cpu_ex_gc_us_per_op") - ab_cpu
+            lines.append(f"| {api} | {task} | {cfg} | {bl:+.1f}% / +{bc:.1f} | {al:+.1f}% / +{ac:.1f} | {al - bl:+.1f} | {ac - bc:+.1f} |")
+    lines.append("\n## Absolute medians (MB/s, CPU ex-GC µs/op)\n")
+    lines.append("| API | Task | Config | Before MB/s | After MB/s | Before CPU | After CPU |")
+    lines.append("|---|---|---|---|---|---|---|")
+    for api, task in TASKS:
+        for cfg in CONFIGS:
+            lines.append(f"| {api} | {task} | {cfg} | {med(b, cfg, api, task, 'megabytes_per_sec'):.3f} | "
+                         f"{med(a, cfg, api, task, 'megabytes_per_sec'):.3f} | "
+                         f"{med(b, cfg, api, task, 'cpu_ex_gc_us_per_op'):.1f} | {med(a, cfg, api, task, 'cpu_ex_gc_us_per_op'):.1f} |")
+    lines.append("\n## sdk-ratio vs sdk-always gap (the spec's gating diagnostic)\n")
+    lines.append("| API | Task | Before gap (pts loss / µs CPU) | After gap |")
+    lines.append("|---|---|---|---|")
+    for api, task in TASKS:
+        def gap(s):
+            off = med(s, "off", api, task, "megabytes_per_sec")
+            r = (1 - med(s, "sdk-ratio", api, task, "megabytes_per_sec") / off) * 100
+            al = (1 - med(s, "sdk-always", api, task, "megabytes_per_sec") / off) * 100
+            c = med(s, "sdk-always", api, task, "cpu_ex_gc_us_per_op") - med(s, "sdk-ratio", api, task, "cpu_ex_gc_us_per_op")
+            return f"{al - r:+.1f} / {c:+.1f}"
+        lines.append(f"| {api} | {task} | {gap(b)} | {gap(a)} |")
+    text = "\n".join(lines) + "\n"
+    if out:
+        Path(out).write_text(text)
+    print(text)
+
+
+if __name__ == "__main__":
+    main(*sys.argv[1:])