Tuscolo2026h2 write-path degradation on August 9th

[Filippo Valsorda]

Hello fellow humans presumably born at 400 ppm CO₂ or less,

On the night between August 8th and August 9th, the Tuscolo2026h2 log experienced 30 minutes of degraded submission performance due to a combination of increased traffic, poor cache database tuning, and a latent lock starvation bug.

During the incident, submission latency grew to up to 80s, accepted throughput fell to ~25/s, and most submissions were rejected with 503s. The read path was unaffected, no successful submissions were lost, and all certificates were incorporated within the 60s MMD. However, there were 1–3 gaps between STHs longer than 60s.

Details

For context, Sunlight has up to two pools: the one incoming submissions are being added to, and the one currently being sequenced. On a ticker, if the previous sequencing has completed, the incoming pool is swapped for a new one, and the previously current one starts sequencing. The Sunlight deduplication cache is a SQLite database that is written to during pool sequencing, and read from while adding an entry to the incoming pool. Adding entries to the incoming pool and swapping the pool for sequencing are done under a lock.

Approximately 24h before the incident, the well-known cross-poster started submitting to the Tuscolo logs, raising submission rates on Tuscolo2026h2 from ~20/s to 100–400/s (and by 20–50/s on Tuscolo2027h1). We noticed and observed top-level metrics were healthy, although we missed that cache p99 times had gone up.

Sequencing times grew, dominated by writes to the SQLite deduplication cache, which was not tuned for the workload. The default SQLite page cache (2MB) was far too small for a 22GB database with random keys, sending all the interior node reads to the filesystem, and the ZFS ARC demand-data miss ratio climbed 5% to 24% over the day. The ZFS dataset had the default 128K record size, leading to a 32× read and ARC utilization amplification on the randomly-distributed B-tree interior pages.

SQLite WAL autocheckpoints (which involve a PASSIVE checkpoint followed by fsyncs in the configured synchronous=NORMAL mode) caused occasional sequencing duration spikes.

Eventually, traffic and spikes triggered two chain reactions. First, cache reads were frequent enough that the WAL autocheckpoints couldn’t complete without waiting, so in the default PASSIVE mode they made what progress they could but didn’t reset the WAL, meaning the next write would also attempt a checkpoint. This made sequencing rounds slower.

Second, and most importantly, the pool insertions (dominated by the cache gets, also slowed down by the same factors above) started contending the incoming pool lock away from the sequencer. In starvation mode (if anything is blocked for more than 1ms), Go mutexes become a FIFO, so the sequencer had to queue behind pool insertions, and paused for tens of seconds between runs.

Finally, the pool size was configured too high. We set it at 750 when the logs were configured with 1s sequencing intervals, but then lowered the interval to 200ms without lowering the pool size. This means sequencing a full pool took longer than the interval, worsening queueing. However, a smaller pool size wouldn’t have helped much because cache gets were happening before pool-full rate-limit rejections.

At this point, a cycle looked like:

• the sequencer takes a long time (1-7s) to sequence a pool;
• while the pool is sequencing, incoming requests hit the degraded cache get, queueing on the pool lock FIFO and keeping the SQLite reader duty cycle high;
• there is no time for the queue to drain, because sequencing took longer than the interval;
• the sequencer queues on the lock for up to 30s, during which no checkpoints are issued, the pool fills up, and requests start being turned away with 503s;
• when the sequencer finally runs, it’s slow because the pool is full, because of the degraded cache put, and because every transaction tries to checkpoint but finds the WAL in use by readers.

Eventually, SRE blocked the Hetzner IPs used by the cross-poster and the log recovered immediately.

Timeline

All times in UTC.

2026-08-08 00:30 — cross-posting traffic starts

2026-08-09 00:24 — first latency spike

2026-08-09 00:25 — spontaneous recovery

2026-08-09 00:26 — second latency spike

2026-08-09 00:27 — lock starvation develops, most write traffic rejected

2026-08-09 00:28 — pager triggers on Skylight /health failure

2026-08-09 00:28 — SRE responds

2026-08-09 00:56 — cross-posting traffic blocked, immediate recovery

2026-08-09 00:57 — pager recovers

An excerpt of logs during the incident, showing all sequencing rounds for the affected log, is here.

What went well

The read path was completely unaffected. Serving static files shares no database with the write path. Other logs were also unaffected, despite being served from the same process.

Skylight noticed the checkpoint was falling behind, because the sequencer was slow and not running as often as it should, and paged us.

No certificates were incorporated more than an MMD after their SCT issuance. In previous architectures, sequencing frequency falling led to that kind of incident. In Sunlight, all submissions were held until the sequencing ran and completed, including publishing the checkpoint, and no SCT was signed until then.

The mechanism to evict lower-priority submissions in favor of recent pre-certificates worked as intended, and at least initially dampened the impact, although latencies grew excessively.

Investigating metrics by providing LLM agents access to a Prometheus endpoint and to the codebase is a lot quicker than what I used to do.

What went poorly

SRE was confused by the Skylight /health lines that said read-only (for shards that are past their submission interval), and lost time investigating those.

Had sequencing not slowed down, we would not have been notified automatically about the rate-limits kicking in and high-priority traffic getting turned away.

I, uh… missed the wireless charger while going to sleep, so my phone ran out of battery overnight and didn’t ring, leaving SRE alone triaging the issue. In my defense, my day had involved an 11h red-eye and an off-duty EMT rescue.

Remediation steps

We implemented a number of fixes over the day on Sunday, and despite the cross-poster switching IPs around 2026-08-10 03:50 and resuming submitting at ~225/s, all relevant metrics look significantly better than the pre-August 8th baseline.

Compared to August 8th, sequencing p99 is 50ms vs 484ms, cache put p50 is 2.2ms vs 7.1ms, put p99 is 5.0ms vs 347ms, get p50 is 0.15ms vs 1.16ms. NVMe reads are 3.4MB/s vs 150MB/s.

You can see submit latency at https://stats.tuscolo.sunlight.geomys.org being less spiky than before, despite the higher traffic.

Done

1. The cache gets are now performed after the pool-full rate-limit check.
2. The pool size is now 150, for a total of 750 submissions/s (where recent pre-certificates are prioritized). This is firmly above the WebPKI issuance rate.
3. The sequencer now has priority over pool insertions in taking the pool lock. (This is apparently called a turnstile? Neat.)
4. The SQLite deduplication cache database is now in its own ZFS dataset with recordsize=4K, removing the 32x read and ARC utilization amplification.
5. The SQLite in-process page cache is now configured at 1GB. This is enough to hold all the interior B-tree nodes, making each get a single filesystem read, reducing ARC pressure, and speeding up gets and puts.
6. SQLite WAL checkpoints are now executed “manually” on every sequencing round. Unlike the autocheckpoints, these run in RESTART mode, so they wait for readers to complete and always restart the WAL. (They wait up to the 1s busy timeout, but there can be at most one reader using the WAL for a cache get at a time, and following readers will not use the WAL because it’s been checkpointed and the sole writer is doing the checkpointing.) Also, the db is opened in synchronous=OFF mode on ZFS, to avoid the fsyncs, making checkpoints cheap to do on every round; durability of the dedup cache is not important, and ZFS guarantees consistency (see below).
7. We’ve added a number of new metrics, including cache timings, sequencing phases, SQLite WAL and checkpointing statistics, and ZFS metadata.
8. The Skylight /health endpoint now reports OK (read-only) for read-only shards.
9. I ordered a Nokia flip phone with a charging dock as a pager. (The HMD 2660 Flip 4G, more precisely. Delightful device.)

Even without the rest of the fixes, 1+2 would have let the rate-limit and pre-certificate prioritization do their job, mitigating the incident.

3 alone would have avoided the chain reaction.

4 and/or 5 would have avoided the cache slowdown, which both caused and dominated the actual performance degradation.

6 would have smoothed the sequencing latency, potentially avoiding the chain-reaction trigger.

9 would have, uh, woken me up.

synchronous=OFF, really?

Hear me out.

SQLite documents that with synchronous=OFF the database is safe from application crashes but can become corrupted if the system crashes, which can cause writes to be persisted out of order.

ZFS, however, commits async writes as transaction groups atomically and in order. Sync writes go to the ZIL and can land out of order, but in synchronous=OFF mode SQLite makes none of those.

Large writes can land across multiple txg, but SQLite has checksums to detect truncated WAL writes, and db writes are page-sized.

The one risk would be manually opening the database and causing an fsync, which might persist the database ahead of the WAL, so we also set sync=disabled on the tank/caches dataset.

I ran an experiment SIGKILL’ing a nested QEMU VM while SQLite was writing, and it resulted in a corrupted database 0/150 times with ZFS, and 50/50 times with ext4.

ZFS is nice.

Sunlight automatically does a statfs() on the cache database’s directory and only uses synchronous=OFF if it detects ZFS.

Planned

We use crawshaw.io/sqlite for SQLite. It’s a great API, but the package (and the SQLite version) hasn’t been updated in years. There’s zombiezen.com/go/sqlite which is a well-maintained alternative, but it uses modernc.org/sqlite which I like but I’m not 100% confident in. Besides updating SQLite, it would be nice to instrument sqlite3_db_status into metrics. I have reached out to David to suggest Geomys take over maintenance (which is, after all, our main job!).

Currently, we alert based on per-log read-path availability, write-path reachability, Skylight-observed log health and freshness (which triggered here), Google-observed uptime (which stayed at 100% during this incident), and witness submissions. We should add two alerting categories:

1. metrics-based, to catch e.g. rate-limits kicking in; and
2. live submissions. We can add our own root to the log and submit a new certificate every minute, and verify SCT and STH inclusion. If we did this to Tuscolo2026h1, it would have inflated its size by less than 0.12%.

We'll update the thread once these are implemented.

Rejected

A few things we decided not to do, because they would have increased software complexity in critical sections of Sunlight:

1. move the cache get out of the pool lock, which would have made lock contention a non-issue but would have made reasoning about deduplication ordering harder;
2. move the cache put out of sequencing’s critical section, same with potatoes;
3. do checkpointing in parallel with sequencing, which would have marginally helped but would have made busy timeouts necessary across checkpointing and puts.
   

Fixes 4, 5, and 6 make cache gets, puts, and checkpoints fast enough that we can afford to keep doing them under the lock, and fixes 1, 2, and 3 make it less catastrophic to hold these locks for long, if we did.

Was there an MMD violation?

RFC 6962, Section 3.5 says

Each log MUST produce on demand a Signed Tree Head that is no older than the Maximum Merge Delay.

The MMD of Static CT logs in the Apple and Google programs is 60s. During the incident, there was a gap of 71s between sequencings, and considering the checkpoint is timed at the start and issued before the end of the sequencing round (and before the slow cache put), there were moments when the read path was serving a checkpoint more than 60s old.

It's unclear whether this should be considered a violation, though. If it is, then also our 3-minute scheduled maintenance on June 7th, after which the read path almost certainly resumed serving before sequencing resumed, was an unnoticed MMD violation.

Similarly, it's unclear if a read-path (or full) downtime of more than 60s is an MMD violation. If yes, it completely overshadows the 99% uptime requirement. If not, the MMD is not actually doing its job ensuring monitors are not delayed in observing logged certificates. (Imagine the read path went down immediately after a new checkpoint is published, before any monitor could observe it. Does a fallen log make a sound if no monitor can hear it?)

I suspect the 60s MMD is actually a policy mistake. It seems to reflect the aspiration of not returning SCTs until the certificates are incorporated, which is an internal log implementation strategy that removes a common failure class, and which should suggest an MMD of zero, not 60s. However, as defined the MMD does not and can not bound the log's internal behavior, but only its observable behavior, which does not include the sequencing strategy but does include downtime.

If we had the cycles to spend on CT, we should maybe discuss raising that back to 24h, and then enforcing it strictly on both the read and write paths. However, the attention at this point is probably best spent on Merkle Tree Certificates.

Alla prossima,

Filippo