possible Instant clock skew detected

[wendajiang]

I use console_subscriber for tracing my app, and terminal sometimes output the possible Instant clock skew detected, and I find #286. So I confuse about why after use Instant instead of SystemTime, this still happend? And what is meaning?

[hawkw]

This message indicates that polling a task appears to have ended before it started:

console/console-subscriber/src/stats.rs

Lines 493 to 503 in abc0830

	let elapsed = match at.checked_duration_since(started) {
	Some(elapsed) => elapsed,
	None => {
	eprintln!(
	"possible Instant clock skew detected: a poll's end timestamp \
	was before its start timestamp\nstart = {:?}\n end = {:?}",
	started, at
	);
	return;
	}
	};

Instant::now type is supposed to be monotonic, but sometimes there are platform-dependent issues in the implementation of Instant for particular operating systems or hardware architectures. What platform is the instrumented application running on?

Alternatively, there might be a bug in the console-subscriber crate. In order to determine what's going on here, it would be very helpful to know some details about the operating system and hardware architecture the instrumented application (not the tokio_console CLI) is running on, as well as the frequency of the warning message.

[wendajiang]

Platform is macOS, arch is arm64. And in tui-rs application, once app is opening, about ten warning per minute.

[hawkw]

Interesting, thanks. Can you possibly also paste the complete text of one or two of the warnings, including the start and end timestamps? It would be useful to see how much skew was observed.

[Rexagon]

Faced a similar error. These messages appear consistently every few minutes.

16:08:08 ...
possible Instant clock skew detected: a poll's end timestamp was before its start timestamp
start = Instant { tv_sec: 4845, tv_nsec: 962726114 }
  end = Instant { tv_sec: 4845, tv_nsec: 962723900 }

...

16:08:19 ...
possible Instant clock skew detected: a poll's end timestamp was before its start timestamp
start = Instant { tv_sec: 4857, tv_nsec: 520769429 }
  end = Instant { tv_sec: 4857, tv_nsec: 520769068 }

...

16:08:19 ...
possible Instant clock skew detected: a poll's end timestamp was before its start timestamp
start = Instant { tv_sec: 4857, tv_nsec: 727735375 }
  end = Instant { tv_sec: 4857, tv_nsec: 727733632 }

...

16:08:23 ...
possible Instant clock skew detected: a poll's end timestamp was before its start timestamp
start = Instant { tv_sec: 4861, tv_nsec: 607221176 }
  end = Instant { tv_sec: 4861, tv_nsec: 607220114 }

Env info:

Linux 5.17.1-3-MANJARO
AMD Ryzen 9 5900HS

rustc 1.60.0 (7737e0b5c 2022-04-04)

tokio 1.18.0 (full, tracing, parking_lot)
tracing 0.1.34
console-subscriber 0.1.5 (parking_lot)

[zbuc]

We are seeing this as well:

possible Instant clock skew detected: a poll's end timestamp was before its start timestamp
start = Instant { tv_sec: 4729132, tv_nsec: 88408831 }
  end = Instant { tv_sec: 4729132, tv_nsec: 88406315 }
possible Instant clock skew detected: a poll's end timestamp was before its start timestamp
start = Instant { tv_sec: 4729243, tv_nsec: 938458369 }
  end = Instant { tv_sec: 4729243, tv_nsec: 938455058 }
possible Instant clock skew detected: a poll's end timestamp was before its start timestamp
start = Instant { tv_sec: 4729793, tv_nsec: 955538207 }
  end = Instant { tv_sec: 4729793, tv_nsec: 955531205 }
possible Instant clock skew detected: a poll's end timestamp was before its start timestamp
start = Instant { tv_sec: 4730224, tv_nsec: 59384090 }
  end = Instant { tv_sec: 4730224, tv_nsec: 59377093 }

Env:

Linux dd0426221be7 5.4.0-100-generic #113-Ubuntu SMP Thu Feb 3 18:43:29 UTC 2022 x86_64 GNU/Linux
rustc 1.60.0 (7737e0b5c 2022-04-04)

tokio 1.18.1 (full)
tracing 0.1.34
console-subscriber 0.1.5

[Rexagon]

I think there is no guarantee that two Instants created sequentially on different cores will also be sequential.

https://stackoverflow.com/questions/46893072/clock-gettimeclock-monotonic-monotonicity-across-cores-threads

[hawkw]

@Rexagon hmm...in this case, a poll's start and end timestamps should be recorded on the same core. The poll start timestamp corresponds to the beginning of a call to the poll function, and the poll end timestamp corresponds to the end of a call to that function — the task cannot cross threads while it's being polled...

[Rexagon]

Yes, span::Entered is not Send, so this skew is strange. But maybe one of the calls of the PollStats::start_poll or its contents are missing somewhere under strange conditions?

[hawkw]

@Rexagon yeah, if I had to guess, i would suspect it's something more like that. Hmmm..

[izderadicka]

Same problem here - Linux Ubuntu 20.04 on Intel.
Having these printout quite often - several times per second - when my program (TCP proxy) is under load.

possible Instant clock skew detected: a poll's end timestamp was before its start timestamp
start = Instant { tv_sec: 255185, tv_nsec: 521611026 }
  end = Instant { tv_sec: 255185, tv_nsec: 521610916 }
possible Instant clock skew detected: a poll's end timestamp was before its start timestamp
start = Instant { tv_sec: 255185, tv_nsec: 720152934 }
  end = Instant { tv_sec: 255185, tv_nsec: 720127010 }
possible Instant clock skew detected: a poll's end timestamp was before its start timestamp
start = Instant { tv_sec: 255186, tv_nsec: 177118060 }
  end = Instant { tv_sec: 255186, tv_nsec: 177056943 }

Difference can be several micros.

console-subscriber = "0.1.8"

If you are interested it can be easily replicated.

[thomasj02]

Also getting this frequently on 0.1.8, with Ubuntu 22.04 on Intel

[ozgunozerk]

Also getting this frequently on macOS