The Tail Is One Stalled Request

On 4 September the notifications service delivered its first production push notification without AWS SNS in the path. Twenty-one notification kinds, our own fan-out query, one HTTP request per device to Firebase, at a concurrency limit of 32.

The ADR had modelled what this would cost. I kept the modelled numbers in the document rather than correcting them away, because the interesting content is the size and direction of the error.

Both directions are wrong. The volume was three times larger than expected and the per-device cost was cheaper than the model implied, which happen to cancel out into a system that works fine and a model that was not predicting anything.

Where 308 came from

The 308 was not a guess. It was the largest fan-out observed across 499 attributed production comparisons during the shadow, and the decision to cut over was authorised partly on it.

The shadow was doing its job correctly. It proved the recipient query was right: every miss it found was attributable to a stale subscription or a switched-off preference, and unexplained misses sat at zero. What it could not do was guarantee that its sample included a big match, and it did not.

So the lesson is narrower than "the shadow was wrong" and more useful. A clean shadow verdict says the query is right. It says nothing about the volume, because the volume depends on which matches happened to run during the window. Those are separate questions and I had been treating one answer as covering both.

No multicast, on either platform

An earlier revision of the ADR claimed FCM offered a multicast endpoint taking 500 tokens per request, and contrasted that favourably with APNs having none. That was simply false. FCM's batch send endpoint was deprecated and stopped working after 21 June 2024. HTTP v1 accepts exactly one device token per request, and the Admin SDK's multicast helper fans out one HTTP request per token on the client side.

Neither platform has multicast. A 2,400-device fan-out is about 2,400 HTTP requests either way, and what governs the tail is not batching but bounded HTTP/2 concurrency. That is why internal/fcm was built with a configurable concurrency limit in its first commit rather than acquiring one later under pressure.

The real fan-outs

Largest first, from the first day in production:

GOAL          1005 recipients   985 delivered   20 dead   2999 ms   slowest send  372 ms   2.98 ms/device
GOAL          1002              982             20        2947 ms                 548 ms   2.94 ms/device
VAR            853              838             15        3602 ms                1747 ms   4.22 ms/device
CORNER         409              395             14        1317 ms                 320 ms   3.22 ms/device
CORNER         289              283              6        1012 ms                 208 ms   3.50 ms/device

A thousand devices in about three seconds. The product budget for a goal notification is seconds, and this service already delays corrections deliberately by five full seconds in its deduplication path, so one intentional delay in our own code is larger than the entire fan-out. Latency was never going to decide this architecture and now it does not decide it for a measured reason rather than an estimated one.

The two slowest were not the largest

Then this, which is the actual finding:

GOAL  1018 recipients   997 delivered   retried=5   duration=18074 ms   slowest send 15371 ms
GOAL  1016              995             retried=4   duration=17563 ms                15360 ms
GOAL  1023                                          duration= 2927 ms   ← same size, 6x faster

Three fan-outs of essentially identical size. One took 2.9 seconds and two took 18.

The cause is in the slowest send column. A handful of individual FCM requests stalled for about 15 seconds each, and with a concurrency limit of 32 a stalled request holds a slot, so the whole fan-out waits on its slowest worker. That works out to 17.75 milliseconds per device against a normal 2.86.

Nothing was lost. The retries recovered all nine affected sends, and the transient failure count stayed at zero. The cost was purely latency.

Two details are worth pulling out. The 250 millisecond retry backoff is irrelevant at this scale: what costs 15 seconds is the first attempt, not the wait before the second. And http.Client{Timeout: 30 * time.Second} means a 15-second stall sits comfortably inside the budget and is never cut short, which is working as configured rather than as a bug.

How rare it is, and why I left it alone

Measured over a fuller day: once.

At 101,471 recipients the counters still read retried = 9 and slowest_send_ms = 15371. Identical to the values recorded at 15,887 recipients. Both stalls belong to a single Firebase episode around 17:20 UTC and nothing has come close since. The average fan-out is 227 milliseconds.

So this goes in the record as an observation rather than a recommendation, and the reasoning is a trade-off I want to be able to point at later.

Capping a request nearer five seconds would have bounded those two fan-outs at roughly 5.5 seconds instead of 18. The retry machinery to absorb the cut-short requests exists and is proven, because it just absorbed nine. That is a real improvement to a real number.

Against it: one episode in 101,471 sends. And a tighter timeout turns slow-but-successful sends into retries, which doubles the request count on exactly the days when Firebase is already struggling. Two fan-outs arriving fifteen seconds late is a worse outcome than nothing at all, and a better one than systematically doubling our load whenever the provider degrades.

What would change the answer is written down next to the decision: retried climbing steadily rather than in a single cluster, or slowest_send_ms reaching 15 seconds regularly rather than once. Both are already in the soak check's output and in the delivery log, so the trigger needs no new instrumentation. Until that pattern appears, 30 seconds stays.

Delivery quality

First 101,471 recipients:

101,471 recipients · 99,175 delivered (97.74%) · 2,296 failed
2,296 token_dead · 0 token_invalid · 0 transient · 0 credential · 9 retried
average fan-out duration 227 ms

Every single failure is device token is no longer registered, an HTTP 404 from Firebase, which means the app was uninstalled. Not one credential error, which for a first day on a new delivery path is the number I was most nervous about.

The thing I want to underline is that SNS was dropping these same notifications, for these same dead devices, the whole time. It reported success, because from its perspective the publish succeeded and the per-endpoint failure went into a feedback log that fed a pruning job. The change is not that we started failing. It is that failures are now counted where the send happens, in a line that says how many of how many.

Counting a retry without double-counting the recipient

The retry design has one property that earned its keep immediately.

A transient failure is retried once after 250 milliseconds. Dead tokens, invalid tokens and credential failures are not retried, because retrying them cannot succeed. A retried recipient produces exactly one result, so delivered + failed still equals the recipient count, and the retry count is reported in its own field.

That separation is why the nine stalls were visible at all. An all-delivered fan-out with a rising retry count is Firebase degrading while the health line reads perfectly clean. Had the retry been folded into the outcome counts, those nine would have shown up as nine successes and nothing else, and the only symptom would have been a duration nobody was looking at.

A caveat on reading any of these numbers

The same 24-hour query, run twice 88 seconds apart with no change in traffic, reported 2,730 recipients and then 6,453.

CloudWatch Logs ingestion lag means a query covering a window that includes the recent past under-counts, sometimes by more than half. Any reading taken close to the events is a lower bound, not a measurement. I have been caught by this twice now, once in each direction, and the only defence I have found is to re-run the query later and compare rather than trusting a single reading.

What I took from it

A model kept next to its measurement is worth more than a model quietly corrected. Both directions of my error are visible now, and the size of the miss is what tells the next person how much to trust the next estimate.

A clean verdict from a comparison harness covers the logic it compared. Volume, distribution and tail behaviour are separate properties, and a sample that never contained a large case has not sampled them.

When you find a dramatic outlier, measure how often it recurs before changing anything. My instinct was to tighten the timeout, and the honest count made the case against it.

And count retries separately from outcomes. A retry that disappears into a success is a provider degrading invisibly.

---

Part of Deleting a Bottleneck, on the SNS Subscribe outage and the migration to direct FCM delivery.