Profiling one frame: where 16.6 ms actually goes

At 60 frames per second a frame has 16.6 ms. That number is the only budget a game has, and almost every performance conversation goes wrong because nobody splits it. A frame that misses the deadline is not necessarily slow everywhere; it is slow somewhere, and the somewhere is measurable.

The budget, split four ways

The stages overlap. The GPU is busy while the next frame's command recording happens, so the numbers do not add up to the frame time and should not. What matters is which stage is closest to its own deadline, and whether the pipeline has enough depth to hide the others.

Instrument before you guess

Two kinds of trace, used together: system-wide scheduling from Perfetto, and in-app markers from ATrace. The markers cost about 60 nanoseconds each when tracing is off, which is cheap enough to leave in release builds.

#include <android/trace.h>

void Game::frame() {
  ATrace_beginSection("frame");
  ATrace_beginSection("input");
  input_.poll();
  ATrace_endSection();

  ATrace_beginSection("simulate");
  world_.step(dt_);
  ATrace_endSection();

  ATrace_beginSection("record");
  renderer_.record(world_);
  ATrace_endSection();
  ATrace_endSection();
}

Capture with a Perfetto config that includes gfx, view, sched and freq, and your package in atrace_apps. A ten-second capture at these settings is about 20 MB, which is small enough to keep in a bug report.

buffers: { size_kb: 32768 }
data_sources: {
  config {
    name: "linux.ftrace"
    ftrace_config {
      atrace_categories: "gfx"
      atrace_categories: "view"
      atrace_categories: "sched"
      atrace_categories: "freq"
      atrace_apps: "com.example.game"
    }
  }
}

GPU time from a timestamp query

The GPU does not report a duration by itself. Write a timestamp before the first draw and after the last, then subtract. Two queries per frame are enough; more add synchronisation than they explain.

VkQueryPoolCreateInfo q{VK_STRUCTURE_TYPE_QUERY_POOL_CREATE_INFO};
q.queryType = VK_QUERY_TYPE_TIMESTAMP;
q.queryCount = 2;
vkCreateQueryPool(device, &q, nullptr, &pool);

vkCmdResetQueryPool(cmd, pool, 0, 2);
vkCmdWriteTimestamp(cmd, VK_PIPELINE_STAGE_TOP_OF_PIPE_BIT, pool, 0);
// ... draws ...
vkCmdWriteTimestamp(cmd, VK_PIPELINE_STAGE_BOTTOM_OF_PIPE_BIT, pool, 1);

Read the results two frames later, never in the frame that wrote them: reading forces a wait and changes what you are measuring. Multiply ticks by timestampPeriod from VkPhysicalDeviceLimits to get nanoseconds, and average over 120 frames before drawing conclusions.

On a tiled GPU — which is what most phones have — the number includes the resolve and the composition pass only if you submit them inside the query range. A query around the main render pass alone will under-report by 2 to 4 ms on a device with a 1440p panel.

What the trace showed

Our first capture of the scene above looked healthy on the CPU and terrible on the GPU. The breakdown:

Physics was the largest CPU cost and the shadow pass the largest GPU cost, but neither was the frame's problem: the frame was missing deadlines because the render thread waited for vkAcquireNextImageKHR while the compositor held the buffers. That wait appears in the trace as a gap with no marker, which is exactly the kind of thing an average frame-time graph hides.

Percentiles, not averages

A mean of 16.4 ms can contain a 48 ms frame every fifty frames. Players notice those; a benchmark summary does not. Record the raw duration of every frame for at least 60 seconds, then report p50, p95 and p99.

# 60 seconds of frame times, one per line, in milliseconds
sort -n frames.txt | awk '{a[NR]=$1} END {
  printf "p50 %.1f  p95 %.1f  p99 %.1f
",
         a[int(NR*0.50)], a[int(NR*0.95)], a[int(NR*0.99)] }'

On Android 12 and newer, FrameTimeline gives the same information with the system's own view of presentation, which is the number that matches what a user sees. Use it when you can; fall back to your own timestamps on older devices.

False leads

• GPU frequency changes mid-trace. A frame that looks faster after a thermal event is a measurement artifact. Pin the frequency on a rooted test device, or compare only the sustained section.
• Debug builds. A debug build of the same scene runs at 40 percent of the release frame rate and changes which stage is the bottleneck. Profile release, with symbols.
• One device. The bottleneck moves between GPU vendors. A shadow pass that costs 4.6 ms on one phone costs 9 ms on another with the same resolution.
• Traces with the profiler attached. Attaching a debugger stops threads; the trace then shows waits that do not exist in the real run.

The checklist we use

1. Set a target: p99 under the frame budget, not an average.
2. Capture ten seconds of a reproducible scene, in release, with markers.
3. Split by stage; find the stage closest to its deadline.
4. Change one thing, capture again, compare p99 and the stage you changed.
5. Repeat on a second device with a different GPU vendor.

Numbers from a single phone are a hypothesis. The power article explains what happens to those numbers after eight minutes of play, and the note on frame pacing has the percentile script in context.