Why are duration and duration_ms different (besides scale)?

General
1

Based on the documentation, duration_ms is the same as duration but in ms. However, I’m seeing differences in the values, for example (these are each on the same request):

"duration": 0.001472462,
"duration_ms": 1.440152,

"duration": 0.013516455,
"duration_ms": 13.495985000000001,

So just trying to understand what each is actually representing and if maybe the documentation is incorrect?

2

Please show your config. Where are you getting these values from?

The difference is sub-millisecond, it’s probably just the amount of time it took between each getting computed. They’re computed separately, from the moment in time they’re invoked.

1 Like
3 
{
    admin 127.0.0.1:2019 {
    }
    log {
        output stdout
        format json
        level INFO
    }
    servers {
        metrics
    }
}

example.com {
    log {
        output stdout
    }
    log_append duration_ms {rp.duration_ms}
    reverse_proxy 127.0.0.1:8080 {
        header_up Host localhost
    }
}

I guess that makes sense but also doesn’t in that the duration should be the duration regardless of when it’s computed.

4 
	start := time.Now()
	defer func() {
		// total proxying duration, including time spent on LB and retries
		repl.Set("http.reverse_proxy.duration", time.Since(start))
		repl.Set("http.reverse_proxy.duration_ms", time.Since(start).Seconds()*1e3) // multiply seconds to preserve decimal (see #4666)
	}()

The times are calculated on separate lines of code so there would be a tiny difference in their values. Sure we could hoist time.Since(start) to be calculated once but it doesn’t really matter.

1 Like