skip to content

time.Since returns a negative duration for a start time.Time your harness reloaded from JSON — how do you diagnose and fix it?

level: seniorimportance: should knowfreq 30%

answer

  1. the sign itself is the clue
  2. one endpoint crossed a boundary
  3. a stopwatch reading cannot be written down
  4. check the printed suffix on both values
  5. carry the duration, not the start instant

basics

~20 s

Decoding drops the monotonic reading, so time.Since fell back to subtracting wall clocks, and the system clock was stepped backwards between the two readings. Print both values and look for the m= suffix, then measure from an in-process time.Time instead.

solid answer

~50 s

A negative elapsed time is the signature of a wall-clock subtraction. `time.Since` uses monotonic readings only when both values have one; the reloaded start value lost its reading when it was encoded, because JSON has nowhere to put a process-local number. So the harness compared two wall-clock readings, and something stepped the system clock backwards in between — a synchronisation correction after a drift, a virtual machine resuming, a manual clock change. Diagnose it by printing both endpoints with `%v` and looking for the `m=+…` suffix: absent on the reloaded value confirms it. The fix is structural, not defensive: measure with a `time.Time` that never left the process, and keep the persisted timestamp for reporting when the run started. If the start genuinely must survive a restart, record it as a wall-clock instant and accept that the elapsed time is an estimate — then validate it rather than trusting a negative number.

code

go · 12 lines
go
type run struct {
	Started time.Time `json:"started"`
}

b, _ := json.Marshal(run{Started: time.Now()})

var r run
_ = json.Unmarshal(b, &r)

// no m= suffix on r.Started: monotonic reading gone
fmt.Printf("start=%v now=%v\n", r.Started, time.Now())
elapsed := time.Since(r.Started) // wall-clock subtraction; can be negative

go deeper

for a junior

Know the shortcut: a negative result from time.Since means the start value lost its monotonic reading, usually by being saved and loaded, and the system clock moved backwards.

for a middle

Explain the mechanism end to end — encoders omit the reading, Sub falls back to wall clocks, a clock step then makes the difference negative — and show the printed suffix as the check.

for a senior

Diagnose from the symptom and fix structurally: measure between two in-process values, persist the computed duration alongside the start timestamp, and validate implausible results rather than clamping them away.

for a principal

Own the convention that prevents the class: elapsed time is a duration computed where both endpoints live in memory, stored timestamps are for reporting, and clock steps are surfaced as an environment signal rather than smoothed over.

## Reading the symptom A negative duration out of `time.Since` is not a rounding artefact and not a bug in the `time` package. It is a precise signal: **the subtraction used wall-clock readings, and the wall clock moved backwards during the interval.** Monotonic subtraction cannot produce it, because the monotonic clock never goes backwards. So the first thing the symptom tells you is that at least one of the two values had no monotonic reading. ## Why the reloaded value has none A `time.Time` holds a wall-clock reading, an optional monotonic reading, and a location. The monotonic reading is an offset from an arbitrary origin private to the process that created it — a number that would be actively misleading anywhere else. That is why every encoder omits it: `MarshalJSON`, `MarshalText`, `MarshalBinary`, `GobEncode`, and there is no layout element to format it. A decoded `time.Time` therefore never carries one, even if the encode and decode happened seconds apart in the same process. The harness stored each run's start instant so the measurement could survive a restart, and in doing so converted a stopwatch reading into a calendar reading without any code changing shape. `time.Since(started)` still compiles, still returns a `time.Duration`, and is right almost all the time — which is why it survived review. ## Why the wall clock went backwards The usual causes, roughly in order of frequency in a server environment: a time-synchronisation daemon stepping rather than slewing the clock after the machine drifted or after a long suspension; a virtual machine or container host resuming a guest whose clock was frozen; a fresh instance correcting a badly wrong boot-time clock; an operator or a provisioning script setting the clock. Any of these can move the wall clock by more than the interval you were measuring, and then the subtraction goes negative. ## The diagnostic One line settles it: ```go fmt.Printf("start=%v now=%v\n", started, time.Now()) ``` `String` appends the monotonic reading as `m=+…` when it is present. If `now` shows the suffix and `started` does not, the comparison fell back to wall clocks and the investigation is over — you now hunt for the clock step, not for a logic error. This is also the check to add to the postmortem's "how would we have caught this sooner" section: assert the suffix on values you intend to measure with, or better, make it impossible to measure with the wrong one. ## The fix, in order of preference **1. Do not measure across the boundary.** Keep the `time.Time` that `time.Now()` returned, in memory, for the duration of the measurement, and pass it to `time.Since` untouched. Persist a separate field for reporting when the run started. The measurement and the report are two different facts and want two different representations — a `time.Duration` you computed in-process, and a wall-clock instant you formatted for a human. **2. If the elapsed time really must survive a process restart**, accept that it is a wall-clock estimate and treat it as one. Compute it explicitly from two wall-clock instants so the reader can see what it is, and validate the result — a negative or absurdly large value is data corruption, not a measurement, and should be dropped or flagged rather than aggregated into a latency percentile. **3. Do not "fix" it by clamping to zero and moving on.** Clamping hides the clock step, and a clock step is usually a fact about the environment that someone else needs to know: it also corrupted every other wall-clock timestamp emitted around that moment. ## The wider lesson for the postmortem The defect is that a value silently changed comparison semantics when it crossed a serialisation boundary, and the type system said nothing. The durable countermeasure is a convention rather than a review comment: keep measurement in a `time.Duration` computed where both endpoints exist in memory, and let stored timestamps be timestamps. Once elapsed time is a duration you carry rather than a subtraction you redo after a reload, the whole class of bug disappears.

  • Would keeping the start value in a package-level variable instead of JSON have avoided this?
    Yes, as long as nothing else strips it. A `time.Time` held in memory keeps its monotonic reading, so `time.Since` stays monotonic. The remaining risk is an innocent-looking transformation on the way in — `UTC()`, `Round`, `Truncate`, `AddDate` all strip — so the value has to be stored exactly as `time.Now()` returned it.
  • The same harness sometimes reports a duration that is hours too long rather than negative. Same cause?
    Almost certainly. A wall-clock subtraction is wrong in whichever direction the clock moved: a backward step gives a negative result, a forward step gives an inflated one. The inflated case is more dangerous because it looks plausible and quietly poisons latency aggregates instead of tripping an obvious sanity check.
  • Is clamping negative durations to zero an acceptable mitigation?
    Only as a guard against corrupting an aggregate, and only alongside a signal. Clamping alone hides a clock step that also skewed every other timestamp emitted around it, so log or count the occurrence. The real fix is to stop deriving elapsed time from a reloaded instant at all.
  • What would you assert in a test to stop this regressing?
    Test the boundary rather than the clock: assert that the record you persist carries an elapsed duration field computed in-process, and that no code path calls `time.Since` on a value produced by decoding. A unit test that decodes a stored record and checks its start value compares by wall clock also documents the semantics for the next reader.

saying these in an interview costs you the question

  • Blames the time package or assumes an overflow
  • Believes the monotonic reading survives being written to storage
  • Clamps the duration to zero and closes the incident
  • Thinks a monotonic subtraction could ever go negative
  • Proposes disabling clock synchronisation on the host as the fix