[New] IO threads utilization INFO field

[zuiderkwast]

When IO threads are running, they use busy-wait loop to wait for jobs. Therefore, they run at 100% all the time and CPU utilization is not a useful metric to understand the load. The problem is explained in this issue:

• Valkey CPU usage is not a comprehensive indicator of server busyness / load #2055

I propose a metric in percentage how much time the IO thread actual does useful work as opposed to busy-waiting.

We could add fields for IO threads under the "CPU" INFO section. Here, the existing fields are CPU time in seconds since, as given by getrusage() system library function. For example, we have the sys and user CPU time of the main thread:

used_cpu_sys_main_thread:123456.123456
used_cpu_user_main_thread:234567.123456

Since IO threads run at 100% CPU, there's not much point in presenting CPU time. I suggest we report useful time or work time in seconds. For that to be useful, we also need to report the IO thread's uptime, so the caller can compute a percentage and compare it over the time window they wish.

uptime_io_thread_1:1234.56789
useful_io_thread_1:291.234567
uptime_io_thread_2:1234.56789
useful_io_thread_2:321.098765
...

Alternatively, we could present something simpler, such as a single INFO field with a percentage for each IO thread. For this, we would need to compute it over some specified time window though.

io_threads_utilization:60%,39%,67%,61%

[zuiderkwast]

According to #2055 (comment) from @uriyage, even the main thread uses busy-waiting when I/O threads are used, so we may want a "usefulness" metric for the main thread too.

[nandihalli]

Hi @zuiderkwast

I was trying to add the observability into io_threads_usage metric and in the process realized that the max possible io_threads are 256. This means, if we are printing one entry per thread, we will be adding a decent amount of payload to the INFO output - 100*256 (assuming 50bytes for uptime and 50bytes for active usage per io thread). This is ~25KB of additional data. I was wondering if we need to put some effort into reducing the payload size? Or if io_thread count > 16 are rare, we can start without that optimization. WDYT?

According to #2055 (comment) from @uriyage, even the main thread uses busy-waiting when I/O threads are used, so we may want a "usefulness" metric for the main thread too.

AFAICT, it doesn’t seem trivial to find out how long the main thread spent busy polling.

I found that the aeProcessEvents gets invoked in the while loop here. aeProcessEvents function returns the processedEvents as the output. However, we can’t use processed_events > 0 as an indicator for whether the main thread did actual work. This is because the main thread could still do some processing in the beforeSleep or afterSleep functions. Even when processed_events > 0, the main thread could also have spent time doing epoll. So, it doesn’t mean that the main thread was actually busy processing during that time window. Did you have something else in mind on how to track this main thread cpu “usefulness” metric?

cc - @sumish163

[zuiderkwast]

I was trying to add the observability into io_threads_usage metric and in the process realized that the max possible io_threads are 256. This means, if we are printing one entry per thread, we will be adding a decent amount of payload to the INFO output - 100*256 (assuming 50bytes for uptime and 50bytes for active usage per io thread). This is ~25KB of additional data. I was wondering if we need to put some effort into reducing the payload size? Or if io_thread count > 16 are rare, we can start without that optimization. WDYT?

Yeah, I've heard that the size of INFO and the time it takes to generate it is a problem. Ideally, users would only request the sections they actually need, but maybe they are lazy and just get all sections all the time. 😞

We could maybe aggregate the data from all IO threads into one? I'm not sure how. Do you have an idea?

TBH, I think io_thread count > 16 are rare. I guess we can start without the optimization.

it doesn’t seem trivial to find out how long the main thread spent busy polling

I didn't investigate this. Are you saying the epoll call is non-blocking when IO threads are active and this is where the main thread does the busy-wait looping?

[nandihalli]

TBH, I think io_thread count > 16 are rare. I guess we can start without the optimization.
Sounds good!

I didn't investigate this. Are you saying the epoll call is non-blocking when IO threads are active and this is where the main thread does the busy-wait looping?

@zuiderkwast - Yes, that is correct.
https://github.com/valkey-io/valkey/blob/unstable/src/io_threads.c#L532 - When io_threads are enabled, this is where the function returns right away if the epoll event isn't done yet. The eventloop keeps busy polling on this.

So basically, the event loop is doing:

1. BeforeSleep()
2. Check if epoll is finished.
3. If Step 2 returns > 0, process numEvents. If Step 2 returns 0, move to Step 4.
4. AfterSleep()

So, as long as Step 2 returns 0, the eventloop is continuously doing beforeSleep, afterSleep and processing timer events. To understand for how long the event loop isn't doing anything useful, we will also need to see if beforeSleep, afterSleep were also a no-op and doing this becomes non-trivial. This is because the main thread does a bunch of things in the before, afterSleep functions.

[PingXie]

TBH, I think io_thread count > 16 are rare. I guess we can start without the optimization.

+1. I don't think we need to optimize >16 threads for the internal implementation right now. however, it is important to ensure that the "interface" is extensible so the INFO output format is a major decision.

I am thinking that the default argument-less INFO command should return an aggregated IO thread CPU time and only when "cpu" or "all" is explicitly specified we return the per (io-thread) cpu usage. taking a step back, I envision that the default argument-less INFO command gives the overview. note that this pattern is not currently supported: the opt-in occurs at the section level only and we don't change the per-section output based on the explicit section selection.

We could maybe aggregate the data from all IO threads into one? I'm not sure how. Do you have an idea?

We could just add up the uptime and useful_time for all threads.

it doesn’t seem trivial to find out how long the main thread spent busy polling

for main thread cpu, can we try counting the time spent in processPendingCommandAndInputBuffer on the main thread? I wonder how close it could be to the reality?

[nandihalli]

I am thinking that the default argument-less INFO command should return an aggregated IO thread CPU time and only when "cpu" or "all" is explicitly specified.

Is this something we have done for any other metrics? i.e. display detailed metrics only if "all" or that specific section is specified? If not, I am wondering how discoverable these observability data points will be to clients? Otherwise, I like the idea of adding up uptime and useful_time across all threads as an aggregation.

for main thread cpu, can we try counting the time spent in processPendingCommandAndInputBuffer on the main thread? I wonder how close it could be to the reality?

when you say "how close it could be to reality", are you referring to what percentage of main_threads spends its time in processPendingCommandAndInputBuffer? Other than this, I guess that the main_thread is spending its other time on cluster/server crons, syncing topology to disk and other management operations?

[PingXie]

Is this something we have done for any other metrics?

No. This is just a thought. This will need a discussion.

when you say "how close it could be to reality", are you referring to what percentage of main_threads spends its time in processPendingCommandAndInputBuffer?

By "reality", I meant the perceived usefulness by the user. On a second thought, processIoThreadsReadDone and processIoThreadsWriteDone seem to capture more "usefulness".

Cron jobs can have impact, especially active defrag (which by the way should be much lighter thanks to @JimB123's recent work) so probably can be estimated as a fixed percentage based on empirical data? Again just a thought.

Otherwise, another option is to instrument all "useful" paths on the main thread.

[zuiderkwast]

So, as long as Step 2 returns 0, the eventloop is continuously doing beforeSleep, afterSleep and processing timer events. To understand for how long the event loop isn't doing anything useful, we will also need to see if beforeSleep, afterSleep were also a no-op and doing this becomes trivial. This is because the main thread does a bunch of things in the before, afterSleep functions.

It seems that afterSleep and beforeSleep runs much more often when epoll doesn't block. This is a difference compared to before and compared to io-threads off. In this case, we run only if there is an event (socket or timer event).

It seems to me that we can skip most of the work in afterSleep and beforeSleep if numevents == 0. Cron, defrag, etc. are timer events, so numevents != 0 in this case. We just need to check for Done notifications from the IO threads, so we should run processIOThreadsReadDone(), processIOThreadsWriteDone() and connTypeProcessPendingData(). If these all return 0, then there was no work to be done, so the main thread was idle in this even loop iteration. Is that right?

[nandihalli]

@zuiderkwast - yeah, that is mostly true. Apart from the events you mentioned, the main thread also does some maintenance things like evicting clients, flushing to AOF and few other cluster maintenance operations. It is likely that when num_events=0 and the main threads keeps busy looping, most of these maintenance operations are a no-op. But I couldn't see an easy way to track when real work was done here.

[zuiderkwast]

Evicting clients, flushing aof, etc. are done either in the cron job (timer event) or after doing some work, so I think all that can be skipped if numevents == 0 and io threads read and write done return zero.

[deepakrn]

Hi @zuiderkwast ,

I tried look at your suggestions for capturing main_thread useful work. But if num_events == 0, we can't assume that main thread isn't doing any work. In beforeSleep() method, the main thread seems to invoke processIOThreadsReadsDone, processIOThreadsWriteDone and a few other things - ref. We aren't capturing any of that work since beforeSleep current has a void return type and the number of events processed in that function isn't tracked.

Given that tracking main thread usage is more complex and involved, maybe we can decouple tracking the useful work for main thread and io threads?

For io threads, I have this PR open. Could you please help with your feedback?