diff --git a/app/src/main/java/com/itsaky/androidide/activities/editor/ProjectHandlerActivity.kt b/app/src/main/java/com/itsaky/androidide/activities/editor/ProjectHandlerActivity.kt index 93713a0063..58fd833fc8 100644 --- a/app/src/main/java/com/itsaky/androidide/activities/editor/ProjectHandlerActivity.kt +++ b/app/src/main/java/com/itsaky/androidide/activities/editor/ProjectHandlerActivity.kt @@ -64,6 +64,7 @@ import com.itsaky.androidide.lookup.Lookup import com.itsaky.androidide.lsp.IDELanguageClientImpl import com.itsaky.androidide.lsp.debug.DebugClientConnectionResult import com.itsaky.androidide.lsp.java.utils.CancelChecker +import com.itsaky.androidide.memprof.Memprof import com.itsaky.androidide.models.EditorIntentExtras import com.itsaky.androidide.models.Position import com.itsaky.androidide.models.Range @@ -1622,9 +1623,26 @@ abstract class ProjectHandlerActivity : } protected open fun onProjectInitialized(result: InitializeResult.Success) { + Memprof.mark("sync_complete") editorActivityScope.launch(Dispatchers.IO) { val manager = ProjectManagerImpl.getInstance() - val gradleBuildResult = ProjectSyncHelper.readGradleBuild(result.cacheFile) + val gradleBuildResult = + Memprof.phase("Parse project model", "cache_parsed") { span -> + val startMs = if (span.isRecording) System.currentTimeMillis() else 0L + val parsed = ProjectSyncHelper.readGradleBuild(result.cacheFile) + if (span.isRecording) { + span.put("bytes", result.cacheFile.length()) + span.put("durationMs", System.currentTimeMillis() - startMs) + if (parsed.isFailure) { + span.put("failed", 1) + } + } + // readGradleBuild returns its failure rather than throwing, so the phase would end as finished. + if (parsed.isFailure) { + span.abandon() + } + parsed + } if (gradleBuildResult.isFailure) { val error = gradleBuildResult.exceptionOrNull() log.error("Failed to read project cache", error) diff --git a/app/src/profileable/AndroidManifest.xml b/app/src/profileable/AndroidManifest.xml new file mode 100644 index 0000000000..bfc9f18ce1 --- /dev/null +++ b/app/src/profileable/AndroidManifest.xml @@ -0,0 +1,30 @@ + + + + + + + + + + + + + + + + + diff --git a/app/src/profileable/java/com/itsaky/androidide/memprof/AllocationSampler.kt b/app/src/profileable/java/com/itsaky/androidide/memprof/AllocationSampler.kt new file mode 100644 index 0000000000..4e43902a04 --- /dev/null +++ b/app/src/profileable/java/com/itsaky/androidide/memprof/AllocationSampler.kt @@ -0,0 +1,174 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import android.os.Debug +import org.slf4j.LoggerFactory +import java.io.File +import java.util.concurrent.atomic.AtomicBoolean + +/** + * Samples ART's cumulative allocation counters to logcat on a fixed interval. + * + * Unlike `dumpsys meminfo`, which forces a full GC on every call and so erases the transient + * garbage a peak-heap investigation exists to measure, every counter read here is free of any GC + * side effect. `art.gc.bytes-allocated` is monotonic for the life of the process, so the difference + * between two samples is exactly what was allocated between them. + */ +object AllocationSampler { + private val logger = LoggerFactory.getLogger(AllocationSampler::class.java) + + /** Fine enough to separate a completion request from its neighbours, cheap enough to leave on. */ + const val DEFAULT_INTERVAL_MS = 250L + + private val running = AtomicBoolean(false) + private val dumped = AtomicBoolean(false) + + @Volatile + private var worker: Thread? = null + + /** + * Heap-in-use fraction at which a one-shot hprof is written, or 0 to never write one. + * + * Deliberately short of the ceiling: `dumpHprofData` needs to allocate, and a dump started with + * a few MB of headroom left dies of the OOM it was meant to explain. + */ + @Volatile + var dumpAtFraction: Double = 0.0 + + /** + * Directory the hprof is written to, set from the app context at startup. + * + * It has to be a directory this uid owns: `/data/local/tmp` belongs to shell, and a dump aimed + * there fails with `Permission denied` only once the heap is already at the threshold. + */ + @Volatile + var dumpDir: String = "/data/local/tmp" + + /** Called on the sampler thread with the heap in use after every tick. */ + @Volatile + var onTick: ((usedBytes: Long) -> Unit)? = null + + /** Starts sampling every [intervalMs] milliseconds. A second call while running is ignored. */ + @JvmOverloads + fun start(intervalMs: Long = DEFAULT_INTERVAL_MS) { + if (!running.compareAndSet(false, true)) { + logger.info("MEMPROF|sampler|{}|state=already_running", System.currentTimeMillis()) + return + } + + val thread = Thread({ loop(intervalMs) }, "memprof-alloc-sampler") + thread.isDaemon = true + thread.priority = Thread.MAX_PRIORITY + worker = thread + thread.start() + logger.info("MEMPROF|sampler|{}|state=started|intervalMs={}", System.currentTimeMillis(), intervalMs) + } + + /** Stops sampling. Safe to call when not running. */ + fun stop() { + if (!running.compareAndSet(true, false)) { + return + } + worker?.interrupt() + worker = null + logger.info("MEMPROF|sampler|{}|state=stopped", System.currentTimeMillis()) + } + + /** Emits one sample immediately, tagged with [reason]. */ + fun sampleNow(reason: String) { + logger.info(sample(reason, RuntimeHeapCounters.read())) + } + + /** Emits a named marker plus a sample, so a phase boundary and its counters share a timestamp. */ + fun mark(name: String) { + logger.info("MEMPROF|mark|{}|name={}", System.currentTimeMillis(), name) + sampleNow(name) + } + + private fun loop(intervalMs: Long) { + while (running.get()) { + val counters = RuntimeHeapCounters.read() + // DEBUG, not INFO: profileable inherits release's Sentry setup, which turns an INFO + // line into a breadcrumb, and this fires up to 4 times a second. + logger.debug(sample("tick", counters)) + onTick?.invoke(counters.usedBytes) + dumpIfAboveThreshold() + try { + Thread.sleep(intervalMs) + } catch (interrupted: InterruptedException) { + Thread.currentThread().interrupt() + return + } + } + } + + /** + * Writes one hprof the first time heap in use crosses [dumpAtFraction] of the growth limit. + * + * A dump taken here shows what is live while the heap is near its peak, which is the state a + * dump taken at idle cannot reach. + */ + private fun dumpIfAboveThreshold() { + val threshold = dumpAtFraction + if (threshold <= 0.0 || dumped.get()) { + return + } + + val runtime = Runtime.getRuntime() + val used = runtime.totalMemory() - runtime.freeMemory() + if (used.toDouble() / runtime.maxMemory() < threshold) { + return + } + + if (!dumped.compareAndSet(false, true)) { + return + } + + val path = "$dumpDir/memprof-peak-${System.currentTimeMillis()}.hprof" + logger.info("MEMPROF|hprof_start|{}|path={}|usedMb={}", System.currentTimeMillis(), path, used shr 20) + runCatching { Debug.dumpHprofData(path) } + .onSuccess { + logger.info("MEMPROF|hprof|{}|path={}|bytes={}", System.currentTimeMillis(), path, File(path).length()) + }.onFailure { failure -> + logger.error("MEMPROF|hprof_failed|{}|path={}", System.currentTimeMillis(), path, failure) + } + } + + /** The `MEMPROF|sample|` line for one already-read [counters], so a caller reads ART's counters only once. */ + private fun sample( + reason: String, + counters: HeapCounters, + ): String { + val runtime = Runtime.getRuntime() + return buildString { + append("MEMPROF|sample|").append(System.currentTimeMillis()) + append("|reason=").append(reason) + append("|alloc=").append(counters.allocatedBytes) + append("|freed=").append(counters.freedBytes) + append("|gcCount=").append(stat("art.gc.gc-count")) + append("|blockingGcCount=").append(counters.blockingGcCount) + append("|gcTime=").append(stat("art.gc.gc-time")) + append("|used=").append(counters.usedBytes) + append("|total=").append(runtime.totalMemory()) + append("|max=").append(runtime.maxMemory()) + } + } + + private fun stat(key: String): Long = Debug.getRuntimeStat(key)?.toLongOrNull() ?: -1L +} diff --git a/app/src/profileable/java/com/itsaky/androidide/memprof/AsyncTraceSection.kt b/app/src/profileable/java/com/itsaky/androidide/memprof/AsyncTraceSection.kt new file mode 100644 index 0000000000..f072c4e193 --- /dev/null +++ b/app/src/profileable/java/com/itsaky/androidide/memprof/AsyncTraceSection.kt @@ -0,0 +1,54 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import android.os.Build +import android.os.Trace +import java.util.concurrent.atomic.AtomicInteger + +/** + * A slice on the Perfetto timeline, which may start and end on different threads. + * + * Each instance carries its own cookie, so overlapping slices with the same name still pair up. + * Async slices need API 29; below that this records nothing. + */ +internal class AsyncTraceSection( + name: String, +) { + private val name = name.take(MAX_NAME_LENGTH) + private val cookie = cookies.incrementAndGet() + + init { + if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.Q) { + Trace.beginAsyncSection(this.name, cookie) + } + } + + fun end() { + if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.Q) { + Trace.endAsyncSection(name, cookie) + } + } + + private companion object { + /** Keeps names within the 127-char limit atrace section names use. */ + const val MAX_NAME_LENGTH = 127 + + val cookies = AtomicInteger() + } +} diff --git a/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofInitProvider.kt b/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofInitProvider.kt new file mode 100644 index 0000000000..786fa94b7c --- /dev/null +++ b/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofInitProvider.kt @@ -0,0 +1,64 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import android.content.ContentProvider +import android.content.ContentValues +import android.database.Cursor +import android.net.Uri + +/** + * Starts the profileable variant's measurement as the process comes up. + * + * A content provider is created before `Application.onCreate`, the earliest hook available without + * editing shared sources, and cold-start allocation is part of what the measurement is for. + */ +class MemprofInitProvider : ContentProvider() { + override fun onCreate(): Boolean { + context?.applicationContext?.let(MemprofSession::install) + return true + } + + override fun query( + uri: Uri, + projection: Array?, + selection: String?, + selectionArgs: Array?, + sortOrder: String?, + ): Cursor? = null + + override fun getType(uri: Uri): String? = null + + override fun insert( + uri: Uri, + values: ContentValues?, + ): Uri? = null + + override fun delete( + uri: Uri, + selection: String?, + selectionArgs: Array?, + ): Int = 0 + + override fun update( + uri: Uri, + values: ContentValues?, + selection: String?, + selectionArgs: Array?, + ): Int = 0 +} diff --git a/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofReceiver.kt b/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofReceiver.kt new file mode 100644 index 0000000000..c8c5520f60 --- /dev/null +++ b/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofReceiver.kt @@ -0,0 +1,245 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import android.content.BroadcastReceiver +import android.content.Context +import android.content.Intent +import android.os.Debug +import com.itsaky.androidide.lsp.api.ILanguageServerRegistry +import com.itsaky.androidide.lsp.java.JavaLanguageServer +import com.itsaky.androidide.lsp.kotlin.KotlinLanguageServer +import com.itsaky.androidide.lsp.models.CompletionParams +import com.itsaky.androidide.lsp.xml.XMLLanguageServer +import com.itsaky.androidide.models.Position +import com.itsaky.androidide.progress.ICancelChecker +import org.slf4j.LoggerFactory +import java.io.File +import java.util.concurrent.Executors + +/** + * Drives a memory measurement from the shell, so a workload runs the same way every time. + * + * Declared only in the `profileable` variant and **not exported**: `am broadcast` still reaches it + * because ActivityManager skips the component export check for root, which the measurement harness + * already runs as. That keeps the surface closed on any build a user could install. + * + * ``` + * su 0 am broadcast -n com.itsaky.androidide/com.itsaky.androidide.memprof.MemprofReceiver \ + * -a com.itsaky.androidide.memprof.CMD --es op mark --es name pre_completion + * su 0 am broadcast -n com.itsaky.androidide/com.itsaky.androidide.memprof.MemprofReceiver \ + * -a com.itsaky.androidide.memprof.CMD --es op report + * su 0 am broadcast -n com.itsaky.androidide/com.itsaky.androidide.memprof.MemprofReceiver \ + * -a com.itsaky.androidide.memprof.CMD --es op completion \ + * --es file /storage/emulated/0/.../Foo.kt --ei line 42 --ei column 8 --ei repeat 5 + * ``` + */ +class MemprofReceiver : BroadcastReceiver() { + override fun onReceive( + context: Context, + intent: Intent, + ) { + val op = intent.getStringExtra(EXTRA_OP) + if (op == null) { + logger.warn("MEMPROF|error|{}|reason=missing_op", System.currentTimeMillis()) + return + } + + // onReceive runs on the main thread and every op here does disk or compiler work. + val pending = goAsync() + worker.execute { + try { + dispatch(op, intent) + } catch (failure: Throwable) { + logger.error("MEMPROF|error|{}|op={}", System.currentTimeMillis(), op, failure) + } + } + // Nothing reads the broadcast result, and holding it through an hprof dump or repeated + // completions risks a background-broadcast ANR; finish as soon as the work is handed off. + pending.finish() + } + + private fun dispatch( + op: String, + intent: Intent, + ) { + when (op) { + "mark" -> { + AllocationSampler.mark(intent.getStringExtra("name") ?: "unnamed") + } + + "sampler" -> { + when (intent.getStringExtra("state")) { + "stop" -> { + AllocationSampler.stop() + } + + else -> { + AllocationSampler.start( + intent.getLongExtra("intervalMs", AllocationSampler.DEFAULT_INTERVAL_MS), + ) + } + } + } + + "hprof" -> { + dumpHprof(intent.getStringExtra("path")) + } + + "report" -> { + MemprofSession.writer?.apply { + write() + log() + } + } + + "dumpat" -> { + val fraction = intent.getFloatExtra("fraction", 0.85f).toDouble() + AllocationSampler.dumpAtFraction = fraction + logger.info("MEMPROF|dumpat|{}|fraction={}", System.currentTimeMillis(), fraction) + } + + "completion" -> { + complete( + file = intent.getStringExtra("file") ?: error("completion needs --es file"), + line = intent.getIntExtra("line", -1), + column = intent.getIntExtra("column", -1), + repeat = intent.getIntExtra("repeat", 1), + ) + } + + else -> { + logger.warn("MEMPROF|error|{}|reason=unknown_op|op={}", System.currentTimeMillis(), op) + } + } + } + + private fun dumpHprof(path: String?) { + val target = path ?: "${AllocationSampler.dumpDir}/memprof-${System.currentTimeMillis()}.hprof" + AllocationSampler.sampleNow("pre_hprof") + val started = System.currentTimeMillis() + Debug.dumpHprofData(target) + logger.info( + "MEMPROF|hprof|{}|path={}|durationMs={}|bytes={}", + System.currentTimeMillis(), + target, + System.currentTimeMillis() - started, + File(target).length(), + ) + AllocationSampler.sampleNow("post_hprof") + } + + private fun complete( + file: String, + line: Int, + column: Int, + repeat: Int, + ) { + val source = File(file) + if (!source.isFile) { + logger.warn("MEMPROF|error|{}|reason=no_such_file|file={}", System.currentTimeMillis(), file) + return + } + + val serverId = serverIdFor(source) + if (serverId == null) { + logger.warn("MEMPROF|error|{}|reason=no_server_for|file={}", System.currentTimeMillis(), file) + return + } + + val server = ILanguageServerRegistry.default.getServer(serverId) + if (server == null) { + logger.warn("MEMPROF|error|{}|reason=server_absent|server={}", System.currentTimeMillis(), serverId) + return + } + + val text = source.readText() + val index = offsetOf(text, line, column) + val prefix = prefixAt(text, index) + + repeat(repeat) { iteration -> + val params = CompletionParams(Position(line, column, index), source.toPath(), ICancelChecker.Default()) + params.content = text + params.prefix = prefix + + AllocationSampler.sampleNow("pre_completion_$iteration") + val started = System.currentTimeMillis() + val result = server.complete(params) + val elapsed = System.currentTimeMillis() - started + AllocationSampler.sampleNow("post_completion_$iteration") + + logger.info( + "MEMPROF|completion|{}|server={}|iteration={}|prefix={}|items={}|incomplete={}|durationMs={}", + System.currentTimeMillis(), + serverId, + iteration, + prefix, + result.items.size, + result.isIncomplete, + elapsed, + ) + } + } + + private fun serverIdFor(file: File): String? = + when (file.extension) { + "kt", "kts" -> KotlinLanguageServer.SERVER_ID + "java" -> JavaLanguageServer.SERVER_ID + "xml" -> XMLLanguageServer.SERVER_ID + else -> null + } + + /** Character offset of a zero-based (line, column), clamped to the end of the text. */ + private fun offsetOf( + text: String, + line: Int, + column: Int, + ): Int { + var offset = 0 + var seen = 0 + while (seen < line && offset < text.length) { + if (text[offset] == '\n') { + seen++ + } + offset++ + } + return (offset + column).coerceIn(0, text.length) + } + + /** The identifier immediately left of [index], which is what a completion request is keyed on. */ + private fun prefixAt( + text: String, + index: Int, + ): String { + var start = index + while (start > 0 && Character.isJavaIdentifierPart(text[start - 1])) { + start-- + } + return text.substring(start, index) + } + + companion object { + private val logger = LoggerFactory.getLogger(MemprofReceiver::class.java) + private val worker = + Executors.newSingleThreadExecutor { runnable -> + Thread(runnable, "memprof-receiver").apply { isDaemon = true } + } + + private const val EXTRA_OP = "op" + } +} diff --git a/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofReportWriter.kt b/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofReportWriter.kt new file mode 100644 index 0000000000..90b1d4b295 --- /dev/null +++ b/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofReportWriter.kt @@ -0,0 +1,92 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import org.slf4j.LoggerFactory +import java.io.File +import java.util.concurrent.Executors +import java.util.concurrent.atomic.AtomicBoolean + +/** + * Keeps the report file current and prints the report to logcat when asked. + * + * The file is rewritten in full on every write, through a temporary file and a rename, so a process + * that dies mid-write leaves the previous complete report rather than a torn one. All file I/O runs + * on one background thread, so callers on any thread, the main thread included, never block on it. + */ +internal class MemprofReportWriter( + private val report: MemprofReport, + private val file: () -> File, +) { + private val dirty = AtomicBoolean(false) + + @Volatile + private var lastWriteMs = 0L + + /** Marks the report as changed, to be written by the next [writeIfDirty]. */ + fun markDirty() { + dirty.set(true) + } + + /** + * Writes the report now. + * + * Rendering happens on the io thread, not the caller's, so that two threads writing back to + * back queue in the order they render: rendering on the caller's thread let two callers queue + * in the opposite order they rendered, so an older report could land as the final file. + */ + fun write() { + dirty.set(false) + io.execute { writeFile(render()) } + } + + /** Writes the report if it changed and the last write is at least [minIntervalMs] old. */ + fun writeIfDirty(minIntervalMs: Long) { + if (System.currentTimeMillis() - lastWriteMs >= minIntervalMs && dirty.get()) { + write() + } + } + + /** Prints the report to logcat, one line per log entry, so a reader sees the table intact. */ + fun log() { + // DEBUG, not INFO: an INFO line becomes a Sentry breadcrumb, and the report is dozens of lines. + render().lineSequence().forEach { line -> logger.debug("MEMPROF|report| {}", line) } + } + + private fun render(): String = report.render(System.currentTimeMillis(), RuntimeHeapCounters.read()) + + private fun writeFile(text: String) { + lastWriteMs = System.currentTimeMillis() + runCatching { + // file() creates the report directory; this is the only place that does. + val target = file() + val temporary = File(target.parentFile, target.name + ".tmp") + temporary.writeText(text) + check(temporary.renameTo(target)) { "rename to $target failed" } + }.onFailure { failure -> logger.error("MEMPROF|report_write_failed|{}", lastWriteMs, failure) } + } + + private companion object { + val logger = LoggerFactory.getLogger(MemprofReportWriter::class.java) + + val io = + Executors.newSingleThreadExecutor { runnable -> + Thread(runnable, "memprof-report").apply { isDaemon = true } + } + } +} diff --git a/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofSession.kt b/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofSession.kt new file mode 100644 index 0000000000..89a8255dfa --- /dev/null +++ b/app/src/profileable/java/com/itsaky/androidide/memprof/MemprofSession.kt @@ -0,0 +1,78 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import android.content.Context +import android.os.Process +import android.os.SystemClock +import java.io.File +import java.text.SimpleDateFormat +import java.util.Date +import java.util.Locale +import kotlin.concurrent.thread + +/** Wires the profileable variant's measurement together, once per process. */ +internal object MemprofSession { + /** Often enough that a report pulled mid-open is current, rarely enough to cost nothing. */ + private const val REPORT_INTERVAL_MS = 2_000L + + @Volatile + var writer: MemprofReportWriter? = null + private set + + /** + * Installs the [Memprof] sink and starts the allocation sampler. + * + * Safe on the main thread: resolving the files directory touches the disk, so it happens on a + * background thread, and the report writer does its own I/O on its own thread. + */ + fun install(context: Context) { + val processStartMs = processStartEpochMs() + val report = MemprofReport(processStartMs, Runtime.getRuntime().maxMemory()) + val startStamp = SimpleDateFormat("yyyyMMdd-HHmmss", Locale.US).format(Date(processStartMs)) + val reportName = "report-$startStamp.txt" + val reportWriter = MemprofReportWriter(report) { File(memprofDir(context), reportName) } + + writer = reportWriter + Memprof.sink = ProfileableMemprofSink(report, reportWriter) + AllocationSampler.onTick = { usedBytes -> + report.sampled(usedBytes) + /* + * An open phase's time, allocation and peak change with every tick, so the file must be + * rewritten while it runs: a phase that ends no sections would otherwise leave the file as + * it was when the phase began, which is all an OOM during that phase leaves behind. + */ + if (report.hasOpenPhases) { + reportWriter.markDirty() + } + reportWriter.writeIfDirty(REPORT_INTERVAL_MS) + } + AllocationSampler.start() + + thread(name = "memprof-init", isDaemon = true) { + AllocationSampler.dumpDir = memprofDir(context).absolutePath + } + } + + private fun memprofDir(context: Context): File = File(context.filesDir, "memprof").apply { mkdirs() } + + private fun processStartEpochMs(): Long { + val uptimeMs = SystemClock.elapsedRealtime() - Process.getStartElapsedRealtime() + return System.currentTimeMillis() - uptimeMs + } +} diff --git a/app/src/profileable/java/com/itsaky/androidide/memprof/ProfileableMemprofSink.kt b/app/src/profileable/java/com/itsaky/androidide/memprof/ProfileableMemprofSink.kt new file mode 100644 index 0000000000..4d54d99a22 --- /dev/null +++ b/app/src/profileable/java/com/itsaky/androidide/memprof/ProfileableMemprofSink.kt @@ -0,0 +1,196 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import org.slf4j.LoggerFactory +import java.util.Collections +import java.util.concurrent.atomic.AtomicBoolean + +/** + * Sends [Memprof] events to three places, one per audience. + * + * - Perfetto: every phase and section is an async slice, so a recorded trace shows the open as a + * labelled timeline beside the GC and allocation tracks. + * - The [MemprofReport]: a plain-text summary, kept current on disk and printed to logcat whenever + * the last open phase ends. + * - Machine lines in logcat: `PHASE|||k=v...` as the memprof harness scripts parse + * them, plus `MEMPROF|file|...` per section instance. See [MemprofLines] for the exact shapes. + */ +internal class ProfileableMemprofSink( + private val report: MemprofReport, + private val writer: MemprofReportWriter, +) : MemprofSink { + override fun beginPhase( + title: String, + marker: String, + ): MemprofSpan = + guarded("beginPhase", marker) { + val start = Start.now() + val phase = report.phaseStarted(title, start.epochMs, start.counters) + logger.info("MEMPROF|phase_begin|{}|marker={}|title={}", start.epochMs, marker, title) + writer.write() + PhaseSpan(marker, phase, start, AsyncTraceSection(title)) + } + + override fun beginSection( + name: String, + detail: String?, + ): MemprofSpan = + guarded("beginSection", name) { + val traceName = if (detail == null) name else "$name: ${detail.substringAfterLast('/')}" + SectionSpan(name, detail, Start.now(), AsyncTraceSection(traceName)) + } + + override fun mark(marker: String) { + logger.info("PHASE|{}|{}", marker, System.currentTimeMillis()) + } + + /** + * Runs [block], turning a failure into a log line and [MemprofSpan.None] instead of letting it + * reach the caller: a measurement probe must never break the product path it is measuring. + */ + private inline fun guarded( + op: String, + label: String, + block: () -> MemprofSpan, + ): MemprofSpan = + try { + block() + } catch (failure: Throwable) { + logger.error("MEMPROF|sink_failed|{}|op={}|label={}", System.currentTimeMillis(), op, label, failure) + MemprofSpan.None + } + + private class Start( + val epochMs: Long, + val counters: HeapCounters, + ) { + companion object { + fun now() = Start(System.currentTimeMillis(), RuntimeHeapCounters.read()) + } + } + + private abstract class RecordingSpan : MemprofSpan { + private val ended = AtomicBoolean(false) + + /** Insertion order, not hash order, so notes and log lines list details as they were put. */ + protected val details: MutableMap = Collections.synchronizedMap(LinkedHashMap()) + + override val isRecording: Boolean = true + + override fun put( + key: String, + value: Long, + ) { + details[key] = value + } + + /** A snapshot of [details] in insertion order, safe to read after ending. */ + protected fun detailsSnapshot(): Map = synchronized(details) { LinkedHashMap(details) } + + final override fun end() = finish(completed = true) + + final override fun abandon() = finish(completed = false) + + /** A span ending must never break the work it timed, so a failure here is logged and swallowed. */ + private fun finish(completed: Boolean) { + if (!ended.compareAndSet(false, true)) { + return + } + try { + onEnd(System.currentTimeMillis(), RuntimeHeapCounters.read(), completed) + } catch (failure: Throwable) { + logger.error("MEMPROF|sink_failed|{}|op=end|completed={}", System.currentTimeMillis(), completed, failure) + } + } + + abstract fun onEnd( + nowMs: Long, + counters: HeapCounters, + completed: Boolean, + ) + } + + private inner class PhaseSpan( + private val marker: String, + private val phase: MemprofReport.Phase, + private val start: Start, + private val trace: AsyncTraceSection, + ) : RecordingSpan() { + override fun onEnd( + nowMs: Long, + counters: HeapCounters, + completed: Boolean, + ) { + trace.end() + val putDetails = detailsSnapshot() + report.phaseEnded(phase, nowMs, counters, putDetails, completed) + logger.info( + if (completed) { + MemprofLines.phaseLine(marker, nowMs, putDetails) + } else { + MemprofLines.phaseAbandonedLine(marker, nowMs, putDetails) + }, + ) + logger.info( + MemprofLines.phaseEndLine( + marker, + nowMs, + durationMs = nowMs - start.epochMs, + allocBytes = counters.allocatedBytes - start.counters.allocatedBytes, + ), + ) + writer.write() + if (!report.hasOpenPhases) { + writer.log() + } + } + } + + private inner class SectionSpan( + private val name: String, + private val detail: String?, + private val start: Start, + private val trace: AsyncTraceSection, + ) : RecordingSpan() { + override fun onEnd( + nowMs: Long, + counters: HeapCounters, + completed: Boolean, + ) { + trace.end() + val durationMs = nowMs - start.epochMs + val allocatedBytes = counters.allocatedBytes - start.counters.allocatedBytes + if (completed) { + /* + * An abandoned (preempted, re-queued) instance is not repeated work: the file it + * touched will be indexed again and counted then, so counting it here too would + * double it in the "Repeated work" table. + */ + report.sectionEnded(name, detail, durationMs, allocatedBytes) + } + // DEBUG, not INFO: an INFO line becomes a Sentry breadcrumb, and this fires once per file. + logger.debug(MemprofLines.fileLine(nowMs, allocatedBytes, durationMs, detail, name, completed)) + writer.markDirty() + } + } + + private companion object { + val logger = LoggerFactory.getLogger(ProfileableMemprofSink::class.java) + } +} diff --git a/app/src/profileable/java/com/itsaky/androidide/memprof/RuntimeHeapCounters.kt b/app/src/profileable/java/com/itsaky/androidide/memprof/RuntimeHeapCounters.kt new file mode 100644 index 0000000000..2f9515427c --- /dev/null +++ b/app/src/profileable/java/com/itsaky/androidide/memprof/RuntimeHeapCounters.kt @@ -0,0 +1,36 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import android.os.Debug + +/** Reads [HeapCounters] from ART, with no GC side effect. */ +internal object RuntimeHeapCounters { + fun read(): HeapCounters { + val runtime = Runtime.getRuntime() + return HeapCounters( + allocatedBytes = stat("art.gc.bytes-allocated"), + freedBytes = stat("art.gc.bytes-freed"), + blockingGcCount = stat("art.gc.blocking-gc-count"), + usedBytes = runtime.totalMemory() - runtime.freeMemory(), + ) + } + + /** -1 for a stat ART does not expose, matching [AllocationSampler]'s convention for the same counters. */ + private fun stat(key: String): Long = Debug.getRuntimeStat(key)?.toLongOrNull() ?: -1L +} diff --git a/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexCommand.kt b/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexCommand.kt index 29e3d94a10..0a0612c767 100644 --- a/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexCommand.kt +++ b/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexCommand.kt @@ -4,12 +4,40 @@ import org.jetbrains.kotlin.com.intellij.openapi.vfs.VirtualFile import org.jetbrains.kotlin.psi.KtFile import java.nio.file.Path +/* + * A `pass` identifies the ScanningWorker.scan() call that sent a command, so a command left over from + * a superseded scan cannot close a newer scan's phase. It is null for a file indexed outside a scan. + */ internal sealed interface IndexCommand { data object Stop : IndexCommand - data object SourceScanningComplete: IndexCommand - data object IndexingComplete: IndexCommand - data class ScanSourceFile(val vf: VirtualFile): IndexCommand - data class IndexModifiedFile(val ktFile: KtFile): IndexCommand - data class IndexSourceFile(val vf: VirtualFile): IndexCommand - data class RemoveFromIndex(val path: Path): IndexCommand -} \ No newline at end of file + + data class SourceScanningStarted( + val pass: Int, + ) : IndexCommand + + data class SourceScanningComplete( + val pass: Int, + ) : IndexCommand + + data class IndexingComplete( + val pass: Int, + ) : IndexCommand + + data class ScanSourceFile( + val vf: VirtualFile, + ) : IndexCommand + + data class IndexModifiedFile( + val ktFile: KtFile, + ) : IndexCommand + + data class IndexSourceFile( + val vf: VirtualFile, + val pass: Int? = null, + val isRetry: Boolean = false, + ) : IndexCommand + + data class RemoveFromIndex( + val path: Path, + ) : IndexCommand +} diff --git a/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexWorker.kt b/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexWorker.kt index 6f6099b20c..58c676356b 100644 --- a/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexWorker.kt +++ b/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexWorker.kt @@ -4,6 +4,8 @@ import com.itsaky.androidide.lsp.kotlin.compiler.CompilationEnvironment import com.itsaky.androidide.lsp.kotlin.compiler.modules.AnalysisPreemptedException import com.itsaky.androidide.lsp.kotlin.compiler.modules.backingFilePath import com.itsaky.androidide.lsp.kotlin.compiler.read +import com.itsaky.androidide.memprof.Memprof +import com.itsaky.androidide.memprof.MemprofSpan import com.itsaky.androidide.progress.ICancelChecker import com.itsaky.androidide.utils.KeyedDebouncingAction import kotlinx.coroutines.CoroutineScope @@ -56,8 +58,8 @@ internal class IndexWorker( ) { (path, ktFile), cancelChecker -> logger.debug("Indexing modified file: {}", path) try { + // Not counted in sourceIndexCount: this runs on another coroutine, and an edit is not part of a pass. indexSourceFile(project, ktFile, fileIndex, sourceIndex, cancelChecker) - sourceIndexCount++ } catch (e: AnalysisPreemptedException) { // Preempted by higher-priority analysis; re-queue so the edit still gets indexed. logger.debug("Indexing of modified file {} preempted; re-queueing", path) @@ -65,112 +67,226 @@ internal class IndexWorker( } } - while (isActive) { - // Defensive guard: if the project was disposed out from under us (e.g. a disposal - // path that didn't first drain this worker), stop instead of calling PsiManager on a - // disposed project, which throws "Project is already disposed" (APPDEVFORALL-17R). - if (project.isDisposed) break - - when (val cmd = queue.take()) { - is IndexCommand.RemoveFromIndex -> { - applyRemovals( - first = cmd, - fileIndex = fileIndex, - sourceIndex = sourceIndex, - pollNext = { queue.pollIndexQueue() }, - pushBack = { queue.pushBackIndexQueue(it) }, - ) - } + var scanPhase: MemprofSpan? = null + var indexPhase: MemprofSpan? = null + + /* + * The counters run for as long as start() does, which spans every scan a build or sync + * restarts, so each phase reports what happened since it began. + */ + var scannedAtScanBegin = 0 + var scannedAtIndexBegin = 0 + var indexedAtIndexBegin = 0 + + fun beginScan(): MemprofSpan { + scannedAtScanBegin = scanCount + return beginScanPhase() + } + + fun beginIndex(): MemprofSpan { + scannedAtIndexBegin = scannedAtScanBegin + indexedAtIndexBegin = sourceIndexCount + return beginIndexPhase() + } + + /* + * The scan pass whose phases are open. A preempted file of that pass is re-queued behind + * the pass's IndexingComplete, so the index phase ends only once that has arrived and + * every retry has run. + */ + var currentPass: Int? = null + var pendingRetries = 0 + var indexingCompleteReceived = false + + fun endIndexPhaseIfDrained() { + if (!indexingCompleteReceived || pendingRetries > 0) return + indexPhase?.apply { + put("scanned", (scanCount - scannedAtIndexBegin).toLong()) + put("indexed", (sourceIndexCount - indexedAtIndexBegin).toLong()) + end() + } + indexPhase = null + currentPass = null + } + + try { + while (isActive) { + // Defensive guard: if the project was disposed out from under us (e.g. a disposal + // path that didn't first drain this worker), stop instead of calling PsiManager on a + // disposed project, which throws "Project is already disposed" (APPDEVFORALL-17R). + if (project.isDisposed) break - is IndexCommand.IndexSourceFile -> { - if (cmd.vf.fileSystem.protocol != "file") { - logger.warn("Unknown source file protocol: {}", cmd.vf.path) - continue + when (val cmd = queue.take()) { + is IndexCommand.RemoveFromIndex -> { + applyRemovals( + first = cmd, + fileIndex = fileIndex, + sourceIndex = sourceIndex, + pollNext = { queue.pollIndexQueue() }, + pushBack = { queue.pushBackIndexQueue(it) }, + ) } - if (project.isDisposed) break + is IndexCommand.IndexSourceFile -> { + if (project.isDisposed) break + + val inCurrentPass = cmd.pass != null && cmd.pass == currentPass + if (cmd.isRetry && inCurrentPass) pendingRetries-- + + when (indexFile(cmd)) { + IndexOutcome.INDEXED -> { + sourceIndexCount++ + } + + IndexOutcome.SKIPPED -> { + Unit + } - val ktFile = - project.read { - PsiManager - .getInstance(project) - .findFile(cmd.vf) as? KtFile + IndexOutcome.PREEMPTED -> { + // Preempted by higher-priority analysis; re-queue so the file still gets indexed. + logger.debug("Indexing of {} preempted; re-queueing", cmd.vf.path) + if (inCurrentPass) pendingRetries++ + scope.launch { submitCommand(cmd.copy(isRetry = true)) } + } } - if (ktFile == null) { - // probably a non-kotlin file - continue + if (inCurrentPass) endIndexPhaseIfDrained() } - try { - indexSourceFile( - project = project, - ktFile = ktFile, - fileIndex = fileIndex, - symbolsIndex = sourceIndex, - // A real (cancellable) checker so the scheduler can preempt this pass - // in favour of completion/diagnostics. - cancelChecker = ICancelChecker.Default(), + is IndexCommand.IndexModifiedFile -> { + modifiedFileIndexer.schedule( + ModFileIndexKey( + cmd.ktFile.backingFilePath!!, + cmd.ktFile, + ), ) + } - sourceIndexCount++ - } catch (e: AnalysisPreemptedException) { - // Preempted by higher-priority analysis; re-queue so the file still gets indexed. - logger.debug("Indexing of {} preempted; re-queueing", cmd.vf.path) - scope.launch { submitCommand(cmd) } + is IndexCommand.IndexingComplete -> { + logger.info( + "Indexing complete: scanned={}, sourceIndexCount={}", + scanCount, + sourceIndexCount, + ) + // A superseded pass's completion must not end the current pass's phase. + if (cmd.pass == currentPass) { + indexingCompleteReceived = true + endIndexPhaseIfDrained() + } } - } - is IndexCommand.IndexModifiedFile -> { - modifiedFileIndexer.schedule( - ModFileIndexKey( - cmd.ktFile.backingFilePath!!, - cmd.ktFile, - ), - ) - } + is IndexCommand.SourceScanningStarted -> { + /* + * A scan can be cancelled before it completes (e.g. KtSymbolIndex.refreshSources() + * restarting it), leaving its phases stale and open; a fresh scan starting + * supersedes them rather than folding into them. + */ + scanPhase?.abandon() + indexPhase?.abandon() + indexPhase = null + currentPass = cmd.pass + pendingRetries = 0 + indexingCompleteReceived = false + scanPhase = beginScan() + } - IndexCommand.IndexingComplete -> { - logger.info( - "Indexing complete: scanned={}, sourceIndexCount={}", - scanCount, - sourceIndexCount, - ) - } + is IndexCommand.ScanSourceFile -> { + if (project.isDisposed) break - is IndexCommand.ScanSourceFile -> { - if (project.isDisposed) break + val ktFile = + project.read { + PsiManager.getInstance(project).findFile(cmd.vf) as? KtFile + } + ?: continue - val ktFile = - project.read { - PsiManager.getInstance(project).findFile(cmd.vf) as? KtFile + val newFile = ktFile.toMetadata(project, isIndexed = false) + val existingFile = fileIndex.get(newFile.filePath) + if (KtFileMetadata.shouldBeSkipped(existingFile, newFile)) { + continue } - ?: continue - val newFile = ktFile.toMetadata(project, isIndexed = false) - val existingFile = fileIndex.get(newFile.filePath) - if (KtFileMetadata.shouldBeSkipped(existingFile, newFile)) { - continue + fileIndex.upsert(newFile) + scanCount++ } - fileIndex.upsert(newFile) - scanCount++ - } - - IndexCommand.SourceScanningComplete -> { - logger.info("Scanning complete. Found {} files to index.", scanCount) - } + is IndexCommand.SourceScanningComplete -> { + logger.info("Scanning complete. Found {} files to index.", scanCount) + if (cmd.pass != currentPass) continue + /* + * The index phase must begin before the scan phase ends, so the report's + * open-phase count never touches zero at this handoff, which would print + * the logcat report mid-open. + */ + if (indexPhase == null) { + indexPhase = beginIndex() + } + scanPhase?.apply { + put("files", (scanCount - scannedAtScanBegin).toLong()) + end() + } + scanPhase = null + } - IndexCommand.Stop -> { - break + IndexCommand.Stop -> { + break + } } } + } finally { + // The worker can stop before the queue reports either phase as complete. + scanPhase?.abandon() + indexPhase?.abandon() } } + private enum class IndexOutcome { INDEXED, SKIPPED, PREEMPTED } + + private suspend fun indexFile(cmd: IndexCommand.IndexSourceFile): IndexOutcome { + if (cmd.vf.fileSystem.protocol != "file") { + logger.warn("Unknown source file protocol: {}", cmd.vf.path) + return IndexOutcome.SKIPPED + } + + val ktFile = + project.read { + PsiManager + .getInstance(project) + .findFile(cmd.vf) as? KtFile + } + // probably a non-kotlin file + ?: return IndexOutcome.SKIPPED + + return try { + // cmd.vf.path is not a plain field read (it builds a system-independent + // path string), so it must not be computed when nothing records it. + val detail = if (Memprof.sink != null) cmd.vf.path else null + Memprof.section("Index Kotlin file", detail) { + indexSourceFile( + project = project, + ktFile = ktFile, + fileIndex = fileIndex, + symbolsIndex = sourceIndex, + // A real (cancellable) checker so the scheduler can preempt this pass + // in favour of completion/diagnostics. + cancelChecker = ICancelChecker.Default(), + ) + } + IndexOutcome.INDEXED + } catch (e: AnalysisPreemptedException) { + IndexOutcome.PREEMPTED + } + } + + private fun beginScanPhase() = Memprof.beginPhase("Scan Kotlin sources", "source_scan_complete") + + private fun beginIndexPhase() = Memprof.beginPhase("Index Kotlin sources", "source_index_complete") + suspend fun submitCommand(cmd: IndexCommand) { when (cmd) { - is IndexCommand.ScanSourceFile, IndexCommand.SourceScanningComplete -> { + is IndexCommand.ScanSourceFile, + is IndexCommand.SourceScanningStarted, + is IndexCommand.SourceScanningComplete, + -> { queue.putScanQueue(cmd) } diff --git a/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/ScanningWorker.kt b/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/ScanningWorker.kt index 3f2c06fdec..f5795dce1d 100644 --- a/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/ScanningWorker.kt +++ b/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/compiler/index/ScanningWorker.kt @@ -9,52 +9,62 @@ import kotlinx.coroutines.coroutineScope import kotlinx.coroutines.isActive import org.appdevforall.codeonthego.indexing.jvm.JvmSymbolIndex import org.slf4j.LoggerFactory +import java.util.concurrent.atomic.AtomicInteger internal class ScanningWorker( - private val kind: CompilationKind, - private val sourceIndex: JvmSymbolIndex, - private val indexWorker: IndexWorker, - private val modules: List, + private val kind: CompilationKind, + private val sourceIndex: JvmSymbolIndex, + private val indexWorker: IndexWorker, + private val modules: List, ) { + companion object { + private val logger = LoggerFactory.getLogger(ScanningWorker::class.java) + } - companion object { - private val logger = LoggerFactory.getLogger(ScanningWorker::class.java) - } - - suspend fun scan() = coroutineScope { - val sourceFiles = modules.asFlatSequence() - .filter { it.isSourceModule } - .flatMap { it.computeFiles(extended = true) } - .filter { - it.toNioPathOrNull()?.let { path -> kind.acceptsFile(path) } ?: run { - logger.warn("rejecting {} from kt source index", it) - false - } - } - .takeWhile { isActive } - .toList() - - sourceIndex.setActiveSources( - sourceFiles - .asSequence() - .map { it.path } - .takeWhile { isActive } - .toSet() - ) - - for (sourceFile in sourceFiles) { - if (!isActive) return@coroutineScope - indexWorker.submitCommand(IndexCommand.ScanSourceFile(sourceFile)) - } - - indexWorker.submitCommand(IndexCommand.SourceScanningComplete) - - sourceFiles.asSequence() - .takeWhile { isActive } - .forEach { sourceFile -> - indexWorker.submitCommand(IndexCommand.IndexSourceFile(sourceFile)) - } - - indexWorker.submitCommand(IndexCommand.IndexingComplete) - } -} \ No newline at end of file + private val passes = AtomicInteger() + + suspend fun scan() = + coroutineScope { + val pass = passes.incrementAndGet() + indexWorker.submitCommand(IndexCommand.SourceScanningStarted(pass)) + + val sourceFiles = + modules + .asFlatSequence() + .filter { it.isSourceModule } + .flatMap { it.computeFiles(extended = true) } + .filter { + it.toNioPathOrNull()?.let { path -> kind.acceptsFile(path) } ?: run { + logger.warn("rejecting {} from kt source index", it) + false + } + }.takeWhile { isActive } + .toList() + + sourceIndex.setActiveSources( + sourceFiles + .asSequence() + .map { it.path } + .takeWhile { isActive } + .toSet(), + ) + + for (sourceFile in sourceFiles) { + if (!isActive) return@coroutineScope + indexWorker.submitCommand(IndexCommand.ScanSourceFile(sourceFile)) + } + + indexWorker.submitCommand(IndexCommand.SourceScanningComplete(pass)) + + sourceFiles + .asSequence() + .takeWhile { isActive } + .forEach { sourceFile -> + indexWorker.submitCommand(IndexCommand.IndexSourceFile(sourceFile, pass)) + } + + // A send into a channel with room does not suspend, so it would not notice cancellation. + if (!isActive) return@coroutineScope + indexWorker.submitCommand(IndexCommand.IndexingComplete(pass)) + } +} diff --git a/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/completion/KotlinCompletions.kt b/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/completion/KotlinCompletions.kt index 66acf35355..09906f6a6c 100644 --- a/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/completion/KotlinCompletions.kt +++ b/lsp/kotlin/src/main/java/com/itsaky/androidide/lsp/kotlin/completion/KotlinCompletions.kt @@ -254,7 +254,8 @@ internal fun doComplete(params: CompletionParams): CompletionResult { throw e } - logger.warn("An error occurred while computing completions for {}", params.file, e) + // The user sees an empty popup, identical to "no matches", so the log must not hide it. + logger.error("Completion analysis failed for {}, returning no items", params.file, e) CompletionResult.EMPTY } finally { currentCancelChecker.remove() diff --git a/lsp/kotlin/src/test/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexWorkerBatchRemovalTest.kt b/lsp/kotlin/src/test/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexWorkerBatchRemovalTest.kt index 70f3d8b12d..9fee622f41 100644 --- a/lsp/kotlin/src/test/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexWorkerBatchRemovalTest.kt +++ b/lsp/kotlin/src/test/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexWorkerBatchRemovalTest.kt @@ -30,181 +30,187 @@ import java.time.Instant */ @RunWith(JUnit4::class) class IndexWorkerBatchRemovalTest { - - /** - * Counting decorator over a real backing [Index] that records how the batched - * vs. per-source removal APIs are exercised. This is the mutation-sensitive - * probe: if the wiring regressed to calling [removeBySource] in a loop, the - * `removeBySourceCalls` counter would climb and `removeBySourcesBatches` stay 0. - */ - private class CountingIndex( - private val backing: Index, - ) : Index by backing { - var removeBySourceCalls = 0 - private set - var removeBySourcesBatches = 0 - private set - val removedInLargestBatch = mutableListOf() - - override suspend fun removeBySource(sourceId: String) { - removeBySourceCalls++ - backing.removeBySource(sourceId) - } - - override suspend fun removeBySources(sourceIds: Collection) { - removeBySourcesBatches++ - if (sourceIds.size >= removedInLargestBatch.size) { - removedInLargestBatch.clear() - removedInLargestBatch.addAll(sourceIds) - } - backing.removeBySources(sourceIds) - } - } - - private fun symbol(sourceId: String) = JvmSymbol( - key = "$sourceId#Type", - sourceId = sourceId, - name = "com/example/Type", - shortName = "Type", - packageName = "com.example", - kind = JvmSymbolKind.CLASS, - language = JvmSourceLanguage.KOTLIN, - data = JvmClassInfo(), - ) - - private fun fileMeta(path: String) = KtFileMetadata( - filePath = path, - packageFqName = "com.example", - lastModified = Instant.EPOCH, - modificationStamp = 1L, - isIndexed = true, - symbolKeys = listOf("$path#Type"), - ) - - private fun makeSymbolIndex( - backing: Index = InMemoryIndex(JvmSymbolDescriptor), - ): Pair, JvmSymbolIndex> { - val counting = CountingIndex(backing) - val index = object : JvmSymbolIndex(counting, BackgroundIndexer(counting)) { - override fun isActive(sourceId: String): Boolean = true - } - return counting to index - } - - private fun makeFileIndex(): Pair, KtFileMetadataIndex> { - val counting = CountingIndex(InMemoryIndex(KtFileMetadataDescriptor)) - return counting to KtFileMetadataIndex(counting) - } - - private fun removeCmd(path: String) = - IndexCommand.RemoveFromIndex(Paths.get(path)) - - /** A run of consecutive removals issues exactly one batched call and deletes every record. */ - @Test - fun `N consecutive removals collapse into ONE batched removeBySources`() = runTest { - val paths = (1..5).map { "/proj/File$it.kt" } - val (counting, symbolIndex) = makeSymbolIndex() - val (fileCounting, fileIndex) = makeFileIndex() - - // Seed: one symbol + one metadata record per file. - symbolIndex.insertAll(paths.asSequence().map { symbol(it) }) - for (p in paths) fileIndex.upsert(fileMeta(p)) - - // The queue holds N-1 further removals after the first, then runs dry. - val rest = ArrayDeque(paths.drop(1).map { removeCmd(it) as IndexCommand }) - val pushedBack = mutableListOf() - - applyRemovals( - first = removeCmd(paths.first()) as IndexCommand.RemoveFromIndex, - fileIndex = fileIndex, - sourceIndex = symbolIndex, - pollNext = { rest.removeFirstOrNull() }, - pushBack = { pushedBack.add(it) }, - ) - - // The fix: exactly one batched transaction, zero per-source deletes — for BOTH indexes. - assertThat(counting.removeBySourcesBatches).isEqualTo(1) - assertThat(counting.removeBySourceCalls).isEqualTo(0) - assertThat(counting.removedInLargestBatch).containsExactlyElementsIn(paths) - assertThat(fileCounting.removeBySourcesBatches).isEqualTo(1) - assertThat(fileCounting.removeBySourceCalls).isEqualTo(0) - assertThat(fileCounting.removedInLargestBatch).containsExactlyElementsIn(paths) - assertThat(pushedBack).isEmpty() - - // Correctness: every symbol and metadata record is gone. - for (p in paths) { - symbolIndex.activateSource(p) - assertThat(symbolIndex.findByKey("$p#Type")).isNull() - assertThat(fileIndex.get(p)).isNull() - } - } - - /** A non-removal command ends the batch and is pushed back unconsumed, preserving order. */ - @Test - fun `a non-removal command stops the batch and is pushed back unconsumed`() = runTest { - val rmPaths = listOf("/proj/A.kt", "/proj/B.kt") - val (counting, symbolIndex) = makeSymbolIndex() - val (fileCounting, fileIndex) = makeFileIndex() - symbolIndex.insertAll(rmPaths.asSequence().map { symbol(it) }) - for (p in rmPaths) fileIndex.upsert(fileMeta(p)) - - val interloper: IndexCommand = IndexCommand.IndexingComplete - val queue = ArrayDeque( - listOf(removeCmd(rmPaths[1]) as IndexCommand, interloper) - ) - val pushedBack = mutableListOf() - - applyRemovals( - first = removeCmd(rmPaths[0]) as IndexCommand.RemoveFromIndex, - fileIndex = fileIndex, - sourceIndex = symbolIndex, - pollNext = { queue.removeFirstOrNull() }, - pushBack = { pushedBack.add(it) }, - ) - - // Both removals batched together (symbol + metadata); the non-removal command preserved. - assertThat(counting.removeBySourcesBatches).isEqualTo(1) - assertThat(counting.removeBySourceCalls).isEqualTo(0) - assertThat(counting.removedInLargestBatch).containsExactlyElementsIn(rmPaths) - assertThat(fileCounting.removeBySourcesBatches).isEqualTo(1) - assertThat(fileCounting.removeBySourceCalls).isEqualTo(0) - assertThat(fileCounting.removedInLargestBatch).containsExactlyElementsIn(rmPaths) - assertThat(pushedBack).containsExactly(interloper) - } - - /** Batched removeBySources yields the same result as N individual removeBySource calls. */ - @Test - fun `InMemory and SQLite-style backings give identical removeBySources results (parity)`() = runTest { - // Parity at the primitive level: removeBySources must equal N removeBySource. - val paths = listOf("/p/X.kt", "/p/Y.kt", "/p/Z.kt") - - val batched = InMemoryIndex(JvmSymbolDescriptor) - val oneByOne = InMemoryIndex(JvmSymbolDescriptor) - for (p in paths) { - batched.insert(symbol(p)) - oneByOne.insert(symbol(p)) - } - - batched.removeBySources(paths) - for (p in paths) oneByOne.removeBySource(p) - - val left = batched.query(IndexQuery.ALL).toList() - val right = oneByOne.query(IndexQuery.ALL).toList() - assertThat(left).isEmpty() - assertThat(left).containsExactlyElementsIn(right) - } - - /** removeBySources deletes only the named sources and leaves unnamed ones intact. */ - @Test - fun `removeBySources only deletes the named sources`() = runTest { - val backing = InMemoryIndex(JvmSymbolDescriptor) - backing.insert(symbol("/p/Keep.kt")) - backing.insert(symbol("/p/Drop1.kt")) - backing.insert(symbol("/p/Drop2.kt")) - - backing.removeBySources(listOf("/p/Drop1.kt", "/p/Drop2.kt")) - - val remaining = backing.query(IndexQuery.ALL).map { it.sourceId }.toList() - assertThat(remaining).containsExactly("/p/Keep.kt") - } + /** + * Counting decorator over a real backing [Index] that records how the batched + * vs. per-source removal APIs are exercised. This is the mutation-sensitive + * probe: if the wiring regressed to calling [removeBySource] in a loop, the + * `removeBySourceCalls` counter would climb and `removeBySourcesBatches` stay 0. + */ + private class CountingIndex( + private val backing: Index, + ) : Index by backing { + var removeBySourceCalls = 0 + private set + var removeBySourcesBatches = 0 + private set + val removedInLargestBatch = mutableListOf() + + override suspend fun removeBySource(sourceId: String) { + removeBySourceCalls++ + backing.removeBySource(sourceId) + } + + override suspend fun removeBySources(sourceIds: Collection) { + removeBySourcesBatches++ + if (sourceIds.size >= removedInLargestBatch.size) { + removedInLargestBatch.clear() + removedInLargestBatch.addAll(sourceIds) + } + backing.removeBySources(sourceIds) + } + } + + private fun symbol(sourceId: String) = + JvmSymbol( + key = "$sourceId#Type", + sourceId = sourceId, + name = "com/example/Type", + shortName = "Type", + packageName = "com.example", + kind = JvmSymbolKind.CLASS, + language = JvmSourceLanguage.KOTLIN, + data = JvmClassInfo(), + ) + + private fun fileMeta(path: String) = + KtFileMetadata( + filePath = path, + packageFqName = "com.example", + lastModified = Instant.EPOCH, + modificationStamp = 1L, + isIndexed = true, + symbolKeys = listOf("$path#Type"), + ) + + private fun makeSymbolIndex( + backing: Index = InMemoryIndex(JvmSymbolDescriptor), + ): Pair, JvmSymbolIndex> { + val counting = CountingIndex(backing) + val index = + object : JvmSymbolIndex(counting, BackgroundIndexer(counting)) { + override fun isActive(sourceId: String): Boolean = true + } + return counting to index + } + + private fun makeFileIndex(): Pair, KtFileMetadataIndex> { + val counting = CountingIndex(InMemoryIndex(KtFileMetadataDescriptor)) + return counting to KtFileMetadataIndex(counting) + } + + private fun removeCmd(path: String) = IndexCommand.RemoveFromIndex(Paths.get(path)) + + /** A run of consecutive removals issues exactly one batched call and deletes every record. */ + @Test + fun `N consecutive removals collapse into ONE batched removeBySources`() = + runTest { + val paths = (1..5).map { "/proj/File$it.kt" } + val (counting, symbolIndex) = makeSymbolIndex() + val (fileCounting, fileIndex) = makeFileIndex() + + // Seed: one symbol + one metadata record per file. + symbolIndex.insertAll(paths.asSequence().map { symbol(it) }) + for (p in paths) fileIndex.upsert(fileMeta(p)) + + // The queue holds N-1 further removals after the first, then runs dry. + val rest = ArrayDeque(paths.drop(1).map { removeCmd(it) as IndexCommand }) + val pushedBack = mutableListOf() + + applyRemovals( + first = removeCmd(paths.first()) as IndexCommand.RemoveFromIndex, + fileIndex = fileIndex, + sourceIndex = symbolIndex, + pollNext = { rest.removeFirstOrNull() }, + pushBack = { pushedBack.add(it) }, + ) + + // The fix: exactly one batched transaction, zero per-source deletes — for BOTH indexes. + assertThat(counting.removeBySourcesBatches).isEqualTo(1) + assertThat(counting.removeBySourceCalls).isEqualTo(0) + assertThat(counting.removedInLargestBatch).containsExactlyElementsIn(paths) + assertThat(fileCounting.removeBySourcesBatches).isEqualTo(1) + assertThat(fileCounting.removeBySourceCalls).isEqualTo(0) + assertThat(fileCounting.removedInLargestBatch).containsExactlyElementsIn(paths) + assertThat(pushedBack).isEmpty() + + // Correctness: every symbol and metadata record is gone. + for (p in paths) { + symbolIndex.activateSource(p) + assertThat(symbolIndex.findByKey("$p#Type")).isNull() + assertThat(fileIndex.get(p)).isNull() + } + } + + /** A non-removal command ends the batch and is pushed back unconsumed, preserving order. */ + @Test + fun `a non-removal command stops the batch and is pushed back unconsumed`() = + runTest { + val rmPaths = listOf("/proj/A.kt", "/proj/B.kt") + val (counting, symbolIndex) = makeSymbolIndex() + val (fileCounting, fileIndex) = makeFileIndex() + symbolIndex.insertAll(rmPaths.asSequence().map { symbol(it) }) + for (p in rmPaths) fileIndex.upsert(fileMeta(p)) + + val interloper: IndexCommand = IndexCommand.IndexingComplete(pass = 1) + val queue = + ArrayDeque( + listOf(removeCmd(rmPaths[1]) as IndexCommand, interloper), + ) + val pushedBack = mutableListOf() + + applyRemovals( + first = removeCmd(rmPaths[0]) as IndexCommand.RemoveFromIndex, + fileIndex = fileIndex, + sourceIndex = symbolIndex, + pollNext = { queue.removeFirstOrNull() }, + pushBack = { pushedBack.add(it) }, + ) + + // Both removals batched together (symbol + metadata); the non-removal command preserved. + assertThat(counting.removeBySourcesBatches).isEqualTo(1) + assertThat(counting.removeBySourceCalls).isEqualTo(0) + assertThat(counting.removedInLargestBatch).containsExactlyElementsIn(rmPaths) + assertThat(fileCounting.removeBySourcesBatches).isEqualTo(1) + assertThat(fileCounting.removeBySourceCalls).isEqualTo(0) + assertThat(fileCounting.removedInLargestBatch).containsExactlyElementsIn(rmPaths) + assertThat(pushedBack).containsExactly(interloper) + } + + /** Batched removeBySources yields the same result as N individual removeBySource calls. */ + @Test + fun `InMemory and SQLite-style backings give identical removeBySources results (parity)`() = + runTest { + // Parity at the primitive level: removeBySources must equal N removeBySource. + val paths = listOf("/p/X.kt", "/p/Y.kt", "/p/Z.kt") + + val batched = InMemoryIndex(JvmSymbolDescriptor) + val oneByOne = InMemoryIndex(JvmSymbolDescriptor) + for (p in paths) { + batched.insert(symbol(p)) + oneByOne.insert(symbol(p)) + } + + batched.removeBySources(paths) + for (p in paths) oneByOne.removeBySource(p) + + val left = batched.query(IndexQuery.ALL).toList() + val right = oneByOne.query(IndexQuery.ALL).toList() + assertThat(left).isEmpty() + assertThat(left).containsExactlyElementsIn(right) + } + + /** removeBySources deletes only the named sources and leaves unnamed ones intact. */ + @Test + fun `removeBySources only deletes the named sources`() = + runTest { + val backing = InMemoryIndex(JvmSymbolDescriptor) + backing.insert(symbol("/p/Keep.kt")) + backing.insert(symbol("/p/Drop1.kt")) + backing.insert(symbol("/p/Drop2.kt")) + + backing.removeBySources(listOf("/p/Drop1.kt", "/p/Drop2.kt")) + + val remaining = backing.query(IndexQuery.ALL).map { it.sourceId }.toList() + assertThat(remaining).containsExactly("/p/Keep.kt") + } } diff --git a/lsp/kotlin/src/test/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexWorkerPhaseLifecycleTest.kt b/lsp/kotlin/src/test/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexWorkerPhaseLifecycleTest.kt new file mode 100644 index 0000000000..263d5aa4d2 --- /dev/null +++ b/lsp/kotlin/src/test/java/com/itsaky/androidide/lsp/kotlin/compiler/index/IndexWorkerPhaseLifecycleTest.kt @@ -0,0 +1,324 @@ +package com.itsaky.androidide.lsp.kotlin.compiler.index + +import com.google.common.truth.Truth.assertThat +import com.itsaky.androidide.lsp.kotlin.compiler.modules.AnalysisPreemptedException +import com.itsaky.androidide.memprof.Memprof +import com.itsaky.androidide.memprof.MemprofSink +import com.itsaky.androidide.memprof.MemprofSpan +import io.mockk.coEvery +import io.mockk.every +import io.mockk.mockk +import io.mockk.mockkStatic +import io.mockk.unmockkAll +import kotlinx.coroutines.CoroutineScope +import kotlinx.coroutines.Dispatchers +import kotlinx.coroutines.SupervisorJob +import kotlinx.coroutines.delay +import kotlinx.coroutines.launch +import kotlinx.coroutines.runBlocking +import kotlinx.coroutines.withTimeout +import org.appdevforall.codeonthego.indexing.InMemoryIndex +import org.appdevforall.codeonthego.indexing.jvm.JvmSymbolDescriptor +import org.appdevforall.codeonthego.indexing.jvm.JvmSymbolIndex +import org.appdevforall.codeonthego.indexing.jvm.KtFileMetadataDescriptor +import org.appdevforall.codeonthego.indexing.jvm.KtFileMetadataIndex +import org.appdevforall.codeonthego.indexing.util.BackgroundIndexer +import org.jetbrains.kotlin.com.intellij.openapi.project.Project +import org.jetbrains.kotlin.com.intellij.openapi.util.Key +import org.jetbrains.kotlin.com.intellij.openapi.vfs.VirtualFile +import org.jetbrains.kotlin.com.intellij.psi.PsiManager +import org.jetbrains.kotlin.psi.KtFile +import org.junit.After +import org.junit.Test +import java.nio.file.Path +import java.util.Collections +import java.util.concurrent.locks.ReentrantReadWriteLock + +/** + * Regression tests for the [IndexWorker] phase lifecycle edge cases: a phase span must never be + * begun-and-immediately-ended for a boundary that never really opened, a scan cancelled mid-way + * must not leave a stale span for the next scan to fold into, and a clean run must report both + * phases as ended, not abandoned. A command from a superseded scan pass, or from no pass at all, + * must not open or close the current pass's phases. + * + * The tests that send file commands mock [PsiManager] and, for indexing, `indexSourceFile`. + */ +class IndexWorkerPhaseLifecycleTest { + private val sink = RecordingSink() + + @After + fun uninstallSink() { + Memprof.sink = null + unmockkAll() + } + + private fun worker(): IndexWorker { + val project = mockk() + every { project.isDisposed } returns false + every { project.getUserData(any>()) } returns ReentrantReadWriteLock() + + val symbolBacking = InMemoryIndex(JvmSymbolDescriptor) + val sourceIndex = + object : JvmSymbolIndex(symbolBacking, BackgroundIndexer(symbolBacking)) { + override fun isActive(sourceId: String) = true + } + + return IndexWorker( + project = project, + queue = WorkerQueue(), + fileIndex = KtFileMetadataIndex(InMemoryIndex(KtFileMetadataDescriptor)), + sourceIndex = sourceIndex, + scope = CoroutineScope(Dispatchers.Default + SupervisorJob()), + ) + } + + @Test + fun `a complete scan and index reports both phases ended, not abandoned`(): Unit = + runBlocking { + Memprof.sink = sink + val worker = worker() + + worker.submitCommand(IndexCommand.SourceScanningStarted(pass = 1)) + worker.submitCommand(IndexCommand.SourceScanningComplete(pass = 1)) + worker.submitCommand(IndexCommand.IndexingComplete(pass = 1)) + worker.submitCommand(IndexCommand.Stop) + + withTimeout(5_000) { worker.start() } + + assertThat(sink.events) + .containsExactly( + "begin phase source_scan_complete", + "begin phase source_index_complete", + "end phase source_scan_complete", + "end phase source_index_complete", + ).inOrder() + } + + @Test + fun `Stop before SourceScanningComplete abandons the open scan phase`(): Unit = + runBlocking { + Memprof.sink = sink + val worker = worker() + + worker.submitCommand(IndexCommand.SourceScanningStarted(pass = 1)) + worker.submitCommand(IndexCommand.Stop) + + withTimeout(5_000) { worker.start() } + + assertThat(sink.events) + .containsExactly("begin phase source_scan_complete", "abandon source_scan_complete") + .inOrder() + } + + @Test + fun `a new scan starting while a stale scan phase is open abandons it and begins fresh`(): Unit = + runBlocking { + Memprof.sink = sink + val worker = worker() + + // The second SourceScanningStarted simulates KtSymbolIndex.refreshSources() restarting + // a scan whose first attempt was cancelled before it ever reached SourceScanningComplete, + // leaving the first scanPhase stale and open. + worker.submitCommand(IndexCommand.SourceScanningStarted(pass = 1)) + worker.submitCommand(IndexCommand.SourceScanningStarted(pass = 2)) + worker.submitCommand(IndexCommand.Stop) + + withTimeout(5_000) { worker.start() } + + assertThat(sink.events) + .containsExactly( + "begin phase source_scan_complete", + "abandon source_scan_complete", + "begin phase source_scan_complete", + "abandon source_scan_complete", + ).inOrder() + } + + @Test + fun `IndexingComplete with no open index phase emits nothing`(): Unit = + runBlocking { + Memprof.sink = sink + val worker = worker() + + worker.submitCommand(IndexCommand.IndexingComplete(pass = 1)) + worker.submitCommand(IndexCommand.Stop) + + withTimeout(5_000) { worker.start() } + + assertThat(sink.events).isEmpty() + } + + @Test + fun `a ScanSourceFile outside a scan pass opens no phase`(): Unit = + runBlocking { + Memprof.sink = sink + mockPsiManager(ktFile = null) + val worker = worker() + + worker.submitCommand(IndexCommand.ScanSourceFile(sourceFile())) + worker.submitCommand(IndexCommand.Stop) + + withTimeout(5_000) { worker.start() } + + assertThat(sink.events).isEmpty() + } + + @Test + fun `a superseded pass's IndexingComplete does not end the current pass's index phase`(): Unit = + runBlocking { + Memprof.sink = sink + val worker = worker() + + worker.submitCommand(IndexCommand.SourceScanningStarted(pass = 1)) + worker.submitCommand(IndexCommand.SourceScanningComplete(pass = 1)) + worker.submitCommand(IndexCommand.SourceScanningStarted(pass = 2)) + worker.submitCommand(IndexCommand.SourceScanningComplete(pass = 2)) + worker.submitCommand(IndexCommand.IndexingComplete(pass = 1)) + worker.submitCommand(IndexCommand.Stop) + + withTimeout(5_000) { worker.start() } + + assertThat(sink.events) + .containsExactly( + "begin phase source_scan_complete", + "begin phase source_index_complete", + "end phase source_scan_complete", + "abandon source_index_complete", + "begin phase source_scan_complete", + "begin phase source_index_complete", + "end phase source_scan_complete", + "abandon source_index_complete", + ).inOrder() + } + + @Test + fun `the index phase ends only after a preempted file's retry is indexed`(): Unit = + runBlocking { + Memprof.sink = sink + mockPsiManager(ktFile = mockk()) + mockkStatic("com.itsaky.androidide.lsp.kotlin.compiler.index.SourceFileIndexerKt") + var attempts = 0 + coEvery { indexSourceFile(any(), any(), any(), any(), any()) } answers { + if (++attempts == 1) throw AnalysisPreemptedException() + sink.events += "indexed retry" + } + val worker = worker() + + worker.submitCommand(IndexCommand.SourceScanningStarted(pass = 1)) + worker.submitCommand(IndexCommand.SourceScanningComplete(pass = 1)) + worker.submitCommand(IndexCommand.IndexSourceFile(sourceFile(), pass = 1)) + worker.submitCommand(IndexCommand.IndexingComplete(pass = 1)) + + withTimeout(5_000) { + val running = launch { worker.start() } + while ("end phase source_index_complete" !in sink.events) delay(10) + worker.submitCommand(IndexCommand.Stop) + running.join() + } + + assertThat(sink.events.filter { "Index Kotlin file" !in it }) + .containsExactly( + "begin phase source_scan_complete", + "begin phase source_index_complete", + "end phase source_scan_complete", + "indexed retry", + "end phase source_index_complete", + ).inOrder() + } + + @Test + fun `an edit re-indexed during a pass is not counted in that pass`(): Unit = + runBlocking { + Memprof.sink = sink + mockkStatic("com.itsaky.androidide.lsp.kotlin.compiler.index.SourceFileIndexerKt") + coEvery { indexSourceFile(any(), any(), any(), any(), any()) } answers { sink.events += "indexed edit" } + val editedFile = mockk() + every { editedFile.getUserData(any>()) } returns Path.of("/project/src/Edited.kt") + val worker = worker() + + worker.submitCommand(IndexCommand.SourceScanningStarted(pass = 1)) + worker.submitCommand(IndexCommand.SourceScanningComplete(pass = 1)) + worker.submitCommand(IndexCommand.IndexModifiedFile(editedFile)) + + withTimeout(5_000) { + val running = launch { worker.start() } + while ("indexed edit" !in sink.events) delay(10) + worker.submitCommand(IndexCommand.IndexingComplete(pass = 1)) + while ("end phase source_index_complete" !in sink.events) delay(10) + worker.submitCommand(IndexCommand.Stop) + running.join() + } + + assertThat(sink.values["source_index_complete.indexed"]).isEqualTo(0L) + } + + private fun mockPsiManager(ktFile: KtFile?) { + val psiManager = mockk() + every { psiManager.findFile(any()) } returns ktFile + mockkStatic(PsiManager::class) + every { PsiManager.getInstance(any()) } returns psiManager + } + + private fun sourceFile(): VirtualFile { + val vf = mockk() + every { vf.fileSystem.protocol } returns "file" + every { vf.path } returns "/project/src/Sample.kt" + return vf + } + + private class RecordingSink : MemprofSink { + val events: MutableList = Collections.synchronizedList(mutableListOf()) + val values: MutableMap = Collections.synchronizedMap(mutableMapOf()) + + override fun beginPhase( + title: String, + marker: String, + ): MemprofSpan { + events += "begin phase $marker" + return RecordingSpan(marker) + } + + override fun beginSection( + name: String, + detail: String?, + ): MemprofSpan { + events += "begin section $name" + return RecordingSpan(name) + } + + override fun mark(marker: String) { + events += "mark $marker" + } + + private inner class RecordingSpan( + private val label: String, + ) : MemprofSpan { + private var finished = false + + override val isRecording: Boolean = true + + override fun put( + key: String, + value: Long, + ) { + values["$label.$key"] = value + } + + // Idempotent, matching MemprofSpan's documented contract: once ended or abandoned, + // further calls do nothing. + override fun end() { + if (!finished) { + finished = true + events += "end phase $label" + } + } + + override fun abandon() { + if (!finished) { + finished = true + events += "abandon $label" + } + } + } + } +} diff --git a/shared/src/main/java/com/itsaky/androidide/memprof/HeapCounters.kt b/shared/src/main/java/com/itsaky/androidide/memprof/HeapCounters.kt new file mode 100644 index 0000000000..40969aa06c --- /dev/null +++ b/shared/src/main/java/com/itsaky/androidide/memprof/HeapCounters.kt @@ -0,0 +1,40 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +/** + * One reading of the runtime's heap counters. + * + * [allocatedBytes], [freedBytes] and [blockingGcCount] are cumulative for the life of the process, + * so the difference between two readings is what happened between them. + */ +data class HeapCounters( + val allocatedBytes: Long, + val freedBytes: Long, + val blockingGcCount: Long, + val usedBytes: Long, +) { + /** + * Bytes allocated minus bytes freed, by the cumulative counters. + * + * Freed bytes only advance when a GC runs, so over a stretch with no GC this equals the bytes + * allocated, garbage included. It is not what the stretch retained. + */ + val netRetainedBytes: Long + get() = allocatedBytes - freedBytes +} diff --git a/shared/src/main/java/com/itsaky/androidide/memprof/Memprof.kt b/shared/src/main/java/com/itsaky/androidide/memprof/Memprof.kt new file mode 100644 index 0000000000..231809f2b3 --- /dev/null +++ b/shared/src/main/java/com/itsaky/androidide/memprof/Memprof.kt @@ -0,0 +1,86 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +/** + * Profiling hooks for measuring memory and time across a project open. + * + * Every hook costs one null check unless a [MemprofSink] is installed, which only the profileable + * build variant does, so the calls can stay in shared code that also ships in release builds. + */ +object Memprof { + /** Where events go, or null to drop them. */ + @JvmStatic + @Volatile + var sink: MemprofSink? = null + + /** Runs [action] as the phase [title]; the phase ends if [action] returns and is abandoned if it throws. */ + inline fun phase( + title: String, + marker: String, + action: (MemprofSpan) -> R, + ): R = runIn(sink?.beginPhase(title, marker), action) + + /** Runs [action] as one instance of the repeated work [name], ended or abandoned like a [phase]. */ + inline fun section( + name: String, + detail: String? = null, + action: (MemprofSpan) -> R, + ): R = runIn(sink?.beginSection(name, detail), action) + + /** + * Starts a phase whose start and end happen in different callbacks. + * + * The caller owns the returned span and must end or abandon it on every path, abandoning it in a + * `finally` if nothing else did; use [phase] whenever the work fits one block. + */ + fun beginPhase( + title: String, + marker: String, + ): MemprofSpan = sink?.beginPhase(title, marker) ?: MemprofSpan.None + + /** Records that the instant named [marker] was reached. */ + fun mark(marker: String) { + sink?.mark(marker) + } + + @PublishedApi + internal inline fun runIn( + span: MemprofSpan?, + action: (MemprofSpan) -> R, + ): R { + if (span == null) { + return action(MemprofSpan.None) + } + + /* + * action is not crossinline, so a return/break/continue out of the caller's block skips + * straight past the end() call below without throwing. finally still runs on that path, + * so abandon() always fires there; end() having already run on the normal path makes that + * abandon() a no-op, per MemprofSpan's own idempotency contract ("once a span has ended or + * been abandoned, further calls are ignored"). + */ + try { + val result = action(span) + span.end() + return result + } finally { + span.abandon() + } + } +} diff --git a/shared/src/main/java/com/itsaky/androidide/memprof/MemprofLines.kt b/shared/src/main/java/com/itsaky/androidide/memprof/MemprofLines.kt new file mode 100644 index 0000000000..1ffc9e80c2 --- /dev/null +++ b/shared/src/main/java/com/itsaky/androidide/memprof/MemprofLines.kt @@ -0,0 +1,73 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +/** + * Formats the machine-readable log lines the memprof harness scripts parse. + * + * Kept as pure string formatting, with no Android dependency, so the exact line shapes can be + * pinned by a JVM unit test instead of only being checked on a device. + */ +object MemprofLines { + /** + * The `PHASE|` line a finished phase emits, parsed by `parse_phases.py`. + * + * Carries only [details], the values the phase itself put on its span. It never carries the + * automatic per-phase duration or allocation: `parse_phases.py` merges every `k=v` pair from + * every `PHASE|` line for a run into one dict, so a key repeated across markers would clobber. + * The automatic figures go on [phaseEndLine] instead. + */ + fun phaseLine( + marker: String, + nowMs: Long, + details: Map, + ): String = "PHASE|$marker|$nowMs" + detailsSuffix(details) + + /** The line an abandoned phase emits instead of [phaseLine], so the harness never mistakes it for a finish. */ + fun phaseAbandonedLine( + marker: String, + nowMs: Long, + details: Map, + ): String = "MEMPROF|phase_abandoned|$marker|$nowMs" + detailsSuffix(details) + + /** The automatic duration and allocation for a phase, kept off [phaseLine] so extras there stay explicit-only. */ + fun phaseEndLine( + marker: String, + nowMs: Long, + durationMs: Long, + allocBytes: Long, + ): String = "MEMPROF|phase_end|$nowMs|marker=$marker|durationMs=$durationMs|allocBytes=$allocBytes" + + /** + * The line one finished section instance emits, read by `alloc_budget.py`'s per-file report. + * + * The field order and names (`allocBytes`, `durationMs`, `path`) after the timestamp are fixed + * by that script's `MEMPROF\|file\|(\d+)\|(.*)` regex and its k=v parsing; changing them breaks + * the harness silently rather than with an error, since unknown keys are ignored. + */ + fun fileLine( + nowMs: Long, + allocBytes: Long, + durationMs: Long, + path: String?, + name: String, + completed: Boolean, + ): String = "MEMPROF|file|$nowMs|allocBytes=$allocBytes|durationMs=$durationMs|path=$path|name=$name|completed=$completed" + + private fun detailsSuffix(details: Map): String = details.entries.joinToString("") { (key, value) -> "|$key=$value" } +} diff --git a/shared/src/main/java/com/itsaky/androidide/memprof/MemprofReport.kt b/shared/src/main/java/com/itsaky/androidide/memprof/MemprofReport.kt new file mode 100644 index 0000000000..9e2f6ffd7a --- /dev/null +++ b/shared/src/main/java/com/itsaky/androidide/memprof/MemprofReport.kt @@ -0,0 +1,248 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import java.time.Instant +import java.time.ZoneId +import java.time.format.DateTimeFormatter +import java.util.Locale + +/** + * Collects phases and repeated work into a plain-text report a person can read without tooling. + * + * A phase still running when the report is rendered is shown as in progress, measured up to the + * moment of rendering, so a report written just before the process dies still says where it was. + * All members are thread-safe. + */ +class MemprofReport( + private val processStartMs: Long, + private val heapLimitBytes: Long, + private val zone: ZoneId = ZoneId.systemDefault(), +) { + private val phases = mutableListOf() + private val repeatedWork = linkedMapOf() + private var heapPeakBytes = 0L + private var heapPeakDuring: String? = null + + /** Whether any phase has started and not yet ended. */ + val hasOpenPhases: Boolean + @Synchronized get() = phases.any { it.end == null } + + /** Records the start of the phase [title], returning the handle to end it with. */ + @Synchronized + fun phaseStarted( + title: String, + nowMs: Long, + counters: HeapCounters, + ): Phase { + val phase = Phase(title, nowMs, counters) + phases += phase + sampled(counters.usedBytes) + return phase + } + + /** + * Records the end of [phase], with the [details] attached to it while it ran. + * + * @param completed False when the phase was abandoned, which the report shows as stopped early. + */ + @Synchronized + fun phaseEnded( + phase: Phase, + nowMs: Long, + counters: HeapCounters, + details: Map, + completed: Boolean = true, + ) { + sampled(counters.usedBytes) + phase.endMs = nowMs + phase.end = counters + phase.details = details + phase.completed = completed + } + + /** Records one finished instance of the repeated work [name]. */ + @Synchronized + fun sectionEnded( + name: String, + detail: String?, + durationMs: Long, + allocatedBytes: Long, + ) { + repeatedWork.getOrPut(name) { RepeatedWork(name) }.add(detail, durationMs, allocatedBytes) + } + + /** Records a heap-in-use reading, which is how peaks between phase boundaries are seen. */ + @Synchronized + fun sampled(usedBytes: Long) { + for (phase in phases) { + if (phase.end == null) { + phase.peakUsedBytes = maxOf(phase.peakUsedBytes, usedBytes) + } + } + + if (usedBytes > heapPeakBytes) { + heapPeakBytes = usedBytes + heapPeakDuring = phases.lastOrNull { it.end == null }?.title + } + } + + /** Renders the report as of [nowMs], measuring phases still in progress against [counters]. */ + @Synchronized + fun render( + nowMs: Long, + counters: HeapCounters, + ): String = + buildString { + appendLine("Code On The Go memory profile") + appendLine("Process started ${timestamp(processStartMs)}, heap limit ${megabytes(heapLimitBytes)}") + appendLine("Updated ${timestamp(nowMs)}, ${seconds(nowMs - processStartMs)} after start") + appendPhases(nowMs, counters) + appendRepeatedWork() + appendLine() + append("Heap peak ${megabytes(heapPeakBytes)} of ${megabytes(heapLimitBytes)}") + appendLine(heapPeakDuring?.let { ", during \"$it\"" } ?: ", outside any phase") + } + + private fun StringBuilder.appendPhases( + nowMs: Long, + counters: HeapCounters, + ) { + appendLine() + appendLine("Phases") + if (phases.isEmpty()) { + appendLine(" none yet") + return + } + + val header = + listOf("Phase", "Start", "Time", "Allocated", "Alloc - freed", "Peak heap", "Blocking GCs", "") + appendTable(listOf(header) + phases.map { it.row(nowMs, counters) }) + } + + private fun StringBuilder.appendRepeatedWork() { + if (repeatedWork.isEmpty()) { + return + } + + appendLine() + appendLine("Repeated work") + val header = listOf("Work", "Count", "Total time", "Allocated", "Largest single instance") + appendTable(listOf(header) + repeatedWork.values.map { it.row() }) + } + + private fun Phase.row( + nowMs: Long, + counters: HeapCounters, + ): List { + val until = end ?: counters + val peak = maxOf(peakUsedBytes, if (end == null) counters.usedBytes else 0L) + val notes = + when { + end == null -> "(in progress)" + !completed -> (listOf("(stopped early)") + details.entries.map { detail(it) }).joinToString(" ") + else -> details.entries.joinToString(" ") { detail(it) } + } + return listOf( + title, + "+" + seconds(startMs - processStartMs), + seconds((endMs ?: nowMs) - startMs), + megabytes(until.allocatedBytes - start.allocatedBytes), + megabytes(until.netRetainedBytes - start.netRetainedBytes), + megabytes(peak), + "%,d".format(Locale.US, until.blockingGcCount - start.blockingGcCount), + notes, + ) + } + + private fun RepeatedWork.row(): List = + listOf( + name, + "%,d".format(Locale.US, count), + seconds(totalMs), + megabytes(totalAllocatedBytes), + "${largestDetail ?: "unnamed"}: ${megabytes(largestAllocatedBytes)} in ${seconds(largestMs)}", + ) + + private fun StringBuilder.appendTable(rows: List>) { + val widths = rows.first().indices.map { column -> rows.maxOf { it[column].length } } + for (row in rows) { + val cells = + row.mapIndexed { column, cell -> + if (column == 0 || column == row.lastIndex) cell.padEnd(widths[column]) else cell.padStart(widths[column]) + } + appendLine(" " + cells.joinToString(" ").trimEnd()) + } + } + + private fun detail(entry: Map.Entry): String = + if (entry.key.endsWith("bytes", ignoreCase = true)) { + "${entry.key}=${megabytes(entry.value)}" + } else { + "${entry.key}=${"%,d".format(Locale.US, entry.value)}" + } + + private fun timestamp(epochMs: Long): String = TIMESTAMP.format(Instant.ofEpochMilli(epochMs).atZone(zone)) + + /** A phase of the report; only [MemprofReport] reads or changes its state. */ + class Phase internal constructor( + internal val title: String, + internal val startMs: Long, + internal val start: HeapCounters, + ) { + internal var endMs: Long? = null + internal var end: HeapCounters? = null + internal var details: Map = emptyMap() + internal var completed: Boolean = true + internal var peakUsedBytes: Long = start.usedBytes + } + + private class RepeatedWork( + val name: String, + ) { + var count = 0L + var totalMs = 0L + var totalAllocatedBytes = 0L + var largestDetail: String? = null + var largestAllocatedBytes = -1L + var largestMs = 0L + + fun add( + detail: String?, + durationMs: Long, + allocatedBytes: Long, + ) { + count++ + totalMs += durationMs + totalAllocatedBytes += allocatedBytes + if (allocatedBytes > largestAllocatedBytes) { + largestDetail = detail + largestAllocatedBytes = allocatedBytes + largestMs = durationMs + } + } + } + + private companion object { + val TIMESTAMP: DateTimeFormatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss", Locale.US) + + fun megabytes(bytes: Long): String = "%,d MB".format(Locale.US, Math.round(bytes / (1024.0 * 1024.0))) + + fun seconds(ms: Long): String = "%.1f s".format(Locale.US, ms / 1000.0) + } +} diff --git a/shared/src/main/java/com/itsaky/androidide/memprof/MemprofSink.kt b/shared/src/main/java/com/itsaky/androidide/memprof/MemprofSink.kt new file mode 100644 index 0000000000..d3fca36db1 --- /dev/null +++ b/shared/src/main/java/com/itsaky/androidide/memprof/MemprofSink.kt @@ -0,0 +1,45 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +/** Receives the events reported through [Memprof]; only the profileable variant installs one. */ +interface MemprofSink { + /** + * Starts a phase: a one-off stage of work, reported as a row of its own. + * + * @param title What a person reading a trace or report should see, e.g. "Parse project model". + * @param marker The machine name emitted when the phase ends, e.g. `cache_parsed`. + */ + fun beginPhase( + title: String, + marker: String, + ): MemprofSpan + + /** + * Starts a section: one instance of repeated work, reported in aggregate under [name]. + * + * @param detail What distinguishes this instance, e.g. the file being indexed. + */ + fun beginSection( + name: String, + detail: String?, + ): MemprofSpan + + /** Records that the instant named [marker] was reached. */ + fun mark(marker: String) +} diff --git a/shared/src/main/java/com/itsaky/androidide/memprof/MemprofSpan.kt b/shared/src/main/java/com/itsaky/androidide/memprof/MemprofSpan.kt new file mode 100644 index 0000000000..518c587435 --- /dev/null +++ b/shared/src/main/java/com/itsaky/androidide/memprof/MemprofSpan.kt @@ -0,0 +1,60 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +/** + * One timed unit of work, started by [MemprofSink] and ended exactly once. + * + * Prefer [Memprof.phase] and [Memprof.section], which end the span for you. Hold a span directly + * only when the work starts and ends in different callbacks. + */ +interface MemprofSpan { + /** Whether anything records this span; false means every other member does nothing. */ + val isRecording: Boolean + + /** Attaches a numeric detail, reported with the span when it ends. */ + fun put( + key: String, + value: Long, + ) + + /** Ends the span as completed. Once a span has ended or been abandoned, further calls are ignored. */ + fun end() + + /** + * Ends the span as not completed, e.g. because its work threw or was stopped. + * + * An abandoned phase does not emit its marker, so nothing waiting for the marker mistakes an + * interrupted phase for a finished one. + */ + fun abandon() + + /** The span handed out when no sink is installed. */ + object None : MemprofSpan { + override val isRecording: Boolean = false + + override fun put( + key: String, + value: Long, + ) = Unit + + override fun end() = Unit + + override fun abandon() = Unit + } +} diff --git a/shared/src/test/java/com/itsaky/androidide/memprof/MemprofLinesTest.kt b/shared/src/test/java/com/itsaky/androidide/memprof/MemprofLinesTest.kt new file mode 100644 index 0000000000..f333c4829b --- /dev/null +++ b/shared/src/test/java/com/itsaky/androidide/memprof/MemprofLinesTest.kt @@ -0,0 +1,79 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import com.google.common.truth.Truth.assertThat +import org.junit.Test + +/** Pins [MemprofLines] against the regexes the memprof harness scripts parse them with. */ +class MemprofLinesTest { + @Test + fun `phaseLine matches the harness PHASE regex and carries only its explicit details`() { + val line = MemprofLines.phaseLine("cache_parsed", 1_700_000_000_123, mapOf("bytes" to 512, "durationMs" to 40)) + + val match = PHASE_REGEX.find(line) + + assertThat(match).isNotNull() + assertThat(match!!.groupValues[1]).isEqualTo("cache_parsed") + assertThat(match.groupValues[2]).isEqualTo("1700000000123") + assertThat(match.groupValues[3]).isEqualTo("|bytes=512|durationMs=40") + } + + @Test + fun `phaseLine with no details still matches the harness PHASE regex`() { + val line = MemprofLines.phaseLine("workspace_built", 1_700_000_000_000, emptyMap()) + + assertThat(PHASE_REGEX.find(line)).isNotNull() + assertThat(line).isEqualTo("PHASE|workspace_built|1700000000000") + } + + @Test + fun `phaseAbandonedLine does not match the harness PHASE regex`() { + val line = MemprofLines.phaseAbandonedLine("source_scan_complete", 1_700_000_000_000, emptyMap()) + + assertThat(PHASE_REGEX.containsMatchIn(line)).isFalse() + } + + @Test + fun `fileLine matches the harness MEMPROF file regex with the fixed field shape`() { + val line = + MemprofLines.fileLine( + nowMs = 1_700_000_000_456, + allocBytes = 2048, + durationMs = 12, + path = "/proj/Foo.kt", + name = "Index Kotlin file", + completed = true, + ) + + val match = FILE_REGEX.find(line) + + assertThat(match).isNotNull() + assertThat(match!!.groupValues[1]).isEqualTo("1700000000456") + assertThat(match.groupValues[2]) + .isEqualTo("allocBytes=2048|durationMs=12|path=/proj/Foo.kt|name=Index Kotlin file|completed=true") + } + + private companion object { + /** `parse_phases.py`'s PHASE regex. */ + val PHASE_REGEX = Regex("""PHASE\|([a-z_]+)\|(\d+)((?:\|[a-zA-Z]+=[^|\s]+)*)""") + + /** `alloc_budget.py`'s FILE regex. */ + val FILE_REGEX = Regex("""MEMPROF\|file\|(\d+)\|(.*)""") + } +} diff --git a/shared/src/test/java/com/itsaky/androidide/memprof/MemprofReportTest.kt b/shared/src/test/java/com/itsaky/androidide/memprof/MemprofReportTest.kt new file mode 100644 index 0000000000..b6afef375a --- /dev/null +++ b/shared/src/test/java/com/itsaky/androidide/memprof/MemprofReportTest.kt @@ -0,0 +1,140 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import com.google.common.truth.Truth.assertThat +import org.junit.Test +import java.time.ZoneOffset + +class MemprofReportTest { + private val report = MemprofReport(processStartMs = START, heapLimitBytes = 512 * MB, zone = ZoneOffset.UTC) + + @Test + fun `a finished phase reports its time, allocation, retention, peak and blocking GCs`() { + val phase = report.phaseStarted("Parse project model", START + 12_000, counters(alloc = 100, freed = 60, gcs = 3)) + report.sampled(usedBytes = 210 * MB) + report.phaseEnded(phase, START + 13_200, counters(alloc = 149, freed = 74, gcs = 3), emptyMap()) + + val row = rowOf(render(), "Parse project model") + + assertThat(row).containsExactly("Parse project model", "+12.0 s", "1.2 s", "49 MB", "35 MB", "210 MB", "0").inOrder() + } + + @Test + fun `a phase still running is measured up to the render and marked in progress`() { + report.phaseStarted("Index Kotlin sources", START + 80_000, counters(alloc = 1_000, gcs = 10)) + + val rendered = report.render(START + 90_000, counters(alloc = 3_000, gcs = 407, used = 500)) + val row = rowOf(rendered, "Index Kotlin sources") + + assertThat(row) + .containsExactly( + "Index Kotlin sources", + "+80.0 s", + "10.0 s", + "2,000 MB", + "2,000 MB", + "500 MB", + "397", + "(in progress)", + ).inOrder() + } + + @Test + fun `an abandoned phase is shown as stopped early, with its details`() { + val phase = report.phaseStarted("Index Kotlin sources", START, counters()) + report.phaseEnded(phase, START + 1, counters(), mapOf("indexed" to 79), completed = false) + + assertThat(rowOf(render(), "Index Kotlin sources").last()).isEqualTo("(stopped early) indexed=79") + } + + @Test + fun `a byte-valued detail is shown in megabytes`() { + val phase = report.phaseStarted("Parse project model", START, counters()) + report.phaseEnded(phase, START + 1, counters(), mapOf("bytes" to 20 * MB, "files" to 1683)) + + assertThat(rowOf(render(), "Parse project model").last()).isEqualTo("bytes=20 MB files=1,683") + } + + @Test + fun `repeated work names its largest single instance`() { + report.sectionEnded("Index Kotlin file", "HelpActivity.kt", durationMs = 800, allocatedBytes = 9 * MB) + report.sectionEnded("Index Kotlin file", "ActionItem.kt", durationMs = 31_400, allocatedBytes = 2_049 * MB) + + val row = rowOf(render(), "Index Kotlin file") + + assertThat(row) + .containsExactly("Index Kotlin file", "2", "32.2 s", "2,058 MB", "ActionItem.kt: 2,049 MB in 31.4 s") + .inOrder() + } + + @Test + fun `the heap peak names the phase it happened in`() { + val phase = report.phaseStarted("Index Kotlin sources", START, counters()) + report.sampled(usedBytes = 512 * MB) + report.phaseEnded(phase, START + 1, counters(used = 300), emptyMap()) + + assertThat(render()).contains("Heap peak 512 MB of 512 MB, during \"Index Kotlin sources\"") + } + + @Test + fun `a peak before any phase is attributed to no phase`() { + report.sampled(usedBytes = 100 * MB) + + assertThat(render()).contains("Heap peak 100 MB of 512 MB, outside any phase") + } + + @Test + fun `a report with no phases says so`() { + assertThat(render()).contains("Phases\n none yet") + } + + @Test + fun `open phases are tracked until each one ends`() { + val phase = report.phaseStarted("Parse project model", START, counters()) + assertThat(report.hasOpenPhases).isTrue() + + report.phaseEnded(phase, START + 1, counters(), emptyMap()) + + assertThat(report.hasOpenPhases).isFalse() + } + + private fun render(): String = report.render(START + 200_000, counters()) + + private fun rowOf( + rendered: String, + title: String, + ): List = + rendered + .lines() + .single { it.trimStart().startsWith(title) } + .trim() + .split(Regex("\\s{2,}")) + + private fun counters( + alloc: Long = 0, + freed: Long = 0, + gcs: Long = 0, + used: Long = 0, + ) = HeapCounters(allocatedBytes = alloc * MB, freedBytes = freed * MB, blockingGcCount = gcs, usedBytes = used * MB) + + private companion object { + const val MB = 1024L * 1024L + const val START = 1_790_000_000_000L + } +} diff --git a/shared/src/test/java/com/itsaky/androidide/memprof/MemprofTest.kt b/shared/src/test/java/com/itsaky/androidide/memprof/MemprofTest.kt new file mode 100644 index 0000000000..26d9df2f89 --- /dev/null +++ b/shared/src/test/java/com/itsaky/androidide/memprof/MemprofTest.kt @@ -0,0 +1,189 @@ +/* + * This file is part of AndroidIDE. + * + * AndroidIDE is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * AndroidIDE is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with AndroidIDE. If not, see . + */ + +package com.itsaky.androidide.memprof + +import com.google.common.truth.Truth.assertThat +import org.junit.After +import org.junit.Assert.assertThrows +import org.junit.Test + +class MemprofTest { + private val sink = RecordingSink() + + @After + fun uninstallSink() { + Memprof.sink = null + } + + @Test + fun `a phase without a sink runs its action with the inert span`() { + val seen = Memprof.phase("Parse project model", "cache_parsed") { span -> span } + + assertThat(seen).isSameInstanceAs(MemprofSpan.None) + } + + @Test + fun `a phase returns what its action returns`() { + Memprof.sink = sink + + val result = Memprof.phase("Parse project model", "cache_parsed") { 42 } + + assertThat(result).isEqualTo(42) + } + + @Test + fun `a phase ends its span once when the action returns`() { + Memprof.sink = sink + + Memprof.phase("Parse project model", "cache_parsed") {} + + assertThat(sink.events).containsExactly("begin phase cache_parsed", "end phase cache_parsed").inOrder() + } + + @Test + fun `a phase is abandoned, not ended, when the action throws`() { + Memprof.sink = sink + + assertThrows(IllegalStateException::class.java) { + Memprof.phase("Parse project model", "cache_parsed") { error("parse failed") } + } + + assertThat(sink.events).containsExactly("begin phase cache_parsed", "abandon cache_parsed").inOrder() + } + + @Test + fun `a section is abandoned when the action throws`() { + Memprof.sink = sink + + assertThrows(IllegalStateException::class.java) { + Memprof.section("Index Kotlin file", "Foo.kt") { error("index failed") } + } + + assertThat(sink.events) + .containsExactly("begin section Index Kotlin file Foo.kt", "abandon Index Kotlin file") + .inOrder() + } + + @Test + fun `a non-local return out of a phase abandons it, not ends it`() { + Memprof.sink = sink + + returnOutOfPhase() + + assertThat(sink.events).containsExactly("begin phase cache_parsed", "abandon cache_parsed").inOrder() + } + + private fun returnOutOfPhase() { + Memprof.phase("Parse project model", "cache_parsed") { return } + } + + @Test + fun `a break out of a loop inside a section abandons it, not ends it`() { + Memprof.sink = sink + + for (i in 0 until 3) { + Memprof.section("Index Kotlin file", "Foo.kt") { break } + } + + assertThat(sink.events) + .containsExactly("begin section Index Kotlin file Foo.kt", "abandon Index Kotlin file") + .inOrder() + } + + @Test + fun `details put on a phase reach the sink before it ends`() { + Memprof.sink = sink + + Memprof.phase("Parse project model", "cache_parsed") { span -> span.put("bytes", 7) } + + assertThat(sink.events) + .containsExactly("begin phase cache_parsed", "put cache_parsed bytes=7", "end phase cache_parsed") + .inOrder() + } + + @Test + fun `a manually started phase without a sink is the inert span`() { + assertThat(Memprof.beginPhase("Scan Kotlin sources", "source_scan_complete")) + .isSameInstanceAs(MemprofSpan.None) + } + + @Test + fun `a mark reaches an installed sink`() { + Memprof.sink = sink + + Memprof.mark("sync_complete") + + assertThat(sink.events).containsExactly("mark sync_complete") + } + + private class RecordingSink : MemprofSink { + val events = mutableListOf() + + override fun beginPhase( + title: String, + marker: String, + ): MemprofSpan { + events += "begin phase $marker" + return RecordingSpan(marker, "end phase $marker") + } + + override fun beginSection( + name: String, + detail: String?, + ): MemprofSpan { + events += "begin section $name $detail" + return RecordingSpan(name, "end section $name") + } + + override fun mark(marker: String) { + events += "mark $marker" + } + + private inner class RecordingSpan( + private val label: String, + private val endEvent: String, + ) : MemprofSpan { + private var finished = false + + override val isRecording: Boolean = true + + override fun put( + key: String, + value: Long, + ) { + events += "put $label $key=$value" + } + + // Idempotent, matching MemprofSpan's documented contract: once ended or abandoned, + // further calls do nothing. + override fun end() { + if (!finished) { + finished = true + events += endEvent + } + } + + override fun abandon() { + if (!finished) { + finished = true + events += "abandon $label" + } + } + } + } +} diff --git a/subprojects/projects/src/main/java/com/itsaky/androidide/projects/ProjectManagerImpl.kt b/subprojects/projects/src/main/java/com/itsaky/androidide/projects/ProjectManagerImpl.kt index 20a5f1c9a7..389d9b928e 100644 --- a/subprojects/projects/src/main/java/com/itsaky/androidide/projects/ProjectManagerImpl.kt +++ b/subprojects/projects/src/main/java/com/itsaky/androidide/projects/ProjectManagerImpl.kt @@ -30,6 +30,7 @@ import com.itsaky.androidide.eventbus.events.file.FileEvent import com.itsaky.androidide.eventbus.events.file.FileRenameEvent import com.itsaky.androidide.eventbus.events.project.ProjectInitializedEvent import com.itsaky.androidide.lookup.Lookup +import com.itsaky.androidide.memprof.Memprof import com.itsaky.androidide.project.AndroidModels import com.itsaky.androidide.project.GradleModels import com.itsaky.androidide.projects.api.AndroidModule @@ -148,6 +149,7 @@ class ProjectManagerImpl : ) val workspace = this.workspace!! + Memprof.mark("workspace_built") // build variants must be updated before the sources and class paths are indexed updateBuildVariants { buildVariants -> @@ -165,26 +167,28 @@ class ProjectManagerImpl : } withStopWatch("Setup project") { - val indexerScope = CoroutineScope(Dispatchers.Default) - val modulesFlow = - flow { - workspace.subProjects.filterIsInstance().forEach { - emit(it) + Memprof.phase("Index module classpaths and sources", "indexing_complete") { + val indexerScope = CoroutineScope(Dispatchers.Default) + val modulesFlow = + flow { + workspace.subProjects.filterIsInstance().forEach { + emit(it) + } } - } - val jobs = - modulesFlow.map { module -> - indexerScope.async { - module.indexSourcesAndClasspaths() - if (module is AndroidModule) { - module.readResources() + val jobs = + modulesFlow.map { module -> + indexerScope.async { + module.indexSourcesAndClasspaths() + if (module is AndroidModule) { + module.readResources() + } } } - } - // wait for the indexing to finish - jobs.toList().awaitAll() + // wait for the indexing to finish + jobs.toList().awaitAll() + } } reportUnreadableClasspathJars(workspace)