Files
sbox-public/engine/Sandbox.Engine/Core/EngineLoop.cs
Lorenz Junglas bae390bcef Improve performance API timing reporting (#5254)
* Track frame-rate cap sleep as an Idle timing stage

* Improve perf stat accumulation

Roll stages and stats up with a single Welford accumulator so window averages are correct, instead of the old running blend.

* Benchmark GCPause timing report millisecond as float instead of int
2026-07-07 10:12:33 +01:00

530 lines
12 KiB
C#

using NativeEngine;
using Sandbox.Audio;
using Sandbox.Engine;
using Sandbox.Engine.Settings;
using Sandbox.Network;
using Sandbox.Rendering;
using Sandbox.TextureLoader;
using Sandbox.UI;
using Sandbox.Utility;
using Sandbox.VR;
using System.Threading.Channels;
namespace Sandbox;
[SkipHotload]
internal static class EngineLoop
{
static double previousTime;
static Superluminal _runFrame = new Superluminal( "RunFrame", "#4d5e73" );
static Superluminal _frameStart = new Superluminal( "FrameStart", "#2c3541" );
static Superluminal _frameEnd = new Superluminal( "FrameEnd", "#2c3541" );
internal static void RunFrame( CMaterialSystem2AppSystemDict appDict, out bool wantsQuit )
{
if ( Application.WantsExit )
{
SoundHandle.Shutdown();
MixingThread.DrainDisposals();
g_pEngineServiceMgr.ExitMainLoop();
}
double time = RealTime.NowDouble;
FastTimer frameTimer = FastTimer.StartNew();
using ( _runFrame.Start() )
{
RealTime.Update( time );
Time.Update( RealTime.Now, RealTime.Delta );
DebugOverlay.Reset();
try
{
using ( _frameStart.Start() )
{
FrameStart();
}
}
catch ( System.Exception e )
{
Log.Error( e );
}
using ( PerformanceStats.Timings.Render.Scope() )
{
wantsQuit = !EngineGlobal.SourceEngineFrame( appDict, time, previousTime );
}
if ( wantsQuit )
{
SoundHandle.Shutdown();
MixingThread.DrainDisposals();
}
try
{
using ( _frameEnd.Start() )
{
FrameEnd();
}
IToolsDll.Current?.RunFrame();
}
catch ( System.Exception e )
{
Log.Error( e );
}
}
SleepForFrameRateClamp( frameTimer );
previousTime = time;
}
static Superluminal _sleepForFrameCap = new Superluminal( "Sleep For Max FPS", Color.Gray );
static double GetMaxFrameRate()
{
if ( Application.IsBenchmark ) return -1;
if ( Application.IsHeadless ) return 60;
double effectiveFps = RenderSettings.Instance.MaxFrameRate;
// Menu and inactive caps tighten the active cap (and each other), applying even when it's uncapped.
if ( Game.IsMainMenuVisible ) effectiveFps = TightenCap( effectiveFps, RenderSettings.Instance.MaxFrameRateMenu );
if ( !InputSystem.IsAppActive() ) effectiveFps = TightenCap( effectiveFps, RenderSettings.Instance.MaxFrameRateInactive );
// Under vsync, a cap above the refresh lets the main thread race ahead of the present queue
// and stall on it (bimodal frame delivery / judder). Clamp to the refresh instead. No-op when
// the cap is already at/below it.
if ( RenderSettings.Instance.VSync )
{
double refresh = GetDisplayRefreshRate();
if ( refresh > 0 && (effectiveFps <= 0 || refresh < effectiveFps) )
effectiveFps = refresh;
}
return effectiveFps;
}
// Lower of two fps caps, treating <= 0 as unlimited so a cap still applies when the other is uncapped.
static double TightenCap( double current, int candidate )
{
if ( candidate <= 0 ) return current;
if ( current <= 0 ) return candidate;
return Math.Min( current, candidate );
}
static double cachedRefreshRate;
static FastTimer refreshRateTimer = FastTimer.StartNew();
/// <summary>
/// Desktop refresh rate (Hz) of the default monitor, cached and re-queried every couple of
/// seconds. Returns 0 if unknown (treat as "no clamp").
/// </summary>
static double GetDisplayRefreshRate()
{
if ( cachedRefreshRate <= 0 || refreshRateTimer.ElapsedSeconds > 2.0 )
{
int w = 0, h = 0;
uint hz = 0;
EngineGlobal.Plat_GetDesktopResolution( EngineGlobal.Plat_GetDefaultMonitorIndex(), ref w, ref h, ref hz );
cachedRefreshRate = hz;
refreshRateTimer = FastTimer.StartNew();
}
return cachedRefreshRate;
}
// Drift-compensated pacing: wake each frame on an absolute 1/fps grid rather than padding from the
// frame's own start, so per-frame overhead doesn't accumulate into drift. Resyncs after a hitch.
static FastTimer pacingClock = FastTimer.StartNew();
static double nextFrameDeadlineMs;
static void SleepForFrameRateClamp( FastTimer frameTime )
{
double frameSleepMs = 0;
double maxFps = GetMaxFrameRate();
double targetMilliseconds = maxFps > 0 ? 1000.0 / maxFps : 0;
if ( targetMilliseconds > 100 ) targetMilliseconds = 100; // min is 10fps
if ( targetMilliseconds <= 0 )
{
nextFrameDeadlineMs = 0; // uncapped — drop the grid
}
else
{
double nowMs = pacingClock.ElapsedMilliSeconds;
// Next grid point is one period after the previous deadline (not after 'now') — the drift
// compensation. Seed from 'now' on the first frame.
double deadlineMs = nextFrameDeadlineMs > 0 ? nextFrameDeadlineMs + targetMilliseconds : nowMs + targetMilliseconds;
// More than a period behind (a hitch)? Resync to 'now' rather than catch up in a burst.
if ( nowMs - deadlineMs > targetMilliseconds )
deadlineMs = nowMs;
if ( nowMs < deadlineMs )
{
using var inst = _sleepForFrameCap.Start();
double sleepMs = deadlineMs - nowMs;
if ( sleepMs > 1.0 )
{
System.Threading.Thread.Sleep( (int)sleepMs );
}
// sleep is inaccurate (to nearest 1ms, we call timeBeginPeriod in engine)
// so bleed off any residual fractions of a millisecond
while ( pacingClock.ElapsedMilliSeconds < deadlineMs )
{
// wait
}
// actual time parked this frame, including any oversleep
frameSleepMs = pacingClock.ElapsedMilliSeconds - nowMs;
}
nextFrameDeadlineMs = deadlineMs;
}
PerformanceStats.Timings.Idle.AddMilliseconds( frameSleepMs );
// Feed the on-screen pacing overlay (no-op unless overlay_fps is on).
DebugOverlay.FrameTimeGraph.Sample( frameTime.ElapsedMilliSeconds );
}
/// <summary>
/// Pumps the input system
/// </summary>
static void UpdateInput()
{
using var __ = PerformanceStats.Timings.Input.Scope();
g_pInputService.Pump();
}
internal static void FrameStart()
{
ThreadSafe.AssertIsMainThread();
//
// Let the Steam API and Steam Game Server API think
//
NativeEngine.Steam.SteamGameServer_RunCallbacks();
NativeEngine.Steam.SteamAPI_RunCallbacks();
//
// Update performance stats (should be called every frame)
//
UpdatePerformance();
DebugOverlay.Draw();
UpdateInput();
//
// Dispatch callbacks for any changed files
//
FileWatch.Tick();
//
// Update any animated textures
//
using ( PerformanceStats.Timings.Video.Scope() )
{
Texture.Tick();
}
//
// Update VR
//
VRSystem.FrameStart();
//
// Expire any unused resources
//
NativeResourceCache.Tick();
Game.Resources.PruneWeakIndex();
Mounting.MountUtility.TickPreviewRenders();
//
// Run Tasks
//
RunAsyncTasks();
//
// Let the context's tick
//
IMenuDll.Current?.Tick();
IGameInstanceDll.Current?.Tick();
IMenuDll.Current?.LateTick();
IToolsDll.Current?.Tick();
//
// Run Tasks
//
RunAsyncTasks();
//
// Misc client systems
//
if ( !Application.IsHeadless )
{
using ( IGameInstanceDll.Current?.PushScope() )
{
VoiceManager.Tick();
Sandbox.TextRendering.Tick();
}
}
//
// If we have any queued console messages, we can print them now
//
Logging.PushQueuedMessages();
//
// Allow the events to push if they want
//
Api.Events.TickEvents();
Api.Stats.TickStats();
Sandbox.Services.Messaging.ProcessMessages();
// Simulate UI last. This works out all the styles and shit, so we want
// that to be reflected right BEFORE the frame is rendered.
using ( PerformanceStats.Timings.Ui.Scope() )
{
SimulateUI();
}
// Give each sound handle an opportunity to for a frame think
using ( PerformanceStats.Timings.Audio.Scope() )
{
MixingThread.UpdateGlobals();
}
//
// Update the mouse visibility status
//
if ( !Application.IsHeadless )
{
Engine.InputRouter.Frame();
}
// Keep room up to date
PartyRoom.Current?.Tick();
Audio.AudioEngine.Tick();
}
public static void RunAsyncTasks()
{
using ( PerformanceStats.Timings.Async.Scope() )
{
using var sceneScope = IGameInstanceDll.Current?.PushScope();
ThreadSafe.AssertIsMainThread();
MainThread.RunQueues();
SyncContext.MainThread?.ProcessQueue();
}
}
internal static void FrameEnd()
{
ThreadSafe.AssertIsMainThread();
//
// Run Tasks
//
Engine.Streamer.CurrentService?.Tick();
RunAsyncTasks();
//
// Update VR
//
VRSystem.FrameEnd();
//
// Free strings allocated by Interop shit, and let us know how many
//
int count = Interop.Free();
if ( count > 10 )
{
//log.Trace( $"Interop Free: {count}" );
}
//
// Run threaded stuff that needed to
// happen on the main thread
//
MainThread.RunQueues();
//
// Trigger recompile of Project
//
Project.Tick();
//
// Free anything that needs to be disposed of at end of frame
//
DrainFrameEndDisposables();
// Free render targets
RenderTarget.EndOfFrame();
}
static unsafe void UpdatePerformance()
{
PerformanceStats.Frame();
Api.Performance.Frame();
}
static Superluminal _simulateUiGame = new Superluminal( "Simulate GameUI", "#2c3541" );
static Superluminal _simulateUiMenu = new Superluminal( "Simulate GameUI", "#2c3541" );
private static void SimulateUI()
{
ThreadSafe.AssertIsMainThread();
VideoTextureLoader.TickVideoPlayers();
TooltipSystem.Frame();
PanelRealTime.Update();
using ( _simulateUiGame.Start() )
{
IGameInstanceDll.Current?.SimulateUI();
}
using ( _simulateUiMenu.Start() )
{
IMenuDll.Current?.SimulateUI();
}
}
private static Logger nativeLogger = Logging.GetLogger( "Native" );
static string partial = "";
internal static void Print( int severity, string logger, string message )
{
partial += message;
if ( !partial.Contains( "\n" ) )
return;
if ( partial.EndsWith( '\n' ) )
{
message = partial;
partial = "";
}
else
{
var i = partial.LastIndexOf( '\n' );
message = partial.Substring( 0, i );
partial = partial.Substring( i );
}
message = message.TrimEnd( new[] { '\n', '\r' } );
NLog.LogLevel level = severity switch
{
0 => NLog.LogLevel.Info,
1 => NLog.LogLevel.Info,
2 => NLog.LogLevel.Warn,
3 => NLog.LogLevel.Warn,
4 => NLog.LogLevel.Error,
5 => NLog.LogLevel.Fatal,
_ => NLog.LogLevel.Info,
};
var logName = $"engine/{logger}";
nativeLogger.WriteToTargets( level, null, $"{message}", logName );
}
internal static void Print( bool debug, string message )
{
message = message.TrimEnd( new[] { '\n', '\r' } );
if ( debug )
{
nativeLogger.Trace( message );
}
else
{
nativeLogger.Info( message );
}
}
/// <summary>
/// A console command has arrived, or a convar has changed
/// </summary>
internal static void DispatchConsoleCommand( string name, string args, long flaglong )
{
var convar = ConVarSystem.Find( name );
if ( convar is null )
{
Log.Warning( $"Unknown Command: {name}" );
return;
}
convar.Run( args );
}
static Superluminal _clientOutput = new Superluminal( "OnClientOutput", "#3a6ea5" );
static Superluminal _toolsRender = new Superluminal( "Tools Render", "#6e6e3a" );
static Superluminal _gameRender = new Superluminal( "Game Render", "#3a6e4d" );
static Superluminal _menuRender = new Superluminal( "Menu Render", "#6e3a6e" );
internal static void OnClientOutput()
{
using var _outputScope = _clientOutput.Start();
// The editor renders it's own game scene
if ( Application.IsEditor )
{
using ( _toolsRender.Start() )
IToolsDll.Current?.OnRender();
return;
}
var engineChain = g_pEngineServiceMgr.GetEngineSwapChain();
using ( _gameRender.Start() )
IGameInstanceDll.Current?.OnRender( engineChain );
using ( _menuRender.Start() )
IMenuDll.Current?.OnRender( engineChain );
}
/// <summary>
/// Called right at the end of a view being submitted, so everything CPU is done and it's handed off to the GPU.
/// This is also called for any dependent views.
/// </summary>
internal static void OnSceneViewSubmitted( ISceneView view )
{
RenderPipeline.OnSceneViewSubmitted( view );
}
static Channel<IDisposable> FrameEndDisposables = Channel.CreateUnbounded<IDisposable>();
/// <summary>
/// Queue something to be disposed of after the frame has ended and everything has finished rendering.
/// </summary>
internal static void DisposeAtFrameEnd( IDisposable disposable ) => FrameEndDisposables.Writer.TryWrite( disposable );
/// <summary>
/// Drain all queued frame-end disposables immediately. Called during shutdown
/// since no more frames will run to process them naturally.
/// </summary>
internal static void DrainFrameEndDisposables()
{
while ( FrameEndDisposables.Reader.TryRead( out var disposable ) )
{
disposable.Dispose();
}
}
}