Repository navigation
Profile build: timelines, simulation trace summary, instrumentation - #594
Merged
Merged
Conversation
…trace. Changes for all builds, from the profile build plan (phase 1): - Start-up timeline: from the process' creation (so the time before the first managed code shows) over Unity's init stages and the host's steps to the first frame after the menu is ready. One log line and a Startup diagnostics section. - Table load timeline: the reader's steps and the load phases as milestones with wall and CPU time, texture cache result and load kind. Playable is the first frame after the table loaded and its gamelogic engine said it started; settled is the first 3 s window without a frame over 1.5x its median. The load ends as settled, timeout, failed or cancelled, with a log line each and a Finished event. - SimulationTrace: a summary mode for players, with a 60 s ring instead of 10 minutes and no CSVs, summarized every minute on a worker. The rings belong to a session and are read with a per-slot seqlock, so a summary never reads a record being written or freed rings. A new run supersedes the cached summary and its file. The summary goes next to the session log, for reports. The editor toggle and --simulation-trace keep the 10-minute CSVs. - The rendered snapshot no longer steps back to an older one when nothing new was published. - Microsecond timestamps no longer overflow after days of uptime.
VpeProfiler exists in every build, but its methods are conditional on VPE_PROFILE, which only the profile build defines, so their calls and arguments compile out of the normal player. A test checks the API's methods, that profiling code stays inside the define, that nothing sends performance data to Sentry outside of it, and that the engine's IL has no calls to the conditional methods. The build info says which flavor a build is.
…file build. All in VPE_PROFILE code, so normal builds are unchanged: - Recorders: a stamp at the start of each top-level PlayerLoop system, the VPE sections per frame (and calls of 0.5 ms or more), Unity's frame timings matched to the frames they belong to (Unity's timer is the platform's monotonic clock, Mono's stopwatch starts with the process), events like focus, display changes and first uses, and the simulation's ticks and lock waits through the trace's seqlock. Two minutes each. - Detectors on frames once their timings are in: stutters, hitches, pacing, simulation stalls and slowdowns, each with its most likely cause (physics lock, GC, a VPE section, render/GPU or the present, scheduling, simulation overload, first use, environment). - A Perfetto trace of the seconds around the worst incidents (3 per table, and F9), copied on the main thread and written on a worker into a reused buffer, into logs/perf. - Ten-second metrics windows, play statistics at the end of a table, log lines per incident, and self tests (--vpe-test-perf=<mode>|all) that make each problem in a real build. - Section and first-use call sites in the player, lamps, balls and DMD. Also, for all builds: start-up ends at a table launched from the command line, and the RAM at playable is read without Process, which says 0 on Mono.
[Medium impact] The changes since the previous review appear safe to merge. SummaryAdds startup and table-load timelines, saved simulation summaries, and profile-only frame recording, incident detection, metrics, and Perfetto traces.
|
…on quit. - The play ends at the table's unload (and when the player goes): the frames still waiting for their timing are handed on, nothing after counts as play, and a trace they asked for is written. - When the application quits, the simulation's last summary is made on the main thread instead of a worker the exit may kill. - A callback that throws no longer leaves its section open. - A frame's incidents count in the metrics window that frame closes. - In a profile build, --no-simulation-trace keeps the summary but not the CSVs; the mode test knows the profile build's modes.
… profile build. The incident detector read Screen.currentResolution for every frame to know the vsync interval. That call runs QueryDisplayConfig, which blocks for about 21 ms while another process holds Windows' window manager (for example while a script starts a console program). The profile build then stalled 2-3 frames in a row on its own, after the frame's end stamp, so the time showed up as unexplained main-thread time outside the PlayerLoop. The recorder now keeps the refresh rate it polls and reads it again only when the resolution, fullscreen mode or display count changes, or every 10 s.
…file build. While a process creates a console window, Windows' window manager is locked for about 85 ms in four slices. Our display queries, Present and input polling wait for it, and the player hitches for 50-80 ms. Until now the profile build reported that as "unknown" or "render-gpu". SystemLockProbe times GetDisplayConfigBufferSizes on a background thread every 10 ms, using a high-resolution waitable timer. It follows a stall every millisecond and merges its slices into one record, so one burst becomes one record of about 90 ms. Samples a garbage collection ran into are dropped. Incidents that overlap a recorded stall by 5 ms or more get the new cause "system-lock" and the locked time. A display mode or focus change keeps "environment" as the primary cause, since the player locks the window manager itself then. The time also appears in the log line, on a trace track of its own and in the trace metadata. --vpe-test-perf=syslock starts a few hidden consoles to check the path end to end.
A Windows build target in a Mac or Linux editor compiled the probe in, and its thread would have died on the missing DLLs. Also checks the OS before starting and logs instead of letting an exception end the process.
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The engine side of the profile build: a version of the player that finds and explains performance problems (stutters, frame pacing, physics stalls, CPU/GPU limits, slow start-up and table loads) on testers' machines and reports them to Sentry. Plan:
PROFILE_BUILD_PLAN.md.For every build
Startup:log line and aStartupdiagnostics section.SimulationTrace:--simulation-tracestill write the CSVs.For the profile build only (
VPE_PROFILE)VpeProfiler: an API with conditional methods, so its calls compile out of normal builds. A test checks that, and checks the IL.--vpe-test-perf=<mode>|all).Testing