using System.Diagnostics; using NeoModLoader.services; using UnityEngine; namespace IdleSpectator; /// /// Lightweight idle hitch sampler. Logs when a frame or idle subsystem exceeds thresholds. /// Enable via harness hitch_probe or temporary always-on while diagnosing FPS hitching. /// public static class IdleHitchProbe { public static bool Enabled { get; private set; } /// Frame delta (unscaled) above this counts as a hitch candidate. public static float FrameSpikeSeconds { get; set; } = 0.028f; /// Idle subsystem slice above this is attributed in the log. 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; private static float _nextDetailLogAt; private const float DetailLogIntervalSeconds = 0.5f; 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; _nextDetailLogAt = 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; float now = Time.unscaledTime; bool recordBreaking = dt > _maxDt || _directorMs > _maxDirectorMs || _captionMs > _maxCaptionMs || _discoveryMs > _maxDiscoveryMs; _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++; // Continuous Unity logging can itself create GC/I/O hitches. Preserve every // record-breaking sample and otherwise cap detail to two lines per second. if (recordBreaking || now >= _nextDetailLogAt) { _nextDetailLogAt = now + DetailLogIntervalSeconds; 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} " + $"schedulerMs={StoryScheduler.LastTickMs:0.0} schedulerCandidates={StoryScheduler.LastCandidateCount} " + $"schedulerParts={StoryScheduler.LastThreadCopyMs:0.0}/" + $"{StoryScheduler.LastThreadScoreMs:0.0}/" + $"{StoryScheduler.LastPendingCopyMs:0.0}/" + $"{StoryScheduler.LastProposalMs:0.0} " + $"selectorParts={EpisodeShotSelector.LastReplayFilterMs:0.0}/" + $"{EpisodeShotSelector.LastPresentabilityMs:0.0}/" + $"{EpisodeShotSelector.LastClassificationMs:0.0}/" + $"{EpisodeShotSelector.LastScoringMs:0.0} " + $"selectParts={InterestDirector.LastSelectCopyMs:0.0}/" + $"{InterestDirector.LastSelectFilterMs:0.0}/" + $"{InterestDirector.LastSelectStoryMs:0.0}/" + $"{InterestDirector.LastSelectVarietyMs:0.0} " + $"selectorPresent={EpisodeShotSelector.LastPresentabilityChecks} " + $"selectorSlow={EpisodeShotSelector.LastSlowCandidateMs:0.0}:" + $"{EpisodeShotSelector.LastSlowCandidateKey} " + $"captionParts={WatchCaption.LastReconcileMs:0.0}/" + $"{WatchCaption.LastPortraitMs:0.0}/" + $"{WatchCaption.LastTaskMs:0.0}/" + $"{WatchCaption.LastIdentityMs:0.0}/" + $"{WatchCaption.LastStatusesMs:0.0}/" + $"{WatchCaption.LastHistoryMs:0.0}/" + $"{WatchCaption.LastReasonMs:0.0}/" + $"{WatchCaption.LastSpineMs:0.0} " + $"feedParts={InterestFeeds.LastHappinessMs:0.0}/" + $"{InterestFeeds.LastHappinessCount}/" + $"{InterestFeeds.LastHappinessMaxItemMs:0.0}:" + $"{InterestFeeds.LastHappinessMaxEffectId}/" + $"{InterestFeeds.LastScannerMs:0.0}[{InterestFeeds.LastBattleScanMs:0.0}," + $"{InterestFeeds.LastWarFeedMs:0.0},{InterestFeeds.LastPlotFeedMs:0.0}," + $"{InterestFeeds.LastFamilyFeedMs:0.0},{InterestFeeds.LastStatusFeedMs:0.0}] " + $"hot={_hotMark}({_hotMarkMs:0.0}ms)"); _hotMark = ""; _hotMarkMs = 0f; } } 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; } }