The Lock Was Fine

Fractal's server took 8.9 seconds to finish building its overview, and the browser saw the last image at 9.1. The obvious suspect, the canvas lock, was held for a total of 5 milliseconds.

Strokes are stored in tiles, and a zoomed-out view shows art drawn at deeper zoom levels as cell images. The server takes everything that falls inside a cell, rasterizes it into a 256 × 256 PNG, and sends it down. Four worker goroutines do the rasterizing. On a cold overview the cells filled in one at a time. Agents wrote most of that code; finding where the time went, and what to change, was my part (how that split works).

The obvious suspect#

Every cell image starts with a snapshot. SnapshotCell takes the canvas read lock, finds every stroke whose reach meets the cell, clones it, and sorts the clones into paint order. At the overview, a cell over the middle of the artwork contains every nested scene below it. That's a lot of cloning under a lock that writers also need.

That reading of the code predates any measurement. A plan for much larger showcase art, around 2,500 strokes per central overview cell and over 8,000 in the biggest tier, said it in one line: "Expect slow first builds and lock contention with writes." At the size I measured, it was right about the symptom and wrong about the cause.

The fixes that theory points toward are expensive. Fractal is one Go process. Each canvas lives in memory behind one sync.RWMutex, and disk snapshots read through that same lock. The persistence plan had already named the escape hatch if read-lock contention on this mutex became a problem: a copy-on-write tile map. That's a change to how the canvas is stored, not a tweak.

What the lock actually did#

Before changing anything, I froze a corpus and measured it: 1,869 strokes and 211,085 points, replayed into a private server through the normal WebSocket path. Everything ran on an M5 over loopback. Temporary instrumentation wrapped each stage of a cell build: snapshot, raster, PNG encode, marshal, socket write.

For the cold overview:

The worker sums overlap, so they don't add up to wall time. Total time spent waiting to acquire the read lock was between 1.46 and 7.38 microseconds per view, across every view that needed images. Five milliseconds of lock can't account for nine seconds of anything.

I only have a small data point on writes. In a separate probe, two viewers watched one small stroke get added and then undone on one cell, and the rebuild's snapshot held the read lock for 0.0646 ms and 0.1038 ms. That's not a many-user test, so it says nothing about write contention under real load.

The code agreed. Only the snapshot runs under the lock; a worker rasterizes the copy after it's released.

Where the 8.9 seconds went#

The same run allocated 45.916 GiB and triggered 1,815 garbage collections. Process RSS afterward was about 92 MiB. That isn't a 46 GiB heap. It's churn: short-lived memory, requested and thrown away over and over.

The allocation profile was blunt about where. Across the profiling runs, polygonSpans accounted for 94.15% of sampled allocated bytes. Trimmed, covering the whole profiling matrix rather than the one run above:

Type: alloc_space
      flat  flat%   sum%        cum   cum%
  419.68GB 94.15% 94.15%   431.57GB 96.81%  canvas.polygonSpans
    9.68GB  2.17% 96.32%    12.88GB  2.89%  internal/reflectlite.Swapper
    9.29GB  2.08% 98.40%   441.85GB 99.12%  canvas.geometrySpans
    3.20GB  0.72% 99.12%     3.20GB  0.72%  internal/reflectlite.unsafe_New
         0     0% 99.28%    12.88GB  2.89%  sort.Slice

The CPU profile was flatter. polygonSpans was 24.1% inclusive, and a substantial share of samples sat in runtime sleep and condition waits, which I can't attribute cleanly to the garbage collector.

The worst overview cell took 8.83 seconds on its own, with 499 strokes in its snapshot. A separate diagnostic build counted what happened inside that one cell:

• 202,329,021 polygon scans
• 729,312,494 edge tests
• 8,917,624 scans that found any crossing at all

So 95.59% of the scans found nothing. Each of those still allocated a slice and sorted it.

Why most scans come up empty#

The rasterizer computes exact fractional coverage. It splits each pixel row into eight horizontal strips, then splits again at every geometry break, including every polygon vertex in the stroke's outline. For each strip it asks every polygon in the stroke which spans it covers at that height. That question walks every edge of the polygon.

At the overview, art from many zoom levels gets squeezed into one 256-pixel cell. More vertices per row means more strips. Every strip still scans every polygon, including the ones that sit nowhere near that height. The same diagnostic counted 287,444 span evaluations in that cell. Dividing the scans by that gives roughly 700 polygons scanned per evaluation, a derived figure rather than a measured one, and most of them answer "nothing here."

Here's the first fix, against the function as it was (trimmed):

 func polygonSpans(poly []xy, y float64) []span {
 	if len(poly) < 3 {
 		return nil
 	}
-	intersections := make([]crossing, 0, len(poly))
+	var intersections []crossing
 	for i, a := range poly {
 		b := poly[(i+1)%len(poly)]
 		if (a.y <= y && b.y > y) || (b.y <= y && a.y > y) {
 			// ...winding direction...
+			if intersections == nil {
+				intersections = make([]crossing, 0, len(poly))
+			}
 			intersections = append(intersections, crossing{ /* x, wind */ })
 		}
 	}
+	if len(intersections) < 2 {
+		return nil
+	}
 	sort.Slice(intersections, func(i, j int) bool { /* by x */ })

The old version allocated a full-capacity slice before it knew whether anything crossed, then handed it to sort.Slice, which goes through reflection and allocates too (the reflectlite rows above). The new one allocates on the first real crossing and returns before sorting when there are fewer than two. Coverage math, winding, and paint order are untouched. Every decoded image in the 960-cell comparison matrix matched the old output exactly.

Typed sorts, vertical bounds, scratch buffers#

The before/after work used a second frozen corpus of 1,792 strokes, so its baseline doesn't line up with the 8.9 seconds above. Each fix was measured with a lightly instrumented server and a socket driver, three fresh-server runs, same overview view. The first fix alone cut cumulative allocation from 30.425 GiB to 8.041 GiB and process CPU from 39.3 to 12.2 core-seconds.

The performance plan said up front that this wouldn't finish the job. Skipping empty allocations doesn't skip the edge walks. So each next change waited for the profile after the last one, and got its own before/after run:¹

Typed sorts means slices.SortFunc instead of reflective sort.Slice. Vertical bounds skips polygons whose vertical range doesn't include the sampled height. In one dense overview cell, polygon calls fell from 116.9 million to 8.1 million. Allocation barely moved, because this one cut walking, not allocating. Scratch buffers are reused within a single cell render, and they took allocation from 6.365 GiB to 0.214 GiB.

The whole first round, measured end to end with uninstrumented Go builds in a real browser, took the cold overview from 6,098.1 ms to 639.9 ms to ready, one sample each. Go CPU for that load went from 19,760 ms to 1,460 ms. The round also included client and transport changes, so not all of it belongs to the rasterizer.²

What I left alone#

The performance plan's decision on the lock was one line: "Do not redesign locking or move rendering out of a lock it does not hold." So the locking stayed, persistence stayed, and Fractal is still one Go process with one RWMutex per canvas. I didn't add workers either. Four of them were already contending with heavy allocation, and more workers can't split one 8.8-second cell. All four raster fixes landed in one file, raster.go, as 62 added lines and 15 removed.

One lock change made the list and got deferred: sorting the cloned snapshot after unlocking instead of before. It would shorten holds that were already measured in milliseconds. The sort still runs under the lock today.

What it cost, and what's left#

The vertical-bounds check made sparse cells slower at the time: 225.87 ms to 236.24 ms per 3,000 renders, about 4.6%. A later active-edge sweep replaced both that check and the habit of walking every polygon and edge at every sample height. Scratch buffers complicated helper signatures and slice ownership: every reused slice now has a lifetime scoped to one render.

The lock also still clones every stroke a cell touches. The showcase plan's forecast was for art about the size of today's live showcase, roughly 20,000 strokes, and nobody has measured the lock at that size. The performance plan wrote down what would reopen the question: a profile showing snapshot selection or lock contention dominating after the raster fixes. Until that profile exists, a lock redesign is the default suspicion, not a finding.