From e14158605336d2852dc5489204d2eb7fbe38a97d Mon Sep 17 00:00:00 2001 From: Trevor Norris Date: Fri, 11 Nov 2022 08:21:58 -0700 Subject: [PATCH] src: add new metrics APIs (#3749) The following metrics are now always recorded and available via the new uv_metrics_info() API. * loop_count: Number of event loop iterations. * events: Total number of events processed by the event handler. * events_waiting: Total number of events waiting in the event queue when the event provider request was made. Benchmarking has shown no noticeable impact recording these metrics. PR-URL: https://github.com/libuv/libuv/pull/3749 --- docs/src/metrics.rst | 48 +++++++++++++++++++- include/uv.h | 11 +++++ src/unix/aix.c | 2 + src/unix/core.c | 2 + src/unix/kqueue.c | 2 + src/unix/linux.c | 2 + src/unix/loop.c | 3 ++ src/unix/os390.c | 2 + src/unix/posix-poll.c | 2 + src/unix/sunos.c | 2 + src/uv-common.c | 9 ++++ src/uv-common.h | 16 +++++++ src/win/core.c | 22 +++++++-- test/test-list.h | 2 + test/test-metrics.c | 103 ++++++++++++++++++++++++++++++++++++++++++ 15 files changed, 223 insertions(+), 5 deletions(-) diff --git a/docs/src/metrics.rst b/docs/src/metrics.rst index 696c620d..0141d032 100644 --- a/docs/src/metrics.rst +++ b/docs/src/metrics.rst @@ -4,8 +4,46 @@ Metrics operations ====================== -libuv provides a metrics API to track the amount of time the event loop has -spent idle in the kernel's event provider. +libuv provides a metrics API to track various internal operations of the event +loop. + + +Data types +---------- + +.. c:type:: uv_metrics_t + + The struct that contains event loop metrics. It is recommended to retrieve + these metrics in a :c:type:`uv_prepare_cb` in order to make sure there are + no inconsistencies with the metrics counters. + + :: + + typedef struct { + uint64_t loop_count; + uint64_t events; + uint64_t events_waiting; + /* private */ + uint64_t* reserved[13]; + } uv_metrics_t; + + +Public members +^^^^^^^^^^^^^^ + +.. c:member:: uint64_t uv_metrics_t.loop_count + + Number of event loop iterations. + +.. c:member:: uint64_t uv_metrics_t.events + + Number of events that have been processed by the event handler. + +.. c:member:: uint64_t uv_metrics_t.events_waiting + + Number of events that were waiting to be processed when the event provider + was called. + API --- @@ -25,3 +63,9 @@ API :c:type:`UV_METRICS_IDLE_TIME`. .. versionadded:: 1.39.0 + +.. c:function:: int uv_metrics_info(uv_loop_t* loop, uv_metrics_t* metrics) + + Copy the current set of event loop metrics to the ``metrics`` pointer. + + .. versionadded:: 1.45.0 diff --git a/include/uv.h b/include/uv.h index d788bc17..68128db1 100644 --- a/include/uv.h +++ b/include/uv.h @@ -246,6 +246,8 @@ typedef struct uv_passwd_s uv_passwd_t; typedef struct uv_utsname_s uv_utsname_t; typedef struct uv_statfs_s uv_statfs_t; +typedef struct uv_metrics_s uv_metrics_t; + typedef enum { UV_LOOP_BLOCK_SIGNAL = 0, UV_METRICS_IDLE_TIME @@ -1274,6 +1276,15 @@ UV_EXTERN int uv_os_gethostname(char* buffer, size_t* size); UV_EXTERN int uv_os_uname(uv_utsname_t* buffer); +struct uv_metrics_s { + uint64_t loop_count; + uint64_t events; + uint64_t events_waiting; + /* private */ + uint64_t* reserved[13]; +}; + +UV_EXTERN int uv_metrics_info(uv_loop_t* loop, uv_metrics_t* metrics); UV_EXTERN uint64_t uv_metrics_idle_time(uv_loop_t* loop); typedef enum { diff --git a/src/unix/aix.c b/src/unix/aix.c index f413f108..656869f7 100644 --- a/src/unix/aix.c +++ b/src/unix/aix.c @@ -321,9 +321,11 @@ void uv__io_poll(uv_loop_t* loop, int timeout) { nevents++; } + uv__metrics_inc_events(loop, nevents); if (reset_timeout != 0) { timeout = user_timeout; reset_timeout = 0; + uv__metrics_inc_events_waiting(loop, nevents); } if (have_signals != 0) { diff --git a/src/unix/core.c b/src/unix/core.c index fc8559ba..b77be274 100644 --- a/src/unix/core.c +++ b/src/unix/core.c @@ -405,6 +405,8 @@ int uv_run(uv_loop_t* loop, uv_run_mode mode) { if ((mode == UV_RUN_ONCE && can_sleep) || mode == UV_RUN_DEFAULT) timeout = uv__backend_timeout(loop); + uv__metrics_inc_loop_count(loop); + uv__io_poll(loop, timeout); /* Process immediate callbacks (e.g. write_cb) a small fixed number of diff --git a/src/unix/kqueue.c b/src/unix/kqueue.c index 9e34a684..abb14785 100644 --- a/src/unix/kqueue.c +++ b/src/unix/kqueue.c @@ -386,9 +386,11 @@ void uv__io_poll(uv_loop_t* loop, int timeout) { uv__wait_children(loop); } + uv__metrics_inc_events(loop, nevents); if (reset_timeout != 0) { timeout = user_timeout; reset_timeout = 0; + uv__metrics_inc_events_waiting(loop, nevents); } if (have_signals != 0) { diff --git a/src/unix/linux.c b/src/unix/linux.c index 13e7661f..d2db848b 100644 --- a/src/unix/linux.c +++ b/src/unix/linux.c @@ -610,9 +610,11 @@ void uv__io_poll(uv_loop_t* loop, int timeout) { } } + uv__metrics_inc_events(loop, nevents); if (reset_timeout != 0) { timeout = user_timeout; reset_timeout = 0; + uv__metrics_inc_events_waiting(loop, nevents); } if (have_signals != 0) { diff --git a/src/unix/loop.c b/src/unix/loop.c index a88e71c3..816ac179 100644 --- a/src/unix/loop.c +++ b/src/unix/loop.c @@ -45,6 +45,9 @@ int uv_loop_init(uv_loop_t* loop) { err = uv_mutex_init(&lfields->loop_metrics.lock); if (err) goto fail_metrics_mutex_init; + memset(&lfields->loop_metrics.metrics, + 0, + sizeof(lfields->loop_metrics.metrics)); heap_init((struct heap*) &loop->timer_heap); QUEUE_INIT(&loop->wq); diff --git a/src/unix/os390.c b/src/unix/os390.c index 3b16318c..315b8cd9 100644 --- a/src/unix/os390.c +++ b/src/unix/os390.c @@ -998,9 +998,11 @@ void uv__io_poll(uv_loop_t* loop, int timeout) { } } + uv__metrics_inc_events(loop, nevents); if (reset_timeout != 0) { timeout = user_timeout; reset_timeout = 0; + uv__metrics_inc_events_waiting(loop, nevents); } if (have_signals != 0) { diff --git a/src/unix/posix-poll.c b/src/unix/posix-poll.c index 0f4bf938..711780ec 100644 --- a/src/unix/posix-poll.c +++ b/src/unix/posix-poll.c @@ -292,9 +292,11 @@ void uv__io_poll(uv_loop_t* loop, int timeout) { } } + uv__metrics_inc_events(loop, nevents); if (reset_timeout != 0) { timeout = user_timeout; reset_timeout = 0; + uv__metrics_inc_events_waiting(loop, nevents); } if (have_signals != 0) { diff --git a/src/unix/sunos.c b/src/unix/sunos.c index 7835bed7..afbc3532 100644 --- a/src/unix/sunos.c +++ b/src/unix/sunos.c @@ -320,9 +320,11 @@ void uv__io_poll(uv_loop_t* loop, int timeout) { QUEUE_INSERT_TAIL(&loop->watcher_queue, &w->watcher_queue); } + uv__metrics_inc_events(loop, nevents); if (reset_timeout != 0) { timeout = user_timeout; reset_timeout = 0; + uv__metrics_inc_events_waiting(loop, nevents); } if (have_signals != 0) { diff --git a/src/uv-common.c b/src/uv-common.c index 6bb57473..df8b8b71 100644 --- a/src/uv-common.c +++ b/src/uv-common.c @@ -963,6 +963,15 @@ void uv__metrics_set_provider_entry_time(uv_loop_t* loop) { } +int uv_metrics_info(uv_loop_t* loop, uv_metrics_t* metrics) { + memcpy(metrics, + &uv__get_loop_metrics(loop)->metrics, + sizeof(*metrics)); + + return 0; +} + + uint64_t uv_metrics_idle_time(uv_loop_t* loop) { uv__loop_metrics_t* loop_metrics; uint64_t entry_time; diff --git a/src/uv-common.h b/src/uv-common.h index bbfaaf70..3b0370c7 100644 --- a/src/uv-common.h +++ b/src/uv-common.h @@ -349,6 +349,21 @@ void uv__threadpool_cleanup(void); #define uv__get_loop_metrics(loop) \ (&uv__get_internal_fields(loop)->loop_metrics) +#define uv__metrics_inc_loop_count(loop) \ + do { \ + uv__get_loop_metrics(loop)->metrics.loop_count++; \ + } while (0) + +#define uv__metrics_inc_events(loop, e) \ + do { \ + uv__get_loop_metrics(loop)->metrics.events += (e); \ + } while (0) + +#define uv__metrics_inc_events_waiting(loop, e) \ + do { \ + uv__get_loop_metrics(loop)->metrics.events_waiting += (e); \ + } while (0) + /* Allocator prototypes */ void *uv__calloc(size_t count, size_t size); char *uv__strdup(const char* s); @@ -362,6 +377,7 @@ typedef struct uv__loop_metrics_s uv__loop_metrics_t; typedef struct uv__loop_internal_fields_s uv__loop_internal_fields_t; struct uv__loop_metrics_s { + uv_metrics_t metrics; uint64_t provider_entry_time; uint64_t provider_idle_time; uv_mutex_t lock; diff --git a/src/win/core.c b/src/win/core.c index 8d4bbefd..09a3c7b1 100644 --- a/src/win/core.c +++ b/src/win/core.c @@ -245,6 +245,9 @@ int uv_loop_init(uv_loop_t* loop) { err = uv_mutex_init(&lfields->loop_metrics.lock); if (err) goto fail_metrics_mutex_init; + memset(&lfields->loop_metrics.metrics, + 0, + sizeof(lfields->loop_metrics.metrics)); /* To prevent uninitialized memory access, loop->time must be initialized * to zero before calling uv_update_time for the first time. @@ -454,6 +457,8 @@ static void uv__poll_wine(uv_loop_t* loop, DWORD timeout) { timeout); if (reset_timeout != 0) { + if (overlapped && timeout == 0) + uv__metrics_inc_events_waiting(loop, 1); timeout = user_timeout; reset_timeout = 0; } @@ -466,6 +471,8 @@ static void uv__poll_wine(uv_loop_t* loop, DWORD timeout) { uv__metrics_update_idle_time(loop); if (overlapped) { + uv__metrics_inc_events(loop, 1); + /* Package was dequeued */ req = uv__overlapped_to_req(overlapped); uv__insert_pending_req(loop, req); @@ -508,6 +515,7 @@ static void uv__poll(uv_loop_t* loop, DWORD timeout) { int repeat; uint64_t timeout_time; uint64_t user_timeout; + uint64_t actual_timeout; int reset_timeout; timeout_time = loop->time + timeout; @@ -521,6 +529,8 @@ static void uv__poll(uv_loop_t* loop, DWORD timeout) { } for (repeat = 0; ; repeat++) { + actual_timeout = timeout; + /* Only need to set the provider_entry_time if timeout != 0. The function * will return early if the loop isn't configured with UV_METRICS_IDLE_TIME. */ @@ -540,9 +550,9 @@ static void uv__poll(uv_loop_t* loop, DWORD timeout) { } /* Placed here because on success the loop will break whether there is an - * empty package or not, or if GetQueuedCompletionStatus returned early then - * the timeout will be updated and the loop will run again. In either case - * the idle time will need to be updated. + * empty package or not, or if pGetQueuedCompletionStatusEx returned early + * then the timeout will be updated and the loop will run again. In either + * case the idle time will need to be updated. */ uv__metrics_update_idle_time(loop); @@ -552,6 +562,10 @@ static void uv__poll(uv_loop_t* loop, DWORD timeout) { * meant only to wake us up. */ if (overlappeds[i].lpOverlapped) { + uv__metrics_inc_events(loop, 1); + if (actual_timeout == 0) + uv__metrics_inc_events_waiting(loop, 1); + req = uv__overlapped_to_req(overlappeds[i].lpOverlapped); uv__insert_pending_req(loop, req); } @@ -609,6 +623,8 @@ int uv_run(uv_loop_t *loop, uv_run_mode mode) { if ((mode == UV_RUN_ONCE && can_sleep) || mode == UV_RUN_DEFAULT) timeout = uv_backend_timeout(loop); + uv__metrics_inc_loop_count(loop); + if (pGetQueuedCompletionStatusEx) uv__poll(loop, timeout); else diff --git a/test/test-list.h b/test/test-list.h index ca24ba5e..45261be2 100644 --- a/test/test-list.h +++ b/test/test-list.h @@ -547,6 +547,7 @@ TEST_DECLARE (utf8_decode1) TEST_DECLARE (utf8_decode1_overrun) TEST_DECLARE (uname) +TEST_DECLARE (metrics_info_check) TEST_DECLARE (metrics_idle_time) TEST_DECLARE (metrics_idle_time_thread) TEST_DECLARE (metrics_idle_time_zero) @@ -1174,6 +1175,7 @@ TASK_LIST_START TEST_ENTRY (readable_on_eof) TEST_HELPER (readable_on_eof, tcp4_echo_server) + TEST_ENTRY (metrics_info_check) TEST_ENTRY (metrics_idle_time) TEST_ENTRY (metrics_idle_time_thread) TEST_ENTRY (metrics_idle_time_zero) diff --git a/test/test-metrics.c b/test/test-metrics.c index f5274944..bfc09251 100644 --- a/test/test-metrics.c +++ b/test/test-metrics.c @@ -25,6 +25,16 @@ #define UV_NS_TO_MS 1000000 +typedef struct { + uv_fs_t open_req; + uv_fs_t write_req; + uv_fs_t close_req; +} fs_reqs_t; + +static uint64_t last_events_count; +static char test_buf[] = "test-buffer\n"; +static fs_reqs_t fs_reqs; + static void timer_spin_cb(uv_timer_t* handle) { uint64_t t; @@ -116,6 +126,7 @@ static void timer_noop_cb(uv_timer_t* handle) { TEST_IMPL(metrics_idle_time_zero) { + uv_metrics_t metrics; uv_timer_t timer; int cntr; @@ -130,6 +141,98 @@ TEST_IMPL(metrics_idle_time_zero) { ASSERT_GT(cntr, 0); ASSERT_EQ(0, uv_metrics_idle_time(uv_default_loop())); + ASSERT_EQ(0, uv_metrics_info(uv_default_loop(), &metrics)); + ASSERT_UINT64_EQ(cntr, metrics.loop_count); + + MAKE_VALGRIND_HAPPY(); + return 0; +} + + +static void close_cb(uv_fs_t* req) { + uv_metrics_t metrics; + + ASSERT_EQ(0, uv_metrics_info(uv_default_loop(), &metrics)); + ASSERT_UINT64_EQ(3, metrics.loop_count); + ASSERT_UINT64_GT(metrics.events, last_events_count); + + uv_fs_req_cleanup(req); + last_events_count = metrics.events; +} + + +static void write_cb(uv_fs_t* req) { + uv_metrics_t metrics; + + ASSERT_EQ(0, uv_metrics_info(uv_default_loop(), &metrics)); + ASSERT_UINT64_EQ(2, metrics.loop_count); + ASSERT_UINT64_GT(metrics.events, last_events_count); + ASSERT_EQ(req->result, sizeof(test_buf)); + + uv_fs_req_cleanup(req); + last_events_count = metrics.events; + + ASSERT_EQ(0, uv_fs_close(uv_default_loop(), + &fs_reqs.close_req, + fs_reqs.open_req.result, + close_cb)); +} + + +static void create_cb(uv_fs_t* req) { + uv_metrics_t metrics; + + ASSERT_EQ(0, uv_metrics_info(uv_default_loop(), &metrics)); + /* Event count here is still 0 so not going to check. */ + ASSERT_UINT64_EQ(1, metrics.loop_count); + ASSERT_GE(req->result, 0); + + uv_fs_req_cleanup(req); + last_events_count = metrics.events; + + uv_buf_t iov = uv_buf_init(test_buf, sizeof(test_buf)); + ASSERT_EQ(0, uv_fs_write(uv_default_loop(), + &fs_reqs.write_req, + req->result, + &iov, + 1, + 0, + write_cb)); +} + + +static void prepare_cb(uv_prepare_t* handle) { + uv_metrics_t metrics; + + uv_prepare_stop(handle); + + ASSERT_EQ(0, uv_metrics_info(uv_default_loop(), &metrics)); + ASSERT_UINT64_EQ(0, metrics.loop_count); + ASSERT_UINT64_EQ(0, metrics.events); + + ASSERT_EQ(0, uv_fs_open(uv_default_loop(), + &fs_reqs.open_req, + "test_file", + O_WRONLY | O_CREAT, S_IRUSR | S_IWUSR, + create_cb)); +} + + +TEST_IMPL(metrics_info_check) { + uv_fs_t unlink_req; + uv_prepare_t prepare; + + uv_fs_unlink(NULL, &unlink_req, "test_file", NULL); + uv_fs_req_cleanup(&unlink_req); + + ASSERT_EQ(0, uv_prepare_init(uv_default_loop(), &prepare)); + ASSERT_EQ(0, uv_prepare_start(&prepare, prepare_cb)); + + ASSERT_EQ(0, uv_run(uv_default_loop(), UV_RUN_DEFAULT)); + + uv_fs_unlink(NULL, &unlink_req, "test_file", NULL); + uv_fs_req_cleanup(&unlink_req); + MAKE_VALGRIND_HAPPY(); return 0; }