From 94d95e3cc2f9a59bd1aaa7b5b6849a4828448c53 Mon Sep 17 00:00:00 2001 From: Raman Gupta Date: Tue, 3 Nov 2026 12:21:04 -0500 Subject: [PATCH 1/3] feat(diagnostics): say what the app was doing when it froze The lag report could say how often git ran and that the UI thread froze, but not why: most freezes showed only nativeRunBlocking, the allocation rate had to be estimated from a GC flag default, and nothing said which repos the watcher kept rescanning. - The perf log reports the allocation rate each minute, split by UI thread, dispatcher workers, watcher threads and the rest; the clipboard report gives the total since launch. - A stall report adds what else was going on: git processes started and running, scans in progress, collections during the stall, and the other threads' stacks, identical ones folded together and idle ones left out. - The vitals include resident memory, so footprint growth can be told apart from heap growth. - The perf log names the busiest watched repos, with their rescans and which folders their events came from. Repos appear by list position and only generic folder names are shown, since reports get posted publicly. Co-Authored-By: Claude Signed-off-by: Raman Gupta --- .../kotlin/com/gitvantage/ArchitectureTest.kt | 8 +- .../com/gitvantage/app/AllocationMeter.kt | 126 ++++++++++++++++++ .../kotlin/com/gitvantage/app/AppState.kt | 39 +++++- .../kotlin/com/gitvantage/app/Diagnostics.kt | 43 +++++- .../com/gitvantage/app/StallWatchdog.kt | 61 ++++++++- .../com/gitvantage/app/ThreadSummary.kt | 66 +++++++++ src/main/kotlin/com/gitvantage/git/Git.kt | 5 + .../kotlin/com/gitvantage/git/RepoScanner.kt | 3 +- .../kotlin/com/gitvantage/model/Activity.kt | 69 ++++++++++ .../kotlin/com/gitvantage/model/WatchStats.kt | 97 ++++++++++++++ .../com/gitvantage/app/DiagnosticsTest.kt | 104 +++++++++++++++ .../com/gitvantage/model/WatchStatsTest.kt | 61 +++++++++ 12 files changed, 670 insertions(+), 12 deletions(-) create mode 100644 src/main/kotlin/com/gitvantage/app/AllocationMeter.kt create mode 100644 src/main/kotlin/com/gitvantage/app/ThreadSummary.kt create mode 100644 src/main/kotlin/com/gitvantage/model/Activity.kt create mode 100644 src/main/kotlin/com/gitvantage/model/WatchStats.kt create mode 100644 src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt create mode 100644 src/test/kotlin/com/gitvantage/model/WatchStatsTest.kt diff --git a/konture-test/src/test/kotlin/com/gitvantage/ArchitectureTest.kt b/konture-test/src/test/kotlin/com/gitvantage/ArchitectureTest.kt index 7a74393..0f2dc68 100644 --- a/konture-test/src/test/kotlin/com/gitvantage/ArchitectureTest.kt +++ b/konture-test/src/test/kotlin/com/gitvantage/ArchitectureTest.kt @@ -235,7 +235,7 @@ val Architecture by testSuite { } /** - * Starting a process is allowed in four places, and only one of them is about git: + * Starting a process is allowed in five places, and only one of them is about git: * * - `git/Git` runs the git binary — the subject of this file; * - `Actions` launches what the user picked from "Open in …" (a terminal, an IDE, `xdg-open`, @@ -245,6 +245,8 @@ val Architecture by testSuite { * `gsettings` and `kreadconfig`, because Skiko cannot: it dlopens an unversioned * `libdbus-1.so` that only a machine with the -devel package installed has, and reports * UNKNOWN otherwise (SKIKO-1177). Shells out only on that UNKNOWN, and only on Linux. + * - `app/Diagnostics` asks `ps` for the process's resident memory on macOS, which has no + * `/proc` and no Java API for it. Once a minute, and only while performance collection is on. * * Each entry has a reason, which is what makes a new name appearing in a failure worth stopping * on rather than adding to the list. @@ -262,10 +264,10 @@ val Architecture by testSuite { * file: Konture attributes a dependency to the file it appears in, so an allowlist over classes * would have to name every class each allowed file declares. */ - test("process spawning is confined to Git and the three non-git callers") { + test("process spawning is confined to Git and the four non-git callers") { architecture { files { - that().notNamed { it in setOf("Git.kt", "Actions.kt", "GitHub.kt", "Theme.kt") } + that().notNamed { it in setOf("Git.kt", "Actions.kt", "GitHub.kt", "Theme.kt", "Diagnostics.kt") } should().notReferenceClass("java.lang.ProcessBuilder") } } diff --git a/src/main/kotlin/com/gitvantage/app/AllocationMeter.kt b/src/main/kotlin/com/gitvantage/app/AllocationMeter.kt new file mode 100644 index 0000000..365c9c5 --- /dev/null +++ b/src/main/kotlin/com/gitvantage/app/AllocationMeter.kt @@ -0,0 +1,126 @@ +// SPDX-FileCopyrightText: 2026 Raman Gupta +// SPDX-License-Identifier: GPL-3.0-or-later + +package com.gitvantage.app + +import java.lang.management.ManagementFactory + +/** + * How fast the app allocates, and which threads do it. + * + * The collector's figures say how often it ran and for how long; they cannot say how much was + * allocated to make it run, and that is the number a busy collector is a symptom of. A field report + * showed 2.5 young collections a second and 6% of the time in GC with a steady ~55MB live — about + * 1GB/s allocated, if the young generation was the 10% of max heap the native image defaults to — + * and that had to be worked out by hand from a flag default, because nothing measured it. + * + * Grouped by thread because the groups are where the possible answers live: the UI thread is + * composition and text layout, the dispatcher workers are scans and the `git` output they read, the + * watcher threads are filesystem events. A total alone would confirm the problem and leave the + * cause exactly where it was. + * + * Measured from the per-thread allocation counters, which a native image may not support; when it + * doesn't, the line says so rather than reporting zero. A thread that ends between two samples takes + * whatever it allocated since the last one with it, so the figures are a slight undercount. + */ +object AllocationMeter { + + /** Where a thread's allocations are filed — see [groupOf]. */ + enum class Group(val label: String) { UI("ui"), WORKERS("workers"), WATCHER("watcher"), OTHER("other") } + + private val bean: com.sun.management.ThreadMXBean? = + runCatching { ManagementFactory.getThreadMXBean() as? com.sun.management.ThreadMXBean }.getOrNull() + ?.takeIf { runCatching { it.isThreadAllocatedMemorySupported && it.isThreadAllocatedMemoryEnabled }.getOrDefault(false) } + + /** Each live thread's allocation counter when it was last read. */ + private val lastSeen = HashMap() + + /** Everything attributed since the process started, by group. */ + private val total = LongArray(Group.entries.size) + + /** Attributed since the last [interval], by group. */ + private val recent = LongArray(Group.entries.size) + private var recentSince = System.nanoTime() + + /** + * Which group a thread belongs to, by its name — and by identity for the UI thread, whose name + * is the platform's ("main" or an AppKit thread) and says nothing. + */ + internal fun groupOf(name: String, isUi: Boolean): Group = when { + isUi -> Group.UI + name.startsWith("DefaultDispatcher-worker") -> Group.WORKERS + name.startsWith("notify-rs") -> Group.WATCHER + else -> Group.OTHER + } + + /** Read every live thread's counter and file what it allocated since the last read. */ + private fun sample(bean: com.sun.management.ThreadMXBean) { + val ids = bean.allThreadIds + // Depth 0: names and nothing else. Stacks would cost a safepoint per sample for no reason. + val infos = bean.getThreadInfo(ids, 0) + val bytes = bean.getThreadAllocatedBytes(ids) + val ui = StallWatchdog.uiThreadId + val live = HashSet(ids.size) + ids.forEachIndexed { i, id -> + val now = bytes[i] + val name = infos[i]?.threadName + if (now < 0 || name == null) return@forEachIndexed // ended since it was listed + live += id + val delta = now - (lastSeen.put(id, now) ?: 0L) + if (delta <= 0) return@forEachIndexed + val g = groupOf(name, id == ui).ordinal + total[g] += delta + recent[g] += delta + } + lastSeen.keys.retainAll(live) + } + + /** + * The allocation rate since the last call, for the periodic perf dump: "alloc 980MB/s over 60s + * (workers 71% · ui 22% · …)", or a line saying the counters aren't available. + */ + @Synchronized + fun interval(): String { + val b = bean ?: return "alloc unavailable (this runtime has no per-thread allocation counters)" + runCatching { sample(b) }.onFailure { return "alloc unavailable (${it.javaClass.simpleName})" } + val now = System.nanoTime() + val seconds = ((now - recentSince) / 1_000_000_000.0).coerceAtLeast(0.001) + val line = "alloc %.1fMB/s over %ds".format(recent.sum() / seconds / (1024 * 1024), seconds.toLong()) + + breakdown(recent) + recent.fill(0) + recentSince = now + return line + } + + /** + * Take the baseline the first [interval] is measured from. Without it the first reading files + * everything each thread allocated since it started under an interval of no length at all. + */ + @Synchronized + fun start() { + val b = bean ?: return + runCatching { sample(b) } + recent.fill(0) + recentSince = System.nanoTime() + } + + /** Everything attributed since the process started, for the clipboard report. Doesn't move [interval]'s baseline. */ + @Synchronized + fun total(): String { + val b = bean ?: return "alloc unavailable (this runtime has no per-thread allocation counters)" + runCatching { sample(b) }.onFailure { return "alloc unavailable (${it.javaClass.simpleName})" } + return "allocated ${mb(total.sum().toDouble())}MB since start" + breakdown(total) + } + + private fun breakdown(byGroup: LongArray): String { + val sum = byGroup.sum() + if (sum <= 0) return "" + return Group.entries + .map { it to byGroup[it.ordinal] } + .filter { it.second > 0 } + .sortedByDescending { it.second } + .joinToString(" · ", prefix = " (", postfix = ")") { (g, n) -> "${g.label} ${n * 100 / sum}%" } + } + + private fun mb(bytes: Double): Long = (bytes / (1024 * 1024)).toLong() +} diff --git a/src/main/kotlin/com/gitvantage/app/AppState.kt b/src/main/kotlin/com/gitvantage/app/AppState.kt index 1947e62..47b20e0 100644 --- a/src/main/kotlin/com/gitvantage/app/AppState.kt +++ b/src/main/kotlin/com/gitvantage/app/AppState.kt @@ -36,6 +36,7 @@ import com.gitvantage.model.Repo import com.gitvantage.model.RepoCandidate import com.gitvantage.model.WatchAction import com.gitvantage.model.WatchPolicy +import com.gitvantage.model.WatchStats import com.gitvantage.model.Worktree import com.gitvantage.model.WorktreeAlert import com.gitvantage.model.WorktreeAlerts @@ -558,6 +559,7 @@ class AppState(private val scope: CoroutineScope) { runCatching { w.events.collect { ev -> Perf.count("watch.events") + if (Perf.enabled) recordWatchEvent(ev) when (val action = actionFor(ev)) { is WatchAction.Rescan -> noteWatchEvent(action.id) WatchAction.RescanAll -> { Perf.count("watch.overflow"); scheduleFullRescan() } @@ -646,6 +648,7 @@ class AppState(private val scope: CoroutineScope) { want.forEach { id -> if (id !in watchRegs) register(w, id) } (watchRegs.keys - want).forEach { id -> runCatching { watchRegs.remove(id)?.forEach { it.close() } } + watchRootById.remove(id) watchBursts.remove(id) } } @@ -656,11 +659,38 @@ class AppState(private val scope: CoroutineScope) { private fun register(w: FsWatcher, id: String) { // A list of one, today. Every registration carries the repo id as its name, which is what // event routing reads, so the shape survives if [WatchRoots] ever returns several again. + watchRootById[id] = watchRootFor(id) watchRegs[id] = WatchRoots.forRepo(id).mapNotNull { root -> runCatching { w.watch(watchRootFor(root.path), root.recursive, id) }.getOrNull() } } + /** + * Each watched repo's root as the watcher was handed it, which is the spelling event paths come + * back under — what [recordWatchEvent] needs to say which folder an event was in. Resolved once + * at registration rather than per event, since resolving touches the filesystem. + */ + private val watchRootById = ConcurrentHashMap() + + /** File [ev] under its repo and folder for [WatchStats]. Only while collecting; runs per event. */ + private fun recordWatchEvent(ev: FsWatchEvent) { + val id = ev.source?.name ?: return + val root = watchRootById[id] ?: return + val folder = eventPaths(ev).firstOrNull()?.let { WatchStats.folderOf(root, it) } ?: "(overflow)" + WatchStats.event(id, folder) + } + + /** + * How a repo appears in a diagnostics report: its position in the list and how many worktrees it + * has, never its path or name — the report is meant to be pasted into a public issue. The + * position is enough for the person who sent it to say which repo it is, if asked. + */ + private fun diagLabel(id: String): String { + val n = order.indexOf(id) + 1 + val trees = repos.firstOrNull { it.id == id }?.worktrees?.size ?: 0 + return if (n > 0) "repo #$n ($trees worktrees)" else "(untracked repo)" + } + /** * What [ev] asks of the app — see [WatchPolicy.actionFor]. * @@ -740,6 +770,7 @@ class AppState(private val scope: CoroutineScope) { else due.filter { entries[it] != null } if (ids.isNotEmpty()) { Perf.count("watch.rescans", ids.size.toLong()) + ids.forEach(WatchStats::rescan) Perf.timed("watch.rescan.batch") { rescanRepos(ids, fetch = false) } } } @@ -1400,6 +1431,7 @@ class AppState(private val scope: CoroutineScope) { // Started whether or not collection is on, since it can be switched on at any point; an // idle timer once a minute is cheaper than starting and stopping one correctly. watchScope.launch { + AllocationMeter.start() while (currentCoroutineContext().isActive) { delay(PERF_REPORT_MS.milliseconds) if (Perf.enabled) dumpPerf("every ${PERF_REPORT_MS / 1000}s") @@ -1411,8 +1443,10 @@ class AppState(private val scope: CoroutineScope) { private fun dumpPerf(label: String) { val lines = Perf.report(markInterval = true) if (lines.isEmpty()) return + val vitals = Diagnostics.vitals() + AllocationMeter.interval() DiagLog.write( - "GitVantage perf [$label] · ${Diagnostics.vitals().joinToString(" · ")}\n" + lines.joinToString("\n"), + "GitVantage perf [$label] · ${vitals.joinToString(" · ")}\n" + + (lines + WatchStats.report(label = ::diagLabel)).joinToString("\n"), ) } @@ -1442,7 +1476,8 @@ class AppState(private val scope: CoroutineScope) { suspend fun diagnosticsReport(): String { val inventory = "${repos.size} repos · ${repos.sumOf { it.worktrees.size }} worktrees · " + "GitHub polling ${if (githubEnabled) "on" else "off"}" - return withContext(Dispatchers.IO) { Diagnostics.report(inventory) } + val watched = WatchStats.report(label = ::diagLabel) + return withContext(Dispatchers.IO) { Diagnostics.report(inventory, watched) } } /** Show the folder holding the log, for attaching the file itself rather than an excerpt. */ diff --git a/src/main/kotlin/com/gitvantage/app/Diagnostics.kt b/src/main/kotlin/com/gitvantage/app/Diagnostics.kt index 13ea116..3951ae4 100644 --- a/src/main/kotlin/com/gitvantage/app/Diagnostics.kt +++ b/src/main/kotlin/com/gitvantage/app/Diagnostics.kt @@ -5,7 +5,9 @@ package com.gitvantage.app import com.gitvantage.BuildInfo import com.gitvantage.model.Perf +import java.io.File import java.lang.management.ManagementFactory +import java.util.concurrent.TimeUnit /** * The report someone pastes into an issue, and the pieces it is assembled from. @@ -59,6 +61,7 @@ object Diagnostics { "heap used=${mb(rt.totalMemory() - rt.freeMemory())}MB committed=${mb(rt.totalMemory())}MB " + "max=${mb(rt.maxMemory())}MB", ) + residentMb()?.let { add("rss ${it}MB") } runCatching { ManagementFactory.getGarbageCollectorMXBeans() .filter { it.collectionCount > 0 } @@ -68,15 +71,50 @@ object Diagnostics { } /** - * The whole report: [environment], [inventory], [vitals], the counters, then the recent log. + * The process's resident memory in MB, or null where it can't be read. + * + * The heap figures are only the Java part. A field report's 1.7GB footprint sat beside ~55MB of + * live heap, and nothing logged could say how the rest grew — the collector keeping memory it had + * touched, or native memory (graphics, the watcher library) the heap never sees. This is the + * number that answers it over a long session. + * + * Linux reads `/proc`. macOS has no such file and no Java API for it, so it asks `ps` — a process + * per call, which is why this is read once a minute while collecting and not more. Windows reports + * nothing. + */ + internal fun residentMb(): Long? = runCatching { + val os = System.getProperty("os.name").orEmpty() + when { + os.startsWith("Linux") -> + File("/proc/self/status").useLines { lines -> + lines.firstOrNull { it.startsWith("VmRSS:") }?.let(::parseVmRssKb) + }?.let { it / 1024 } + os.startsWith("Mac") -> { + val p = ProcessBuilder("ps", "-o", "rss=", "-p", ProcessHandle.current().pid().toString()) + .redirectError(ProcessBuilder.Redirect.DISCARD).start() + val out = p.inputStream.bufferedReader().readText() + if (p.waitFor(5, TimeUnit.SECONDS)) out.trim().toLongOrNull()?.let { it / 1024 } else null + } + else -> null + } + }.getOrNull() + + /** The kB figure from a `/proc` `VmRSS:` line — "VmRSS: 123456 kB". */ + internal fun parseVmRssKb(line: String): Long? = + line.removePrefix("VmRSS:").trim().substringBefore(' ').toLongOrNull() + + /** + * The whole report: [environment], [inventory], [vitals], the counters and [watched] — the + * caller's `WatchStats` lines, labelled by it — then the recent log. * * [inventory] is the caller's, because how much is being tracked is application state and this * object holds none. Reads the log from disk, so not for the UI thread. */ - fun report(inventory: String): String = buildString { + fun report(inventory: String, watched: List = emptyList()): String = buildString { appendLine(environment) appendLine(inventory) vitals().forEach { appendLine(it) } + appendLine(AllocationMeter.total()) appendLine() val counters = Perf.report() when { @@ -84,6 +122,7 @@ object Diagnostics { val since = Perf.collectingSeconds()?.let { "collecting for ${formatUptime(it)}" } appendLine("Counters (${since ?: "collection now off"})") counters.forEach { appendLine(it) } + watched.forEach { appendLine(it) } } Perf.enabled -> appendLine("Counters: collecting, nothing recorded yet") else -> appendLine("Counters: not collected — turn on \"Collect performance data\" in Settings") diff --git a/src/main/kotlin/com/gitvantage/app/StallWatchdog.kt b/src/main/kotlin/com/gitvantage/app/StallWatchdog.kt index 03e7493..c958550 100644 --- a/src/main/kotlin/com/gitvantage/app/StallWatchdog.kt +++ b/src/main/kotlin/com/gitvantage/app/StallWatchdog.kt @@ -3,7 +3,9 @@ package com.gitvantage.app +import com.gitvantage.model.Activity import com.gitvantage.model.Perf +import java.lang.management.ManagementFactory import kotlinx.coroutines.CoroutineScope import kotlinx.coroutines.delay import kotlinx.coroutines.launch @@ -65,6 +67,29 @@ object StallWatchdog { @Volatile private var uiThread: Thread? = null + /** The UI thread's id once it is known — [AllocationMeter] files its allocations separately. */ + internal val uiThreadId: Long? get() = uiThread?.threadId() + + /** + * What the rest of the app was up to at one moment, from [Activity] and the collectors, so two of + * these subtract to "during the stall". Each figure is a suspect: `git` starts (a `fork()` apiece, which on macOS holds + * locks the UI thread needs), scans, and collections, which pause every thread. + */ + private data class Moment(val gitStarted: Long, val gitRunning: Int, val scans: Int, val gcCount: Long, val gcMillis: Long) { + companion object { + fun now(): Moment { + val gc = runCatching { ManagementFactory.getGarbageCollectorMXBeans() }.getOrDefault(emptyList()) + return Moment( + gitStarted = Activity.gitStartedTotal, + gitRunning = Activity.gitRunningNow, + scans = Activity.scansRunningNow, + gcCount = gc.sumOf { it.collectionCount.coerceAtLeast(0) }, + gcMillis = gc.sumOf { it.collectionTime.coerceAtLeast(0) }, + ) + } + } + } + @Volatile private var started = false @@ -125,6 +150,7 @@ object StallWatchdog { while (true) { Thread.sleep(INTERVAL_MS) val sent = System.nanoTime() + val before = Moment.now() val arrived = CountDownLatch(1) // A cancelled scope silently never runs this, which is why the wait below is bounded. runCatching { @@ -142,18 +168,38 @@ object StallWatchdog { if (took >= SLUGGISH_NANOS) Perf.count("ui.dispatch.sluggish") continue } - // Still waiting, so the thread is stuck *now* — take the stack before it recovers. - val stack = uiThread?.stackTrace + // Still waiting, so the thread is stuck *now* — take the stacks before it recovers: its + // own, and everyone else's, since the UI thread is often only waiting on one of them. + val ui = uiThread + val stack = ui?.stackTrace + val others = runCatching { otherThreads(ui) }.getOrDefault(emptyList()) + val caught = Moment.now() val recovered = arrived.await(ABANDON_MS, TimeUnit.MILLISECONDS) val blockedMs = (System.nanoTime() - sent) / 1_000_000 Perf.count("ui.stalls") Perf.time("ui.dispatch", System.nanoTime() - sent) - report(blockedMs, recovered, stack) + report(blockedMs, recovered, stack, others, before, caught, Moment.now()) if (!recovered) return // the scope is gone; nothing left to watch } } - private fun report(blockedMs: Long, recovered: Boolean, stack: Array?) { + /** Every thread but the UI thread and this one, as [ThreadSummary] reads them. */ + private fun otherThreads(ui: Thread?): List { + val self = Thread.currentThread() + return Thread.getAllStackTraces() + .filterKeys { it !== ui && it !== self } + .map { (t, frames) -> ThreadSummary.Snap(t.name, t.state, frames.toList()) } + } + + private fun report( + blockedMs: Long, + recovered: Boolean, + stack: Array?, + others: List, + before: Moment, + caught: Moment, + after: Moment, + ) { stalls++ val err = StringBuilder() err.append("GitVantage: UI thread blocked for ${blockedMs}ms") @@ -165,6 +211,13 @@ object StallWatchdog { stack.take(STACK_FRAMES).forEach { err.append(" at ").append(it).append('\n') } if (stack.size > STACK_FRAMES) err.append(" … ${stack.size - STACK_FRAMES} more frames\n") } + err.append( + " while blocked: ${after.gitStarted - before.gitStarted} git started " + + "(${caught.gitRunning} running when caught) · ${caught.scans} scans running · " + + "${after.gcCount - before.gcCount} collections, ${after.gcMillis - before.gcMillis}ms in GC\n", + ) + err.append(" other threads when caught:\n") + ThreadSummary.lines(others).forEach { err.append(it).append('\n') } DiagLog.write(err.toString()) } } diff --git a/src/main/kotlin/com/gitvantage/app/ThreadSummary.kt b/src/main/kotlin/com/gitvantage/app/ThreadSummary.kt new file mode 100644 index 0000000..7ab889e --- /dev/null +++ b/src/main/kotlin/com/gitvantage/app/ThreadSummary.kt @@ -0,0 +1,66 @@ +// SPDX-FileCopyrightText: 2026 Raman Gupta +// SPDX-License-Identifier: GPL-3.0-or-later + +package com.gitvantage.app + +/** + * Every other thread's stack at the moment the UI thread was caught stuck, reduced to what is worth + * reading. + * + * The UI thread's own stack is often no help. On macOS it usually reads `nativeRunBlocking` and + * nothing else — 18 of 20 stalls in one field report — because the thread is inside AppKit or the + * allocator, where a Java stack cannot follow, waiting on a lock some *other* thread holds. So what + * names the cause is what the rest of the process was doing: a dozen workers in `forkAndExec`, say. + * + * Idle threads are left out, since a pool parked waiting for work says nothing, and threads doing the + * same thing are folded into one entry with a count, since twelve identical stacks are one fact. + */ +internal object ThreadSummary { + + /** One thread as captured: what it's called, what state it was in, and its frames. */ + data class Snap(val name: String, val state: Thread.State, val frames: List) + + /** + * Whether [t] is doing something: inside app code (starting or waiting on a `git` process, say), + * blocked on a monitor, or running Java code. + * + * `RUNNABLE` alone is not enough. A thread parked in a native call — the JDK's watch-service + * `poll`, the reference handler — reports `RUNNABLE` while it waits for nothing in particular, + * and a thread with no Java frames at all has nothing here to read. Both are left out unless app + * code is on the stack, which is what keeps a worker inside the native `forkAndExec` in. + */ + fun interesting(t: Snap): Boolean = when { + t.frames.any { it.className.startsWith("com.gitvantage.") } -> true + t.state == Thread.State.BLOCKED -> true + t.state == Thread.State.RUNNABLE -> t.frames.firstOrNull()?.isNativeMethod == false + else -> false + } + + /** + * The interesting threads in [threads] as report lines, identical stacks folded together, the + * most common first: at most [maxGroups] entries of at most [maxFrames] frames each. + */ + fun lines(threads: List, maxGroups: Int = 8, maxFrames: Int = 12): List { + val shown = threads.filter(::interesting) + if (shown.isEmpty()) return listOf(" (no other thread was doing anything)") + val groups = shown + .groupBy { it.state to it.frames.take(maxFrames) } + .entries + .sortedByDescending { it.value.size } + return buildList { + groups.take(maxGroups).forEach { (key, members) -> + val (state, frames) = key + val names = members.map { it.name }.distinct() + val named = names.take(3).joinToString(", ") + if (names.size > 3) ", …" else "" + add(" ${members.size}× $named ($state)") + frames.forEach { add(" at $it") } + if (frames.isEmpty()) add(" (no Java frames)") + } + if (groups.size > maxGroups) { + add(" … and ${groups.drop(maxGroups).sumOf { it.value.size }} more threads in ${groups.size - maxGroups} other states") + } + val idle = threads.size - shown.size + if (idle > 0) add(" ($idle idle threads not shown)") + } + } +} diff --git a/src/main/kotlin/com/gitvantage/git/Git.kt b/src/main/kotlin/com/gitvantage/git/Git.kt index 4db98a7..602e730 100644 --- a/src/main/kotlin/com/gitvantage/git/Git.kt +++ b/src/main/kotlin/com/gitvantage/git/Git.kt @@ -3,6 +3,7 @@ package com.gitvantage.git +import com.gitvantage.model.Activity import com.gitvantage.model.Perf import java.io.File import java.util.concurrent.TimeUnit @@ -148,7 +149,11 @@ object Git { return "?" } + // Counted always, not only while collecting — see [Activity] for who reads it and why. private fun spawn(dir: File, args: List, timeoutSeconds: Long, captureErr: Boolean, readOnly: Boolean = false): Result = + Activity.git { spawnMeasured(dir, args, timeoutSeconds, captureErr, readOnly) } + + private fun spawnMeasured(dir: File, args: List, timeoutSeconds: Long, captureErr: Boolean, readOnly: Boolean): Result = // Keyed on the subcommand, not the full argument list: "status" is the useful grouping, and // the arguments would make a cardinality explosion out of a handful of real commands. // diff --git a/src/main/kotlin/com/gitvantage/git/RepoScanner.kt b/src/main/kotlin/com/gitvantage/git/RepoScanner.kt index b1386e9..5e4ab58 100644 --- a/src/main/kotlin/com/gitvantage/git/RepoScanner.kt +++ b/src/main/kotlin/com/gitvantage/git/RepoScanner.kt @@ -5,6 +5,7 @@ package com.gitvantage.git import com.gitvantage.git.model.BranchStatus import com.gitvantage.git.model.StatusResult +import com.gitvantage.model.Activity import com.gitvantage.model.ChangedFile import com.gitvantage.model.DETACHED_BRANCH import com.gitvantage.model.Meta @@ -40,7 +41,7 @@ object RepoScanner { * a couple of idle hours. */ suspend fun scan(entry: RegistryEntry, fetch: Boolean, userInitiated: Boolean = true): Repo = - withContext(Dispatchers.IO) { Perf.timed("scan.repo") { scanNow(entry, fetch, userInitiated) } } + withContext(Dispatchers.IO) { Activity.scan { Perf.timed("scan.repo") { scanNow(entry, fetch, userInitiated) } } } private fun scanNow(entry: RegistryEntry, fetch: Boolean, userInitiated: Boolean): Repo { val dir = File(entry.path) diff --git a/src/main/kotlin/com/gitvantage/model/Activity.kt b/src/main/kotlin/com/gitvantage/model/Activity.kt new file mode 100644 index 0000000..e878053 --- /dev/null +++ b/src/main/kotlin/com/gitvantage/model/Activity.kt @@ -0,0 +1,69 @@ +// SPDX-FileCopyrightText: 2026 Raman Gupta +// SPDX-License-Identifier: GPL-3.0-or-later + +package com.gitvantage.model + +import java.util.concurrent.atomic.AtomicInteger +import java.util.concurrent.atomic.AtomicLong + +/** + * What the background is doing right now: `git` processes running and started, scans in progress. + * + * Always counted, unlike [Perf], which is off unless asked for, because the stall report reads it and + * the stall report is always on. It is how a frozen UI thread gets explained: on macOS every `git` + * start is a `fork()` that holds locks the UI thread needs, so "37 git started while blocked" next + * to a stall says what [Perf]'s totals can only hint at. + * + * Here rather than beside the code it counts so the UI layer can read it without reaching the git + * runner, which only the state layer may. + */ +object Activity { + private val gitRunning = AtomicInteger() + private val gitStarted = AtomicLong() + private val scans = AtomicInteger() + + val gitRunningNow: Int get() = gitRunning.get() + val gitStartedTotal: Long get() = gitStarted.get() + val scansRunningNow: Int get() = scans.get() + + /** Run [body] counted as one `git` process. */ + inline fun git(body: () -> T): T { + gitStart() + try { + return body() + } finally { + gitEnd() + } + } + + /** Run [body] counted as one scan in progress. */ + inline fun scan(body: () -> T): T { + scanStart() + try { + return body() + } finally { + scanEnd() + } + } + + @PublishedApi + internal fun gitStart() { + gitStarted.incrementAndGet() + gitRunning.incrementAndGet() + } + + @PublishedApi + internal fun gitEnd() { + gitRunning.decrementAndGet() + } + + @PublishedApi + internal fun scanStart() { + scans.incrementAndGet() + } + + @PublishedApi + internal fun scanEnd() { + scans.decrementAndGet() + } +} diff --git a/src/main/kotlin/com/gitvantage/model/WatchStats.kt b/src/main/kotlin/com/gitvantage/model/WatchStats.kt new file mode 100644 index 0000000..e5464bc --- /dev/null +++ b/src/main/kotlin/com/gitvantage/model/WatchStats.kt @@ -0,0 +1,97 @@ +// SPDX-FileCopyrightText: 2026 Raman Gupta +// SPDX-License-Identifier: GPL-3.0-or-later + +package com.gitvantage.model + +import java.nio.file.Path +import java.util.concurrent.ConcurrentHashMap +import java.util.concurrent.atomic.AtomicLong + +/** + * Which repos the filesystem watcher keeps rescanning, and which of their folders the events come + * from. + * + * The totals say how busy the watcher is: one field report had 3.4 events and half a rescan a + * second. They can't say whether that is one repo with a build running or forty trickling, nor + * whether the writes are in `build/` — which git ignores, so a rescan finds nothing new — or in the + * code. The second question decides whether to stop watching ignored folders, and only the folders + * can answer it. + * + * Folders are reported by name only when the name is a generic one — build output, tool state, + * git's own files. Diagnostics reports get pasted into public issues, and a project's own folder + * names are its business, so anything else is "(other folder)". Repos are labelled by the caller for + * the same reason. + * + * Recorded only while performance collection is on. Concurrent because the watcher's collector + * writes while the periodic dump reads. + */ +object WatchStats { + + private class RepoStats { + val events = AtomicLong() + val rescans = AtomicLong() + val folders = ConcurrentHashMap() + } + + private val byRepo = ConcurrentHashMap() + + /** Folder names common enough to say nothing about the project they're in. */ + private val GENERIC = setOf( + "build", "out", "dist", "target", "bin", "obj", "node_modules", "vendor", "coverage", "tmp", "logs", + "__pycache__", ".gradle", ".idea", ".vscode", ".claude", ".venv", "venv", ".next", ".nuxt", ".cache", + ".kotlin", ".turbo", ".pytest_cache", ".mypy_cache", ".terraform", + ) + + /** + * Where [path] sits in the repo rooted at [root], as a report label: `.git/` for git's own + * files, the folder's name when [GENERIC], `(root files)` for a file at the top, and + * `(other folder)` otherwise. `(outside)` for a path not under [root] at all. + */ + fun folderOf(root: Path, path: Path): String { + if (!path.startsWith(root)) return "(outside)" + val rel = root.relativize(path) + if (rel.nameCount == 0 || rel.toString().isEmpty()) return "(root files)" + val first = rel.getName(0).toString() + return when { + first == ".git" -> if (rel.nameCount > 1) ".git/${rel.getName(1)}" else ".git" + rel.nameCount == 1 -> "(root files)" + first in GENERIC -> "$first/" + else -> "(other folder)" + } + } + + /** One filesystem event for [repo], in [folder] as [folderOf] named it. */ + fun event(repo: String, folder: String) { + if (!Perf.enabled) return + val s = byRepo.computeIfAbsent(repo) { RepoStats() } + s.events.incrementAndGet() + s.folders.computeIfAbsent(folder) { AtomicLong() }.incrementAndGet() + } + + /** One rescan of [repo] that the watcher caused. */ + fun rescan(repo: String) { + if (!Perf.enabled) return + byRepo.computeIfAbsent(repo) { RepoStats() }.rescans.incrementAndGet() + } + + /** + * The busiest [top] repos by events, one line each, labelled by [label] — which is how the caller + * keeps paths out of the report. Each lists its rescans and where its events came from, the + * biggest share first. + */ + fun report(top: Int = 5, label: (String) -> String): List { + val busiest = byRepo.entries.sortedByDescending { it.value.events.get() }.take(top) + if (busiest.isEmpty()) return emptyList() + return listOf(" busiest watched repos (events · rescans · where the events were)") + + busiest.map { (repo, s) -> + val events = s.events.get() + val folders = s.folders.entries + .sortedByDescending { it.value.get() } + .take(5) + .joinToString(" · ") { (f, n) -> "$f ${n.get() * 100 / events.coerceAtLeast(1)}%" } + " %-26s events=%-7d rescans=%-5d %s".format(label(repo), events, s.rescans.get(), folders) + } + } + + fun reset() = byRepo.clear() +} diff --git a/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt b/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt new file mode 100644 index 0000000..444da07 --- /dev/null +++ b/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt @@ -0,0 +1,104 @@ +// SPDX-FileCopyrightText: 2026 Raman Gupta +// SPDX-License-Identifier: GPL-3.0-or-later + +package com.gitvantage.app + +import de.infix.testBalloon.framework.core.testSuite + +/** The figures the diagnostics report adds beyond the counters: allocation, resident memory, other threads. */ +val DiagnosticsFigures by testSuite { + + // ---- allocation ---- + + test("threads are filed by what they do, and the UI thread by identity") { + assert(AllocationMeter.groupOf("main", isUi = true) == AllocationMeter.Group.UI) + assert(AllocationMeter.groupOf("DefaultDispatcher-worker-7", isUi = false) == AllocationMeter.Group.WORKERS) + assert(AllocationMeter.groupOf("notify-rs fsevents loop", isUi = false) == AllocationMeter.Group.WATCHER) + // The watchdog's name contains "watch" and must not be mistaken for the filesystem watcher. + assert(AllocationMeter.groupOf("gitvantage-stall-watchdog", isUi = false) == AllocationMeter.Group.OTHER) + } + + test("the interval rate reports what this thread allocated, and attributes it") { + AllocationMeter.interval() // set the baseline + val sink = ArrayList() + repeat(64) { sink += ByteArray(1024 * 1024) } // 64MB, held so it can't be optimised away + val line = AllocationMeter.interval() + assert(sink.size == 64) + assert(line.startsWith("alloc ") && "MB/s" in line) { "got $line" } + assert("%)" in line) { "no breakdown: $line" } + } + + test("the running total does not move the interval's baseline") { + AllocationMeter.interval() + val held = ByteArray(32 * 1024 * 1024) + assert(AllocationMeter.total().startsWith("allocated ")) + val line = AllocationMeter.interval() + // The 32MB still counts towards the interval, though total() sampled in between. + val seconds = line.substringAfter("over ").substringBefore("s").toDouble().coerceAtLeast(1.0) + val rate = line.substringAfter("alloc ").substringBefore("MB/s").toDouble() + assert(rate * seconds >= 32 || held.isEmpty()) { "got $line" } + } + + // ---- resident memory ---- + + test("a /proc VmRSS line is read in kB") { + assert(Diagnostics.parseVmRssKb("VmRSS:\t 123456 kB") == 123456L) + assert(Diagnostics.parseVmRssKb("VmRSS: garbage") == null) + } + + test("resident memory is reported on Linux and macOS") { + val os = System.getProperty("os.name") + val rss = Diagnostics.residentMb() + if (os.startsWith("Linux") || os.startsWith("Mac")) assert(rss != null && rss > 0) { "got $rss on $os" } + assert(Diagnostics.vitals().any { it.startsWith("rss ") } == (rss != null)) + } + + // ---- other threads at a stall ---- + + fun frame(cls: String, method: String) = StackTraceElement(cls, method, null, -1) + val forking = listOf( + frame("java.lang.ProcessImpl", "forkAndExec"), + frame("com.gitvantage.git.Git", "spawnNow"), + ) + val parked = listOf(frame("jdk.internal.misc.Unsafe", "park"), frame("java.util.concurrent.locks.LockSupport", "park")) + + test("identical stacks are folded into one entry with a count, the most common first") { + val threads = (1..5).map { ThreadSummary.Snap("DefaultDispatcher-worker-$it", Thread.State.RUNNABLE, forking) } + + ThreadSummary.Snap("other", Thread.State.BLOCKED, listOf(frame("x.Y", "z"))) + val lines = ThreadSummary.lines(threads) + assert(lines[0].startsWith(" 5× DefaultDispatcher-worker-1, DefaultDispatcher-worker-2, DefaultDispatcher-worker-3, …")) { + "got ${lines[0]}" + } + assert(lines.count { "forkAndExec" in it } == 1) { "the shared stack was printed more than once: $lines" } + assert(lines.any { it.startsWith(" 1× other (BLOCKED)") }) + } + + test("idle pool threads are counted, not printed, but app threads waiting on git are kept") { + val waitingOnGit = listOf(frame("java.lang.ProcessImpl", "waitFor"), frame("com.gitvantage.git.Git", "spawnNow")) + val threads = listOf( + ThreadSummary.Snap("DefaultDispatcher-worker-1", Thread.State.TIMED_WAITING, parked), + ThreadSummary.Snap("DefaultDispatcher-worker-2", Thread.State.WAITING, waitingOnGit), + ) + val lines = ThreadSummary.lines(threads) + assert(lines.any { "waitFor" in it }) { "got $lines" } + assert(lines.none { "park" in it }) { "got $lines" } + assert(lines.last() == " (1 idle threads not shown)") { "got $lines" } + } + + test("threads waiting in a native call, or with no Java frames, count as idle") { + val polling = listOf(StackTraceElement("sun.nio.fs.LinuxWatchService", "poll", null, -2)) // -2: native + val threads = listOf( + ThreadSummary.Snap("FileSystemWatchService", Thread.State.RUNNABLE, polling), + ThreadSummary.Snap("Signal Dispatcher", Thread.State.RUNNABLE, emptyList()), + ThreadSummary.Snap("worker", Thread.State.RUNNABLE, listOf(StackTraceElement("java.lang.ProcessImpl", "forkAndExec", null, -2), StackTraceElement("com.gitvantage.git.Git", "spawnNow", null, -1))), + ) + val lines = ThreadSummary.lines(threads) + assert(lines.first().startsWith(" 1× worker")) { "got $lines" } + assert(lines.last() == " (2 idle threads not shown)") { "got $lines" } + } + + test("a stall with nothing else going on says so") { + val lines = ThreadSummary.lines(listOf(ThreadSummary.Snap("pool", Thread.State.WAITING, parked))) + assert(lines.first() == " (no other thread was doing anything)") { "got $lines" } + } +} diff --git a/src/test/kotlin/com/gitvantage/model/WatchStatsTest.kt b/src/test/kotlin/com/gitvantage/model/WatchStatsTest.kt new file mode 100644 index 0000000..f19dd02 --- /dev/null +++ b/src/test/kotlin/com/gitvantage/model/WatchStatsTest.kt @@ -0,0 +1,61 @@ +// SPDX-FileCopyrightText: 2026 Raman Gupta +// SPDX-License-Identifier: GPL-3.0-or-later + +package com.gitvantage.model + +import de.infix.testBalloon.framework.core.testSuite +import java.nio.file.Path + +/** Which repos and folders the watcher's events come from — see [WatchStats]. */ +val WatchStatistics by testSuite { + + val root = Path.of("/home/u/src/proj") + fun at(rel: String) = root.resolve(rel) + + test("git's own files are named, down to the entry under .git") { + assert(WatchStats.folderOf(root, at(".git/index")) == ".git/index") + assert(WatchStats.folderOf(root, at(".git/refs/heads/main")) == ".git/refs") + } + + test("generic folders are named, and a project's own folders are not") { + assert(WatchStats.folderOf(root, at("build/classes/A.class")) == "build/") + assert(WatchStats.folderOf(root, at("node_modules/x/index.js")) == "node_modules/") + assert(WatchStats.folderOf(root, at(".claude/worktrees/wt/a.txt")) == ".claude/") + assert(WatchStats.folderOf(root, at("acme-secret/plan.md")) == "(other folder)") + } + + test("a file at the top and a path elsewhere are told apart") { + assert(WatchStats.folderOf(root, at("README.md")) == "(root files)") + assert(WatchStats.folderOf(root, root) == "(root files)") + assert(WatchStats.folderOf(root, Path.of("/home/u/src/proj-two/a")) == "(outside)") + } + + test("the report ranks repos by events, with their rescans and folder shares, under the caller's label") { + WatchStats.reset() + Perf.enable(true) + try { + repeat(3) { WatchStats.event("/quiet", "(root files)") } + repeat(6) { WatchStats.event("/busy", "build/") } + repeat(2) { WatchStats.event("/busy", ".git/index") } + WatchStats.rescan("/busy") + val lines = WatchStats.report { if (it == "/busy") "repo #2" else "repo #1" } + assert(lines.size == 3) { "got $lines" } + assert(lines[1].trim().startsWith("repo #2")) { "busiest not first: $lines" } + assert("events=8" in lines[1] && "rescans=1" in lines[1]) { "got ${lines[1]}" } + assert("build/ 75% · .git/index 25%" in lines[1]) { "got ${lines[1]}" } + assert(lines.none { "/busy" in it || "/quiet" in it }) { "a path leaked into the report: $lines" } + } finally { + Perf.enable(false) + WatchStats.reset() + } + } + + test("nothing is recorded while collection is off") { + WatchStats.reset() + Perf.enable(false) + if (!Perf.forcedOn) { + WatchStats.event("/r", "build/") + assert(WatchStats.report { it }.isEmpty()) + } + } +} From a47fbef0cbf25ab3ff6268877b88fa00bc3db915 Mon Sep 17 00:00:00 2001 From: Raman Gupta Date: Tue, 3 Nov 2026 12:38:44 -0500 Subject: [PATCH 2/3] fix(diagnostics): measure allocation only while collecting The allocation baseline was taken at launch whether or not collection was on, so switching it on mid-session gave a first reading averaged over the whole session. It is now taken when collection starts, at launch or from Settings, and a reading with no baseline takes one instead of reporting a rate. Clicking Off while GITVANTAGE_PERF=1 forces collection on now does nothing. It used to log "collection switched off" for collection that carried on, and save "off" for the next launch. Co-Authored-By: Claude Signed-off-by: Raman Gupta --- .../kotlin/com/gitvantage/app/AllocationMeter.kt | 15 +++++++++++++-- src/main/kotlin/com/gitvantage/app/AppState.kt | 8 +++++++- .../kotlin/com/gitvantage/app/DiagnosticsTest.kt | 4 ++-- 3 files changed, 22 insertions(+), 5 deletions(-) diff --git a/src/main/kotlin/com/gitvantage/app/AllocationMeter.kt b/src/main/kotlin/com/gitvantage/app/AllocationMeter.kt index 365c9c5..6999545 100644 --- a/src/main/kotlin/com/gitvantage/app/AllocationMeter.kt +++ b/src/main/kotlin/com/gitvantage/app/AllocationMeter.kt @@ -42,6 +42,9 @@ object AllocationMeter { private val recent = LongArray(Group.entries.size) private var recentSince = System.nanoTime() + /** Whether [start] has taken the baseline [recent] is measured from. */ + private var baselined = false + /** * Which group a thread belongs to, by its name — and by identity for the UI thread, whose name * is the platform's ("main" or an AppKit thread) and says nothing. @@ -82,6 +85,10 @@ object AllocationMeter { @Synchronized fun interval(): String { val b = bean ?: return "alloc unavailable (this runtime has no per-thread allocation counters)" + if (!baselined) { + start() + return "alloc measuring from now" + } runCatching { sample(b) }.onFailure { return "alloc unavailable (${it.javaClass.simpleName})" } val now = System.nanoTime() val seconds = ((now - recentSince) / 1_000_000_000.0).coerceAtLeast(0.001) @@ -93,8 +100,11 @@ object AllocationMeter { } /** - * Take the baseline the first [interval] is measured from. Without it the first reading files - * everything each thread allocated since it started under an interval of no length at all. + * Take the baseline the next [interval] is measured from — whenever collection switches on, so + * the first reading covers the time it has been on rather than the whole session. + * + * Without one the first reading would file everything each thread allocated since it started + * under an interval of no length at all; [interval] takes it itself if nobody did. */ @Synchronized fun start() { @@ -102,6 +112,7 @@ object AllocationMeter { runCatching { sample(b) } recent.fill(0) recentSince = System.nanoTime() + baselined = true } /** Everything attributed since the process started, for the clipboard report. Doesn't move [interval]'s baseline. */ diff --git a/src/main/kotlin/com/gitvantage/app/AppState.kt b/src/main/kotlin/com/gitvantage/app/AppState.kt index 47b20e0..3a3f8d7 100644 --- a/src/main/kotlin/com/gitvantage/app/AppState.kt +++ b/src/main/kotlin/com/gitvantage/app/AppState.kt @@ -1431,7 +1431,8 @@ class AppState(private val scope: CoroutineScope) { // Started whether or not collection is on, since it can be switched on at any point; an // idle timer once a minute is cheaper than starting and stopping one correctly. watchScope.launch { - AllocationMeter.start() + // Only when collecting: switching on later takes its own baseline (see setPerfCollection). + if (Perf.enabled) AllocationMeter.start() while (currentCoroutineContext().isActive) { delay(PERF_REPORT_MS.milliseconds) if (Perf.enabled) dumpPerf("every ${PERF_REPORT_MS / 1000}s") @@ -1461,7 +1462,12 @@ class AppState(private val scope: CoroutineScope) { */ fun setPerfCollection(on: Boolean) { if (on == perfCollecting) return + // `GITVANTAGE_PERF=1` can't be undone from here, which is why Settings dims Off. Ignore the + // click outright: going on would log "collection switched off" for collection that carries + // on, and save "off" as a choice the user can't see took effect. + if (!on && Perf.forcedOn) return if (!on) watchScope.launch { dumpPerf("collection switched off") } + if (on) watchScope.launch { AllocationMeter.start() } Perf.enable(on) perfCollecting = Perf.enabled Registry.saveSettings(Registry.settings().copy(collectPerf = on)) diff --git a/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt b/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt index 444da07..a9de66b 100644 --- a/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt +++ b/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt @@ -19,7 +19,7 @@ val DiagnosticsFigures by testSuite { } test("the interval rate reports what this thread allocated, and attributes it") { - AllocationMeter.interval() // set the baseline + AllocationMeter.start() val sink = ArrayList() repeat(64) { sink += ByteArray(1024 * 1024) } // 64MB, held so it can't be optimised away val line = AllocationMeter.interval() @@ -29,7 +29,7 @@ val DiagnosticsFigures by testSuite { } test("the running total does not move the interval's baseline") { - AllocationMeter.interval() + AllocationMeter.start() val held = ByteArray(32 * 1024 * 1024) assert(AllocationMeter.total().startsWith("allocated ")) val line = AllocationMeter.interval() From 186610c319f5d04f4f35bb3c43c536981fdfbb2b Mon Sep 17 00:00:00 2001 From: Raman Gupta Date: Tue, 3 Nov 2026 12:43:49 -0500 Subject: [PATCH 3/3] fix(diagnostics): keep the busiest-repos list to repos with events A watcher overflow rescans every repo, and those repos filled the busiest-repos list with "events=0", pushing out the one actually churning. The list now shows only repos with events of their own; the overflow already has its own counter. Shares too small to round now read "<1%" rather than "0%", and "1 worktrees" is singular. Also fixes the detekt formatting that failed CI. Co-Authored-By: Claude Signed-off-by: Raman Gupta --- .../kotlin/com/gitvantage/app/AppState.kt | 2 +- .../com/gitvantage/app/StallWatchdog.kt | 8 ++++++- .../kotlin/com/gitvantage/model/WatchStats.kt | 19 ++++++++++++++--- .../com/gitvantage/app/DiagnosticsTest.kt | 6 ++++-- .../com/gitvantage/model/WatchStatsTest.kt | 21 +++++++++++++++++++ 5 files changed, 49 insertions(+), 7 deletions(-) diff --git a/src/main/kotlin/com/gitvantage/app/AppState.kt b/src/main/kotlin/com/gitvantage/app/AppState.kt index 3a3f8d7..3441f29 100644 --- a/src/main/kotlin/com/gitvantage/app/AppState.kt +++ b/src/main/kotlin/com/gitvantage/app/AppState.kt @@ -688,7 +688,7 @@ class AppState(private val scope: CoroutineScope) { private fun diagLabel(id: String): String { val n = order.indexOf(id) + 1 val trees = repos.firstOrNull { it.id == id }?.worktrees?.size ?: 0 - return if (n > 0) "repo #$n ($trees worktrees)" else "(untracked repo)" + return if (n > 0) "repo #$n ($trees ${if (trees == 1) "worktree" else "worktrees"})" else "(untracked repo)" } /** diff --git a/src/main/kotlin/com/gitvantage/app/StallWatchdog.kt b/src/main/kotlin/com/gitvantage/app/StallWatchdog.kt index c958550..9dd7221 100644 --- a/src/main/kotlin/com/gitvantage/app/StallWatchdog.kt +++ b/src/main/kotlin/com/gitvantage/app/StallWatchdog.kt @@ -75,7 +75,13 @@ object StallWatchdog { * these subtract to "during the stall". Each figure is a suspect: `git` starts (a `fork()` apiece, which on macOS holds * locks the UI thread needs), scans, and collections, which pause every thread. */ - private data class Moment(val gitStarted: Long, val gitRunning: Int, val scans: Int, val gcCount: Long, val gcMillis: Long) { + private data class Moment( + val gitStarted: Long, + val gitRunning: Int, + val scans: Int, + val gcCount: Long, + val gcMillis: Long, + ) { companion object { fun now(): Moment { val gc = runCatching { ManagementFactory.getGarbageCollectorMXBeans() }.getOrDefault(emptyList()) diff --git a/src/main/kotlin/com/gitvantage/model/WatchStats.kt b/src/main/kotlin/com/gitvantage/model/WatchStats.kt index e5464bc..fc5430e 100644 --- a/src/main/kotlin/com/gitvantage/model/WatchStats.kt +++ b/src/main/kotlin/com/gitvantage/model/WatchStats.kt @@ -78,9 +78,16 @@ object WatchStats { * The busiest [top] repos by events, one line each, labelled by [label] — which is how the caller * keeps paths out of the report. Each lists its rescans and where its events came from, the * biggest share first. + * + * Only repos that had events of their own. A watcher overflow rescans every repo, and those + * rescans would otherwise fill the list with repos nothing happened in, pushing out the one that + * is churning — the overflow is already its own counter, `watch.overflow`. */ fun report(top: Int = 5, label: (String) -> String): List { - val busiest = byRepo.entries.sortedByDescending { it.value.events.get() }.take(top) + val busiest = byRepo.entries + .filter { it.value.events.get() > 0 } + .sortedByDescending { it.value.events.get() } + .take(top) if (busiest.isEmpty()) return emptyList() return listOf(" busiest watched repos (events · rescans · where the events were)") + busiest.map { (repo, s) -> @@ -88,10 +95,16 @@ object WatchStats { val folders = s.folders.entries .sortedByDescending { it.value.get() } .take(5) - .joinToString(" · ") { (f, n) -> "$f ${n.get() * 100 / events.coerceAtLeast(1)}%" } - " %-26s events=%-7d rescans=%-5d %s".format(label(repo), events, s.rescans.get(), folders) + .joinToString(" · ") { (f, n) -> "$f ${share(n.get(), events)}" } + " %-26s events=%-7d rescans=%-5d %s".format(label(repo), events, s.rescans.get(), folders).trimEnd() } } + /** [n] of [total] as a whole percentage, "<1%" for a share too small to round to one. */ + internal fun share(n: Long, total: Long): String { + val pct = n * 100 / total.coerceAtLeast(1) + return if (pct == 0L && n > 0) "<1%" else "$pct%" + } + fun reset() = byRepo.clear() } diff --git a/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt b/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt index a9de66b..61bbc3a 100644 --- a/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt +++ b/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt @@ -60,7 +60,8 @@ val DiagnosticsFigures by testSuite { frame("java.lang.ProcessImpl", "forkAndExec"), frame("com.gitvantage.git.Git", "spawnNow"), ) - val parked = listOf(frame("jdk.internal.misc.Unsafe", "park"), frame("java.util.concurrent.locks.LockSupport", "park")) + val parked = + listOf(frame("jdk.internal.misc.Unsafe", "park"), frame("java.util.concurrent.locks.LockSupport", "park")) test("identical stacks are folded into one entry with a count, the most common first") { val threads = (1..5).map { ThreadSummary.Snap("DefaultDispatcher-worker-$it", Thread.State.RUNNABLE, forking) } + @@ -74,7 +75,8 @@ val DiagnosticsFigures by testSuite { } test("idle pool threads are counted, not printed, but app threads waiting on git are kept") { - val waitingOnGit = listOf(frame("java.lang.ProcessImpl", "waitFor"), frame("com.gitvantage.git.Git", "spawnNow")) + val waitingOnGit = + listOf(frame("java.lang.ProcessImpl", "waitFor"), frame("com.gitvantage.git.Git", "spawnNow")) val threads = listOf( ThreadSummary.Snap("DefaultDispatcher-worker-1", Thread.State.TIMED_WAITING, parked), ThreadSummary.Snap("DefaultDispatcher-worker-2", Thread.State.WAITING, waitingOnGit), diff --git a/src/test/kotlin/com/gitvantage/model/WatchStatsTest.kt b/src/test/kotlin/com/gitvantage/model/WatchStatsTest.kt index f19dd02..ac74662 100644 --- a/src/test/kotlin/com/gitvantage/model/WatchStatsTest.kt +++ b/src/test/kotlin/com/gitvantage/model/WatchStatsTest.kt @@ -50,6 +50,27 @@ val WatchStatistics by testSuite { } } + test("repos rescanned without events of their own stay out of the list") { + WatchStats.reset() + Perf.enable(true) + try { + // What a watcher overflow leaves: every repo rescanned, one with real events. + (1..6).forEach { WatchStats.rescan("/r$it") } + WatchStats.event("/r6", "build/") + val lines = WatchStats.report { it.removePrefix("/") } + assert(lines.size == 2 && lines[1].trim().startsWith("r6")) { "got $lines" } + } finally { + Perf.enable(false) + WatchStats.reset() + } + } + + test("a share too small to round to a percent reads as under one") { + assert(WatchStats.share(1, 994) == "<1%") + assert(WatchStats.share(0, 994) == "0%") + assert(WatchStats.share(990, 994) == "99%") + } + test("nothing is recorded while collection is off") { WatchStats.reset() Perf.enable(false)