Ollin

Profiling

Ollin renders on the GPU, so a sketch can draw a great deal before it slows down. When a sketch does slow down, you need to know which half of the frame, the CPU or the GPU, is taking the time. The inspector shows this. Its cell grid ends with three counts, and two bars sit under the grid. Together, the counts and the bars show where the frame time went.

In a standalone sketch, open the inspector with ⌘/. In OllinLive, the gallery, and the live-coding host, the inspector is in the sidebar. Every host shows the same card.

A diagram of the inspector's cost row: a row of cells reading 1 draw, 2 passes, 1 batch, over a CPU bar filled a little over half and a GPU bar filled less, with callouts naming what each part means

Contents

The two bars

The CPU bar is the time spent in your draw() plus the time spent encoding it into GPU commands. Tessellation is part of this time, and in an immediate-mode renderer it is the first cost to grow. The GPU bar is the time the device spent on the frame, read from the device's own timestamps.

Both bars use the same scale: the period of one frame. At 60 frames a second, that period is 16.7 ms. So the longer bar is the bottleneck, and two short bars mean the sketch has time to spare.

The two bars are not stacked into one, on purpose. The CPU builds frame N while the GPU is still drawing frame N-1, so the two times overlap instead of adding up. One stacked bar would suggest a total that does not exist.

Hover over either bar for the detail. The CPU tooltip splits its number into drawing time and encoding time, and it also shows the time spent waiting for the display. That wait is spare time, not work, so a large wait means the sketch has headroom.

The GPU number has one caveat. It is measured on the frame the device has just finished, which is a frame or two behind the one being built. The number is smoothed for display, so you only notice the lag when a sketch changes cost suddenly.

The three counts

  • Draws is the number of draw calls the frame issued. Hover over it for the breakdown by path. The paths are instanced SDF shapes, fill and stroke vertices, mesh vertices, glyphs, images, fields, point splats, particles, and compute dispatches.
  • Passes is the number of render passes the frame encoded. The canvas and the present are always two of them, and every effects layer, filter, shadow map, and probe bake adds its own pass.
  • Batches is the number of runs the drawer recorded. A run ends, and a new one starts, whenever the pipeline, blend mode, texture, or clip level changes.

The ratio of batches to shapes is the useful number. Ten thousand circles in one batch cost one draw call, but ten circles that each change the blend mode cost ten draw calls.

The first frame reads higher than the frames after it, because some setup happens once and is then cached for the life of the window.

What to do about a slow frame

Read the bars first, then act on the longer one.

The CPU bar is longer. The frame is spending its time building geometry.

  • Check the draws tooltip for a large vertex count. Fills and strokes are tessellated on the CPU, but each closed shape in the SDF catalog is one instance.
  • Put static geometry in a retained batch. A batch is recorded once and then replayed from GPU memory on every later frame.
  • A high batch count with few shapes means the state changes for each shape. Group together the shapes that share a blend mode, a texture, or a clip.

The GPU bar is longer. The frame is spending its time shading pixels.

  • Look at the pass count. A long filter chain is a series of passes over the whole canvas, and each pass costs fill rate.
  • An effects layer can render at a fraction of the canvas size. Pass scale: to makeRenderTarget(scale:) for any soft effect, such as a blur or a glow.
  • In 3D, shadows, reflections, and global illumination each add passes of their own. The 3D pages give the cost of each one.

Both bars are short and the frame rate is still low. Something outside the drawing is holding up the frame. A file read or a heavy setup() call in the middle of draw() will do it.

Capturing a frame for Xcode

When the GPU bar is longer and you need to know which pass is slow, hand the frame to Metal's own debugger:

if frameCount == 120 { captureGPUFrame() }        // or: captureGPUFrame(to: "slow.gputrace")

The captured frame is the same frame you call captureGPUFrame() from, because the request is taken between your draw() and the render that follows it. Ollin writes a .gputrace file. That file opens in Xcode and shows per-pass timings, the pipeline state, and every bound resource.

Metal does not capture unless the process asks for it at launch. Run the sketch with the capture flag set:

MTL_CAPTURE_ENABLED=1 ollin MySketch.swift

Without the flag, the sketch prints the command line above and keeps drawing. The host menu offers the same capture as an action. View ▸ Capture GPU Frame (⌘⇧G) captures the next frame.

Either way, Ollin prints the frame's passes in order next to the file path. That list alone often answers the question, and you do not need to open Xcode to read it.

Reading the numbers from code

A sketch can read the same numbers through the extension seam. FrameInfo carries a FrameProfile, so an extension can log a frame, watch for a threshold, or draw its own readout:

final class SlowFrameLog: SketchExtension {
    func afterFrame(_ sketch: Sketch, _ info: FrameInfo) {
        let p = info.profile
        guard p.cpuMS > 8 else { return }
        print("frame \(sketch.frameCount): \(p.cpuMS) ms CPU, \(p.drawCalls) draws, \(p.batches) batches")
    }
}

FrameProfile holds three groups of values. The first group is the four times (cpuDrawMS, cpuEncodeMS, gpuMS, waitMS). The second is the submitted work (drawCalls, passes, computeDispatches, batches). The third is the geometry, one count per path the frame drew:

  • triangleVertices through the tessellated fills, fringeVertices through the stroke expander, and clipVertices for clip regions, which draw into the stencil rather than the canvas and still cost tessellation.
  • sdfInstances, one quad and one struct write for each analytic shape, and fieldQuads, one covering quad for each composed SDF field, 2D or raymarched.
  • imageVertices for the textured quads (images and depth backdrops) and glyphVertices for text through the glyph atlas.
  • meshVertices for 3D triangle meshes and pointSplats for instanced point-cloud splats.

cpuMS is the sum of the two CPU times, tessellatedVertices the sum of every vertex the CPU built this frame, and hasData is false until a frame has actually been measured, which is what an overlay reads before it draws anything.

The same three geometry totals reach an extension more cheaply on FrameInfo itself: vertexCount is what the CPU tessellated, sdfCount the instanced analytic shapes, and pointCount the GPU-resident splats and particle discs, which live in no CPU array at all.

The counts reflect what was drawn, not what was recorded, so a batch the renderer skipped does not appear in them.

An export fires the same hook once per frame it renders, a warmup frame that renders or a settle draw included, so the cost of a written frame can be read from the run that writes it. The numbers there are the frame's own rather than smoothed. frameRate is the rate the frame was timed at and deltaTime the clock's step, zero for a settle draw. cpuDrawMS is that one draw. waitMS is the drive's wait for the GPU to finish the frame, which covers gpuMS, since a headless render is synchronous.

Related: Sketch - Drawing - Retained batches - Effects - Parameters

↑↓ move ↩ open