tokio-rs/console

console_subscriber: "poll's start timestamp was before the wake time/last poll timestamp"

h33p opened this issue · 2 comments

h33p commented

What crate(s) in this repo are involved in the problem?

console-subscriber

What is the issue?

console subscriber spams "possible Instant skew" message.

How can the bug be reproduced?

Running a relatively complex project on a multithreaded runtime. I suspect the error happens when a task is moved between threads.

This is happening on an intel platform with big and little cores.

Logs, error output, etc

possible Instant clock skew detected: a poll's start timestamp was before the wake time/last poll end timestamp                                                                                                                                                                                                               
wake = Instant { tv_sec: 68792, tv_nsec: 171614373 }                                                                                                                                                                                                                                                                          
  start = Instant { tv_sec: 68792, tv_nsec: 171610785 }

Versions

Current git version (ea00694). v0.1.9 as well. Anything past ac20daa

Possible solution

Remove symmetric eprintln! from here. Unlike the warning in end_poll, this warning can be triggered in regular situations on multithreaded runtime, because tasks may be moved across threads in-between the polls.

One alternative we may want to consider is using saturating subtraction, which would lead to slightly inaccurate results (lower runtime?), but would not drop the sample.

Additional context

This is not the same as #299, this is coming from a different line.

This bug was introduced in here

Would you like to work on fixing this bug?

yes

hawkw commented

Thanks for the report! I think your hypothesis that this occurs when a scheduled task is stolen by a different worker thread seems like a likely explanation.

I would be happy to accept a PR that removes the warning in this case and switches to saturating subtraction. It would be nice if we could eventually solve this in a way that doesn't lose accuracy in this case, but removing the warnings would still be an improvement over the current situation.

h33p commented

Thanks for the report! I think your hypothesis that this occurs when a scheduled task is stolen by a different worker thread seems like a likely explanation.

I would be happy to accept a PR that removes the warning in this case and switches to saturating subtraction. It would be nice if we could eventually solve this in a way that doesn't lose accuracy in this case, but removing the warnings would still be an improvement over the current situation.

Great, thanks! I've implemented a solution in #434

  • 👍2