From 815b93db5f280e6fa0ddc98c15058df3380bc85f Mon Sep 17 00:00:00 2001 From: Kurt Himebauch <136133082+xXJSONDeruloXx@users.noreply.github.com> Date: Sun, 25 Oct 2026 16:49:35 -0400 Subject: [PATCH] feat: profile PRoot costs and test fast-path libraries without an APK rebuild (#1528) --- .../com/droiddeck/launcher/agent/AgentEnv.kt | 47 ++++++++- .../droiddeck/launcher/core/HostProcess.kt | 11 ++- .../launcher/session/SessionFiles.kt | 6 +- .../launcher/session/SessionService.kt | 12 ++- .../launcher/agent/AgentSecurityTest.kt | 27 +++++ .../launcher/core/HostProcessTest.kt | 37 +++++++ docs/agent-control.md | 15 +++ docs/development/proot-performance.md | 90 +++++++++++++++++ tools/droiddeckctl | 33 ++++++- tools/proot/PATCHES.md | 8 ++ tools/proot/build.sh | 1 + .../0018-syscall-handler-profile.patch | 38 +++++++ tools/proot/profile.h | 99 +++++++++++++++++++ tools/proot_profile.py | 56 +++++++++++ tools/tests/test_droiddeckctl.py | 15 +++ tools/tests/test_proot_profile.py | 91 +++++++++++++++++ tools/tests/test_session_guest_command.py | 2 +- 17 files changed, 578 insertions(+), 10 deletions(-) create mode 100644 app/src/test/java/com/droiddeck/launcher/core/HostProcessTest.kt create mode 100644 tools/proot/patches/0018-syscall-handler-profile.patch create mode 100644 tools/proot/profile.h create mode 100644 tools/proot_profile.py create mode 100644 tools/tests/test_proot_profile.py diff --git a/app/src/main/java/com/droiddeck/launcher/agent/AgentEnv.kt b/app/src/main/java/com/droiddeck/launcher/agent/AgentEnv.kt index 5f7f09262..e15fbab41 100644 --- a/app/src/main/java/com/droiddeck/launcher/agent/AgentEnv.kt +++ b/app/src/main/java/com/droiddeck/launcher/agent/AgentEnv.kt @@ -3,9 +3,13 @@ package com.droiddeck.launcher.agent import android.content.Context import android.util.Log import com.droiddeck.launcher.runtime.LinuxRuntime +import com.droiddeck.launcher.runtime.ProotFastPath +import com.droiddeck.launcher.session.SessionPhase +import com.droiddeck.launcher.session.SessionState import org.json.JSONArray import org.json.JSONObject import java.io.File +import java.security.MessageDigest import java.nio.file.Files import java.nio.file.LinkOption.NOFOLLOW_LINKS import java.nio.file.StandardOpenOption.READ @@ -55,6 +59,9 @@ object AgentEnv { fun override(context: Context, name: String): JSONObject = synchronized(lock) { AgentAccess.requireCommands(context) if (NAME.matchEntire(name) == null || name in setOf(".", "..")) throw AgentException("INVALID_NAME", "Override names are letters, digits, '.', '_' and '-'") + if (name == "libblfastpath.so" && (SessionState.running || SessionState.guestPid > 0 || SessionState.phase == SessionPhase.STOPPING)) { + throw AgentException("SESSION_ACTIVE", "Stop the session before installing a fast-path library") + } val source = File(inbox(context), name) if (Files.isSymbolicLink(source.toPath())) throw AgentException("INVALID_NAME", "The override must be a regular file") if (!source.isFile) throw AgentException("NO_SUCH_FILE", "Push the binary to ${source.path} first") @@ -67,6 +74,10 @@ object AgentEnv { staged.delete() throw AgentException("OVERRIDE_FAILED", "Could not stage the override") } + if (name == "libblfastpath.so" && !arm64SharedLibrary(staged)) { + staged.delete() + throw AgentException("INVALID_LIBRARY", "The fast path must be a 64-bit little-endian ARM64 ELF shared library") + } if (!staged.setExecutable(true, false) || !staged.renameTo(target)) { staged.delete() throw AgentException("OVERRIDE_FAILED", "Could not install $name in the rootfs") @@ -76,6 +87,40 @@ object AgentEnv { state.put("pendingOverrides", JSONArray(merge(strings(state.optJSONArray("pendingOverrides")), listOf(name)))) save(context, state) state.put("installed", "$GUEST_BIN/$name") + if (name == "libblfastpath.so") { + val digest = MessageDigest.getInstance("SHA-256") + target.inputStream().use { input -> + val buffer = ByteArray(65536) + while (true) { + val count = input.read(buffer) + if (count < 0) break + digest.update(buffer, 0, count) + } + } + state.put("sha256", digest.digest().joinToString("") { "%02x".format(it) }) + } + state + } + + fun fastPathLibrary(context: Context): String = synchronized(lock) { + if (!AgentAccess.commandsAllowed(context)) return@synchronized ProotFastPath.LIBRARY + if ("libblfastpath.so" !in strings(load(context).optJSONArray("activeOverrides"))) return@synchronized ProotFastPath.LIBRARY + val file = File(bin(context), "libblfastpath.so") + if (!file.isFile || Files.isSymbolicLink(file.toPath())) return@synchronized ProotFastPath.LIBRARY + "$GUEST_BIN/libblfastpath.so" + } + + private fun arm64SharedLibrary(file: File): Boolean = file.inputStream().use { input -> + val header = ByteArray(20) + var count = 0 + while (count < header.size) { + val read = input.read(header, count, header.size - count) + if (read < 0) return@use false + count += read + } + header.take(7) == listOf(0x7f, 0x45, 0x4c, 0x46, 2, 1, 1) && + header[16] == 3.toByte() && header[17] == 0.toByte() && + header[18] == 183.toByte() && header[19] == 0.toByte() } fun beginSession(context: Context): List = synchronized(lock) { @@ -92,7 +137,7 @@ object AgentEnv { bin(context).listFiles() ?.filter { it.name !in overrides }?.forEach { it.delete() } val lines = strings(state.optJSONArray("persistent")) + active - val withPath = if (overrides.isEmpty()) lines else lines + "PATH=$GUEST_BIN:${pathOf(lines)}" + val withPath = if (overrides.none { it != "libblfastpath.so" }) lines else lines + "PATH=$GUEST_BIN:${pathOf(lines)}" if (withPath.isNotEmpty()) Log.i(TAG, "agent environment keys for this session: ${withPath.map { it.substringBefore('=') }}") withPath } diff --git a/app/src/main/java/com/droiddeck/launcher/core/HostProcess.kt b/app/src/main/java/com/droiddeck/launcher/core/HostProcess.kt index 4a8b12934..075719246 100644 --- a/app/src/main/java/com/droiddeck/launcher/core/HostProcess.kt +++ b/app/src/main/java/com/droiddeck/launcher/core/HostProcess.kt @@ -8,7 +8,11 @@ object HostProcess { private const val TAG = "HostProcess" @JvmStatic - fun start(command: String, env: Array?, dir: File?, onExit: Consumer?, onLine: Consumer?): Int { + fun start(command: String, env: Array?, dir: File?, onExit: Consumer?, onLine: Consumer?): Int = + start(command, env, dir, onExit, onLine, null) + + @JvmStatic + fun start(command: String, env: Array?, dir: File?, onExit: Consumer?, onLine: Consumer?, outputFile: File?): Int { val argv = split(command) if (argv.isEmpty()) return -1 return try { @@ -19,7 +23,10 @@ object HostProcess { if (eq > 0) builder.environment()[line.substring(0, eq)] = line.substring(eq + 1) } builder.redirectErrorStream(true) - if (onLine == null) builder.redirectOutput(File("/dev/null")) + if (onLine == null) { + if (outputFile == null) builder.redirectOutput(File("/dev/null")) + else builder.redirectOutput(ProcessBuilder.Redirect.appendTo(outputFile)) + } val process = builder.start() val pid = pidOf(process) Log.i(TAG, "started pid $pid: ${argv.first()} (${argv.size - 1} arguments)") diff --git a/app/src/main/java/com/droiddeck/launcher/session/SessionFiles.kt b/app/src/main/java/com/droiddeck/launcher/session/SessionFiles.kt index 958aa2df5..73c2c915f 100644 --- a/app/src/main/java/com/droiddeck/launcher/session/SessionFiles.kt +++ b/app/src/main/java/com/droiddeck/launcher/session/SessionFiles.kt @@ -208,7 +208,11 @@ object SessionFiles { if (!File(Environment.getExternalStorageDirectory(), NO_PAD_SWITCH).exists()) { preload.append("/usr/local/lib/libfakeinput.so\n") } - if (ProotFastPath.enabled(context)) preload.append(ProotFastPath.LIBRARY + "\n") + if (ProotFastPath.enabled(context)) { + val library = com.droiddeck.launcher.agent.AgentEnv.fastPathLibrary(context) + preload.append(library + "\n") + if (startsSession && library != ProotFastPath.LIBRARY) Log.i(TAG, "fast path preload: $library (debugging override)") + } val etc = File(root, "etc").apply { mkdirs() } val staged = File(etc, "ld.so.preload.staged") if (!FileUtils.writeString(staged, preload.toString()) diff --git a/app/src/main/java/com/droiddeck/launcher/session/SessionService.kt b/app/src/main/java/com/droiddeck/launcher/session/SessionService.kt index 630feeb92..979c737a4 100644 --- a/app/src/main/java/com/droiddeck/launcher/session/SessionService.kt +++ b/app/src/main/java/com/droiddeck/launcher/session/SessionService.kt @@ -431,6 +431,7 @@ class SessionService : Service() { killStragglers() for (pack in listOf(AddonPack.PROOT, AddonPack.DIRECTAUDIO)) if (!pack.await(this, { gen == sessionGen && SessionState.running })) Log.w(TAG, "${pack.name} pack unavailable") + val agentEnvironment = com.droiddeck.launcher.agent.AgentEnv.beginSession(this) SessionFiles.stage(this, root, startsSession = true) // Earlier sessions' reports still read the Steam logs and VAC marker this session replaces. SessionArtifacts.awaitCollections() @@ -454,7 +455,7 @@ class SessionService : Service() { .onSuccess { if (it != null) Log.i(TAG, it) } .onFailure { Log.w(TAG, "forced components", it) } } - addClientEnvironment(guest, steamHere) + addClientEnvironment(guest, steamHere, agentEnvironment) if (steamHere) guest.add("BL_EPIC_APP_ID=" + com.droiddeck.launcher.stores.epic.EpicClient.shortcutAppId) val fastPathAt = guest.size @@ -574,6 +575,9 @@ class SessionService : Service() { Log.i(TAG, "proot: seccomp acceleration off by request") } fastPathKey?.let { ProotFastPath.hostEnv(it).let { (k, v) -> hostEnv[k] = v } } + for (key in listOf("PROOT_PROFILE", "PROOT_PROFILE_SLOW_US")) { + guest.lastOrNull { it.startsWith("$key=") }?.substringAfter('=')?.let { hostEnv[key] = it } + } val prootLibs = LinuxRuntime.prootLibraryPath(this) if (prootLibs.isNotEmpty()) hostEnv["LD_LIBRARY_PATH"] = prootLibs @@ -616,7 +620,7 @@ class SessionService : Service() { val program = programStatus(sessionRoot) Log.i(TAG, "session ended: $status" + if (program != null) " (program $program)" else "") stopSession(program ?: status ?: -1) - }, null) + }, null, sessionLog.takeIf { "PROOT_PROFILE=1" in hostEnv.asArray() }) Log.i(TAG, "session pid $pid, log ${sessionLog.path}") if (gen != sessionGen || !SessionState.running) { Log.i(TAG, "session stopped while its guest was starting; taking it down") @@ -689,7 +693,7 @@ class SessionService : Service() { return sessionDir } - private fun addClientEnvironment(guest: MutableList, steamHere: Boolean) { + private fun addClientEnvironment(guest: MutableList, steamHere: Boolean, agentEnvironment: List) { guest.add("/usr/bin/env") guest.add("-i") guest.add("DROIDDECK_BWRAP_SOCKET=" + com.droiddeck.launcher.runtime.BwrapSpawner.socket(this)) @@ -760,7 +764,7 @@ class SessionService : Service() { } SessionPrefs.vramCapMb(this).takeIf { it > 0 }?.let { guest.add("BL_VRAM_MB=$it") } guest.add("BANNER_AUDIO_DIRECT_DECAY=0") - val extra = extraEnv() + com.droiddeck.launcher.agent.AgentEnv.beginSession(this) + val extra = extraEnv() + agentEnvironment if (extra.none { it.startsWith("TU_DEBUG=") }) guest.add("$GAME_TU_DEBUG=" + (tuOverride ?: if (tuDriver) "sysmem" else "")) extra.forEach { guest.add(it) } com.droiddeck.launcher.gpu.TpUbwcHint.forThisDevice(this)?.let { guest.add("${com.droiddeck.launcher.gpu.TpUbwcHint.ENV}=$it") } diff --git a/app/src/test/java/com/droiddeck/launcher/agent/AgentSecurityTest.kt b/app/src/test/java/com/droiddeck/launcher/agent/AgentSecurityTest.kt index df4bb15fc..f625d6b41 100644 --- a/app/src/test/java/com/droiddeck/launcher/agent/AgentSecurityTest.kt +++ b/app/src/test/java/com/droiddeck/launcher/agent/AgentSecurityTest.kt @@ -9,6 +9,8 @@ import androidx.compose.ui.semantics.SemanticsProperties import androidx.compose.ui.text.AnnotatedString import com.droiddeck.launcher.R import com.droiddeck.launcher.runtime.LinuxRuntime +import com.droiddeck.launcher.runtime.ProotFastPath +import com.droiddeck.launcher.session.SessionState import org.json.JSONObject import org.junit.Assert.* import org.junit.After @@ -179,6 +181,31 @@ class AgentSecurityTest { assertEquals(listOf("TEST=old", "STICKY=1"), AgentEnv.beginSession(context)) } + @Test fun fastPathLibraryIsValidatedAndSelectedForOneSession() { + AgentAccess.setCommandsEnabled(context, true) + val source = File(AgentEnv.inbox(context).apply { mkdirs() }, "libblfastpath.so") + source.writeText("wrong architecture") + refused("INVALID_LIBRARY") { AgentEnv.override(context, source.name) } + val header = ByteArray(64) + byteArrayOf(0x7f, 0x45, 0x4c, 0x46, 2, 1, 1).copyInto(header) + header[16] = 3 + header[18] = 183.toByte() + source.writeBytes(header) + SessionState.running = true + try { + refused("SESSION_ACTIVE") { AgentEnv.override(context, source.name) } + } finally { + SessionState.running = false + } + val response = AgentEnv.override(context, source.name) + assertEquals(64, response.getString("sha256").length) + assertEquals(ProotFastPath.LIBRARY, AgentEnv.fastPathLibrary(context)) + AgentEnv.beginSession(context) + assertEquals("/opt/droiddeck-agent/bin/libblfastpath.so", AgentEnv.fastPathLibrary(context)) + AgentEnv.endSession(context) + assertEquals(ProotFastPath.LIBRARY, AgentEnv.fastPathLibrary(context)) + } + @Test fun environmentValuesAreNotLogged() { AgentAccess.setCommandsEnabled(context, true) AgentEnv.set(context, listOf("CUSTOM=synthetic-private-value"), false) diff --git a/app/src/test/java/com/droiddeck/launcher/core/HostProcessTest.kt b/app/src/test/java/com/droiddeck/launcher/core/HostProcessTest.kt new file mode 100644 index 000000000..6fbe7ed10 --- /dev/null +++ b/app/src/test/java/com/droiddeck/launcher/core/HostProcessTest.kt @@ -0,0 +1,37 @@ +package com.droiddeck.launcher.core + +import org.junit.Assert.assertEquals +import org.junit.Assert.assertTrue +import org.junit.Rule +import org.junit.Test +import org.junit.rules.TemporaryFolder +import org.junit.runner.RunWith +import org.robolectric.RobolectricTestRunner +import org.robolectric.annotation.Config +import java.util.concurrent.CountDownLatch +import java.util.concurrent.TimeUnit + +@RunWith(RobolectricTestRunner::class) +@Config(sdk = [28], manifest = Config.NONE) +class HostProcessTest { + @get:Rule val temporary = TemporaryFolder() + + @Test fun appendsBothOutputStreamsToTheExistingLog() { + val windows = System.getProperty("os.name").orEmpty().startsWith("Windows") + val log = temporary.newFile("session.log").apply { writeText("guest output\n") } + val script = temporary.newFile(if (windows) "tracer.cmd" else "tracer.sh").apply { + writeText(if (windows) "@echo off\r\necho tracer stdout\r\necho tracer stderr>&2\r\n" + else "printf 'tracer stdout\\n'\nprintf 'tracer stderr\\n' >&2\n") + } + val finished = CountDownLatch(1) + var exitCode = -1 + val shell = if (windows) "cmd.exe /c" else "/bin/sh" + HostProcess.start("$shell ${script.name}", null, temporary.root, { + exitCode = it + finished.countDown() + }, null, log) + assertTrue(finished.await(5, TimeUnit.SECONDS)) + assertEquals(0, exitCode) + assertEquals(listOf("guest output", "tracer stdout", "tracer stderr"), log.readLines()) + } +} diff --git a/docs/agent-control.md b/docs/agent-control.md index b3ec1c073..5dc16253e 100644 --- a/docs/agent-control.md +++ b/docs/agent-control.md @@ -113,6 +113,10 @@ tools/droiddeckctl env set DXVK_HUD=fps tools/droiddeckctl env list tools/droiddeckctl env clear [next|persistent|all] tools/droiddeckctl override gamescope ./gamescope +tools/droiddeckctl override libblfastpath.so ./libblfastpath.so +tools/droiddeckctl proot-profile enable --slow-us 1000 +tools/droiddeckctl proot-profile disable +tools/droiddeckctl proot-profile report ./session.log --sort wall tools/droiddeckctl prefs get session tools/droiddeckctl prefs set session some_key true --type bool @@ -367,3 +371,14 @@ sees it, and quits it: the test that catches a game left behind Steam's loading shows up in some fraction of launches. A game with a launcher of its own needs the launcher pressed through first, since the launcher window carries the game's app id too: `tools/scenarios/skyrim-launcher-focus.json` taps Skyrim's Play before checking. + +## PRoot performance experiments + +`proot-profile enable` queues handler profiling for the next session using the existing debugging +consent gate. Counters and bounded slow samples appear in `session.log`; `proot-profile report` +ranks a saved local log without ADB. This measures PRoot handler work, not full syscall latency. +`override libblfastpath.so FILE` selects a glibc ARM64 shared library in the next session's preload +list, reports its SHA-256, and refuses installation until the current session stops. It lasts for +one session; the next session stages the bundled library again. See +[the profiling workflow](development/proot-performance.md#finding-the-next-fast-path) for timing +boundaries, build commands, path diagnostics, and A/B validation. diff --git a/docs/development/proot-performance.md b/docs/development/proot-performance.md index 217650b53..bcf3424c1 100644 --- a/docs/development/proot-performance.md +++ b/docs/development/proot-performance.md @@ -314,3 +314,93 @@ it needs `patches/0014`, enabled with `PROOT_FASTPATH=1`. and `PROOT_FP_STATS` hit rates for steam, steamwebhelper, wine and wineserver. - **FEX**, inside Proton as a DLL, translates x86 path syscalls through glibc's `syscall()`, not the wrappers, so they still trap. A `syscall()` hook could route `openat` and `newfstatat` there too. + +## Finding the next fast path + +The prototype notes above describe the original experiments. Main now includes the fast path, +expanded wrappers, FEX raw-open routing ([#1283](https://github.com/Droid-Deck/DroidDeck/pull/1283)), +and SD-library bind-name resolution ([#1331](https://github.com/Droid-Deck/DroidDeck/pull/1331)). +Those fixes show why wrapper hit rates alone are insufficient: a caller can bypass the wrappers, +or repeatedly hit a path the wrappers cannot resolve. + +### Opt-in tracer profiling + +With **Setup > Diagnostics > Debugging tools** enabled, queue profiling for one session: + +```sh +tools/droiddeckctl proot-profile enable --slow-us 1000 +tools/droiddeckctl start steam --wait +# Reproduce the startup, game load, or streaming workload. +tools/droiddeckctl stop +tools/droiddeckctl logs latest ./profile-run +tools/droiddeckctl proot-profile report ./profile-run/session.log --sort wall +# Also inspect --sort cpu and --sort calls. +``` + +`PROOT_PROFILE=1` is forwarded from the session environment to the host tracer. Patch 0018 records +entry/exit **handler visits**, including PRoot's chained calls, by portable syscall name. It emits +`proot-profile` JSON lines to the existing `session.log`: cumulative totals every five seconds while +handling calls, totals at normal exit, and up to 32 slow-handler samples per five-second window exceeding `PROOT_PROFILE_SLOW_US` +(default 1,000 microseconds). The report uses each counter's last snapshot rather than adding +snapshots together and retains the most recent 128 slow samples. Logs can be pulled and reported while the session is running; final totals can +be lost if the tracer is killed. An empty report (`hasCounters: false`) is not evidence of zero +PRoot cost: check for the `start` record and that the installed PRoot pack contains patch 0018. + +**What the clocks mean:** handler wall time includes PRoot's path translation, filesystem waits +inside the tracer, and time the tracer is descheduled inside the handler. Thread CPU time measures +CPU used by that handler. Neither clock includes the tracee's subsequent kernel syscall, the +wake-up/queue delay before handler entry, or work outside `translate_syscall` (such as standalone +SIGSYS emulation, signal delivery, and process-event handling). Fast-path calls that avoid PRoot +are absent. Counts are handler visits, not a count of all guest syscalls. No extra ptrace stops or +syscall-exit interception are enabled for profiling. Profiling still costs clock reads, counters, +and log output; turn it off for final performance measurements. + +Rank cumulative time and frequency before chasing individual outliers. High handler CPU suggests +translation work; high handler wall with low CPU suggests filesystem or scheduling waits. Neither +proves how much a new fast path would save. Reproduce with the same app/PRoot/library build, +workload, storage, CPU policy, and cache state, then alternate A/B runs and measure the real load +milestone without profiling too. Keep `PROOT_FP_OFF=1` runs for correctness comparisons. + +For path context, the existing `PROOT_FP_LOG=/tmp/fastpath-misses.log` logs wrapper fallbacks and +`PROOT_FP_STATS=1` prints per-process hit/miss counts at normal exit. These are separate opt-ins: +miss logging writes on every fallback, may contain personal paths, and cannot see callers that +bypass the wrappers. Capture it separately from the session artifact folder. The new profiler +records syscall names, numeric IDs, and timings without paths or arguments. + +### Test a replacement library without rebuilding the APK + +Build a **glibc ARM64** library using the same toolchain as the shipped fast path: + +```sh +docker run --rm --platform linux/amd64 --user "$(id -u):$(id -g)" \ + -v "$PWD:/src" -w /src droiddeck-local-cross:24.04-v3 \ + aarch64-linux-gnu-gcc -shared -fPIC -O2 -Wall -pthread \ + -o /src/libblfastpath.so tools/proot/fastpath/fastpath.c -ldl + +tools/droiddeckctl stop +tools/droiddeckctl override libblfastpath.so ./libblfastpath.so +tools/droiddeckctl proot-profile enable +tools/droiddeckctl start steam --wait +``` + +The existing override bridge now recognizes `libblfastpath.so`: it checks ELF class, endianness, +type, and machine, reports SHA-256, and selects that file in `/etc/ld.so.preload` for one session. +It rejects installation while a session is active. This is an architecture check, not validation +of libc compatibility or the library's behavior. The fast path still requires its normal enabled +setting and the patched PRoot pack. Its basename stays `libblfastpath.so`, so `libblsession`'s FEX +routing finds it. Guest-command restaging retains the active selection. After stopping, the next +session stages the bundled preload again; `env clear all` cancels queued overrides. + +This replaces a library **for a fresh session**. It does not rebind already-resolved symbols in +running Wine/FEX processes, unload old code, or load arbitrary plug-ins through a new ABI. True +in-process patching would need an explicit dispatch API and synchronization across every process. +[The dynamic loader](https://man7.org/linux/man-pages/man3/dlopen.3.html) resolves symbols within each process. +For now, restarting the session avoids those lifetime and binding problems while removing APK +build/install time from a fast-path iteration. Changes to the trampoline/filter contract still +require a matching PRoot build, not just a library swap. The profiler itself also needs a new +PRoot pack; CI builds and pins that pack alongside the APK. + +The next useful extensions are bounded path sampling tied to handler time, separate process/signal +stop counters, and scenario reports that compare the same game-load milestone across builds. +Keep candidate fast paths behind equivalence tests: a slow symlink, `/proc` lookup, unsupported +flag, or ambiguous bind must retain PRoot's semantics. diff --git a/tools/droiddeckctl b/tools/droiddeckctl index 9544e65c7..b3a6c2d5b 100755 --- a/tools/droiddeckctl +++ b/tools/droiddeckctl @@ -21,6 +21,7 @@ from pathlib import Path sys.path.insert(0, str(Path(__file__).resolve().parent)) from adb_device import DeviceResolutionError, resolve_serial +from proot_profile import report as proot_profile_report # tools/release/variants.txt: the same app also ships as other packages (e.g. com.antutu.benchmark.full). @@ -37,6 +38,13 @@ class ControlError(RuntimeError): self.code = code +def profile_slow_us(value: str) -> int: + number = int(value) + if not 1 <= number <= 1_000_000_000: + raise argparse.ArgumentTypeError("--slow-us must be between 1 and 1000000000") + return number + + def adb_path(configured: str | None) -> str: if configured: return configured @@ -628,6 +636,10 @@ def execute(args: argparse.Namespace, adb: str, serial: str) -> dict: request["text"] = args.text return add_serial(checked(provider_call(adb, serial, "ui", request=request), "UI_FAILED"), serial) + if command == "proot-profile": + lines = ["PROOT_PROFILE=1", f"PROOT_PROFILE_SLOW_US={args.slow_us}"] if args.profile_op == "enable" else ["PROOT_PROFILE=0"] + return add_serial(checked(provider_call(adb, serial, "env", request={"op": "set", "lines": lines, "persistent": False}), "ENV_FAILED"), serial) + if command == "env": if args.env_op == "set": request = {"op": "set", "lines": args.lines, "persistent": args.persistent} @@ -828,6 +840,16 @@ def build_parser() -> argparse.ArgumentParser: if name == "set-text": op.add_argument("--text", required=True) + profile = commands.add_parser("proot-profile", help="profile PRoot syscall handlers in the next session, or rank a saved log") + profile_ops = profile.add_subparsers(dest="profile_op", required=True) + profile_enable = profile_ops.add_parser("enable", help="enable counters and bounded slow samples for the next session") + profile_enable.add_argument("--slow-us", type=profile_slow_us, default=1000, metavar="US") + profile_ops.add_parser("disable", help="disable profiling for the next session") + profile_report = profile_ops.add_parser("report", help="read a local session.log without a device") + profile_report.add_argument("path", type=Path) + profile_report.add_argument("--sort", choices=["wall", "cpu", "calls"], default="wall") + profile_report.add_argument("--limit", type=int, default=20) + env = commands.add_parser("env", help="session environment lines (debugging tools)") env_ops = env.add_subparsers(dest="env_op", required=True) env_ops.add_parser("list") @@ -837,7 +859,7 @@ def build_parser() -> argparse.ArgumentParser: env_clear = env_ops.add_parser("clear") env_clear.add_argument("scope", nargs="?", choices=["next", "persistent", "all"], default="next") - override = commands.add_parser("override", help="put a binary first on the next session's PATH (debugging tools)") + override = commands.add_parser("override", help="override a program or libblfastpath.so for the next session (debugging tools)") override.add_argument("name", help="the program name, e.g. gamescope") override.add_argument("path", help="the local file to push") @@ -941,6 +963,15 @@ def main(argv: list[str] | None = None) -> int: try: if not PACKAGE_NAME.fullmatch(PACKAGE): # it reaches the device shell through `am start` and `content call` raise ControlError(f"DROIDDECK_PACKAGE is not an Android package name: {PACKAGE!r}", "INVALID_REQUEST") + if args.command == "proot-profile" and args.profile_op == "report": + if args.limit < 1: + raise ControlError("--limit must be positive", "INVALID_ARGUMENTS") + try: + result = proot_profile_report(args.path.expanduser(), args.sort, args.limit) + except OSError as exc: + raise ControlError(str(exc), "FILE_IO") from exc + print(json.dumps(result, indent=2, sort_keys=True)) + return 0 adb = adb_path(args.adb) serial = resolve_serial(adb, args.serial, log=True) result = execute(args, adb, serial) diff --git a/tools/proot/PATCHES.md b/tools/proot/PATCHES.md index f379b4d7d..a0faf4704 100644 --- a/tools/proot/PATCHES.md +++ b/tools/proot/PATCHES.md @@ -124,3 +124,11 @@ Old kernel fixes: by the kernel instead. The original clone flags are preserved. When the kernel supplies a valid ID in the notification, normal setup is unchanged. No timers or background polling are added. Completely missing notifications and ambiguous matches for separate processes are not recovered. + +Development diagnostics: + +- `0018-syscall-handler-profile.patch` - `PROOT_PROFILE=1` enables per-syscall entry/exit handler + counts, wall/CPU time, periodic cumulative JSON totals, and bounded slow-handler samples on + stderr. `profile.h` is copied into the source tree by `build.sh`. It adds no ptrace stops; + handler timing excludes tracee kernel time and scheduling before handler entry. See + `docs/development/proot-performance.md` for the capture and library-override workflow. diff --git a/tools/proot/build.sh b/tools/proot/build.sh index 718190552..5b76dd38f 100755 --- a/tools/proot/build.sh +++ b/tools/proot/build.sh @@ -31,6 +31,7 @@ fetch() { fetch proot.tar.gz "https://github.com/termux/proot/archive/${PROOT_COMMIT}.tar.gz" "$PROOT_SHA256" fetch talloc.tar.gz "https://www.samba.org/ftp/talloc/talloc-${TALLOC_VERSION}.tar.gz" "$TALLOC_SHA256" cp "$HERE/statx_mnt_id.h" "$WORK/proot/src/tracee/statx_mnt_id.h" +cp "$HERE/profile.h" "$WORK/proot/src/syscall/profile.h" for patch in "$HERE"/patches/*.patch; do patch -d "$WORK/proot" -p1 --forward --quiet < "$patch" done diff --git a/tools/proot/patches/0018-syscall-handler-profile.patch b/tools/proot/patches/0018-syscall-handler-profile.patch new file mode 100644 index 000000000..20d4859c5 --- /dev/null +++ b/tools/proot/patches/0018-syscall-handler-profile.patch @@ -0,0 +1,38 @@ +--- a/src/syscall/syscall.c ++++ b/src/syscall/syscall.c +@@ -32,6 +32,7 @@ + #include "tracee/reg.h" + #include "tracee/mem.h" + #include "cli/note.h" ++#include "syscall/profile.h" + + /** + * Copy in @path a C string (PATH_MAX bytes max.) from the @tracee's +@@ -100,7 +101,7 @@ + return set_sysarg_data(tracee, path, strlen(path) + 1, reg); + } + +-void translate_syscall(Tracee *tracee) ++static void translate_syscall_impl(Tracee *tracee) + { + const bool is_enter_stage = IS_IN_SYSENTER(tracee); + int status; +@@ -283,3 +284,18 @@ + else + print_current_regs(tracee, 4, "sysexit end"); + } ++ ++void translate_syscall(Tracee *tracee) ++{ ++ if (!dd_profile_enabled()) { ++ translate_syscall_impl(tracee); ++ return; ++ } ++ int saved = errno; ++ const bool entering = IS_IN_SYSENTER(tracee); ++ uint64_t wall = dd_profile_clock(CLOCK_MONOTONIC); ++ uint64_t cpu = dd_profile_clock(CLOCK_THREAD_CPUTIME_ID); ++ errno = saved; ++ translate_syscall_impl(tracee); ++ dd_profile_record(get_sysnum(tracee, ORIGINAL), entering, tracee->pid, wall, cpu); ++} diff --git a/tools/proot/profile.h b/tools/proot/profile.h new file mode 100644 index 000000000..71173b31e --- /dev/null +++ b/tools/proot/profile.h @@ -0,0 +1,99 @@ +/* SPDX-License-Identifier: GPL-2.0-or-later */ +#ifndef DROIDDECK_PROOT_PROFILE_H +#define DROIDDECK_PROOT_PROFILE_H + +#include +#include +#include +#include +#include +#include +#include +#include + +struct dd_profile_counter { + uint64_t calls, wall_ns, cpu_ns, max_ns; +}; +static struct dd_profile_counter dd_profile_counts[PR_NB_SYSNUM][2]; +static int dd_profile_on = -1; +static uint64_t dd_profile_id, dd_profile_next, dd_profile_slow_ns = 1000000; +static unsigned dd_profile_samples; + +static uint64_t dd_profile_clock(clockid_t clock) +{ + struct timespec ts; + if (clock_gettime(clock, &ts) != 0) return 0; + return (uint64_t)ts.tv_sec * 1000000000 + ts.tv_nsec; +} + +static void dd_profile_flush(void) +{ + int saved = errno; + for (unsigned nr = 0; nr < PR_NB_SYSNUM; nr++) { + for (unsigned stage = 0; stage < 2; stage++) { + const struct dd_profile_counter *c = &dd_profile_counts[nr][stage]; + if (!c->calls) continue; + fprintf(stderr, "proot-profile {\"type\":\"total\",\"tracer\":%d,\"id\":%" PRIu64 + ",\"syscall\":\"%s\",\"stage\":\"%s\",\"calls\":%" PRIu64 + ",\"wall_ns\":%" PRIu64 ",\"cpu_ns\":%" PRIu64 ",\"max_ns\":%" PRIu64 "}\n", + getpid(), dd_profile_id, stringify_sysnum(nr), stage ? "exit" : "enter", + c->calls, c->wall_ns, c->cpu_ns, c->max_ns); + } + } + errno = saved; +} + +static int dd_profile_enabled(void) +{ + if (dd_profile_on >= 0) return dd_profile_on; + int saved = errno; + const char *value = getenv("PROOT_PROFILE"); + dd_profile_on = value && strcmp(value, "1") == 0; + if (dd_profile_on) { + value = getenv("PROOT_PROFILE_SLOW_US"); + if (value && *value) { + char *end; + unsigned long long us = strtoull(value, &end, 10); + if (!*end && us > 0 && us <= 1000000000ULL) dd_profile_slow_ns = us * 1000; + } + dd_profile_id = dd_profile_clock(CLOCK_MONOTONIC); + dd_profile_next = dd_profile_id + 5000000000ULL; + atexit(dd_profile_flush); + fprintf(stderr, "proot-profile {\"type\":\"start\",\"tracer\":%d,\"id\":%" PRIu64 + ",\"slow_ns\":%" PRIu64 ",\"sample_limit\":32,\"sample_window_ms\":5000,\"scope\":\"syscall-handler\"}\n", + getpid(), dd_profile_id, dd_profile_slow_ns); + } + errno = saved; + return dd_profile_on; +} + +static void dd_profile_record(unsigned nr, int entering, pid_t pid, + uint64_t start_wall, uint64_t start_cpu) +{ + int saved = errno; + uint64_t cpu = dd_profile_clock(CLOCK_THREAD_CPUTIME_ID); + uint64_t wall = dd_profile_clock(CLOCK_MONOTONIC); + if (nr >= PR_NB_SYSNUM) nr = PR_void; + if (!start_wall || !start_cpu || wall < start_wall || cpu < start_cpu) goto done; + uint64_t elapsed = wall - start_wall, used = cpu - start_cpu; + struct dd_profile_counter *c = &dd_profile_counts[nr][!entering]; + c->calls++; + c->wall_ns += elapsed; + c->cpu_ns += used; + if (elapsed > c->max_ns) c->max_ns = elapsed; + if (wall >= dd_profile_next) { + dd_profile_flush(); + dd_profile_next = wall + 5000000000ULL; + dd_profile_samples = 0; + } + if (elapsed >= dd_profile_slow_ns && dd_profile_samples < 32) { + dd_profile_samples++; + fprintf(stderr, "proot-profile {\"type\":\"slow\",\"tracer\":%d,\"id\":%" PRIu64 + ",\"pid\":%d,\"syscall\":\"%s\",\"stage\":\"%s\",\"wall_ns\":%" PRIu64 + ",\"cpu_ns\":%" PRIu64 "}\n", getpid(), dd_profile_id, pid, + stringify_sysnum(nr), entering ? "enter" : "exit", elapsed, used); + } + done: + errno = saved; +} +#endif diff --git a/tools/proot_profile.py b/tools/proot_profile.py new file mode 100644 index 000000000..bfe4418f4 --- /dev/null +++ b/tools/proot_profile.py @@ -0,0 +1,56 @@ +"""Read cumulative PRoot handler counters from a session log without double counting snapshots.""" +from __future__ import annotations + +import json +from collections import deque +from pathlib import Path + +PREFIX = "proot-profile " + + +def report(path: Path, sort: str = "wall", limit: int = 20) -> dict: + latest = {} + starts = set() + samples = deque(maxlen=128) + malformed = 0 + with path.open(errors="replace") as stream: + for line in stream: + if PREFIX not in line: + continue + try: + row = json.loads(line.split(PREFIX, 1)[1]) + identity = (int(row["tracer"]), int(row["id"])) + if row["type"] == "start": + starts.add(identity) + elif row["type"] in {"total", "slow"}: + if row["stage"] not in {"enter", "exit"} or not isinstance(row["syscall"], str): + raise ValueError("invalid syscall/stage") + fields = ("calls", "wall_ns", "cpu_ns", "max_ns") if row["type"] == "total" else ("wall_ns", "cpu_ns", "pid") + if any(type(row[key]) is not int or row[key] < 0 for key in fields): + raise ValueError("invalid counter") + if row["type"] == "total": + latest[identity + (row["syscall"], row["stage"])] = row + else: + samples.append(row) + except (ValueError, TypeError, KeyError): + malformed += 1 + groups = {} + for (_, _, syscall, stage), row in latest.items(): + total = groups.setdefault((syscall, stage), dict(syscall=syscall, stage=stage, calls=0, wall_ns=0, cpu_ns=0, max_ns=0)) + for key in ("calls", "wall_ns", "cpu_ns"): + total[key] += row[key] + total["max_ns"] = max(total["max_ns"], row["max_ns"]) + for row in groups.values(): + row["wallMs"] = round(row["wall_ns"] / 1_000_000, 3) + row["cpuMs"] = round(row["cpu_ns"] / 1_000_000, 3) + row["meanUs"] = round(row["wall_ns"] / max(row["calls"], 1) / 1000, 3) + row["maxUs"] = round(row["max_ns"] / 1000, 3) + rows = sorted(groups.values(), key=lambda row: row[{"wall": "wall_ns", "cpu": "cpu_ns", "calls": "calls"}[sort]], reverse=True) + return dict(ok=True, command="proot-profile", scope="syscall-handler", + note="Handler wall time includes tracer descheduling and filesystem waits; it excludes tracee kernel time and wake-up/queue delay before the handler. Counts are handler visits, including chained calls, not unique syscalls.", + path=str(path), tracers=len(starts | {key[:2] for key in latest}), + handlerCalls=sum(row["calls"] for row in rows), + handlerWallNs=sum(row["wall_ns"] for row in rows), + handlerCpuNs=sum(row["cpu_ns"] for row in rows), + malformedRecords=malformed, totals=rows[:limit], slowSamples=list(samples), + hasCounters=bool(latest)) diff --git a/tools/tests/test_droiddeckctl.py b/tools/tests/test_droiddeckctl.py index f6d29030a..82ff7daa0 100644 --- a/tools/tests/test_droiddeckctl.py +++ b/tools/tests/test_droiddeckctl.py @@ -413,6 +413,21 @@ class DroiddeckctlTest(FakeAdbTest): self.assertEqual("Awake", out["wakefulness"]) self.assertIn(["shell", "input", "keyevent", "KEYCODE_WAKEUP"], [c["args"] for c in self.calls()]) + def test_proot_profile_queues_only_the_next_session(self): + self.configure({"env": {"ok": True}}) + code, out = self.run_ctl("proot-profile", "enable", "--slow-us", "250") + self.assertEqual(0, code, out) + self.assertEqual({"op": "set", "lines": ["PROOT_PROFILE=1", "PROOT_PROFILE_SLOW_US=250"], "persistent": False}, + self.calls("env")[0]["request"]) + + def test_proot_profile_report_needs_no_adb_or_device(self): + path = self.dir / "session.log" + path.write_text('ordinary log') + with unittest.mock.patch.object(ctl, "adb_path", side_effect=AssertionError("must stay offline")): + code, out = self.run_ctl("proot-profile", "report", str(path)) + self.assertEqual(0, code, out) + self.assertFalse(out["hasCounters"]) + def test_override_pushes_to_the_inbox_first(self): self.configure({ "access": {"ok": True, "commands": True, "inbox": "/sdcard/Android/data/x/files/agent-inbox"}, diff --git a/tools/tests/test_proot_profile.py b/tools/tests/test_proot_profile.py new file mode 100644 index 000000000..954870515 --- /dev/null +++ b/tools/tests/test_proot_profile.py @@ -0,0 +1,91 @@ +import json +import os +from pathlib import Path +import shutil +import subprocess +import sys +import tempfile +import unittest + +TOOLS = Path(__file__).resolve().parents[1] +sys.path.insert(0, str(TOOLS)) +from proot_profile import report + +PROGRAM = r''' +#define _POSIX_C_SOURCE 200809L +#define PR_NB_SYSNUM 2 +#define PR_void 0 +static const char *stringify_sysnum(unsigned nr) { return nr ? "openat" : "void"; } +#include "profile.h" +int main(void) { + errno = EBUSY; + if (!dd_profile_enabled()) return errno != EBUSY; + if (errno != EBUSY) return 1; + for (int i = 0; i < 40; i++) { + uint64_t wall = dd_profile_clock(CLOCK_MONOTONIC); + uint64_t cpu = dd_profile_clock(CLOCK_THREAD_CPUTIME_ID); + struct timespec wait = {0, 2000000}; + nanosleep(&wait, 0); + errno = ENOENT; + dd_profile_record(1, 1, 123, wall, cpu); + if (errno != ENOENT) return 2; + if (i == 9) dd_profile_flush(); + } + dd_profile_next = 0; + uint64_t wall = dd_profile_clock(CLOCK_MONOTONIC); + uint64_t cpu = dd_profile_clock(CLOCK_THREAD_CPUTIME_ID); + struct timespec wait = {0, 2000000}; + nanosleep(&wait, 0); + dd_profile_record(1, 0, 123, wall, cpu); + return 0; +} +''' + + +class ProotProfileTest(unittest.TestCase): + def test_snapshots_replace_instead_of_adding_and_tracers_remain_separate(self): + with tempfile.TemporaryDirectory() as work: + path = Path(work) / 'session.log' + records = [dict(type='total', tracer=1, id=2, syscall='statx', stage='enter', + calls=n, wall_ns=n * 100, cpu_ns=n * 10, max_ns=100) for n in (3, 8)] + records.append(dict(records[-1], tracer=2, calls=2)) + records += [dict(type='total', tracer=1, id=3, syscall='openat', stage='enter', + calls=1, wall_ns=1000, cpu_ns=1000, max_ns=1000)] + path.write_text('unrelated log\n' + ''.join('prefix proot-profile ' + json.dumps(r) + '\n' for r in records) + + 'proot-profile {truncated\n' + 'proot-profile []\n') + result = report(path) + self.assertEqual(11, result['handlerCalls']) + self.assertEqual(3, result['tracers']) + self.assertEqual(2, result['malformedRecords']) + self.assertEqual('statx', result['totals'][0]['syscall']) + self.assertEqual('openat', report(path, 'cpu')['totals'][0]['syscall']) + + def test_empty_logs_do_not_claim_profiling_ran(self): + with tempfile.TemporaryDirectory() as work: + path = Path(work) / 'session.log' + path.write_text('ordinary log\n') + self.assertFalse(report(path)['hasCounters']) + + @unittest.skipUnless(shutil.which('cc'), 'C compiler required') + def test_real_clocks_bounded_samples_errno_and_periodic_counters(self): + with tempfile.TemporaryDirectory() as work: + source = Path(work) / 'profile.c' + binary = Path(work) / 'profile' + source.write_text(PROGRAM) + subprocess.run(['cc', '-Wall', '-Wextra', '-Werror', '-std=c99', '-I', str(TOOLS / 'proot'), + str(source), '-o', str(binary)], check=True) + for setting in ('0', ''): + result = subprocess.run([binary], env=dict(os.environ, PROOT_PROFILE=setting), capture_output=True, check=True) + self.assertEqual(b'', result.stderr) + result = subprocess.run([binary], env=dict(os.environ, PROOT_PROFILE='1', PROOT_PROFILE_SLOW_US='1'), + capture_output=True, check=True) + rows = [json.loads(line.split(b'proot-profile ', 1)[1]) for line in result.stderr.splitlines()] + self.assertEqual(33, sum(row['type'] == 'slow' for row in rows)) + self.assertEqual(32, sum(row['type'] == 'slow' and row['stage'] == 'enter' for row in rows)) + self.assertGreater(sum(row['type'] == 'total' for row in rows), 2) + log = Path(work) / 'session.log' + log.write_bytes(result.stderr) + counters = report(log) + self.assertEqual(41, counters['handlerCalls']) + self.assertGreater(counters['handlerWallNs'], counters['handlerCpuNs']) + self.assertEqual(40, counters['totals'][0]['calls']) diff --git a/tools/tests/test_session_guest_command.py b/tools/tests/test_session_guest_command.py index 9c319ce95..d6f352a8e 100644 --- a/tools/tests/test_session_guest_command.py +++ b/tools/tests/test_session_guest_command.py @@ -22,7 +22,7 @@ PACKAGES = [line.split()[1] for line in VARIANTS.read_text().splitlines() def guest_prefix(package): source = SERVICE.read_text() before_environment = source.split("val guest = ArrayList()", 1)[1].split( - "addClientEnvironment(guest, steamHere)", 1)[0] + "addClientEnvironment(guest,", 1)[0] environment = source.split("private fun addClientEnvironment(", 1)[1].split( 'guest.add("HOME=/root")', 1)[0] prefix = []