skip to content

A Go service takes seconds to reach main.main - how do you find which package init is slow?

level: seniorimportance: nice to knowfreq 28%

answer

  1. you cannot instrument code preceding your code
  2. the runtime already measures this for you
  3. an environment setting, not a rebuild
  4. one line per package, on standard error
  5. GODEBUG has a startup trace member

basics

~20 s

Run the binary with GODEBUG=inittrace=1. The runtime prints one line per package to standard error as its initialisation finishes, with elapsed time since start, time spent in that package, and bytes and allocations - so the expensive package names itself.

solid answer

~50 s

Set `GODEBUG=inittrace=1` and start the binary. The runtime writes a line to standard error as each package finishes initialising, carrying the offset from process start, the clock time that package's own initialisation took, and the bytes and allocations it made. Sort by clock time and the culprit is usually obvious: a package that dials a service, parses a large embedded asset, compiles a pile of regular expressions, or builds a big table at import time - often a transitive import nobody chose deliberately. That also tells you whether the delay is initialisation at all: if the trace totals a few milliseconds, the time is going somewhere else, such as work `main` does before it becomes ready. The fix is to move the expensive work into a function `main` calls, where it can be deferred until needed, done concurrently with other startup, given a deadline, and made to return an error.

code

text · 4 lines
text
$ GODEBUG=inittrace=1 ./svc
init internal/bytealg @0.02 ms, 0 ms clock, 0 bytes, 0 allocs
init unicode @2.1 ms, 1.4 ms clock, 45056 bytes, 20 allocs
init svc/rules @318 ms, 291 ms clock, 8421376 bytes, 12043 allocs

go deeper

for a junior

Know that Go can report startup work for you: running the binary with GODEBUG=inittrace=1 prints how long each package took to initialise, with no code change.

for a middle

Explain how to read the output - offset, clock time, bytes and allocations per package - and why initialisation time is additive, so a couple of packages usually explain the whole delay.

for a senior

Demonstrate the full investigation: confirm the time really is in initialisation, identify the package (often a transitive import), and move the work to a call from main where it can be lazy, bounded and error-reporting.

for a principal

Treat startup latency as a budget you set: what a service is allowed to do before it reports ready, who reviews a new heavyweight import, and how that budget is measured rather than argued about.

## The symptom A service is slow to become ready, and the slowness is *before* any of your log lines. Nothing in `main` has run yet, so there is nothing to instrument in the usual way - you cannot time code that runs before your timing code exists. ## The tool ``` GODEBUG=inittrace=1 ./svc ``` With this set, the runtime prints one line to standard error for each package that does initialisation work, as that work completes. Each line names the package and gives: - **an offset** - how long after process start that package's initialisation happened; - **clock time** - how long that package's own initialisation took; - **bytes and allocations** - how much it allocated doing it. Because the lines appear as initialisation progresses, the output is useful in two different ways: 1. **For slowness**, scan the clock column. Startup time is additive across packages, so one or two large numbers usually account for the whole delay. 2. **For a hang**, watch where the output *stops*. Initialisation is sequential on the main goroutine, so the package after the last printed line is the one that is stuck. The allocation columns matter too: a package that allocates tens of megabytes at import time has both made your startup slow and given your service a permanently larger baseline heap. ## What usually turns out to be responsible - **Import-time I/O** - reading a file, dialling a database or a cache, resolving a name. This is also the worst kind, because it can fail or block with no error path. - **Expensive table building** - decoding a large embedded blob into a map, or precomputing something derived that almost no request needs. - **Compiling many patterns** at package level, one per rule, in a package with hundreds of rules. - **A transitive import** you did not choose. A helper package pulls in something heavyweight, and every binary that touches the helper pays for it. The trace is what makes this visible, because the package name in the slow line is often one nobody in the room recognises. ## Interpreting the total Add up the clock column. If it accounts for the delay, you know where to work. If it does not - the trace totals a handful of milliseconds while the service takes five seconds to serve its first request - then initialisation is not your problem and the time is going into what `main` does: connection pools warming, migrations, discovery, waiting on a dependency. That negative result is worth as much as the positive one, because it stops you optimising the wrong phase. ## Fixing what you find The general move is from *import time* to *a call site*: - Give the package an exported constructor or a `Load`/`Prepare` function that `main` calls, so the work is explicit, ordered where you want it, and can return an `error`. - Once it is a call, it can be **deferred** until first use, **overlapped** with other startup work in a goroutine that `main` waits on, or **bounded** with a `context.Context` deadline - none of which is available inside `init`. - If the work is genuinely needed by every binary and cannot fail, it can stay - but measure it, because "cannot fail" is not the same as "is fast". - For a heavyweight transitive import that is not really needed, breaking the import is the whole fix: the cost is paid because of an edge in the graph, not because anyone wanted it. ## Related knobs `GODEBUG` carries a family of runtime tracing settings - `gctrace=1` for collector cycles, `schedtrace` for scheduler state - and `inittrace=1` is the startup member of that family. It is cheap, needs no code change and no rebuild, so it belongs in the first five minutes of any "why is this binary slow to start" investigation, including in a container where you can only change the environment.

  • The inittrace output totals 6ms but the service takes five seconds to serve traffic. What now?
    Initialisation is exonerated, so the time is in `main`: connection pools, schema checks, service discovery, cache warming, or waiting on a dependency that is not up. Instrument `main` directly - you have a logger and a clock there - and time each step until the five seconds is accounted for.
  • Beyond clock time, what do the byte and allocation columns tell you?
    They show which packages permanently inflate the baseline heap. A package that allocates tens of megabytes at import time has raised the floor the collector works against for the life of the process, which shows up as higher memory limits and more frequent cycles, not just a slower start.
  • Why is moving the work out of init worth it even when the total is only a few hundred milliseconds?
    Because the call site buys you options that `init` cannot offer: a deadline, an error you can log and act on, the ability to run it concurrently with other startup, and the ability to skip it entirely in a binary or a test that does not need it.

saying these in an interview costs you the question

  • Reaches for a CPU profile that only starts once main runs
  • Adds timing log lines to code that runs before the logger exists
  • Assumes slow startup must be the container image or the linker
  • Thinks an unused import costs nothing at run time
  • Says init work cannot be measured without a debugger