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..6999545 --- /dev/null +++ b/src/main/kotlin/com/gitvantage/app/AllocationMeter.kt @@ -0,0 +1,137 @@ +// 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() + + /** 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. + */ + 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)" + 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) + 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 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() { + val b = bean ?: return + 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. */ + @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..3441f29 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 ${if (trees == 1) "worktree" else "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,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 { + // 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") @@ -1411,8 +1444,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"), ) } @@ -1427,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)) @@ -1442,7 +1482,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..9dd7221 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,35 @@ 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 +156,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 +174,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 +217,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..fc5430e --- /dev/null +++ b/src/main/kotlin/com/gitvantage/model/WatchStats.kt @@ -0,0 +1,110 @@ +// 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. + * + * 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 + .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) -> + val events = s.events.get() + val folders = s.folders.entries + .sortedByDescending { it.value.get() } + .take(5) + .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 new file mode 100644 index 0000000..61bbc3a --- /dev/null +++ b/src/test/kotlin/com/gitvantage/app/DiagnosticsTest.kt @@ -0,0 +1,106 @@ +// 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.start() + 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.start() + 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..ac74662 --- /dev/null +++ b/src/test/kotlin/com/gitvantage/model/WatchStatsTest.kt @@ -0,0 +1,82 @@ +// 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("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) + if (!Perf.forcedOn) { + WatchStats.event("/r", "build/") + assert(WatchStats.report { it }.isEmpty()) + } + } +}