This address #2065 part for tracking the main thread utilization

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 74.38%. Comparing base (33a1b51) to head (8de3456).
⚠️ Report is 6 commits behind head on unstable.

@@             Coverage Diff              @@
##           unstable    #2931      +/-   ##
============================================
+ Coverage     74.16%   74.38%   +0.22%     
============================================
  Files           129      129              
  Lines         70988    71007      +19     
============================================
+ Hits          52649    52822     +173     
+ Misses        18339    18185     -154     

@dvkashapov how much of a difference is this compared to using the serverCron taking periodic measurements of CLOCK_THREAD_CPUTIME_ID?

how much of a difference is this compared to using the serverCron taking periodic measurements of CLOCK_THREAD_CPUTIME_ID?

Compared locally with clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts), diff_perc = busy_time_perc - thread_cputime_perc was from 0 to -7%, as load approaches 100% diff is getting smaller which kinda makes sense.

I think the main benefit of this approach is close to 0 overhead, compared to clock_gettime() WDYT?

how much of a difference is this compared to using the serverCron taking periodic measurements of CLOCK_THREAD_CPUTIME_ID?

Compared locally with clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts), diff_perc = busy_time_perc - thread_cputime_perc was from 0 to -7%, as load approaches 100% diff is getting smaller which kinda makes sense.

I think the main benefit of this approach is close to 0 overhead, compared to clock_gettime() WDYT?

Not sure how you compared the 2 options. I was mainly pointing out that having a single cron point where we calculate and update the engine CPU time, might simplify this feature (maybe at a slight loss of precision)

I was mainly pointing out that having a single cron point where we calculate and update the engine CPU time, might simplify this feature (maybe at a slight loss of precision)

Ah, I thought that you were concerned about accuracy of percentage value of this approach.
Both are probably the same in terms of complexity, but this one is just lightweight and uses everything we already have.

The metric tracks percentage of time the main thread spends in busy event loop cycles (those with file events, IO responses, or client writes), exposed as main_thread_utilization_perc in INFO CPU section.

It's a percentage of the total time since the server started?

We need to be able to observe changes over time. The current metrics show server uptime in seconds and CPU time in seconds (used_cpu_user_main_thread). To see this over time, you would call INFO CPU every "monitoring period" (e.g. one minute) and compare the current to the previous number. With this information, you can calculate the CPU usage per monitoring period.

I think we should expose the CPU utilization field in the same way, i.e. as number of useful seconds since server start, as suggested in the issue #2065.

Here's an example:

Time 1:

used_cpu_user_main_thread:100.000000
busy_cpu_user_main_thread:50.000000

Time 2:

used_cpu_user_main_thread:160.000000
busy_cpu_user_main_thread:55.000000

With these two samples, we can calculate the delta between time 1 and 2. The delta for used CPU time is 50 seconds and for busy time it's 5 seconds, so for this period, the CPU utilization is 10%. It's possible to draw a graph over time and we don't need to hard-code the sampling interval in the server.

I don't know if "busy" or "useful" is a better prefix. Maybe "useful" (suggested in the issue) is too similar to the exiting fields prefix "used", so maybe busy is better. 🤔

I see now that you implemented it as an instantaneous metric. It works by calculating the utilization over the last 1.6 seconds. (It makes a sample every 100 milliseconds, it has a ring of 16 samples and each sample overwrite the oldest one.) IMO this kind of metrics are less useful for monitoring the system. If you monitor a system with an INFO call every minute or every 5 minutes, you can easily miss a spike of a few seconds high CPU utilization, etc.

Yes, exactly, I'll expose cumulative metric then

"busy" can be confusing because it sounds like busy-waiting, which is the non-useful time. We are interested in the useful time.

New suggestion: "active"

We can use it as

1. a prefix as in active_cpu_user_main_thread or
2. instead of the sys/user part as in used_cpu_active_main_thread

If we pick the latter, we'll have these three which looks pretty nice:

used_cpu_sys_main_thread:123.123456
used_cpu_user_main_thread:567.123456
used_cpu_active_main_thread:345.123456

Clang Format failed at setup, not on check itself, checked locally - everything should be OK

activeExpireCycle()

Makes sense to mark this as active work but should we check that this expire cycle took more than some noticeable amount of time, so that we won't accidentally count all loops to be active. What about 250-500 us?

activeExpireCycle()

Makes sense to mark this as active work but should we check that this expire cycle took more than some noticeable amount of time, so that we won't accidentally count all loops to be active. What about 250-500 us?

A threshold is not perfect. I have an idea: This function internally already keeps track of the elapsed time spent on active expiration. We could change the function so it returns the elapsed time and count it as active CPU time even during an inactive iteration. Does it make sense?

I have an idea: This function internally already keeps track of the elapsed time spent on active expiration. We could change the function so it returns the elapsed time and count it as active CPU time even during an inactive iteration. Does it make sense?

Definitely makes sense, I added a comment to indicate that we count expiry time as active CPU time for all event loops.

@ranshid I'm not sure I understand how your suggestion can solve this.

If we're asking the clock or the kernel about CPU time, it will return 100% CPU usage (or close to) because when IO threads are used, the main thread does a busy loop with non-blocking epoll, i.e. it busy-loops beforeSleep, epoll, afterSleep.

The purpose of the metric is to know what margin the server has, i.e. how much more work the thread can handle, which we get if we excude the CPU time that consists of only busy-looping.

Am I missing anything?

@ranshid I'm not sure I understand how your suggestion can solve this.

If we're asking the clock or the kernel about CPU time, it will return 100% CPU usage (or close to) because when IO threads are used, the main thread does a busy loop with non-blocking epoll, i.e. it busy-loops beforeSleep, epoll, afterSleep.

The purpose of the metric is to know what margin the server has, i.e. how much more work the thread can handle, which we get if we excude the CPU time that consists of only busy-looping.

Am I missing anything?

Oh @zuiderkwast thank you for putting me back on the relevant motivation :) for some reason I only thought you wanted to provide a percentage calculation from the server (which has it's own benefits). I guess I am fine with that direction then.

Update. We have been chatting about this in other channels. Thanks also for feedback from @JimB123.

We should measure the times intervals using clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts) instead of monotonic wall clock time, because:

• CPU time excludes time that the thread is not allowed to run because of preemption.
• CPU time excludes time spent on blocking calls to epoll, disk IO, etc.
• used_cpu_active_main_thread is not expected to be higher than the CPU time reported in used_cpu_user_main_thread. That would be quite confusing. It's more expected that the "active" time is always equal to or lower than used_cpu_user_main_thread.
• The name of the field used_cpu_active_main_thread and the INFO section # CPU hint that this metric is all about CPU time, minus the busy spinning.

I believe we can get away with only a single clock_gettime call per event loop iteration. If we do it only in beforeSleep, we can use the delta between one and the next. The delta then includes the exact total CPU time of the cycle.

Update again. I've been talking to various people about measuring CPU time vs monotonic time.

Going back to the purpose of this metric. The purpose is to see how much spare capacity the thread has to handle more work.

If we measure CPU time and it shows 90% utilization, it doesn't necessarily mean that the thread has capacity to handle more work. The remaining 10% can be that the thread is waiting, not for more work but waiting for other reasons:

• preemtion, i.e. the thread is not allowed to run full time
• waiting for blocking IO or syscalls (CPU time spent by kernel, not userspace)

On the other hand, if we measure these active work time in monotonic time and the metric shows 90% of the time the thread is working, it means that the remaining 10% of the time, it is waiting for work. Thus, measuring monotonic time is more useful for this metric.

We'll keep measuring active time using monotonic clock and we'll change the name of the INFO field so that it doesn't include "cpu". New name of the field is used_active_time_main_thread. (Ack by @madolson.)