skill/keybase-rpc-log-analysis/scripts/rpc-why.py - master - githubmirror/client

skill/keybase-rpc-log-analysis/scripts/rpc-why.py
137 строк6 KB
chrisnojima
perf: cut the client-side RPC floods, and repair four desktop e2e tests (#29466)
04 авг 2026, 17:30
04 авг 2026, 17:30f90db8b
#!/usr/bin/env python3
"""Explain a flood: who drives it, how it is paced, how big its batches are.

  python3 rpc-why.py <log>... --match 'refreshParticipantsRemote' [--start ...] [--end ...]

DRIVERS   the '+ X' logged immediately before each hit on the same chat-trace.
          This is what turns 'GetURL is called 8000 times' into 'userEmojis calls it'.
CADENCE   hits per second. A flat rate that never stops is a loop; spikes are mounts.
GAPS      ms between the end of one hit and the start of the next. Consistently
          ~0 means the caller re-fires the instant the previous lands - a feedback
          loop, not a user action.
BATCHES   distribution of any 'msgIDs: N' / 'convs: N' count on the line. A pile of
          1s means the caller is not batching.
"""

import argparse
import collections
import re

import kblog

COUNT_RE = re.compile(r"(msgIDs|convs|len|msgs): (\d+)")
# the +/-/| marker sits right after the log's sequence number, optionally behind
# a '++Chat: ' prefix. + enters a span, - leaves it, | is a note inside one.
MARKER_RE = re.compile(r"\]\s+\w+\s+(?:\+\+\w+:\s+)?([+\-|])\s+(.*)")


def main():
    ap = argparse.ArgumentParser()
    ap.add_argument("logs", nargs="+")
    ap.add_argument("--match", required=True, help="substring to explain")
    ap.add_argument("--start")
    ap.add_argument("--end")
    ap.add_argument("--top", type=int, default=10)
    args = ap.parse_args()

    drivers = collections.Counter()
    roots = collections.Counter()
    per_second = collections.Counter()
    batches = collections.Counter()
    last_enter = {}  # trace -> most recent span entered outside our match
    root_rpc = {}  # trace -> first 'Server: X' seen, i.e. what the app asked for
    inside = collections.Counter()  # trace -> depth inside our match
    hits = 0

    for line in kblog.iter_lines(args.logs, args.start, args.end):
        m = MARKER_RE.search(line)
        if not m:
            continue
        marker, text = m.group(1), kblog.TAGS_RE.sub("", m.group(2)).strip()
        # Lines with no chat-trace tag are unrelated to each other. Sharing one
        # bucket for them latched every untraced hit onto whichever "+ Server:"
        # line happened to come first in the file and reported it as the root -
        # a confident, wrong answer, in the section SKILL.md says to trust most.
        tr = kblog.trace(line)
        untraced = tr is None
        mine = args.match in text

        srv = kblog.SERVER_RE.search(line)
        if srv and not untraced and tr not in root_rpc:
            root_rpc[tr] = srv.group(1)

        if mine and marker == "+":
            hits += 1
            ts = kblog.stamp(line)
            if ts:
                per_second[ts] += 1
            # Every hit gets attributed to its trace's originating RPC. Do NOT gate
            # this on nesting depth: the service fans out concurrent goroutines
            # under a single chat-trace, so most hits are "inside" an earlier one
            # and gating would attribute only a handful of thousands of calls.
            if untraced:
                roots["<untraced: no chat-trace tag>"] += 1
            else:
                roots[root_rpc.get(tr, "<no app RPC on this trace>")] += 1
            # DRIVERS stays gated - the nearest preceding span is only meaningful
            # for a hit that is not nested inside another of our own
            if not untraced and not inside[tr]:
                drivers[last_enter.get(tr, "<nothing preceding on this trace>")] += 1
            c = COUNT_RE.search(text)
            if c:
                batches[int(c.group(2))] += 1
            inside[tr] += 1
        elif mine and marker == "-":
            inside[tr] = max(0, inside[tr] - 1)
        elif marker == "+" and not inside[tr]:
            # a span entered outside our match is a candidate driver; spans entered
            # while inside it are its own children
            last_enter[tr] = text[:55]

    if not hits:
        print(f"no lines matched {args.match!r}")
        return

    print(f"{hits} hits on {args.match!r}")

    print("\n== ROOT  app RPC that opened the trace this ran on")
    for k, v in roots.most_common(args.top):
        print(f"{v:8d}  {k}")
    # Both buckets mean "nothing asked for this": a hit whose trace never saw a
    # server RPC, and a hit with no trace at all. The DRIVERS placeholder is not
    # one of them - it is only ever counted into drivers, so reading it back out
    # of roots always added zero.
    unrooted = roots.get("<no app RPC on this trace>", 0) + roots.get(
        "<untraced: no chat-trace tag>", 0
    )
    if unrooted > hits * 0.5:
        print("  most hits have no app RPC above them: this is service-side background")
        print("  work, not something the client asked for. Look at DRIVERS instead, and")
        print("  grep the trace tags for CHTBKG= to confirm.")

    print("\n== DRIVERS  call logged just before, same chat-trace")
    for k, v in drivers.most_common(args.top):
        print(f"{v:8d}  {k}")

    print("\n== CADENCE  busiest seconds")
    for k, v in per_second.most_common(args.top):
        print(f"{v:8d}  {k}")
    spread = len(per_second)
    print(f"  spread over {spread} distinct seconds, mean {hits / max(spread, 1):.1f}/s")

    if batches:
        print("\n== BATCHES  count on the line")
        for size, n in batches.most_common(args.top):
            print(f"{n:8d}x  size {size}")
        ones = batches.get(1, 0)
        if ones > sum(batches.values()) * 0.5:
            print("  >half are size 1 - the caller is not batching")
    else:
        print("\n== BATCHES  none: these lines carry no item count")
        print("  Remote calls usually do not log one. To see batch sizes, match the")
        print("  local span that wraps this call instead - e.g. match")
        print("  'HybridConversationSource: GetMessages' rather than 'getMessagesRemote'.")


if __name__ == "__main__":
    main()