diff --git a/README.md b/README.md index ae8566d..74e1fdd 100644 --- a/README.md +++ b/README.md @@ -20,7 +20,7 @@ I originally planned on releasing individual mods, but considering my workflow o | Physics Optimizer | Cuts CPU spent on train physics (LOD fast-path + auto-freeze), with debug car tinting. Console: `/rpf` | | Mesh LOD | Adds level-of-detail to rolling stock: distant cars progressively shed detail and finally collapse to a cheap proxy box, cutting triangle count on large saves. | | Base Game Performance | Smooths Unity's incremental garbage collector and Nature Renderer grass streaming to reduce camera-motion hitches without lowering visual quality. | -| Profiler | Unified in-game performance overlay: a frame-time graph plus live readouts that adapt to whichever optimization modules are enabled. Console: `/rpf overlay` | +| Profiler | Unified in-game performance overlay with hitch attribution captures. Console: `/rpf overlay`, `/s3bench` | All modules are disabled by default; enable them per-module from the S³ settings page. A game restart is required for enable/disable to take effect. More modules will follow; S³ is designed to grow. @@ -176,12 +176,16 @@ the same. The original runtime values are restored immediately when the module i ## Profiler -A unified in-game performance overlay. It always shows a render + physics frame-time graph (render, FixedUpdate, Tick, and PosCars times) and a timing report, and it grows extra sections for whichever optimization modules are enabled: +A unified in-game performance overlay. It shows a render + physics frame-time graph and now +supports automated hitch-attribution captures with per-frame GC, camera, render-pipeline, +car/scenery/culling, and streaming timings. Benchmark output includes `frames.csv`, +`hitches.jsonl`, `probes.csv`, and an optional Unity binary-profiler log. - **Physics Optimizer**: LOD fast-path and auto-freeze quick-toggles with live fast/full and frozen counts. - **Mesh LOD**: total tracked cars, the locomotive/freight split, and how many cars sit at each LOD level right now. -Toggle the overlay with `/rpf overlay`, or from the Profiler settings page. +Toggle the overlay with `/rpf overlay`, or from the Profiler settings page. Run +`/s3bench start` for a four-pass stationary/motion A/B capture. ![Profiler settings](img/profiler/umm_settings.png) diff --git a/src/Modules/Profiler/AutomatedBenchmark.cs b/src/Modules/Profiler/AutomatedBenchmark.cs new file mode 100644 index 0000000..807d54c --- /dev/null +++ b/src/Modules/Profiler/AutomatedBenchmark.cs @@ -0,0 +1,1100 @@ +using System; +using System.Collections; +using System.Collections.Generic; +using System.Diagnostics; +using System.Globalization; +using System.IO; +using System.Text; +using System.Threading; +using HarmonyLib; +using Newtonsoft.Json; +using Newtonsoft.Json.Linq; +using S3.Core; +using UI.Console; +using UnityEngine; +using UnityEngine.Profiling; +using UnityEngine.Scripting; + +namespace S3.Modules.Profiler; + +[HarmonyPatch(typeof(ConsoleCommandHandler))] +[HarmonyPatch("_HandleSlashCommand")] +static class BenchmarkCommandPatch +{ + static bool Prefix(string[] comps, ref string __result) + { + if (comps.Length == 0 + || !string.Equals(comps[0], "/s3bench", StringComparison.OrdinalIgnoreCase)) + return true; + __result = AutomatedBenchmark.Handle(comps); + return false; + } +} + +public sealed class BenchmarkOptions +{ + public string Label = "s3"; + public float SecondsPerPass = 5f; + public string MotionMode = "orbit"; + public string DisabledModules = ""; + public string BaselineDisabledModules = ""; + public string ScenarioDisabledModules = ""; + public bool? CaptureHitchProbes; + public float? HitchThresholdMs; + public bool? CaptureUnityBinaryLog; + public float? CameraX; + public float? CameraY; + public float? CameraZ; + public float? CameraPitch; + public float? CameraYaw; + public float? CameraFov; +} + +[DefaultExecutionOrder(10000)] +public sealed class AutomatedBenchmark : MonoBehaviour +{ + static readonly float[] LookStressYaw = + { 0f, 145f, -115f, 178f, -165f, 72f, -38f, 121f, -92f, 32f }; + static readonly float[] LookStressPitch = + { 0f, -52f, 38f, -24f, 57f, -43f, 22f, 48f, -36f, 12f }; + + sealed class MarkerCounter + { + public readonly string Name; + public readonly Recorder Recorder; + public long Nanoseconds; + public long Blocks; + + public MarkerCounter(string name) + { + Name = name; + Recorder = Recorder.Get(name); + } + + public void Start() + { + Nanoseconds = 0; + Blocks = 0; + Recorder.enabled = true; + } + + public void Sample() + { + Nanoseconds += Recorder.elapsedNanoseconds; + Blocks += Recorder.sampleBlockCount; + } + + public void Stop() => Recorder.enabled = false; + } + + sealed class DirectCounters + { + public long PrepareTicks; + public long PrepareMaxTicks; + public long RenderTicks; + public long RenderMaxTicks; + public long TrackCollectTicks; + public long TrackCollectMaxTicks; + public long SnapTicks; + public long SnapMaxTicks; + public long PlaceTicks; + public long PlaceMaxTicks; + public long CatalogTicks; + public long CatalogMaxTicks; + public int PrepareCalls; + public int RenderCalls; + public long PortalSamples; + public int MaxPortals; + } + + sealed class PhaseResult + { + public string Name = ""; + public int Frames; + public float AverageMs; + public float P95Ms; + public float P99Ms; + public float WorstMs; + public long MonoDelta; + public int Gc0; + public int Gc1; + public int Gc2; + public int Over33; + public int Over50; + public int Over100; + public int Over200; + public double GcSliceMs; + public double PeekyPrepareMsPerFrame; + public double PeekyPrepareMaxMs; + public double PeekyRenderMsPerFrame; + public double PeekyRenderMsPerCall; + public double PeekyRenderMaxMs; + public double TrackCollectMsPerFrame; + public double TrackCollectMaxMs; + public double SnapMsPerFrame; + public double SnapMaxMs; + public double PlaceMsPerFrame; + public double PlaceMaxMs; + public double CatalogMsPerFrame; + public double CatalogMaxMs; + public int PeekyRenderCalls; + public double AveragePortals; + public int MaxPortals; + public string UnityProfilerPath = ""; + public readonly Dictionary Markers = new(); + public readonly List FrameTimes = new(); + public readonly List HitchFrames = new(); + } + + sealed class ProbeAggregate + { + public string Id = ""; + public long Calls; + public double TotalMs; + public double MaxFrameMs; + public int FramesPresent; + } + + static readonly string[] MarkerNames = + { + "Camera.Render", + "BehaviourUpdate", + "LateBehaviourUpdate", + "FixedBehaviourUpdate", + "Physics.Simulate", + "RenderLoop.Draw", + }; + + static long _prepareTicks; + static long _prepareMaxTicks; + static long _renderTicks; + static long _renderMaxTicks; + static long _trackCollectTicks; + static long _trackCollectMaxTicks; + static long _snapTicks; + static long _snapMaxTicks; + static long _placeTicks; + static long _placeMaxTicks; + static long _catalogTicks; + static long _catalogMaxTicks; + static int _prepareCalls; + static int _renderCalls; + static long _portalSamples; + static int _maxPortals; + + public static AutomatedBenchmark? Instance { get; private set; } + public static bool Running => Instance != null && Instance._running; + public static string Status => Instance == null ? "benchmark host unavailable" : Instance._status; + public static string LastReportPath => Instance?._lastReportPath ?? ""; + + bool _running; + bool _cancel; + bool _motion; + string _status = "idle"; + string _lastReportPath = ""; + string _benchmarkDir = ""; + float _duration = 5f; + float _motionStart; + Camera? _camera; + Vector3 _savedPosition; + Quaternion _savedRotation; + Vector3 _originalPosition; + Quaternion _originalRotation; + float _savedFov; + float _originalFov; + Vector3 _pivot; + bool _anchorOverride; + readonly Dictionary _savedModuleStates = + new(StringComparer.OrdinalIgnoreCase); + BenchmarkOptions _options = new(); + HashSet _disabledAll = new(StringComparer.OrdinalIgnoreCase); + HashSet _disabledBaseline = new(StringComparer.OrdinalIgnoreCase); + HashSet _disabledScenario = new(StringComparer.OrdinalIgnoreCase); + PhaseResult? _phaseResult; + bool _hasSavedState; + + void Awake() => Instance = this; + + void OnDestroy() + { + _cancel = true; + if (_hasSavedState) Restore(); + if (Instance == this) Instance = null; + } + + public static void RecordPeekyPrepare(long stopwatchTicks, int portals) + { + if (!Running) return; + Interlocked.Add(ref _prepareTicks, stopwatchTicks); + UpdateMax(ref _prepareMaxTicks, stopwatchTicks); + Interlocked.Increment(ref _prepareCalls); + Interlocked.Add(ref _portalSamples, portals); + int current; + while (portals > (current = _maxPortals) + && Interlocked.CompareExchange(ref _maxPortals, portals, current) != current) { } + } + + public static void RecordPeekyRender(long stopwatchTicks) + { + if (!Running) return; + Interlocked.Add(ref _renderTicks, stopwatchTicks); + UpdateMax(ref _renderMaxTicks, stopwatchTicks); + Interlocked.Increment(ref _renderCalls); + } + + public static void RecordTrackCollect(long stopwatchTicks) + { + if (!Running) return; + Interlocked.Add(ref _trackCollectTicks, stopwatchTicks); + UpdateMax(ref _trackCollectMaxTicks, stopwatchTicks); + } + + public static void RecordSnap(long stopwatchTicks) + { + if (!Running) return; + Interlocked.Add(ref _snapTicks, stopwatchTicks); + UpdateMax(ref _snapMaxTicks, stopwatchTicks); + } + + public static void RecordPlace(long stopwatchTicks) + { + if (!Running) return; + Interlocked.Add(ref _placeTicks, stopwatchTicks); + UpdateMax(ref _placeMaxTicks, stopwatchTicks); + } + + public static void RecordCatalog(long stopwatchTicks) + { + if (!Running) return; + Interlocked.Add(ref _catalogTicks, stopwatchTicks); + UpdateMax(ref _catalogMaxTicks, stopwatchTicks); + } + + public static string SetModule(string id, bool active, bool persist) + { + if (string.IsNullOrWhiteSpace(id)) return "module id required"; + if (string.Equals(id, "mcp", StringComparison.OrdinalIgnoreCase) + || string.Equals(id, "profiler", StringComparison.OrdinalIgnoreCase)) + return "The mcp and profiler modules are protected from live disable."; + if (Running) return "Cannot change modules while a benchmark is running."; + + ModuleRegistry registry = Main.Registry; + if (!registry.TrySetActive(id, active, out string message)) + return message; + if (persist) + { + IModule? module = registry.Find(id); + if (module != null) + { + module.Enabled = active; + module.SaveSettings(); + message += " configured=" + active; + } + } + return message; + } + + public static string Handle(string[] comps) + { + if (Instance == null) return "Benchmark host unavailable; enable the Profiler module."; + string action = comps.Length >= 2 ? comps[1].ToLowerInvariant() : "status"; + if (action == "status") + return $"{Status}{(LastReportPath.Length > 0 ? " report=" + LastReportPath : "")}"; + if (action == "cancel") + { + Instance._cancel = true; + return "Benchmark cancellation requested."; + } + if (action != "start") + return "Usage: /s3bench start [seconds-per-pass] | status | cancel"; + float seconds = 5f; + if (comps.Length >= 3 && float.TryParse(comps[2], NumberStyles.Float, + CultureInfo.InvariantCulture, out float parsed)) + seconds = parsed; + return Start(new BenchmarkOptions { SecondsPerPass = seconds }); + } + + public static string Start(BenchmarkOptions options) + { + if (Instance == null) return "Benchmark host unavailable; enable the Profiler module."; + return Instance.StartBenchmark(options); + } + + string StartBenchmark(BenchmarkOptions options) + { + if (_running) return "Benchmark already running: " + _status; + _options = options ?? new BenchmarkOptions(); + _options.Label = SafeLabel(_options.Label); + _duration = Mathf.Clamp(_options.SecondsPerPass, 2f, 20f); + _disabledAll = ParseModules(_options.DisabledModules); + _disabledBaseline = ParseModules(_options.BaselineDisabledModules); + _disabledScenario = ParseModules(_options.ScenarioDisabledModules); + _cancel = false; + StartCoroutine(RunBenchmark()); + return $"Benchmark '{_options.Label}' started: four {_duration:0.#}s passes."; + } + + IEnumerator RunBenchmark() + { + _running = true; + _status = "preparing"; + _lastReportPath = ""; + _camera = Camera.main; + if (_camera == null) + { + _status = "failed: no main camera"; + _running = false; + yield break; + } + + SaveState(); + var results = new List(4); + string stamp = DateTime.Now.ToString("yyyyMMdd-HHmmss"); + string dir = Path.Combine(Main.ModEntry.Path, "benchmarks", + SafeLabel(_options.Label) + "-" + stamp); + Directory.CreateDirectory(dir); + _benchmarkDir = dir; + + try + { + yield return RunPhase("baseline-stationary", false, false); + AddPhase(results); + if (_cancel) yield break; + yield return RunPhase("scenario-stationary", true, false); + AddPhase(results); + if (_cancel) yield break; + yield return RunPhase("baseline-motion", false, true); + AddPhase(results); + if (_cancel) yield break; + yield return RunPhase("scenario-motion", true, true); + AddPhase(results); + if (_cancel) yield break; + + _lastReportPath = WriteReport(dir, results); + _status = "complete"; + } + finally + { + HitchSampler.CancelCapture(); + StopUnityProfilerCapture(); + Restore(); + _running = false; + if (_cancel) _status = "cancelled"; + } + } + + void AddPhase(List results) + { + if (_phaseResult != null) results.Add(_phaseResult); + } + + IEnumerator RunPhase(string name, bool scenario, bool moving) + { + _phaseResult = null; + _status = name + " warmup"; + ApplyModules(scenario); + RestoreCamera(); + _motion = moving; + _motionStart = Time.unscaledTime; + + float warmUntil = Time.unscaledTime + 1.5f; + while (!_cancel && Time.unscaledTime < warmUntil) + yield return null; + if (_cancel) yield break; + + ResetDirectCounters(); + bool captureHitches = _options.CaptureHitchProbes + ?? ProfilerModule.Settings.captureHitchProbes; + float hitchThreshold = Mathf.Clamp( + _options.HitchThresholdMs ?? ProfilerModule.Settings.hitchThresholdMs, + 16.7f, 1000f); + if (captureHitches) + HitchSampler.BeginCapture(name, hitchThreshold); + + string unityProfilerPath = ""; + bool captureBinary = _options.CaptureUnityBinaryLog + ?? ProfilerModule.Settings.captureUnityBinaryLog; + if (captureBinary) + { + unityProfilerPath = Path.Combine( + _benchmarkDir, "unity-" + SafeLabel(name) + ".data"); + if (!StartUnityProfilerCapture(unityProfilerPath)) + unityProfilerPath = ""; + } + + var markers = new List(MarkerNames.Length); + for (int i = 0; i < MarkerNames.Length; i++) + { + var marker = new MarkerCounter(MarkerNames[i]); + marker.Start(); + markers.Add(marker); + } + + _status = name + " sampling"; + var frames = new List(Mathf.CeilToInt(_duration * 120f)); + long monoStart = UnityEngine.Profiling.Profiler.GetMonoUsedSizeLong(); + int gc0 = GC.CollectionCount(0); + int gc1 = GC.CollectionCount(1); + int gc2 = GC.CollectionCount(2); + float until = Time.unscaledTime + _duration; + while (!_cancel && Time.unscaledTime < until) + { + yield return null; + float ms = Time.unscaledDeltaTime * 1000f; + if (ms > 0f && ms < 1000f) frames.Add(ms); + for (int i = 0; i < markers.Count; i++) + markers[i].Sample(); + } + List hitchFrames = captureHitches + ? HitchSampler.EndCapture() + : new List(); + if (captureBinary) + StopUnityProfilerCapture(); + long monoEnd = UnityEngine.Profiling.Profiler.GetMonoUsedSizeLong(); + gc0 = GC.CollectionCount(0) - gc0; + gc1 = GC.CollectionCount(1) - gc1; + gc2 = GC.CollectionCount(2) - gc2; + for (int i = 0; i < markers.Count; i++) + markers[i].Stop(); + DirectCounters direct = ReadDirectCounters(); + _motion = false; + RestoreCamera(); + if (_cancel) yield break; + + var sorted = new List(frames); + sorted.Sort(); + var result = new PhaseResult + { + Name = name, + Frames = frames.Count, + AverageMs = Average(frames), + P95Ms = Percentile(sorted, 0.95f), + P99Ms = Percentile(sorted, 0.99f), + WorstMs = sorted.Count > 0 ? sorted[sorted.Count - 1] : 0f, + MonoDelta = monoEnd - monoStart, + Gc0 = gc0, + Gc1 = gc1, + Gc2 = gc2, + GcSliceMs = GarbageCollector.incrementalTimeSliceNanoseconds / 1_000_000.0, + PeekyPrepareMsPerFrame = TicksToMs(direct.PrepareTicks) / Math.Max(1, frames.Count), + PeekyPrepareMaxMs = TicksToMs(direct.PrepareMaxTicks), + PeekyRenderMsPerFrame = TicksToMs(direct.RenderTicks) / Math.Max(1, frames.Count), + PeekyRenderMsPerCall = TicksToMs(direct.RenderTicks) / Math.Max(1, direct.RenderCalls), + PeekyRenderMaxMs = TicksToMs(direct.RenderMaxTicks), + TrackCollectMsPerFrame = + TicksToMs(direct.TrackCollectTicks) / Math.Max(1, frames.Count), + TrackCollectMaxMs = TicksToMs(direct.TrackCollectMaxTicks), + SnapMsPerFrame = TicksToMs(direct.SnapTicks) / Math.Max(1, frames.Count), + SnapMaxMs = TicksToMs(direct.SnapMaxTicks), + PlaceMsPerFrame = TicksToMs(direct.PlaceTicks) / Math.Max(1, frames.Count), + PlaceMaxMs = TicksToMs(direct.PlaceMaxTicks), + CatalogMsPerFrame = TicksToMs(direct.CatalogTicks) / Math.Max(1, frames.Count), + CatalogMaxMs = TicksToMs(direct.CatalogMaxTicks), + PeekyRenderCalls = direct.RenderCalls, + AveragePortals = direct.PrepareCalls > 0 + ? direct.PortalSamples / (double)direct.PrepareCalls : 0, + MaxPortals = direct.MaxPortals, + UnityProfilerPath = unityProfilerPath, + }; + result.FrameTimes.AddRange(frames); + result.HitchFrames.AddRange(hitchFrames); + for (int i = 0; i < frames.Count; i++) + { + float ms = frames[i]; + if (ms >= 33.333f) result.Over33++; + if (ms >= 50f) result.Over50++; + if (ms >= 100f) result.Over100++; + if (ms >= 200f) result.Over200++; + } + for (int i = 0; i < markers.Count; i++) + { + MarkerCounter marker = markers[i]; + if (marker.Blocks > 0) + result.Markers[marker.Name] = + marker.Nanoseconds / 1_000_000.0 / Math.Max(1, frames.Count); + } + _phaseResult = result; + yield return null; + } + + void LateUpdate() + { + if (!_running || _camera == null) return; + if (!_motion) + { + if (_anchorOverride) + _camera.transform.SetPositionAndRotation(_savedPosition, _savedRotation); + return; + } + float t = Mathf.Repeat((Time.unscaledTime - _motionStart) / Mathf.Max(0.1f, _duration), 1f); + float a = t * Mathf.PI * 2f; + if (string.Equals(_options.MotionMode, "look360", StringComparison.OrdinalIgnoreCase)) + { + Vector3 euler = _savedRotation.eulerAngles; + float pitch = Mathf.DeltaAngle(0f, euler.x) + Mathf.Sin(a * 2f) * 18f; + _camera.transform.SetPositionAndRotation( + _savedPosition, + Quaternion.Euler(pitch, euler.y + t * 360f, 0f)); + return; + } + if (string.Equals( + _options.MotionMode, "lookstress", + StringComparison.OrdinalIgnoreCase)) + { + const float stepSeconds = 0.42f; + const float transitionSeconds = 0.055f; + float elapsed = Mathf.Max(0f, Time.unscaledTime - _motionStart); + int step = Mathf.FloorToInt(elapsed / stepSeconds); + int current = step % LookStressYaw.Length; + int previous = + (current + LookStressYaw.Length - 1) % LookStressYaw.Length; + float transition = Mathf.Clamp01( + Mathf.Repeat(elapsed, stepSeconds) / transitionSeconds); + transition = transition * transition * (3f - 2f * transition); + Vector3 euler = _savedRotation.eulerAngles; + float yawOffset = Mathf.LerpAngle( + LookStressYaw[previous], LookStressYaw[current], transition); + float pitchOffset = Mathf.Lerp( + LookStressPitch[previous], LookStressPitch[current], transition); + _camera.transform.SetPositionAndRotation( + _savedPosition, + Quaternion.Euler( + Mathf.DeltaAngle(0f, euler.x) + pitchOffset, + euler.y + yawOffset, + 0f)); + return; + } + Vector3 right = _savedRotation * Vector3.right; + Vector3 forward = _savedRotation * Vector3.forward; + Vector3 position = _savedPosition + + right * (Mathf.Sin(a) * 30f) + + forward * ((Mathf.Cos(a) - 1f) * 10f) + + Vector3.up * (Mathf.Sin(a * 2f) * 4f); + _camera.transform.SetPositionAndRotation( + position, + Quaternion.LookRotation((_pivot - position).normalized, Vector3.up)); + } + + void SaveState() + { + if (_camera == null) return; + _savedPosition = _camera.transform.position; + _savedRotation = _camera.transform.rotation; + _originalPosition = _savedPosition; + _originalRotation = _savedRotation; + _savedFov = _camera.fieldOfView; + _originalFov = _savedFov; + _hasSavedState = true; + _anchorOverride = _options.CameraX.HasValue + || _options.CameraY.HasValue + || _options.CameraZ.HasValue + || _options.CameraPitch.HasValue + || _options.CameraYaw.HasValue; + if (_anchorOverride) + { + _savedPosition = new Vector3( + _options.CameraX ?? _savedPosition.x, + _options.CameraY ?? _savedPosition.y, + _options.CameraZ ?? _savedPosition.z); + Vector3 euler = _savedRotation.eulerAngles; + _savedRotation = Quaternion.Euler( + _options.CameraPitch ?? euler.x, + _options.CameraYaw ?? euler.y, + 0f); + } + if (_options.CameraFov.HasValue) + { + _savedFov = Mathf.Clamp(_options.CameraFov.Value, 20f, 100f); + _camera.fieldOfView = _savedFov; + } + _pivot = _savedPosition + _savedRotation * Vector3.forward * 120f; + Ray ray = new(_savedPosition, _savedRotation * Vector3.forward); + if (Physics.Raycast(ray, out RaycastHit hit, 1000f, ~(1 << 31), + QueryTriggerInteraction.Ignore)) + _pivot = hit.point; + + _savedModuleStates.Clear(); + foreach (IModule module in Main.Registry.Modules) + _savedModuleStates[module.Id] = Main.Registry.IsActive(module); + } + + void ApplyModules(bool scenario) + { + HashSet phaseDisabled = scenario + ? _disabledScenario : _disabledBaseline; + foreach (IModule module in Main.Registry.Modules) + { + if (module.Id.Equals("mcp", StringComparison.OrdinalIgnoreCase) + || module.Id.Equals("profiler", StringComparison.OrdinalIgnoreCase)) + continue; + bool wasActive = _savedModuleStates.TryGetValue(module.Id, out bool value) && value; + bool desired = wasActive + && !_disabledAll.Contains(module.Id) + && !phaseDisabled.Contains(module.Id); + if (!Main.Registry.TrySetActive(module.Id, desired, out string message)) + throw new InvalidOperationException(message); + } + } + + void Restore() + { + _motion = false; + if (_camera != null) + { + _camera.transform.SetPositionAndRotation(_originalPosition, _originalRotation); + _camera.fieldOfView = _originalFov; + } + + foreach (IModule module in Main.Registry.Modules) + { + if (!_savedModuleStates.TryGetValue(module.Id, out bool active)) continue; + Main.Registry.TrySetActive(module.Id, active, out _); + } + _hasSavedState = false; + } + + void RestoreCamera() + { + if (_camera != null) + { + _camera.transform.SetPositionAndRotation(_savedPosition, _savedRotation); + _camera.fieldOfView = _savedFov; + } + } + + static HashSet ParseModules(string csv) + { + var result = new HashSet(StringComparer.OrdinalIgnoreCase); + if (string.IsNullOrWhiteSpace(csv)) return result; + string[] pieces = csv.Split(','); + for (int i = 0; i < pieces.Length; i++) + { + string value = pieces[i].Trim(); + if (value.Length > 0) result.Add(value); + } + return result; + } + + static string SafeLabel(string value) + { + if (string.IsNullOrWhiteSpace(value)) return "benchmark"; + var sb = new StringBuilder(); + foreach (char c in value.Trim()) + sb.Append(char.IsLetterOrDigit(c) || c == '-' || c == '_' ? c : '-'); + return sb.ToString().Trim('-'); + } + + static void ResetDirectCounters() + { + Interlocked.Exchange(ref _prepareTicks, 0); + Interlocked.Exchange(ref _prepareMaxTicks, 0); + Interlocked.Exchange(ref _renderTicks, 0); + Interlocked.Exchange(ref _renderMaxTicks, 0); + Interlocked.Exchange(ref _trackCollectTicks, 0); + Interlocked.Exchange(ref _trackCollectMaxTicks, 0); + Interlocked.Exchange(ref _snapTicks, 0); + Interlocked.Exchange(ref _snapMaxTicks, 0); + Interlocked.Exchange(ref _placeTicks, 0); + Interlocked.Exchange(ref _placeMaxTicks, 0); + Interlocked.Exchange(ref _catalogTicks, 0); + Interlocked.Exchange(ref _catalogMaxTicks, 0); + Interlocked.Exchange(ref _prepareCalls, 0); + Interlocked.Exchange(ref _renderCalls, 0); + Interlocked.Exchange(ref _portalSamples, 0); + Interlocked.Exchange(ref _maxPortals, 0); + } + + static DirectCounters ReadDirectCounters() => new() + { + PrepareTicks = Interlocked.Read(ref _prepareTicks), + PrepareMaxTicks = Interlocked.Read(ref _prepareMaxTicks), + RenderTicks = Interlocked.Read(ref _renderTicks), + RenderMaxTicks = Interlocked.Read(ref _renderMaxTicks), + TrackCollectTicks = Interlocked.Read(ref _trackCollectTicks), + TrackCollectMaxTicks = Interlocked.Read(ref _trackCollectMaxTicks), + SnapTicks = Interlocked.Read(ref _snapTicks), + SnapMaxTicks = Interlocked.Read(ref _snapMaxTicks), + PlaceTicks = Interlocked.Read(ref _placeTicks), + PlaceMaxTicks = Interlocked.Read(ref _placeMaxTicks), + CatalogTicks = Interlocked.Read(ref _catalogTicks), + CatalogMaxTicks = Interlocked.Read(ref _catalogMaxTicks), + PrepareCalls = _prepareCalls, + RenderCalls = _renderCalls, + PortalSamples = Interlocked.Read(ref _portalSamples), + MaxPortals = _maxPortals, + }; + + static double TicksToMs(long ticks) => + ticks * 1000.0 / Stopwatch.Frequency; + + static void UpdateMax(ref long target, long value) + { + long current; + while (value > (current = Interlocked.Read(ref target)) + && Interlocked.CompareExchange(ref target, value, current) != current) { } + } + + static bool StartUnityProfilerCapture(string path) + { + try + { + UnityEngine.Profiling.Profiler.enabled = false; + UnityEngine.Profiling.Profiler.logFile = path; + UnityEngine.Profiling.Profiler.enableBinaryLog = true; + UnityEngine.Profiling.Profiler.enabled = true; + return true; + } + catch (Exception e) + { + Log.Warn("[profiler] Unity binary capture unavailable: " + e.Message); + StopUnityProfilerCapture(); + return false; + } + } + + static void StopUnityProfilerCapture() + { + try + { + UnityEngine.Profiling.Profiler.enabled = false; + UnityEngine.Profiling.Profiler.enableBinaryLog = false; + } + catch { } + } + + static float Average(List values) + { + if (values.Count == 0) return 0f; + double total = 0; + for (int i = 0; i < values.Count; i++) total += values[i]; + return (float)(total / values.Count); + } + + static float Percentile(List sorted, float percentile) + { + if (sorted.Count == 0) return 0f; + int index = Mathf.Clamp( + Mathf.CeilToInt(sorted.Count * percentile) - 1, + 0, + sorted.Count - 1); + return sorted[index]; + } + + string WriteReport(string dir, List results) + { + string path = Path.Combine(dir, "report.txt"); + var text = new StringBuilder(); + text.AppendLine("S3 automated scenario benchmark"); + text.AppendLine($"Generated: {DateTime.Now:O}"); + text.AppendLine($"Label: {_options.Label}"); + text.AppendLine( + $"Camera: ({_savedPosition.x:0.0},{_savedPosition.y:0.0},{_savedPosition.z:0.0}) " + + $"fov={_savedFov:0.0}"); + text.AppendLine($"Motion: {_options.MotionMode}"); + text.AppendLine($"Disabled all: {_options.DisabledModules}"); + text.AppendLine($"Disabled baseline: {_options.BaselineDisabledModules}"); + text.AppendLine($"Disabled scenario: {_options.ScenarioDisabledModules}"); + text.AppendLine( + $"Hitch probes: {_options.CaptureHitchProbes ?? ProfilerModule.Settings.captureHitchProbes} " + + $"threshold={_options.HitchThresholdMs ?? ProfilerModule.Settings.hitchThresholdMs:0.#}ms"); + text.AppendLine( + $"Unity binary capture: {_options.CaptureUnityBinaryLog ?? ProfilerModule.Settings.captureUnityBinaryLog}"); + text.AppendLine(); + for (int i = 0; i < results.Count; i++) + { + PhaseResult phase = results[i]; + text.AppendLine(phase.Name); + text.AppendLine( + $" frames={phase.Frames} avg={phase.AverageMs:0.00}ms " + + $"p95={phase.P95Ms:0.00}ms p99={phase.P99Ms:0.00}ms " + + $"worst={phase.WorstMs:0.00}ms monoDelta={phase.MonoDelta / 1024.0:0.0}KiB"); + text.AppendLine( + $" hitches>=33ms:{phase.Over33} >=50ms:{phase.Over50} " + + $">=100ms:{phase.Over100} >=200ms:{phase.Over200} " + + $"gc=({phase.Gc0},{phase.Gc1},{phase.Gc2}) slice={phase.GcSliceMs:0.###}ms"); + text.AppendLine( + $" peekyPrepare={phase.PeekyPrepareMsPerFrame:0.000}ms/frame " + + $"max={phase.PeekyPrepareMaxMs:0.000}ms " + + $"peekyRender={phase.PeekyRenderMsPerFrame:0.000}ms/frame " + + $"renderCall={phase.PeekyRenderMsPerCall:0.000}ms " + + $"max={phase.PeekyRenderMaxMs:0.000}ms renders={phase.PeekyRenderCalls} " + + $"portals={phase.AveragePortals:0.0}/{phase.MaxPortals}"); + text.AppendLine( + $" trackCollect={phase.TrackCollectMsPerFrame:0.000}ms/frame " + + $"max={phase.TrackCollectMaxMs:0.000}ms " + + $"snap={phase.SnapMsPerFrame:0.000}ms/frame max={phase.SnapMaxMs:0.000}ms " + + $"place={phase.PlaceMsPerFrame:0.000}ms/frame max={phase.PlaceMaxMs:0.000}ms " + + $"catalog={phase.CatalogMsPerFrame:0.000}ms/frame max={phase.CatalogMaxMs:0.000}ms"); + foreach (var marker in phase.Markers) + text.AppendLine($" marker.{marker.Key}={marker.Value:0.000}ms/frame"); + foreach (var probe in AggregateProbes(phase.HitchFrames, 6)) + text.AppendLine( + $" probe.{probe.Id}={probe.TotalMs / Math.Max(1, phase.HitchFrames.Count):0.000}ms/frame " + + $"max={probe.MaxFrameMs:0.000}ms calls={probe.Calls}"); + if (phase.UnityProfilerPath.Length > 0) + text.AppendLine($" unityProfiler={phase.UnityProfilerPath}"); + text.AppendLine(); + } + File.WriteAllText(path, text.ToString()); + + var summary = new StringBuilder(); + summary.AppendLine( + "phase,frames,average_ms,p95_ms,p99_ms,worst_ms,mono_delta_bytes," + + "gc0,gc1,gc2,gc_slice_ms,over_33ms,over_50ms,over_100ms,over_200ms," + + "peeky_prepare_ms_per_frame,peeky_prepare_max_ms," + + "peeky_render_ms_per_frame,peeky_render_ms_per_call,peeky_render_max_ms," + + "track_collect_ms_per_frame,track_collect_max_ms,snap_ms_per_frame,snap_max_ms," + + "place_ms_per_frame,place_max_ms,catalog_ms_per_frame,catalog_max_ms,peeky_render_calls,avg_portals,max_portals," + + "worst_hitch_frame,top_probe_id,top_probe_ms"); + for (int i = 0; i < results.Count; i++) + { + PhaseResult p = results[i]; + var worstProbe = WorstProbe(p.HitchFrames); + summary.AppendLine(string.Join(",", new[] + { + p.Name, p.Frames.ToString(), F(p.AverageMs), F(p.P95Ms), F(p.P99Ms), + F(p.WorstMs), p.MonoDelta.ToString(), p.Gc0.ToString(), p.Gc1.ToString(), + p.Gc2.ToString(), F(p.GcSliceMs), p.Over33.ToString(), p.Over50.ToString(), + p.Over100.ToString(), p.Over200.ToString(), + F(p.PeekyPrepareMsPerFrame), F(p.PeekyPrepareMaxMs), + F(p.PeekyRenderMsPerFrame), F(p.PeekyRenderMsPerCall), + F(p.PeekyRenderMaxMs), F(p.TrackCollectMsPerFrame), + F(p.TrackCollectMaxMs), F(p.SnapMsPerFrame), F(p.SnapMaxMs), + F(p.PlaceMsPerFrame), F(p.PlaceMaxMs), F(p.CatalogMsPerFrame), F(p.CatalogMaxMs), + p.PeekyRenderCalls.ToString(), + F(p.AveragePortals), p.MaxPortals.ToString(), + worstProbe.Frame.ToString(), Csv(worstProbe.Id), F(worstProbe.Ms), + })); + } + File.WriteAllText(Path.Combine(dir, "summary.csv"), summary.ToString()); + + var probeIds = new SortedSet(StringComparer.Ordinal); + for (int p = 0; p < results.Count; p++) + for (int f = 0; f < results[p].HitchFrames.Count; f++) + foreach (string id in results[p].HitchFrames[f].Probes.Keys) + probeIds.Add(id); + + var frames = new StringBuilder(); + frames.Append( + "phase,frame,frame_ms,hitch_bucket,gc0_delta,gc1_delta,gc2_delta," + + "mono_delta_bytes,camera_x,camera_y,camera_z"); + foreach (string id in probeIds) + { + string column = SafeColumn(id); + frames.Append(",probe_").Append(column).Append("_ms"); + frames.Append(",probe_").Append(column).Append("_calls"); + } + frames.AppendLine(); + for (int p = 0; p < results.Count; p++) + { + PhaseResult phase = results[p]; + if (phase.HitchFrames.Count > 0) + { + for (int i = 0; i < phase.HitchFrames.Count; i++) + AppendFrameCsv(frames, phase.HitchFrames[i], probeIds); + } + else + { + for (int i = 0; i < phase.FrameTimes.Count; i++) + { + float ms = phase.FrameTimes[i]; + string bucket = HitchBucket(ms); + frames.AppendLine( + $"{phase.Name},{i},{F(ms)},{bucket},0,0,0,0,0,0,0" + + EmptyProbeColumns(probeIds.Count)); + } + } + } + File.WriteAllText(Path.Combine(dir, "frames.csv"), frames.ToString()); + + WriteHitchesJsonl(dir, results); + WriteProbeAggregates(dir, results); + return path; + } + + static List AggregateProbes( + List records, int limit = int.MaxValue) + { + var byId = new Dictionary(StringComparer.Ordinal); + for (int i = 0; i < records.Count; i++) + { + foreach (var pair in records[i].Probes) + { + if (!byId.TryGetValue(pair.Key, out ProbeAggregate? total)) + { + total = new ProbeAggregate { Id = pair.Key }; + byId[pair.Key] = total; + } + total.Calls += pair.Value.Calls; + total.TotalMs += pair.Value.TotalMs; + if (pair.Value.TotalMs > total.MaxFrameMs) + total.MaxFrameMs = pair.Value.TotalMs; + total.FramesPresent++; + } + } + + var result = new List(byId.Values); + result.Sort((a, b) => b.TotalMs.CompareTo(a.TotalMs)); + if (result.Count > limit) + result.RemoveRange(limit, result.Count - limit); + return result; + } + + static (string Id, double Ms, int Frame) WorstProbe(List frames) + { + HitchFrameRecord? worst = null; + for (int i = 0; i < frames.Count; i++) + if (worst == null || frames[i].FrameMs > worst.FrameMs) + worst = frames[i]; + if (worst == null) return ("", 0, -1); + + string id = ""; + double ms = 0; + foreach (var pair in worst.Probes) + { + if (pair.Value.TotalMs <= ms) continue; + id = pair.Key; + ms = pair.Value.TotalMs; + } + return (id, ms, worst.Frame); + } + + static void AppendFrameCsv( + StringBuilder output, + HitchFrameRecord frame, + SortedSet probeIds) + { + output.Append(Csv(frame.Phase)).Append(',') + .Append(frame.Frame).Append(',') + .Append(F(frame.FrameMs)).Append(',') + .Append(HitchBucket(frame.FrameMs)).Append(',') + .Append(frame.Gc0).Append(',') + .Append(frame.Gc1).Append(',') + .Append(frame.Gc2).Append(',') + .Append(frame.MonoDelta).Append(',') + .Append(F(frame.CameraPosition.x)).Append(',') + .Append(F(frame.CameraPosition.y)).Append(',') + .Append(F(frame.CameraPosition.z)); + foreach (string id in probeIds) + { + if (frame.Probes.TryGetValue(id, out HitchProbeSample? probe)) + output.Append(',').Append(F(probe.TotalMs)).Append(',').Append(probe.Calls); + else + output.Append(",0,0"); + } + output.AppendLine(); + } + + void WriteHitchesJsonl(string dir, List results) + { + float threshold = Mathf.Clamp( + _options.HitchThresholdMs ?? ProfilerModule.Settings.hitchThresholdMs, + 16.7f, 1000f); + var output = new StringBuilder(); + for (int p = 0; p < results.Count; p++) + { + PhaseResult phase = results[p]; + for (int i = 0; i < phase.HitchFrames.Count; i++) + { + HitchFrameRecord frame = phase.HitchFrames[i]; + if (!frame.IsHitch(threshold)) continue; + + var probes = new JArray(); + var sorted = new List>(frame.Probes); + sorted.Sort((a, b) => b.Value.TotalMs.CompareTo(a.Value.TotalMs)); + for (int j = 0; j < sorted.Count; j++) + { + var pair = sorted[j]; + probes.Add(new JObject + { + ["id"] = pair.Key, + ["ms"] = Math.Round(pair.Value.TotalMs, 4), + ["calls"] = pair.Value.Calls, + ["maxMs"] = Math.Round(pair.Value.MaxMs, 4), + }); + } + + var json = new JObject + { + ["schema"] = 1, + ["phase"] = frame.Phase, + ["frame"] = frame.Frame, + ["frameMs"] = Math.Round(frame.FrameMs, 4), + ["hitchBucket"] = HitchBucket(frame.FrameMs), + ["gc"] = new JObject + { + ["g0"] = frame.Gc0, + ["g1"] = frame.Gc1, + ["g2"] = frame.Gc2, + ["monoDeltaBytes"] = frame.MonoDelta, + ["duringFrame"] = frame.Gc0 != 0 || frame.Gc1 != 0 || frame.Gc2 != 0, + }, + ["camera"] = new JObject + { + ["x"] = Math.Round(frame.CameraPosition.x, 3), + ["y"] = Math.Round(frame.CameraPosition.y, 3), + ["z"] = Math.Round(frame.CameraPosition.z, 3), + ["motionMode"] = _options.MotionMode, + }, + ["probes"] = probes, + }; + if (phase.UnityProfilerPath.Length > 0) + json["unityProfilerPath"] = phase.UnityProfilerPath; + output.AppendLine(json.ToString(Formatting.None)); + } + } + File.WriteAllText(Path.Combine(dir, "hitches.jsonl"), output.ToString()); + } + + static void WriteProbeAggregates(string dir, List results) + { + var output = new StringBuilder(); + output.AppendLine( + "phase,probe_id,calls_total,ms_total,ms_per_frame,max_frame_ms,frames_present"); + for (int p = 0; p < results.Count; p++) + { + PhaseResult phase = results[p]; + List aggregates = AggregateProbes(phase.HitchFrames); + for (int i = 0; i < aggregates.Count; i++) + { + ProbeAggregate probe = aggregates[i]; + output.Append(Csv(phase.Name)).Append(',') + .Append(Csv(probe.Id)).Append(',') + .Append(probe.Calls).Append(',') + .Append(F(probe.TotalMs)).Append(',') + .Append(F(probe.TotalMs / Math.Max(1, phase.HitchFrames.Count))).Append(',') + .Append(F(probe.MaxFrameMs)).Append(',') + .Append(probe.FramesPresent).AppendLine(); + } + } + File.WriteAllText(Path.Combine(dir, "probes.csv"), output.ToString()); + } + + static string HitchBucket(float ms) => + ms >= 200f ? "200+" : ms >= 100f ? "100+" + : ms >= 50f ? "50+" : ms >= 33.333f ? "33+" : ""; + + static string EmptyProbeColumns(int count) => + count <= 0 ? "" : new string(',', count * 2).Replace(",", ",0"); + + static string SafeColumn(string value) + { + var sb = new StringBuilder(value.Length); + for (int i = 0; i < value.Length; i++) + { + char c = value[i]; + sb.Append(char.IsLetterOrDigit(c) ? char.ToLowerInvariant(c) : '_'); + } + return sb.ToString(); + } + + static string Csv(string value) + { + if (string.IsNullOrEmpty(value)) return ""; + if (value.IndexOfAny(new[] { ',', '"', '\r', '\n' }) < 0) return value; + return "\"" + value.Replace("\"", "\"\"") + "\""; + } + + static string F(double value) => + value.ToString("0.000", CultureInfo.InvariantCulture); +} diff --git a/src/Modules/Profiler/HitchFrameDriver.cs b/src/Modules/Profiler/HitchFrameDriver.cs new file mode 100644 index 0000000..672ba9b --- /dev/null +++ b/src/Modules/Profiler/HitchFrameDriver.cs @@ -0,0 +1,63 @@ +using System.Diagnostics; +using UnityEngine; +using UnityEngine.Rendering; + +namespace S3.Modules.Profiler; + +[DefaultExecutionOrder(-32000)] +public sealed class HitchFrameDriver : MonoBehaviour +{ + internal static long FrameStartTicks; + internal static long LateTicks; + long _renderStartTicks; + + void OnEnable() + { + RenderPipelineManager.beginFrameRendering += BeginFrameRendering; + RenderPipelineManager.endFrameRendering += EndFrameRendering; + } + + void OnDisable() + { + RenderPipelineManager.beginFrameRendering -= BeginFrameRendering; + RenderPipelineManager.endFrameRendering -= EndFrameRendering; + } + + void Update() + { + HitchSampler.AdvanceFrame(Time.unscaledDeltaTime * 1000f); + FrameStartTicks = Stopwatch.GetTimestamp(); + LateTicks = 0; + } + + void BeginFrameRendering(ScriptableRenderContext _, Camera[] __) + { + if (!HitchSampler.Active) return; + long now = Stopwatch.GetTimestamp(); + long boundary = LateTicks != 0 ? LateTicks : FrameStartTicks; + if (boundary != 0) + HitchSampler.Record("phase.pre_render_gap", now - boundary); + _renderStartTicks = now; + } + + void EndFrameRendering(ScriptableRenderContext _, Camera[] __) + { + if (!HitchSampler.Active || _renderStartTicks == 0) return; + HitchSampler.Record( + "phase.render_pipeline", + Stopwatch.GetTimestamp() - _renderStartTicks); + _renderStartTicks = 0; + } +} + +[DefaultExecutionOrder(32000)] +public sealed class HitchLateFrameDriver : MonoBehaviour +{ + void LateUpdate() + { + if (!HitchSampler.Active || HitchFrameDriver.FrameStartTicks == 0) return; + long now = Stopwatch.GetTimestamp(); + HitchSampler.Record("phase.scripts_to_late", now - HitchFrameDriver.FrameStartTicks); + HitchFrameDriver.LateTicks = now; + } +} diff --git a/src/Modules/Profiler/HitchProbePatches.cs b/src/Modules/Profiler/HitchProbePatches.cs new file mode 100644 index 0000000..9b2b3b0 --- /dev/null +++ b/src/Modules/Profiler/HitchProbePatches.cs @@ -0,0 +1,140 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using System.Reflection; +using HarmonyLib; +using S3.Core; + +namespace S3.Modules.Profiler; + +/// +/// Resolves vanilla targets at runtime so game-version method drift degrades telemetry rather +/// than preventing the Profiler module from loading. +/// +public static class HitchProbePatches +{ + readonly struct Target + { + public readonly string Type; + public readonly string Method; + public readonly string Id; + + public Target(string type, string method, string id) + { + Type = type; + Method = method; + Id = id; + } + } + + static readonly Target[] Targets = + { + new("RollingStock.CarCuller", "Update", "cars.culler_update"), + new("RollingStock.CarCuller", "ProcessPending", "cars.process_pending"), + new("RollingStock.CarCuller", "OnCarCullingGroupStateChanged", "cars.cull_transition"), + new("Model.Car", "ModelLoadRetain", "cars.model_retain"), + new("Model.Car", "HandleModelsLoaded", "cars.model_loaded"), + new("Model.Car", "UnloadModels", "cars.model_unload"), + new("Model.Car", "SetCullerDistanceBand", "cars.distance_band"), + new("Model.Car", "PositionWheelBoundsFront", "cars.position_wheels"), + new("Helpers.SceneryAssetInstance", "SetLoaded", "scenery.set_loaded"), + new("Helpers.SceneryAssetInstance", "DidLoadModel", "scenery.did_load_model"), + new("Helpers.SceneryAssetInstance", "CullingSphereStateChanged", "scenery.cull_transition"), + new("Helpers.Culling.CullingManager", "Update", "culling.update"), + new("Helpers.Culling.CullingManager", "FixedUpdate", "culling.fixed_update"), + new("Cameras.StrategyCameraController", "Update", "camera.strategy_update"), + new("Cameras.StrategyCameraController", "UpdateCameraPosition", "camera.update_position"), + new("Cameras.StrategyCameraController", "FindGround", "camera.find_ground"), + new("TrainController", "FixedUpdate", "train.fixed_update"), + new("TrainController", "CarDidPosition", "train.car_did_position"), + new("WorldStreamer2.Streamer", "Update", "streamer.update"), + new("WorldStreamer2.Streamer", "CheckPositionTiles", "streamer.check_tiles"), + new("WorldStreamer2.Streamer", "LoadLevelAsyncManage", "streamer.load_pump"), + new("WorldStreamer2.Streamer", "SceneLoading", "streamer.scene_loading"), + new("WorldStreamer2.Streamer", "SceneUnloading", "streamer.scene_unloading"), + new("WorldStreamer2.StreamerLoadingManager", "Update", "streamer.manager_update"), + new("WorldStreamer2.TerrainCullingSystem", "Update", "terrain.culling_update"), + new("WorldStreamer2.TerrainCullingSystem", "CheckVisibility", "terrain.check_visibility"), + new("WorldStreamer2.PhysicCullingSystem", "Update", "physics_culling.update"), + new("WorldStreamer2.PhysicCullingSystem", "CheckVisibility", "physics_culling.check_visibility"), + }; + + static readonly Dictionary ProbeIds = new(); + + public static void Install(Harmony harmony) + { + ProbeIds.Clear(); + var prefix = new HarmonyMethod(typeof(HitchProbePatches), nameof(Prefix)); + var postfix = new HarmonyMethod(typeof(HitchProbePatches), nameof(Postfix)); + int patched = 0; + int missed = 0; + + foreach (Target target in Targets) + { + Type? type = FindType(target.Type); + if (type == null) + { + Log.Warn($"[profiler] Hitch probe type missing: {target.Type}"); + missed++; + continue; + } + + bool found = false; + foreach (MethodInfo method in AccessTools.GetDeclaredMethods(type)) + { + if (method.Name != target.Method || method.IsAbstract || method.ContainsGenericParameters) + continue; + found = true; + if (ProbeIds.ContainsKey(method)) continue; + try + { + ProbeIds[method] = target.Id; + harmony.Patch(method, prefix, postfix); + patched++; + } + catch (Exception e) + { + ProbeIds.Remove(method); + Log.Warn($"[profiler] Hitch probe failed: {type.FullName}.{method.Name}: {e.Message}"); + missed++; + } + } + + if (!found) + { + Log.Warn($"[profiler] Hitch probe method missing: {target.Type}.{target.Method}"); + missed++; + } + } + + Log.Info($"[profiler] Hitch probes installed: {patched}; unavailable: {missed}."); + } + + public static void Prefix(MethodBase __originalMethod, out long __state) + { + __state = HitchSampler.Active && ProbeIds.ContainsKey(__originalMethod) + ? Stopwatch.GetTimestamp() + : 0; + } + + public static void Postfix(MethodBase __originalMethod, long __state) + { + if (__state == 0 || !HitchSampler.Active) return; + if (ProbeIds.TryGetValue(__originalMethod, out string? id)) + HitchSampler.Record(id, Stopwatch.GetTimestamp() - __state); + } + + static Type? FindType(string fullName) + { + foreach (Assembly assembly in AppDomain.CurrentDomain.GetAssemblies()) + { + try + { + Type? type = assembly.GetType(fullName, false); + if (type != null) return type; + } + catch { } + } + return null; + } +} diff --git a/src/Modules/Profiler/HitchSampler.cs b/src/Modules/Profiler/HitchSampler.cs new file mode 100644 index 0000000..0a22883 --- /dev/null +++ b/src/Modules/Profiler/HitchSampler.cs @@ -0,0 +1,163 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics; +using UnityEngine; + +namespace S3.Modules.Profiler; + +public sealed class HitchProbeSample +{ + public int Calls; + public long Ticks; + public long MaxTicks; + + public double TotalMs => HitchSampler.TicksToMs(Ticks); + public double MaxMs => HitchSampler.TicksToMs(MaxTicks); +} + +public sealed class HitchFrameRecord +{ + public string Phase = ""; + public int Frame; + public float FrameMs; + public int Gc0; + public int Gc1; + public int Gc2; + public long MonoDelta; + public Vector3 CameraPosition; + public readonly Dictionary Probes = + new(StringComparer.Ordinal); + + public bool IsHitch(float thresholdMs) => FrameMs >= thresholdMs; +} + +/// +/// Low-overhead, main-thread frame aggregator for direct Harmony and render-pipeline timings. +/// Accumulators are committed at the beginning of the following Unity frame so LateUpdate and +/// render callbacks are included in the frame whose unscaled delta is being reported. +/// +public static class HitchSampler +{ + static readonly Dictionary Current = + new(StringComparer.Ordinal); + static readonly List Frames = new(1024); + + static string _phase = ""; + static int _frame; + static int _gc0; + static int _gc1; + static int _gc2; + static long _mono; + static bool _hasPendingFrame; + + public static bool Active { get; private set; } + public static float HitchThresholdMs { get; private set; } = 100f; + + public static void BeginCapture(string phase, float hitchThresholdMs) + { + Current.Clear(); + Frames.Clear(); + _phase = phase; + _frame = 0; + HitchThresholdMs = Mathf.Clamp(hitchThresholdMs, 16.7f, 1000f); + SnapshotGc(); + _hasPendingFrame = false; + Active = true; + } + + public static List EndCapture() + { + Active = false; + _hasPendingFrame = false; + Current.Clear(); + return new List(Frames); + } + + public static void CancelCapture() + { + Active = false; + _hasPendingFrame = false; + Current.Clear(); + Frames.Clear(); + } + + public static void Record(string id, long ticks, int calls = 1) + { + if (!Active || ticks < 0) return; + if (!Current.TryGetValue(id, out HitchProbeSample? sample)) + { + sample = new HitchProbeSample(); + Current[id] = sample; + } + sample.Calls += calls; + sample.Ticks += ticks; + if (ticks > sample.MaxTicks) sample.MaxTicks = ticks; + } + + public static void Count(string id, int calls = 1) + { + if (!Active || calls <= 0) return; + if (!Current.TryGetValue(id, out HitchProbeSample? sample)) + { + sample = new HitchProbeSample(); + Current[id] = sample; + } + sample.Calls += calls; + } + + /// Called at the first Update of each frame by . + public static void AdvanceFrame(float frameMs) + { + if (!Active) return; + + int gc0 = GC.CollectionCount(0); + int gc1 = GC.CollectionCount(1); + int gc2 = GC.CollectionCount(2); + long mono = UnityEngine.Profiling.Profiler.GetMonoUsedSizeLong(); + + if (_hasPendingFrame && frameMs > 0f && frameMs < 2000f) + { + var record = new HitchFrameRecord + { + Phase = _phase, + Frame = _frame++, + FrameMs = frameMs, + Gc0 = gc0 - _gc0, + Gc1 = gc1 - _gc1, + Gc2 = gc2 - _gc2, + MonoDelta = mono - _mono, + CameraPosition = Camera.main != null + ? Camera.main.transform.position + : Vector3.zero, + }; + foreach (var pair in Current) + { + record.Probes[pair.Key] = new HitchProbeSample + { + Calls = pair.Value.Calls, + Ticks = pair.Value.Ticks, + MaxTicks = pair.Value.MaxTicks, + }; + } + Frames.Add(record); + } + + Current.Clear(); + _gc0 = gc0; + _gc1 = gc1; + _gc2 = gc2; + _mono = mono; + _hasPendingFrame = true; + } + + static void SnapshotGc() + { + _gc0 = GC.CollectionCount(0); + _gc1 = GC.CollectionCount(1); + _gc2 = GC.CollectionCount(2); + _mono = UnityEngine.Profiling.Profiler.GetMonoUsedSizeLong(); + } + + internal static double TicksToMs(long ticks) => + ticks * 1000.0 / Stopwatch.Frequency; +} diff --git a/src/Modules/Profiler/ProfilerModule.cs b/src/Modules/Profiler/ProfilerModule.cs index 151508b..95d244e 100644 --- a/src/Modules/Profiler/ProfilerModule.cs +++ b/src/Modules/Profiler/ProfilerModule.cs @@ -1,3 +1,4 @@ +using HarmonyLib; using S3.Core; using UnityEngine; @@ -10,6 +11,7 @@ public sealed class ProfilerModule : IModule public static ProfilerSettings Settings { get; private set; } = new(); private static GameObject? _hostGo; + private static Harmony? _harmony; public ProfilerModule() => Settings = SettingsStore.Load(SettingsFile); @@ -28,15 +30,24 @@ public sealed class ProfilerModule : IModule public void OnEnable() { + _harmony = new Harmony("S3.profiler"); + _harmony.CreateClassProcessor(typeof(BenchmarkCommandPatch)).Patch(); + HitchProbePatches.Install(_harmony); _hostGo = new GameObject("[S3] ProfilerHost"); UnityEngine.Object.DontDestroyOnLoad(_hostGo); var overlay = _hostGo.AddComponent(); overlay.Visible = Settings.visible; overlay.Opacity = Settings.opacity; + _hostGo.AddComponent(); + _hostGo.AddComponent(); + _hostGo.AddComponent(); } public void OnDisable() { + HitchSampler.CancelCapture(); + _harmony?.UnpatchAll(_harmony.Id); + _harmony = null; if (_hostGo != null) UnityEngine.Object.Destroy(_hostGo); _hostGo = null; } diff --git a/src/Modules/Profiler/ProfilerSettings.cs b/src/Modules/Profiler/ProfilerSettings.cs index 6940a5e..f22e8b4 100644 --- a/src/Modules/Profiler/ProfilerSettings.cs +++ b/src/Modules/Profiler/ProfilerSettings.cs @@ -10,4 +10,7 @@ public class ProfilerSettings public float opacity = 0.85f; public bool showPhysicsSection = true; public bool showMeshLodSection = true; + public bool captureHitchProbes = true; + public float hitchThresholdMs = 100f; + public bool captureUnityBinaryLog = false; } diff --git a/src/Modules/Profiler/ProfilerSettingsUI.cs b/src/Modules/Profiler/ProfilerSettingsUI.cs index f542f8f..f26dd4d 100644 --- a/src/Modules/Profiler/ProfilerSettingsUI.cs +++ b/src/Modules/Profiler/ProfilerSettingsUI.cs @@ -69,6 +69,39 @@ static class ProfilerSettingsUI if (newMesh != s.showMeshLodSection && meshAvail) { s.showMeshLodSection = newMesh; changed = true; } + GUILayout.Space(10f); + GUILayout.Label("Benchmark hitch capture"); + GUILayout.Space(4f); + + bool newCapture = GUILayout.Toggle( + s.captureHitchProbes, + " Attribute base-game work on every benchmark frame"); + if (newCapture != s.captureHitchProbes) + { + s.captureHitchProbes = newCapture; + changed = true; + } + + GUILayout.BeginHorizontal(); + GUILayout.Label($"Hitch threshold: {s.hitchThresholdMs:F0}ms", GUILayout.Width(160f)); + float newThreshold = GUILayout.HorizontalSlider( + s.hitchThresholdMs, 33f, 250f, GUILayout.Width(200f)); + GUILayout.EndHorizontal(); + if (Mathf.Abs(newThreshold - s.hitchThresholdMs) > 0.5f) + { + s.hitchThresholdMs = newThreshold; + changed = true; + } + + bool newBinary = GUILayout.Toggle( + s.captureUnityBinaryLog, + " Write Unity binary profiler data (high overhead)"); + if (newBinary != s.captureUnityBinaryLog) + { + s.captureUnityBinaryLog = newBinary; + changed = true; + } + GUILayout.EndVertical(); if (changed) ProfilerModule.Persist();