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

@@ -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

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 {

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) {

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

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) {

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) {

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);

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) {

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) {

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) {

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;

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;

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

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)

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;
 }