Add API for measuring event loop idle time#2725
Conversation
trevnorris
force-pushed
the
time-in-provider
branch
5 times, most recently
from
00bf674 to
792e760
Compare
santigimeno
left a comment
santigimeno
left a comment
There was a problem hiding this comment.
Also, the test file should be added to CMakeLists.txt
trevnorris
force-pushed
the
time-in-provider
branch
2 times, most recently
from
7e829fe to
f19c78f
Compare
|
The performance impact can probably be mitigated if the machinery is disabled by default and it's only initialized with a call to As for the general approach, I'm not an expert, but arent tools like perf and eBPF capable of gathering this insight, without instrumenting the application? Regarding the specific metric introduced: in what context is it useful? The way libuv operates it will have 3 types of values:
What kind of application would be interested in these? |
That sounds like a reasonable solution.
This is meant to be used in a production environment where the data can be collected at mass scale. The overhead is low enough that it has no noticeable impact on a (Node.js) process. It also serves as a single interface that is platform agnostic.
Allow me to dive into some of my research. Last year I began to investigate:
Note: From here on the percentage of idle time spent in the event loop's event provider will simply be referred to as the "event loop utilization" or ELU. To better understand the problem scope I began running simulations of (Node.js) HTTP server request/response characteristics based on different workloads, and did comparisons of the number of requests each workload could support. Then I did a comparison of the request data to the process's CPU usage and the ELU. After doing a lot of analysis on several dozen types of workloads I found a correlation between these three data points. This research, and the analysis presented below on the ELU, come from the patch in this PR. The following two graphs represent two different server workloads. The X-axis is the number of connections to the server. The right Y-axis is the number of responses (blue line). The left Y-axis is the CPU% (yellow line) and the ELU (red line). Notice that the graph shows "req/period" and not "req/second". This is because for a complex applications the number of requests per second isn't as reliable a metric. So some measurements are the number of requests per 5 or 10 seconds. Simply using "req/period" is a generic way of labeling this.
The differences in the response curves based on the workload type is a discussion on its own, but that's for another time. Instead we'll focus on the fact that in these two cases the ELU almost perfectly matches the CPU. This is because in both of these workloads V8 is able to GC immediately, instead of needing to do any off-thread or idle-time cleanup. Also notice that both CPU and ELU closely match the response curve. And both curves closely match the req/period curve. I found this to generally be true, except when doing things like HTTP request pipelining. Now for the next example:
This use case causes the GC to be constantly doing cleanup off-thread and during idle-time. The CPU usage maxes out at around 125%. If we were to scale the application soley based on CPU usage (which is how most Node.js applications are scaled), let's say at 80%, then we could be scaling to early. At 80% CPU usage ELU% is only at 61% and the server is serving 369 req/period, of the maximum 710 req/period that it's capable of. This translates to scaling the application when it's only at ~51% of its actual maximum capacity. Note that in this graph it shows the total req/period increasing slightly after the ELU has reached 100%. This is because of V8 GC and code optimization specifics. To recap the above, the ELU has the following advantages over the usual CPU usage:
Sorry, I'm not sure how the three timeout values are applicable. |
|
@saghul I've added the loop configuration option |
trevnorris
force-pushed
the
time-in-provider
branch
from
1ea2332 to
bf26e56
Compare
|
@trevnorris Thanks for the thorough explanation, I think I get what you're after here. 👍
Disregard that, I'm nott sure where I was going there... 🙈 |
While this is true, the application/libraries still need some level of instrumentation for eBPF to be used properly. Inlined functions, lack of debug symbols and frame pointers omitted usually hurt eBPF observability. Also, BPF is only available on Linux, and is complicated to use on FaaS or containerized platforms. A while ago I suggested re-adding DTrace-style tracepoints to libuv (#2209) to make the event loop more observable. But I like this approach better, as it doesn't require users to learn and setup a system-level observability tool and can be used regardless of underlying stack or operating system. And for users who need those system level tools, this approach improves the information they can get, becaue now it's possible to hook those tools to uv__metrics_update_idle_time. |
|
Review suggestions have been addressed. Is there anyone willing to give tips on the Windows implementation? The first question I need to answer is if The other main thing is to see if there are platform-agnostic atomics. I can switch to using a mutex lock if necessary, but I'd like to prevent that overhead if possible. If anything guess I could |
trevnorris
force-pushed
the
time-in-provider
branch
from
7b3f82d to
8b6dac5
Compare
/cc @libuv/windows |
|
The user callbacks are called by |
|
Added a commit that will switch to using a |
|
Also, the implementation of the internal metrics functions is almost identical. Except for the atomic operations. I'm going to benchmark the performance difference between using the atomics and the mutex. Depending on the difference, I might just drop the atomics part completely and unify the implementations. |
trevnorris
force-pushed
the
time-in-provider
branch
2 times, most recently
from
851880c to
bcf3900
Compare
trevnorris
changed the title
|
Bummer. Same failure. I'm now managing to reproduce it on my Windows VM. I'm confused why this is happening on a spawned thread. Even when I only spawn a single thread, and use the noop timer callback, it still shows an extremely low idle time. Will give this another look tomorrow. |
trevnorris
force-pushed
the
time-in-provider
branch
2 times, most recently
from
d2f871a to
c785eb7
Compare
|
@vtjnash @santigimeno I've updated and cleaned up the PR. Tests should be passing on Windows. The bug came from me overlooking this comment in The result was that the internal tracking mechanism for when poll was entered was being unexpectedly reset. So placement of Should be ready for CI. |
trevnorris
force-pushed
the
time-in-provider
branch
from
c785eb7 to
6975c49
Compare
|
I forgot to remove the |
This is a port of 70002c8 to z/OS to fix the same potential issue that could effectively enter an infinite loop (but not a busy loop) under certain conditions when polling for events. PR-URL: libuv#2725 Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Jameson Nash <[email protected]>
Add struct `uv__loop_internal_fields_t` as a location for future additions to `uv_loop_t` while also maintaining v1.x compatibility. Currently `uv__loop_internal_fields_t` only contains the `flags` field. The reason for adding the `flags` field is because the same field was never added to `UV_LOOP_PRIVATE_FIELDS` in Windows as it was in Unix. The idea for creating a struct and attaching it to `uv_loop_t` for future API enhancements was taken from a comment by bnoordhuis in: libuv#2506 (comment) Also add `internal_fields` to `uv_loop_t` to store the pointer to `uv__loop_internal_fields_t`. This naming makes more sense than just using `active_reqs.unused[1]`. To maintain ABI compatibility, shrink the `unused` array. PR-URL: libuv#2725 Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Jameson Nash <[email protected]>
The API addition `uv_metrics_idle_time()` is a thread safe call that allows the user to retrieve the amount of time the event loop has spent in the kernel's event provider (i.e. poll). It was done this way to allow retrieving this value without needing to interrupt the execution of the event loop. This option can be enabled by passing `UV_METRICS_IDLE_TIME` to `uv_loop_configure()`. One important aspect of this change is, when enabled, to always first call the event provider with a `timeout == 0`. This allows libuv to know whether any events were waiting in the event queue when the event provider was called. The importance of this is because libuv is tracking the amount of "idle time", not "poll time". Thus the provider entry time is not recorded when `timeout == 0` (the event provider never idles in this case). While this does add a small amount of overhead, when enabled, but the overhead decreases when the event loop has a heavier load. This is because poll events will be waiting when the event provider is called. Thus never actually recording the provider entry time. Checking if `uv_loop_t` is configured with `UV_METRICS_IDLE_TIME` always happens in `uv__metrics_set_provider_entry_time()` and `uv__metrics_update_idle_time()`. Making the conditional logic wrapping each call simpler and allows for instrumentation to always hook into those two function calls. Rather than placing the fields directly on `uv__loop_internal_fields_t` add the struct `uv__loop_metrics_t` as a location for future metrics API additions. Tests and additional documentation has been included. PR-URL: libuv#2725 Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Jameson Nash <[email protected]>
vtjnash
force-pushed
the
time-in-provider
branch
from
6975c49 to
e8effd4
Compare
|
@vtjnash Thanks a lot for helping this make it through. |
Refs: #2725 PR-URL: #2984 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]>
|
The documentation here should probably mention the unit of the returned value as well |
This is a port of 70002c8 to z/OS to fix the same potential issue that could effectively enter an infinite loop (but not a busy loop) under certain conditions when polling for events. PR-URL: libuv#2725 Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Jameson Nash <[email protected]>
Add struct `uv__loop_internal_fields_t` as a location for future additions to `uv_loop_t` while also maintaining v1.x compatibility. Currently `uv__loop_internal_fields_t` only contains the `flags` field. The reason for adding the `flags` field is because the same field was never added to `UV_LOOP_PRIVATE_FIELDS` in Windows as it was in Unix. The idea for creating a struct and attaching it to `uv_loop_t` for future API enhancements was taken from a comment by bnoordhuis in: libuv#2506 (comment) Also add `internal_fields` to `uv_loop_t` to store the pointer to `uv__loop_internal_fields_t`. This naming makes more sense than just using `active_reqs.unused[1]`. To maintain ABI compatibility, shrink the `unused` array. PR-URL: libuv#2725 Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Jameson Nash <[email protected]>
The API addition `uv_metrics_idle_time()` is a thread safe call that allows the user to retrieve the amount of time the event loop has spent in the kernel's event provider (i.e. poll). It was done this way to allow retrieving this value without needing to interrupt the execution of the event loop. This option can be enabled by passing `UV_METRICS_IDLE_TIME` to `uv_loop_configure()`. One important aspect of this change is, when enabled, to always first call the event provider with a `timeout == 0`. This allows libuv to know whether any events were waiting in the event queue when the event provider was called. The importance of this is because libuv is tracking the amount of "idle time", not "poll time". Thus the provider entry time is not recorded when `timeout == 0` (the event provider never idles in this case). While this does add a small amount of overhead, when enabled, but the overhead decreases when the event loop has a heavier load. This is because poll events will be waiting when the event provider is called. Thus never actually recording the provider entry time. Checking if `uv_loop_t` is configured with `UV_METRICS_IDLE_TIME` always happens in `uv__metrics_set_provider_entry_time()` and `uv__metrics_update_idle_time()`. Making the conditional logic wrapping each call simpler and allows for instrumentation to always hook into those two function calls. Rather than placing the fields directly on `uv__loop_internal_fields_t` add the struct `uv__loop_metrics_t` as a location for future metrics API additions. Tests and additional documentation has been included. PR-URL: libuv#2725 Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Jameson Nash <[email protected]>
Refs: libuv#2725 PR-URL: libuv#2984 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]>
This is a port of 70002c8 to z/OS to fix the same potential issue that could effectively enter an infinite loop (but not a busy loop) under certain conditions when polling for events. PR-URL: libuv/libuv#2725 Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Jameson Nash <[email protected]>
Add struct `uv__loop_internal_fields_t` as a location for future additions to `uv_loop_t` while also maintaining v1.x compatibility. Currently `uv__loop_internal_fields_t` only contains the `flags` field. The reason for adding the `flags` field is because the same field was never added to `UV_LOOP_PRIVATE_FIELDS` in Windows as it was in Unix. The idea for creating a struct and attaching it to `uv_loop_t` for future API enhancements was taken from a comment by bnoordhuis in: libuv/libuv#2506 (comment) Also add `internal_fields` to `uv_loop_t` to store the pointer to `uv__loop_internal_fields_t`. This naming makes more sense than just using `active_reqs.unused[1]`. To maintain ABI compatibility, shrink the `unused` array. PR-URL: libuv/libuv#2725 Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Jameson Nash <[email protected]>
The API addition `uv_metrics_idle_time()` is a thread safe call that allows the user to retrieve the amount of time the event loop has spent in the kernel's event provider (i.e. poll). It was done this way to allow retrieving this value without needing to interrupt the execution of the event loop. This option can be enabled by passing `UV_METRICS_IDLE_TIME` to `uv_loop_configure()`. One important aspect of this change is, when enabled, to always first call the event provider with a `timeout == 0`. This allows libuv to know whether any events were waiting in the event queue when the event provider was called. The importance of this is because libuv is tracking the amount of "idle time", not "poll time". Thus the provider entry time is not recorded when `timeout == 0` (the event provider never idles in this case). While this does add a small amount of overhead, when enabled, but the overhead decreases when the event loop has a heavier load. This is because poll events will be waiting when the event provider is called. Thus never actually recording the provider entry time. Checking if `uv_loop_t` is configured with `UV_METRICS_IDLE_TIME` always happens in `uv__metrics_set_provider_entry_time()` and `uv__metrics_update_idle_time()`. Making the conditional logic wrapping each call simpler and allows for instrumentation to always hook into those two function calls. Rather than placing the fields directly on `uv__loop_internal_fields_t` add the struct `uv__loop_metrics_t` as a location for future metrics API additions. Tests and additional documentation has been included. PR-URL: libuv/libuv#2725 Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Jameson Nash <[email protected]>
Refs: libuv/libuv#2725 PR-URL: libuv/libuv#2984 Reviewed-By: Colin Ihrig <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]>
This is a port of 70002c8 to z/OS to fix the same potential issue that could effectively enter an infinite loop (but not a busy loop) under certain conditions when polling for events. PR-URL: libuv/libuv#2725 Reviewed-By: Fedor Indutny <[email protected]> Reviewed-By: Santiago Gimeno <[email protected]> Reviewed-By: Jameson Nash <[email protected]>
15 participants
This PR contains code that I've been working on for a while as part of some research I've been doing at work, and decided it would be good to submit this for review after seeing @indutny's Node.js PR nodejs/node#32018.
The main reasons for writing this patch are:
A lot is explain in the commit message below, and I'll be happy to explain in detail why the implementation was done this way. For example, this approach was a conclusion I came to last year after researching whether it was possible to infer the state of the application based solely on event loop metrics. In order to achieve that goal it's necessary to have the level of accuracy this patch provides.
There are a few things I'm unsure about and would like feedback on, like how I've implemented atomics, and I'll need some assistance with the Windows implementation.
/cc @bnoordhuis @indutny @saghul
Commit message:
Add API for measuring event loop idle time
The API addition
uv_metrics_idle_time()is a thread safe call thatallows the user to retrieve the amount of time the event loop has spent
in the kernel's event provider (i.e. poll). It was done this way to
allow retrieving this value without needing to interrupt the execution
of the event loop. This option can be enabled by passing
UV_METRICS_IDLE_TIMEtouv_loop_configure().One important aspect of this change is, when enabled, to always first
call the event provider with a
timeout == 0. This allows libuv to knowwhether any events were waiting in the event queue when the event
provider was called. The importance of this is because libuv is tracking
the amount of "idle time", not "poll time". Thus the provider entry time
is not recorded when
timeout == 0(the event provider never idles inthis case).
While this does add a small amount of overhead, when enabled, but the
overhead decreases when the event loop has a heavier load. This is
because poll events will be waiting when the event provider is called.
Thus never actually recording the provider entry time.
Checking if
uv_loop_tis configured withUV_METRICS_IDLE_TIMEalwayshappens in
uv__metrics_set_provider_entry_time()anduv__metrics_update_idle_time(). Making the conditional logic wrappingeach call simpler and allows for instrumentation to always hook into
those two function calls.
Add struct
uv__metrics_loop_tas a location for future metrics APIadditions.
Add struct
uv__loop_internal_fields_tas a location for futureadditions to
uv_loop_twhile also maintaining v1.x compatibility. Apointer to this struct has been placed in the
uv_loop_t::unused[1]space to allow for fast retrieval and maintaining ABI compatibility with
v1.x.
Currently
uv__loop_internal_fields_tonly contains both theuv__metrics_loop_tandflagsfield. The reason for adding theflagsfield is because the same field was never added toUV_LOOP_PRIVATE_FIELDSin Windows as it was in Unix, and adding thatfield would break ABI.
The idea for creating a struct and attaching it to
uv_loop_tforfuture API enhancements was taken from a comment by bnoordhuis in:
#2506 (comment)
Tests and additional documentation has been included.