msg/async: round timeouts up (fix busy loops) by MaxKellermann · Pull Request #60265 · ceph/ceph

MaxKellermann · 2024-10-11T18:01:15Z

Currently, we always round down, which has a bad side effect: when a timer comes closer, we have lots of early wakeups, and eventually we'll run into a busy loop (timeout=0) when the timeout is less than one millisecond; the process will remain this busy loop for one millisecond, wasting lots of CPU time.

Checklist

Tracker (select at least one)
- References tracker ticket
- Very recent bug; references commit where it was introduced
- New feature (ticket optional)
- Doc update (no ticket needed)
- Code cleanup (no ticket needed)
Component impact
- Affects Dashboard, opened tracker ticket
- Affects Orchestrator, opened tracker ticket
- No impact that needs to be tracked
Documentation (select at least one)
- Updates relevant documentation
- No doc update is appropriate
Tests (select at least one)
- Includes unit test(s)
- Includes integration test(s)
- Includes bug reproducer
- No tests

rzarzynski

Good catch! The comments are just minors / nits.

rzarzynski · 2024-10-13T21:36:41Z

src/msg/async/Timeout.h

+ *
+ */
+
+#ifndef CEPH_MSG_TIMEOUT_H


Do we need a dedicated header? There is already common/ceph_time.h.

Need not, but I thought this was a special function that is tailored for converting timeouts and nothing else, and is only ever used by msg/async/Event.cc. And ceph_time.h comes with heavy dependencies on <string>, fmt, <ostream> and even <fstream> (via fmt/ostream.h).
I have a passionate hate for fat headers with a deep dependency tree. And I long for the day C++20 modules solve this problem once and for all, and Ceph could switch to them any day if you want to. (cmake supports modules, but I prefer Meson over cmake, but unfortunately Meson won't support modules for a long time.)

src/msg/async/Timeout.h

MaxKellermann · 2024-10-14T07:40:18Z

Force-push with amendments; I havn't moved to ceph_time.h for now, but will do it if that's your preference.

This is duplicate code, and it's buggy, but I want to fix only one copy. Signed-off-by: Max Kellermann <max.kellermann@ionos.com>

Currently, we always round down, which has a bad side effect: when a timer comes closer, we have lots of early wakeups, and eventually we'll run into a busy loop (timeout=0) when the timeout is less than one millisecond; the process will remain this busy loop for one millisecond, wasting lots of CPU time. Signed-off-by: Max Kellermann <max.kellermann@ionos.com>

src/msg/async/Event.cc

idryomov

Overall LGTM.

Do you have any numbers, flamegraphs, etc to demonstrate the effect? You said that in your testing there were no sub-second timers, I wonder if we aren't missing something else especially given that this PR has performance label.

MaxKellermann · 2024-10-22T15:18:02Z

Do you have any numbers, flamegraphs, etc to demonstrate the effect?

No, I only observed in an strace that there were numerous spikes of epoll_wait() calls with timeout=0 running in a busy loop, every time a scheduled timer was approached. Its due time was still not yet reached, thus nothing was done in this EventCenter iteration, so it called epoll_wait(timeout=0) again and again until that busy loop ran for long enough that the timer's due time was eventually reached and then everything looked normal again - until the next time a timer was approached.

You said that in your testing there were no sub-second timers

Initially those times were not sub-second, but eventually they became sub-second, of course.
My second patch resolved the problem, and my third patch introduced another problem which added up to one second to all timers. But:

if you schedule a timer in 5 seconds, you don't notice if it fires only after 6 seconds; but if you schedule a timer in 10ms and it doesn't fire until after 1 whole second, you'll notice that - but my point was that such timers do not exist in Ceph, therefore my bug was unnoticed
this is only about the epoll_wait() timeout calculation; if epoll_wait() wakes up earlier (because there's traffic on a socket), the timer callback gets invoked soon enough; it is extremely unlikely that there's no traffic at all for one second

That's two reasons why the bug you found in my third patch didn't have any noticable effect. But of course it was wrong and I removed it.

MaxKellermann · 2024-10-22T15:46:15Z

btw. this is where I should have put the rounding code:

ceph/src/msg/async/Event.cc

Line 406 in ee6523b

    
           timeout_microseconds = std::chrono::duration_cast<std::chrono::microseconds>(end_time - now).count();

A duration_cast() rounds down, and this can trigger the same bug.

Unfortunately the whole EventCenter infrastructure is a lot of inefficient spaghetti code. process_events() rounds down, and then EpollDriver::event_wait() rounds down again.
Just look at the type conversions:

EventCenter::create_time_event() takes a raw integer parameter denoting microseconds
EventCenter::process_events() takes a raw integer parameter denoting microseconds again
timer events are stored as ceph::coarse_mono_clock = NANOseconds
those NANOseconds are then converted to microseconds, always rounding down
those microseconds are then converted to struct timeval, split to seconds and microseconds
finally, EpollDriver::event_wait() reconstructs the struct timeval back to a single integer, but MILLIseconds this time, again rounding down

All of this could be so much easier, (type-) safer AND faster by consistently using one single std::chrono::duration type alias globally. This is what I do in my projects: https://github.com/CM4all/libcommon/blob/master/src/event/Chrono.hxx
All timeouts can be constexpr and never need to be converted until epoll_wait() is called, but then I round up: https://github.com/CM4all/libcommon/blob/master/src/event/Loop.cxx#L215

Right now, I'm integrating io_uring into EventCenter to offload all sendmsg() calls to kernel threads and eliminate the latency from Ceph, but it's a bit painful. I might soon send patches to improve the whole EventCenter class (and the rest of msg/async).

idryomov · 2024-10-23T11:04:04Z

Unfortunately the whole EventCenter infrastructure is a lot of inefficient spaghetti code.

I don't disagree ;)

MaxKellermann · 2024-12-03T12:24:39Z

@yuriw, how did your testing go?

MaxKellermann · 2024-12-09T11:36:39Z

@idryomov, is there anything I can do to get this merged?

idryomov · 2024-12-09T11:42:34Z

We need @yuriw's response here, I have pinged him.

yuriw · 2024-12-09T15:27:09Z

@MaxKellermann @idryomov
See https://tracker.ceph.com/issues/68795#note-18
It's under review
cc: @ljflores

MaxKellermann · 2025-01-04T14:08:59Z

@yuriw, how did the review go? I don't understand the tracker ticket.

MaxKellermann · 2025-01-15T07:37:03Z

@yuriw?

ceph-jenkins · 2025-01-15T07:37:06Z

Can one of the admins verify this patch?

idryomov · 2025-01-15T09:41:20Z

No idea what the previous comment from @ceph-jenkins is about, but this PR appears to be pending on @ljflores reviewing the results captured in https://tracker.ceph.com/issues/68795. It's out of @yuriw's hands.

ljflores · 2025-01-16T22:55:58Z

QA results looked good. Rados approved: https://tracker.ceph.com/projects/rados/wiki/MAIN#httpstrackercephcomissues68795

Apologies for the delay- there were some issues with this batch coming from other PRs.

MaxKellermann requested a review from a team as a code owner October 11, 2024 18:01

github-actions bot added the core label Oct 11, 2024

MaxKellermann force-pushed the timeout_round_up branch from 782f7f0 to e380b34 Compare October 13, 2024 13:37

rzarzynski added the performance label Oct 13, 2024

rzarzynski reviewed Oct 13, 2024

View reviewed changes

rzarzynski requested a review from idryomov October 13, 2024 21:42

MaxKellermann force-pushed the timeout_round_up branch from e380b34 to 3fd98bd Compare October 14, 2024 07:38

MaxKellermann added 2 commits October 22, 2024 12:22

msg/async/Event{Poll,Epoll}: move timeout calculation to Timeout.h

32dcaa9

This is duplicate code, and it's buggy, but I want to fix only one copy. Signed-off-by: Max Kellermann <max.kellermann@ionos.com>

MaxKellermann force-pushed the timeout_round_up branch from 3fd98bd to f3c59eb Compare October 22, 2024 10:22

idryomov reviewed Oct 22, 2024

View reviewed changes

src/msg/async/Event.cc Outdated Show resolved Hide resolved

MaxKellermann force-pushed the timeout_round_up branch from f3c59eb to c2d192f Compare October 22, 2024 12:09

idryomov reviewed Oct 22, 2024

View reviewed changes

idryomov approved these changes Oct 23, 2024

View reviewed changes

idryomov added the needs-qa label Oct 23, 2024

yuriw added the wip-yuri3-testing label Oct 31, 2024

yuriw merged commit 70ed84b into ceph:main Jan 16, 2025

MaxKellermann deleted the timeout_round_up branch January 17, 2025 09:44

Conversation

MaxKellermann commented Oct 11, 2024

Checklist

Uh oh!

rzarzynski left a comment

Choose a reason for hiding this comment

Uh oh!

rzarzynski Oct 13, 2024

Choose a reason for hiding this comment

Uh oh!

MaxKellermann Oct 14, 2024

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

MaxKellermann commented Oct 14, 2024

Uh oh!

Uh oh!

idryomov left a comment

Choose a reason for hiding this comment

Uh oh!

MaxKellermann commented Oct 22, 2024

Uh oh!

MaxKellermann commented Oct 22, 2024

Uh oh!

idryomov commented Oct 23, 2024

Uh oh!

MaxKellermann commented Dec 3, 2024

Uh oh!

MaxKellermann commented Dec 9, 2024

Uh oh!

idryomov commented Dec 9, 2024

Uh oh!

yuriw commented Dec 9, 2024

Uh oh!

MaxKellermann commented Jan 4, 2025

Uh oh!

MaxKellermann commented Jan 15, 2025

Uh oh!

ceph-jenkins commented Jan 15, 2025

Uh oh!

idryomov commented Jan 15, 2025

Uh oh!

ljflores commented Jan 16, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants