|
| 1 | +// Copyright (c) ppy Pty Ltd <contact@ppy.sh>. Licensed under the MIT Licence. |
| 2 | +// See the LICENCE file in the repository root for full licence text. |
| 3 | + |
| 4 | +using System; |
| 5 | +using System.Collections.Generic; |
| 6 | +using System.IO; |
| 7 | +using System.Runtime.InteropServices; |
| 8 | +using System.Text; |
| 9 | +using System.Threading; |
| 10 | +using Debug = System.Diagnostics.Debug; |
| 11 | +using osu.Framework.Platform; |
| 12 | +using osu.Framework.Threading; |
| 13 | + |
| 14 | +namespace osu.Android |
| 15 | +{ |
| 16 | + /// <summary> |
| 17 | + /// Per-GameThread liveness watchdog that detects multi-second stalls on the |
| 18 | + /// Update / Draw / Audio / Input threads and dumps a rich snapshot of every |
| 19 | + /// Linux thread in the process (comm, wchan, syscall, status) into the |
| 20 | + /// existing <c>native_crash.log</c>. |
| 21 | + /// |
| 22 | + /// <para> |
| 23 | + /// The dump is the actionable signal: <c>/proc/self/task/<tid>/wchan</c> |
| 24 | + /// names the kernel function each thread is waiting in, and |
| 25 | + /// <c>/proc/self/task/<tid>/syscall</c> gives the active syscall number |
| 26 | + /// plus the user-space PC. Together these pinpoint Vulkan present-queue |
| 27 | + /// stalls (futex on the GPU driver), Realm fifo waits, AAudio polls, GC |
| 28 | + /// pauses, etc., without needing adb access. |
| 29 | + /// </para> |
| 30 | + /// |
| 31 | + /// <para> |
| 32 | + /// The hang threshold is intentionally short (5s): the runtime log can grow |
| 33 | + /// to ~70MB on the user's device, so we'd rather over-dump than miss a |
| 34 | + /// stall, but we still rate-limit re-dumps of the same hang to one every |
| 35 | + /// 10s so we don't fill the log in a single second of frozen state. |
| 36 | + /// </para> |
| 37 | + /// </summary> |
| 38 | + internal static class HangWatchdog |
| 39 | + { |
| 40 | + // Threshold above which a thread is considered hung. Any GameThread that |
| 41 | + // fails to drain a queued no-op for this long triggers a snapshot. |
| 42 | + private const int hang_threshold_ms = 5_000; |
| 43 | + |
| 44 | + // Heartbeat scheduling cadence. Each game thread executes a no-op every |
| 45 | + // ~1s via Scheduler.AddDelayed(repeat: true) which updates its last-tick |
| 46 | + // timestamp; the monitor wakes at the same cadence to evaluate ages. |
| 47 | + private const int heartbeat_interval_ms = 1_000; |
| 48 | + |
| 49 | + // Minimum gap between two consecutive snapshots while still hung. Without |
| 50 | + // this, a 60s hang would generate 12 full /proc/self/task dumps and |
| 51 | + // potentially blow the log size cap in a few seconds. |
| 52 | + private const int redump_cooldown_ms = 10_000; |
| 53 | + |
| 54 | + // Maximum number of distinct hang dumps written for the lifetime of the |
| 55 | + // process. Prevents pathological "permanent hang plus runaway watchdog" |
| 56 | + // from filling the log indefinitely if the cooldown logic ever misbehaves. |
| 57 | + private const int max_dumps_per_process = 200; |
| 58 | + |
| 59 | + private static int started; |
| 60 | + private static Thread? monitorThread; |
| 61 | + private static readonly Heartbeat[] heartbeats = new Heartbeat[4]; |
| 62 | + private static int dumpCount; |
| 63 | + |
| 64 | + // libc.gettid: returns the Linux kernel thread id of the calling thread. |
| 65 | + // We need this (not managed Thread.ManagedThreadId) to map heartbeats to |
| 66 | + // /proc/self/task/<tid>/* entries. |
| 67 | + [DllImport("libc", EntryPoint = "gettid", SetLastError = false)] |
| 68 | + private static extern int gettid(); |
| 69 | + |
| 70 | + /// <summary> |
| 71 | + /// Begin watchdog monitoring against the four standard <see cref="GameHost"/> |
| 72 | + /// threads. Idempotent: a second call after the monitor is already running |
| 73 | + /// is a no-op. Safe to call from any thread; the monitor itself runs on a |
| 74 | + /// dedicated background OS thread that never enters managed game code. |
| 75 | + /// </summary> |
| 76 | + public static void Start(GameHost? host) |
| 77 | + { |
| 78 | + if (host == null) return; |
| 79 | + |
| 80 | + if (Interlocked.Exchange(ref started, 1) != 0) |
| 81 | + return; |
| 82 | + |
| 83 | + try |
| 84 | + { |
| 85 | + heartbeats[0] = new Heartbeat("Update", host.UpdateThread); |
| 86 | + heartbeats[1] = new Heartbeat("Draw", host.DrawThread); |
| 87 | + heartbeats[2] = new Heartbeat("Audio", host.AudioThread); |
| 88 | + heartbeats[3] = new Heartbeat("Input", host.InputThread); |
| 89 | + |
| 90 | + foreach (var hb in heartbeats) |
| 91 | + hb.Arm(); |
| 92 | + |
| 93 | + monitorThread = new Thread(monitorLoop) |
| 94 | + { |
| 95 | + Name = "HangWatchdog", |
| 96 | + IsBackground = true, |
| 97 | + }; |
| 98 | + monitorThread.Start(); |
| 99 | + |
| 100 | + CrashDiagnostics.WriteAliveMarker($"HangWatchdog.Start (threshold={hang_threshold_ms}ms, cooldown={redump_cooldown_ms}ms)"); |
| 101 | + } |
| 102 | + catch (Exception e) |
| 103 | + { |
| 104 | + Debug.WriteLine($"[osu!] HangWatchdog.Start failed: {e.Message}"); |
| 105 | + Interlocked.Exchange(ref started, 0); |
| 106 | + } |
| 107 | + } |
| 108 | + |
| 109 | + private static void monitorLoop() |
| 110 | + { |
| 111 | + // Per-thread cooldown so each thread can dump independently without |
| 112 | + // starving the others (e.g. Audio hung 30s while Draw hangs at 50s |
| 113 | + // should still produce two distinct snapshots). |
| 114 | + long[] lastDumpUtcMs = new long[heartbeats.Length]; |
| 115 | + |
| 116 | + while (true) |
| 117 | + { |
| 118 | + try |
| 119 | + { |
| 120 | + Thread.Sleep(heartbeat_interval_ms); |
| 121 | + |
| 122 | + if (dumpCount >= max_dumps_per_process) |
| 123 | + continue; |
| 124 | + |
| 125 | + long nowMs = nowUtcMs(); |
| 126 | + |
| 127 | + for (int i = 0; i < heartbeats.Length; i++) |
| 128 | + { |
| 129 | + var hb = heartbeats[i]; |
| 130 | + if (hb == null) continue; |
| 131 | + |
| 132 | + long lastTickMs = Interlocked.Read(ref hb.LastTickUtcMs); |
| 133 | + long armedAtMs = Interlocked.Read(ref hb.ArmedAtUtcMs); |
| 134 | + |
| 135 | + // A thread that has never ticked yet is treated as hung |
| 136 | + // once it has been armed for longer than the threshold — |
| 137 | + // this catches startup deadlocks where the GameThread |
| 138 | + // never actually starts running its Scheduler. |
| 139 | + long referenceMs = lastTickMs > 0 ? lastTickMs : armedAtMs; |
| 140 | + if (referenceMs <= 0) continue; |
| 141 | + |
| 142 | + long ageMs = nowMs - referenceMs; |
| 143 | + if (ageMs < hang_threshold_ms) continue; |
| 144 | + |
| 145 | + if (nowMs - lastDumpUtcMs[i] < redump_cooldown_ms) continue; |
| 146 | + |
| 147 | + lastDumpUtcMs[i] = nowMs; |
| 148 | + dumpHang(hb, ageMs, lastTickMs > 0); |
| 149 | + |
| 150 | + // Re-arm so that if the thread eventually recovers we |
| 151 | + // start counting from the recovery point, not the start |
| 152 | + // of the original hang. |
| 153 | + hb.Arm(); |
| 154 | + } |
| 155 | + } |
| 156 | + catch (Exception e) |
| 157 | + { |
| 158 | + Debug.WriteLine($"[osu!] HangWatchdog monitor loop iteration failed: {e.Message}"); |
| 159 | + } |
| 160 | + } |
| 161 | + // ReSharper disable once FunctionNeverReturns -- by design; monitor lives for the process. |
| 162 | + } |
| 163 | + |
| 164 | + private static void dumpHang(Heartbeat hb, long ageMs, bool everTicked) |
| 165 | + { |
| 166 | + int currentDump = Interlocked.Increment(ref dumpCount); |
| 167 | + |
| 168 | + try |
| 169 | + { |
| 170 | + var sb = new StringBuilder(16 * 1024); |
| 171 | + sb.Append("\n=========================================================\n"); |
| 172 | + sb.Append("=== HANG WATCHDOG TRIGGER ===\n"); |
| 173 | + sb.Append($" utc_time = {DateTime.UtcNow:O}\n"); |
| 174 | + sb.Append($" thread = {hb.Name} (GameThread)\n"); |
| 175 | + sb.Append($" age_ms = {ageMs}\n"); |
| 176 | + sb.Append($" ever_ticked = {everTicked}\n"); |
| 177 | + sb.Append($" game_tid = {Interlocked.Read(ref hb.LinuxTid)}\n"); |
| 178 | + sb.Append($" dump_index = {currentDump}/{max_dumps_per_process}\n"); |
| 179 | + sb.Append("\n--- Heartbeats ---\n"); |
| 180 | + |
| 181 | + long now = nowUtcMs(); |
| 182 | + foreach (var other in heartbeats) |
| 183 | + { |
| 184 | + if (other == null) continue; |
| 185 | + |
| 186 | + long t = Interlocked.Read(ref other.LastTickUtcMs); |
| 187 | + long a = Interlocked.Read(ref other.ArmedAtUtcMs); |
| 188 | + long otherAge = t > 0 ? now - t : (a > 0 ? now - a : -1); |
| 189 | + sb.Append($" {other.Name,-7} tid={Interlocked.Read(ref other.LinuxTid),-7} age_ms={otherAge,-7} ticks={Interlocked.Read(ref other.TickCount)}\n"); |
| 190 | + } |
| 191 | + |
| 192 | + sb.Append("\n--- /proc/self/task snapshot ---\n"); |
| 193 | + appendProcTaskSnapshot(sb); |
| 194 | + |
| 195 | + sb.Append("=== END OF HANG WATCHDOG TRIGGER ===\n\n"); |
| 196 | + |
| 197 | + CrashDiagnostics.AppendDiagnosticBlock(sb.ToString()); |
| 198 | + } |
| 199 | + catch (Exception e) |
| 200 | + { |
| 201 | + Debug.WriteLine($"[osu!] HangWatchdog.dumpHang failed: {e.Message}"); |
| 202 | + } |
| 203 | + } |
| 204 | + |
| 205 | + private static void appendProcTaskSnapshot(StringBuilder sb) |
| 206 | + { |
| 207 | + try |
| 208 | + { |
| 209 | + // /proc/self/task entries are subdirectories, not files, so |
| 210 | + // enumerate via Directory.EnumerateDirectories and extract the |
| 211 | + // numeric tid from each path leaf. |
| 212 | + var collected = new List<string>(64); |
| 213 | + try |
| 214 | + { |
| 215 | + foreach (string dir in Directory.EnumerateDirectories("/proc/self/task")) |
| 216 | + { |
| 217 | + string leaf = Path.GetFileName(dir); |
| 218 | + if (!string.IsNullOrEmpty(leaf)) |
| 219 | + collected.Add(leaf); |
| 220 | + } |
| 221 | + } |
| 222 | + catch (Exception e) |
| 223 | + { |
| 224 | + sb.Append($" (failed to enumerate /proc/self/task: {e.Message})\n"); |
| 225 | + return; |
| 226 | + } |
| 227 | + |
| 228 | + collected.Sort(StringComparer.Ordinal); |
| 229 | + |
| 230 | + foreach (string tid in collected) |
| 231 | + { |
| 232 | + string basePath = "/proc/self/task/" + tid; |
| 233 | + |
| 234 | + string comm = readProcLine(basePath + "/comm", 64); |
| 235 | + string wchan = readProcLine(basePath + "/wchan", 128); |
| 236 | + string syscall = readProcLine(basePath + "/syscall", 256); |
| 237 | + string state = parseStateFromStat(readProcLine(basePath + "/stat", 256)); |
| 238 | + |
| 239 | + sb.Append(" tid=").Append(tid) |
| 240 | + .Append(" state=").Append(state) |
| 241 | + .Append(" comm=").Append(comm) |
| 242 | + .Append(" wchan=").Append(wchan) |
| 243 | + .Append(" syscall=").Append(syscall) |
| 244 | + .Append('\n'); |
| 245 | + } |
| 246 | + } |
| 247 | + catch (Exception e) |
| 248 | + { |
| 249 | + sb.Append($" (proc snapshot outer failure: {e.Message})\n"); |
| 250 | + } |
| 251 | + } |
| 252 | + |
| 253 | + private static string readProcLine(string path, int maxLen) |
| 254 | + { |
| 255 | + try |
| 256 | + { |
| 257 | + // /proc files can change between open and read; tolerate short |
| 258 | + // reads and EAGAIN, and never throw out to the caller. |
| 259 | + using var fs = new FileStream(path, FileMode.Open, FileAccess.Read, FileShare.ReadWrite); |
| 260 | + byte[] buf = new byte[maxLen]; |
| 261 | + int n = fs.Read(buf, 0, buf.Length); |
| 262 | + if (n <= 0) return "<empty>"; |
| 263 | + |
| 264 | + string s = Encoding.UTF8.GetString(buf, 0, n).Trim(); |
| 265 | + // Replace newlines/control chars so we keep one tid per line in the dump. |
| 266 | + return s.Replace('\n', ' ').Replace('\r', ' ').Replace('\t', ' '); |
| 267 | + } |
| 268 | + catch (Exception e) |
| 269 | + { |
| 270 | + return "<err:" + e.GetType().Name + ">"; |
| 271 | + } |
| 272 | + } |
| 273 | + |
| 274 | + private static string parseStateFromStat(string stat) |
| 275 | + { |
| 276 | + // /proc/<tid>/stat: "<pid> (comm) <state> ..." The comm field can |
| 277 | + // contain parentheses and spaces, so locate the LAST ')' and read |
| 278 | + // the next non-space char as the state code (R/S/D/Z/T/...). |
| 279 | + if (string.IsNullOrEmpty(stat)) return "?"; |
| 280 | + |
| 281 | + int rp = stat.LastIndexOf(')'); |
| 282 | + if (rp < 0 || rp + 2 >= stat.Length) return "?"; |
| 283 | + |
| 284 | + return stat.Substring(rp + 2, 1); |
| 285 | + } |
| 286 | + |
| 287 | + private static long nowUtcMs() => DateTimeOffset.UtcNow.ToUnixTimeMilliseconds(); |
| 288 | + |
| 289 | + // Captures all heartbeat state for one game thread. Fields are mutated |
| 290 | + // from both the monitor (read) and the game thread (write), all via |
| 291 | + // Interlocked to avoid torn 64-bit reads on 32-bit ABIs (we only ship |
| 292 | + // arm64-v8a today, but the explicit Interlocked also documents the |
| 293 | + // cross-thread contract). |
| 294 | + private sealed class Heartbeat |
| 295 | + { |
| 296 | + public readonly string Name; |
| 297 | + private readonly GameThread thread; |
| 298 | + public long LastTickUtcMs; |
| 299 | + public long ArmedAtUtcMs; |
| 300 | + public long LinuxTid; |
| 301 | + public long TickCount; |
| 302 | + |
| 303 | + public Heartbeat(string name, GameThread thread) |
| 304 | + { |
| 305 | + Name = name; |
| 306 | + this.thread = thread; |
| 307 | + } |
| 308 | + |
| 309 | + // Schedule a self-pinging recurring delegate that bumps the |
| 310 | + // heartbeat from the game thread itself. If the game thread is |
| 311 | + // hung, this delegate simply does not run, and LastTickUtcMs |
| 312 | + // stays stale — exactly the signal the monitor consumes. |
| 313 | + public void Arm() |
| 314 | + { |
| 315 | + Interlocked.Exchange(ref ArmedAtUtcMs, nowUtcMs()); |
| 316 | + |
| 317 | + try |
| 318 | + { |
| 319 | + thread.Scheduler.AddDelayed(tick, heartbeat_interval_ms, true); |
| 320 | + } |
| 321 | + catch (Exception e) |
| 322 | + { |
| 323 | + Debug.WriteLine($"[osu!] HangWatchdog.Heartbeat({Name}).Arm failed: {e.Message}"); |
| 324 | + } |
| 325 | + } |
| 326 | + |
| 327 | + private void tick() |
| 328 | + { |
| 329 | + Interlocked.Exchange(ref LastTickUtcMs, nowUtcMs()); |
| 330 | + |
| 331 | + // gettid is cheap (single syscall) and only meaningfully |
| 332 | + // changes on the very first tick — but we re-record it on |
| 333 | + // every tick so a thread restart (e.g. ExecutionMode swap) |
| 334 | + // is reflected without needing a re-Arm. |
| 335 | + try { Interlocked.Exchange(ref LinuxTid, gettid()); } |
| 336 | + catch { /* libc unavailable: leave as 0, dump still useful */ } |
| 337 | + |
| 338 | + Interlocked.Increment(ref TickCount); |
| 339 | + } |
| 340 | + } |
| 341 | + } |
| 342 | +} |
0 commit comments