Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
h33p opened this issue Jun 7, 2023 · 2 comments · Fixed by #434
Closed
Labels
S-bug Severity: bug

Comments

@h33p
Copy link
Contributor

h33p commented Jun 7, 2023

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

@h33p h33p added the S-bug Severity: bug label Jun 7, 2023
@hawkw
Copy link
Member

hawkw commented Jun 7, 2023

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 added a commit to ChorusOne/console that referenced this issue Jun 8, 2023
Remove "possible Instant clock skew" message in start_poll. This warning could occur when a task switches threads between 2 polls. Replaced the code to use saturating_duration_since, which clamps the elapsed time to 0, if the starting poll time is less than the scheduled time.

Fixes tokio-rs#433
@h33p
Copy link
Contributor Author

h33p commented Jun 8, 2023

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
S-bug Severity: bug
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants