report median and p99 from the pith grpc client

bench/grpc/pith/client.pith

@@ -1,12 +1,12 @@
 # the pith grpc benchmark client: warm up, then time many unary echo calls over
-# one channel and print calls/sec. parameters come from the environment so the
-# runner can drive it the same way it drives the go and rust clients:
+# one channel and print calls/sec plus per-call median and p99. parameters come
+# from the environment so the runner can drive it the same way it drives the go
+# and rust clients:
 #   PITH_GRPC_SIZE, PITH_GRPC_CALLS, PITH_GRPC_WARMUP, PITH_GRPC_CONC, PITH_GRPC_CA
 #
-# pith has only millisecond wall-clock resolution, so the batch (thousands of
-# calls, seconds long) gives the throughput and an average latency — the fair
-# common metric across all three clients. per-call percentiles are left to the
-# go and rust clients.
+# each call is timed with the monotonic nanosecond clock and every worker hands
+# its latencies back; the merged, sorted list gives the same median and p99 the
+# go and rust clients report, so the three rows read alike.
 
 import std.net.http2.connection as http2
 import std.net.grpc as grpc
@@ -16,6 +16,7 @@ import std.bytes as bytes
 import std.time as time
 import std.os as os
 import std.concurrent as concurrent
+import std.algo as algo
 
 fn env_str(name: String, fallback: String) -> String:
     value := os.get_env(name).unwrap_or(fallback)
@@ -57,39 +58,73 @@ fn echo_request(payload: Bytes) -> Bytes:
     w.write_bytes(1, payload) catch false
     return w.bytes()
 
-fn run_serial(ch: grpc.Conn, method: String, request: Bytes, calls: Int):
-    mut i := 0
-    while i < calls:
-        ch.unary(method, request) catch bytes.empty()
-        i = i + 1
-
-fn worker(ch: grpc.Conn, method: String, request: Bytes, count: Int) -> Int:
+# time each call, pushing the latency of every call into `lat` (a shared list
+# handle created by the caller — task results with list payloads are avoided on
+# purpose, the handle is the simpler contract).
+fn timed_batch(ch: grpc.Conn, method: String, request: Bytes, count: Int, lat: List[Int]) -> Int:
     mut i := 0
     while i < count:
+        t0 := time.mono_nanos()
         ch.unary(method, request) catch bytes.empty()
+        lat.push(time.mono_nanos() - t0)
         i = i + 1
     return count
 
 # each worker gets its OWN connection from the pool (round-robin) and keeps its
-# calls on that one connection's pipeline, so the pool spreads load across cores.
-fn run_concurrent(pool: grpc.PoolConn, method: String, request: Bytes, calls: Int, conc: Int):
+# calls on that one connection's pipeline, so the pool spreads load across
+# cores. every worker's latencies come back through its task result and are
+# merged for the percentile report.
+fn run_concurrent(pool: grpc.PoolConn, method: String, request: Bytes, calls: Int, conc: Int, merged: List[Int]):
     per := calls / conc
     mut tasks := []
+    mut buckets: List[List[Int]] := []
     mut w := 0
     while w < conc:
         c := pool.at(w % pool.size())
-        tasks.push(spawn worker(c, method, request, per))
+        bucket: List[Int] := []
+        buckets.push(bucket)
+        tasks.push(spawn timed_batch(c, method, request, per, bucket))
         w = w + 1
     for t in tasks:
         await t
-
-fn report(size: Int, conc: Int, calls: Int, elapsed_ms: Int):
+    for bucket in buckets:
+        for v in bucket:
+            merged.push(v)
+
+# the value at `pct` percent of the way through a sorted list, matching the
+# nearest-rank convention the go client uses.
+fn percentile_ns(sorted: List[Int], pct: Int) -> Int:
+    if sorted.len() == 0:
+        return 0
+    mut rank := (sorted.len() * pct) / 100
+    if rank >= sorted.len():
+        rank = sorted.len() - 1
+    return sorted[rank]
+
+# nanoseconds as the go client prints durations: microseconds below one
+# millisecond, fractional milliseconds above. the micro sign is built from its
+# utf-8 byte pair, the same way other non-ascii output in this repo is.
+fn fmt_ns(ns: Int) -> String:
+    micro := chr(194) + chr(181)
+    if ns < 1000000:
+        return (ns / 1000).to_string() + micro + "s"
+    whole := ns / 1000000
+    frac := (ns % 1000000) / 1000
+    if frac < 10:
+        return whole.to_string() + ".00" + frac.to_string() + "ms"
+    if frac < 100:
+        return whole.to_string() + ".0" + frac.to_string() + "ms"
+    return whole.to_string() + "." + frac.to_string() + "ms"
+
+fn report(size: Int, conc: Int, calls: Int, elapsed_ms: Int, latencies: List[Int]):
     mut ms := elapsed_ms
     if ms <= 0:
         ms = 1
     throughput := (calls * 1000) / ms
-    avg_us := (ms * 1000) / calls
-    print("pith   size={size}   conc={conc}   calls={calls}  avg={avg_us}us   {throughput} calls/sec")
+    sorted := algo.sort(latencies)
+    med := fmt_ns(percentile_ns(sorted, 50))
+    p99 := fmt_ns(percentile_ns(sorted, 99))
+    print("pith   size={size}     conc={conc}   calls={calls}  median={med}    p99={p99}   {throughput} calls/sec")
 
 fn main():
     size := env_int("PITH_GRPC_SIZE", 16)
@@ -123,11 +158,12 @@ fn main():
         w = w + 1
 
     start := time.now()
+    latencies: List[Int] := []
     if conc <= 1:
-        run_serial(ch.at(0), method, request, calls)
+        timed_batch(ch.at(0), method, request, calls, latencies)
     else:
-        run_concurrent(ch, method, request, calls, conc)
+        run_concurrent(ch, method, request, calls, conc, latencies)
     elapsed := time.now() - start
 
-    report(size, conc, calls, elapsed)
+    report(size, conc, calls, elapsed, latencies)
     ch.close()

docs/performance.md

@@ -24,7 +24,7 @@ rows are the green backend, which is the default on linux; rows marked
 | services and compute | pith | go | rust | zig |
 |---|---:|---:|---:|---:|
 | catalog workload, 200k requests | **~114 ms** | ~436 ms | ~80 ms | — |
-| grpc unary echo, conc=8, 16 B | 8326 calls/s | 14795 | 11788 | — |
+| grpc unary echo, conc=8, 16 B | 7476 calls/s | 14731 | 12005 | — |
 | http server under wrk, 30 s | 8079 req/s, rss flat (+4 kb) | 28453 req/s (+6.1 mb) | — | — |
 | event_ledger, 200k events | 618 ms (1.28x go) | 481 ms | 117 ms | 137 ms |
 | std_pipeline, 50k records | 576 ms (1.63x go) | 352 ms | 177 ms | — |
@@ -227,18 +227,20 @@ binaries.
 
 | payload, conc=8 | pith | go | rust |
 |---|---:|---:|---:|
-| 16 B, calls/sec | 8326 | **14795** | 11788 |
-| 16 B, latency | 120 µs avg | 465 µs median, 1.7 ms p99 | 593 µs median, 2.3 ms p99 |
-| 1 KiB, calls/sec | 6216 | **11339** | 9557 |
-| 1 KiB, latency | 160 µs avg | 600 µs median, 2.9 ms p99 | 712 µs median, 3.3 ms p99 |
-
-pith sits at ~55% of go and ~65-70% of rust on throughput. the latency
-rows are not directly comparable — the pith client reports a plain
-average where go and rust report median and p99 — but the shape is
-consistent: pith's per-call time is low and its ceiling is the two-core
-box splitting the client, the server, and the connection's single reader
-task. teaching the pith client to report percentiles is a small follow-up
-that would make the row honest to compare.
+| 16 B, calls/sec | 7476 | **14731** | 12005 |
+| 16 B, median / p99 | 954 µs / 2.9 ms | 471 µs / 2.0 ms | 591 µs / 2.3 ms |
+| 1 KiB, calls/sec | 7598 | **12366** | 9545 |
+| 1 KiB, median / p99 | 957 µs / 2.5 ms | 555 µs / 2.5 ms | 717 µs / 3.3 ms |
+
+all three clients now report the same metrics: per-call median and p99
+from the full sorted latency set, timed with each language's monotonic
+clock. pith sits at ~50-60% of go and ~60-80% of rust on throughput, with
+a per-call median about 2x go's — one connection means one reader task,
+and the two-core box splits it against the server and seven sibling
+callers. the earlier revision of this table printed a pith "average"
+computed as wall-clock over total calls, which under eight-way concurrency
+flattered pith by nearly an order of magnitude; the percentile reporting
+replaced it.
 
 | 16 B, conc=8 | calls/sec | ctx-switches/call | cpu |
 |---|---|---|---|