This function is supposed to time how long a batch of work takes and log the total elapsed duration when it returns. It runs cleanly, prints something sensible-looking, and passes review. Then metrics start showing that every batch takes zero milliseconds — regardless of size.

package main

import (
    "fmt"
    "time"
)

func processBatch(items []string) {
    start := time.Now()
    defer fmt.Printf("processBatch: processed %d items in %v\n",
        len(items), time.Since(start))

    for _, item := range items {
        handle(item)
    }
}

func handle(s string) {
    time.Sleep(50 * time.Millisecond) // simulate real work
    _ = s
}

func main() {
    processBatch([]string{"a", "b", "c", "d"})
    // Output: processBatch: processed 4 items in 0s
}

The Bug

In Go, the arguments to a deferred function call are evaluated when the defer statement executes, not when the deferred call actually runs. The call is postponed to function exit; the arguments are computed immediately and captured.

So on the line defer fmt.Printf(..., len(items), time.Since(start)):

• len(items) is evaluated now → 4.
• time.Since(start) is evaluated now → essentially zero, because start was set on the previous line.
• Both values are frozen into the deferred call.

When processBatch finally returns, Printf runs with those captured values. The 200ms of actual work happens in between — but the duration argument was baked in before any work happened. The 0s isn't a rounding artifact; it's the literal timestamp of the defer statement.

This trap is nasty because the code looks like it's saying "when this function exits, compute the elapsed time and print it." That intuition matches how finally blocks work in Java or Python — but Go's defer is not a lexical block. It's a function call whose arguments are snapshotted at declaration.

The fix is to wrap the deferred work in a closure. A closure body is executed at defer time, so time.Since(start) runs at the moment of return:

func processBatch(items []string) {
    start := time.Now()
    defer func() {
        fmt.Printf("processBatch: processed %d items in %v\n",
            len(items), time.Since(start))
    }()

    for _, item := range items {
        handle(item)
    }
}

Now time.Since(start) is inside the function body of the deferred call, so it's evaluated at exit and reflects the true elapsed duration. len(items) is fine either way because items doesn't change, but wrapping both is consistent and future-proof.

The same trap bites logging patterns like defer log.Printf("finished job %s at %v", jobID, time.Now()) — the timestamp is defer-time, not exit-time. It also bites any deferred call that reads a variable expected to change during the function's execution, such as an error accumulator or a counter. If you want late binding, use a closure. If you want a value frozen at defer time (say, the initial state of a mutable slice), the direct form is exactly the right tool — but only if you actually meant that.

A useful mental model: defer f(x) is roughly _x := x; atExit(func() { f(_x) }). Once you see the implicit snapshot, the zero-duration mystery becomes obvious.