worldbox-observer-mod/IdleSpectator/IdleHitchProbe.cs

using System.Diagnostics;
using NeoModLoader.services;
using UnityEngine;

namespace IdleSpectator;

/// <summary>
/// Lightweight idle hitch sampler. Logs when a frame or idle subsystem exceeds thresholds.
/// Enable via harness <c>hitch_probe</c> or temporary always-on while diagnosing FPS hitching.
/// </summary>
public static class IdleHitchProbe
{
    public static bool Enabled { get; private set; }

    /// <summary>Frame delta (unscaled) above this counts as a hitch candidate.</summary>
    public static float FrameSpikeSeconds { get; set; } = 0.028f;

    /// <summary>Idle subsystem slice above this is attributed in the log.</summary>
    public static float SliceSpikeMs { get; set; } = 4f;

    private static readonly Stopwatch Sw = new Stopwatch();
    private static float _directorMs;
    private static float _discoveryMs;
    private static float _captionMs;
    private static float _otherMs;
    private static string _hotMark = "";
    private static float _hotMarkMs;
    private static float _markStartedAt;
    private static string _markName = "";
    private static float _nextSummaryAt;
    private static int _spikes;
    private static float _maxDt;
    private static float _maxDirectorMs;
    private static float _maxCaptionMs;
    private static float _maxDiscoveryMs;

    public static void SetEnabled(bool on)
    {
        Enabled = on;
        if (on)
        {
            ResetStats();
            LogService.LogInfo(
                $"[IdleSpectator][HITCH] probe on frame>={FrameSpikeSeconds * 1000f:0}ms slice>={SliceSpikeMs:0.#}ms");
        }
        else
        {
            LogService.LogInfo($"[IdleSpectator][HITCH] probe off spikes={_spikes}");
        }
    }

    public static void ResetStats()
    {
        _spikes = 0;
        _maxDt = 0f;
        _maxDirectorMs = 0f;
        _maxCaptionMs = 0f;
        _maxDiscoveryMs = 0f;
        _nextSummaryAt = Time.unscaledTime + 5f;
    }

    public static void BeginSlice()
    {
        if (!Enabled)
        {
            return;
        }

        Sw.Restart();
    }

    public static void Mark(string name)
    {
        if (!Enabled || string.IsNullOrEmpty(name))
        {
            return;
        }

        float nowMs = Time.realtimeSinceStartup * 1000f;
        if (!string.IsNullOrEmpty(_markName))
        {
            float elapsed = nowMs - _markStartedAt;
            if (elapsed > _hotMarkMs)
            {
                _hotMarkMs = elapsed;
                _hotMark = _markName + "->" + name;
            }
        }

        _markName = name;
        _markStartedAt = nowMs;
    }

    public static void EndDirector()
    {
        if (!Enabled)
        {
            return;
        }

        Sw.Stop();
        _directorMs = (float)Sw.Elapsed.TotalMilliseconds;
        _markName = "";
    }

    public static void EndDiscovery()
    {
        if (!Enabled)
        {
            return;
        }

        Sw.Stop();
        _discoveryMs = (float)Sw.Elapsed.TotalMilliseconds;
    }

    public static void EndCaption()
    {
        if (!Enabled)
        {
            return;
        }

        Sw.Stop();
        _captionMs = (float)Sw.Elapsed.TotalMilliseconds;
    }

    public static void EndOther()
    {
        if (!Enabled)
        {
            return;
        }

        Sw.Stop();
        _otherMs = (float)Sw.Elapsed.TotalMilliseconds;
    }

    public static void AfterFrame()
    {
        if (!Enabled)
        {
            return;
        }

        float dt = Time.unscaledDeltaTime;
        _maxDt = Mathf.Max(_maxDt, dt);
        _maxDirectorMs = Mathf.Max(_maxDirectorMs, _directorMs);
        _maxCaptionMs = Mathf.Max(_maxCaptionMs, _captionMs);
        _maxDiscoveryMs = Mathf.Max(_maxDiscoveryMs, _discoveryMs);

        bool frameSpike = dt >= FrameSpikeSeconds;
        bool sliceSpike = _directorMs >= SliceSpikeMs
                          || _captionMs >= SliceSpikeMs
                          || _discoveryMs >= SliceSpikeMs;
        if (frameSpike || sliceSpike)
        {
            _spikes++;
            string idle = SpectatorMode.Active ? "on" : "off";
            LogService.LogInfo(
                $"[IdleSpectator][HITCH] spike idle={idle} dt={dt * 1000f:0.0}ms "
                + $"dir={_directorMs:0.0}ms disc={_discoveryMs:0.0}ms cap={_captionMs:0.0}ms "
                + $"other={_otherMs:0.0}ms roster={LifeSagaRoster.Count} pending={InterestRegistry.PendingCount} "
                + $"scanMs={LifeSagaRoster.LastWorldScanMs:0.0} softMs={LifeSagaRoster.LastSoftRefillMs:0.0} "
                + $"hot={_hotMark}({_hotMarkMs:0.0}ms)");
            _hotMark = "";
            _hotMarkMs = 0f;
        }

        float now = Time.unscaledTime;
        if (now >= _nextSummaryAt)
        {
            _nextSummaryAt = now + 5f;
            LogService.LogInfo(
                $"[IdleSpectator][HITCH] summary idle={(SpectatorMode.Active ? "on" : "off")} "
                + $"spikes={_spikes} maxDt={_maxDt * 1000f:0.0}ms "
                + $"maxDir={_maxDirectorMs:0.0}ms maxDisc={_maxDiscoveryMs:0.0}ms maxCap={_maxCaptionMs:0.0}ms "
                + $"roster={LifeSagaRoster.Count}");
            _spikes = 0;
            _maxDt = 0f;
            _maxDirectorMs = 0f;
            _maxCaptionMs = 0f;
            _maxDiscoveryMs = 0f;
        }

        _directorMs = 0f;
        _discoveryMs = 0f;
        _captionMs = 0f;
        _otherMs = 0f;
    }
}