Slow screens

A loading screen waits on eight pieces and one takes 30 seconds. Nothing failed, so nothing was logged. A trace logs it.

Some failures never throw. A loading screen waits on eight pieces, one of them takes 30 seconds, and the logs say nothing, because nothing failed. Traces report that case and only that case: something took longer than you said it should, or never finished. A trace that finishes in time sends nothing at all.

Name the steps, set a limit once, and a run that passes it is reported while it is still waiting, with which steps were done and which one was not.

Wrap the steps

src/boot.ts

import { trace, startTrace } from '@dasasian/firebase-structured-logger/client/timing'

await trace('app_boot', async (boot) => {
  const user = await boot.step('sign-in', () => signIn())
  await Promise.all([
    boot.step('products', () => loadProducts(user)),
    boot.step('places', () => loadPlaces(user)),
  ])
})

// A flow that spans functions: starts on mount, ends when the data is in
const open = startTrace('order_open')
await open.step('order', () => loadOrder(id))
open.end()

trace ends the run when the function settles, either way. startTrace is for a flow that spans functions, and you call end() yourself. A step after end(), or a second end(), is ignored.

Set the limits once

Your code holds names only. The limits live in one place, set at startup:

src/main.ts

import { configureTraces } from '@dasasian/firebase-structured-logger/client/timing'

configureTraces({
  app_boot: { warnAfterMs: 8000, steps: { products: 3000 } },
  order_open: { warnAfterMs: 2000 },
})

Caution

A trace with no limits configured is timed but never reported. Limits are read when a run starts, so call configureTraces before the first run. Limits are looked up by name, so use fixed names: a name built from an id, such as load_${id}, has no limits configured.

What gets sent

One WARNING per run, the moment the first limit is crossed, the trace’s or a step’s own. It is sent while the run is still going, so a step that never finishes is reported too. Nothing more is sent for that run.

WARNING  app_boot slow: products passed 3000 ms, still waiting
         labels.trace="app_boot"  labels.run="<id>"  labels.slow="step"  labels.step="products"
         timing: { elapsedMs: 3000, limitMs: 3000,
                   steps: { sign-in: 610, places: 410 }, waiting: ["products"] }

labels.slow is trace or step. Durations are in milliseconds, always in timing. labels.run tells two overlapping runs of the same trace apart.

A paused page is not a slow app

A browser pauses pages it is not showing: a hidden tab, a phone switching apps, a laptop going to sleep. A run that was hidden at any point is not reported, nor is one that was paused, meaning a one-second check that arrives five or more seconds late. Laptop sleep often fires no event at all, which is why the late check exists.

Each step is also a standard performance.mark and performance.measure, so it shows in the browser’s Performance panel. The package clears its own when the run ends.

On the server

trace, startTrace and configureTraces come from /functions with the same entry:

functions/src/index.ts

import { configureTraces, trace } from '@dasasian/firebase-structured-logger/functions'

A server run is judged when a step or the trace ends. There is no timer, because Cloud Functions and Cloud Run can throttle the CPU once a response is sent. A request that hangs outright is ended by the platform’s timeout, which logs it.

Traces explain the slow case. They do not measure what is normal: there are no percentiles and no sampling here, and that is a monitoring tool’s job.