Add MainloopStats option.

This patch adds support for MainloopStats that allow developers to get
main event loop statistics via Tor's heartbeat status messages. The new
status log message will show how many succesful, erroneous, and idle
event loop iterations we have had.

See: https://bugs.torproject.org/24605

changes/bug24605

@@ -0,0 +1,4 @@
+  o Minor features (instrumentation):
+    - Add the MainloopStats option to Tor that allows developers to get
+      instrumentation information from the main event loop via the heartbeat
+      messages. Closes ticket 24605.

doc/tor.1.txt

@@ -2032,6 +2032,11 @@ is non-zero):
     to 0 will disable the heartbeat. Otherwise, it must be at least 30
     minutes. (Default: 6 hours)
 
+[[MainloopStats]] **MainloopStats** **0**|**1**::
+    Log main loop statistics every **HeartbeatPeriod** seconds. This is a log
+    level __notice__ message designed to help developers instrumenting Tor's
+    main event loop. (Default: 0)
+
 [[AccountingMax]] **AccountingMax** __N__ **bytes**|**KBytes**|**MBytes**|**GBytes**|**TBytes**|**KBits**|**MBits**|**GBits**|**TBits**::
     Limits the max number of bytes sent and received within a set time period
     using a given calculation rule (see: AccountingStart, AccountingRule).

src/or/config.c

@@ -360,6 +360,7 @@ static config_var_t option_vars_[] = {
   V(GuardLifetime,               INTERVAL, "0 minutes"),
   V(HardwareAccel,               BOOL,     "0"),
   V(HeartbeatPeriod,             INTERVAL, "6 hours"),
+  V(MainloopStats,               BOOL,     "0"),
   V(AccelName,                   STRING,   NULL),
   V(AccelDir,                    FILENAME, NULL),
   V(HashedControlPassword,       LINELIST, NULL),
@@ -2157,6 +2158,10 @@ options_act(const or_options_t *old_options)
     if (options->PerConnBWRate != old_options->PerConnBWRate ||
         options->PerConnBWBurst != old_options->PerConnBWBurst)
       connection_or_update_token_buckets(get_connection_array(), options);
+
+    if (options->MainloopStats != old_options->MainloopStats) {
+      reset_main_loop_counters();
+    }
   }
 
   /* Only collect directory-request statistics on relays and bridges. */

src/or/main.c

@@ -179,6 +179,12 @@ static uint64_t stats_n_bytes_written = 0;
 time_t time_of_process_start = 0;
 /** How many seconds have we been running? */
 long stats_n_seconds_working = 0;
+/** How many times have we returned from the main loop successfully? */
+static uint64_t stats_n_main_loop_successes = 0;
+/** How many times have we received an error from the main loop? */
+static uint64_t stats_n_main_loop_errors = 0;
+/** How many times have we returned from the main loop with no events. */
+static uint64_t stats_n_main_loop_idle = 0;
 
 /** How often will we honor SIGNEWNYM requests? */
 #define MAX_SIGNEWNYM_RATE 10
@@ -493,6 +499,57 @@ connection_is_reading(connection_t *conn)
     (conn->read_event && event_pending(conn->read_event, EV_READ, NULL));
 }
 
+/** Reset our main loop counters. */
+void
+reset_main_loop_counters(void)
+{
+  stats_n_main_loop_successes = 0;
+  stats_n_main_loop_errors = 0;
+  stats_n_main_loop_idle = 0;
+}
+
+/** Increment the main loop success counter. */
+static void
+increment_main_loop_success_count(void)
+{
+  ++stats_n_main_loop_successes;
+}
+
+/** Get the main loop success counter. */
+uint64_t
+get_main_loop_success_count(void)
+{
+  return stats_n_main_loop_successes;
+}
+
+/** Increment the main loop error counter. */
+static void
+increment_main_loop_error_count(void)
+{
+  ++stats_n_main_loop_errors;
+}
+
+/** Get the main loop error counter. */
+uint64_t
+get_main_loop_error_count(void)
+{
+  return stats_n_main_loop_errors;
+}
+
+/** Increment the main loop idle counter. */
+static void
+increment_main_loop_idle_count(void)
+{
+  ++stats_n_main_loop_idle;
+}
+
+/** Get the main loop idle counter. */
+uint64_t
+get_main_loop_idle_count(void)
+{
+  return stats_n_main_loop_idle;
+}
+
 /** Check whether <b>conn</b> is correct in having (or not having) a
  * read/write event (passed in <b>ev</b>). On success, return 0. On failure,
  * log a warning and return -1. */
@@ -2693,6 +2750,8 @@ run_main_loop_once(void)
   if (main_loop_should_exit)
     return 0;
 
+  const or_options_t *options = get_options();
+
 #ifndef _WIN32
   /* Make it easier to tell whether libevent failure is our fault or not. */
   errno = 0;
@@ -2702,7 +2761,14 @@ run_main_loop_once(void)
    * so that libevent knows to run their callbacks. */
   SMARTLIST_FOREACH(active_linked_connection_lst, connection_t *, conn,
                     event_active(conn->read_event, EV_READ, 1));
-  called_loop_once = smartlist_len(active_linked_connection_lst) ? 1 : 0;
+
+  if (options->MainloopStats) {
+    /* We always enforce that EVLOOP_ONCE is passed to event_base_loop() if we
+     * are collecting main loop statistics. */
+    called_loop_once = 1;
+  } else {
+    called_loop_once = smartlist_len(active_linked_connection_lst) ? 1 : 0;
+  }
 
   /* Make sure we know (about) what time it is. */
   update_approx_time(time(NULL));
@@ -2714,6 +2780,21 @@ run_main_loop_once(void)
   loop_result = event_base_loop(tor_libevent_get_base(),
                                 called_loop_once ? EVLOOP_ONCE : 0);
 
+  if (options->MainloopStats) {
+    /* Update our main loop counters. */
+    if (loop_result == 0) {
+      // The call was succesful.
+      increment_main_loop_success_count();
+    } else if (loop_result == -1) {
+      // The call was erroneous.
+      increment_main_loop_error_count();
+    } else if (loop_result == 1) {
+      // The call didn't have any active or pending events
+      // to handle.
+      increment_main_loop_idle_count();
+    }
+  }
+
   /* Oh, the loop failed.  That might be an error that we need to
    * catch, but more likely, it's just an interrupted poll() call or something,
    * and we should try again. */

src/or/main.h

@@ -79,6 +79,11 @@ void tor_free_all(int postfork);
 int do_main_loop(void);
 int tor_init(int argc, char **argv);
 
+void reset_main_loop_counters(void);
+uint64_t get_main_loop_success_count(void);
+uint64_t get_main_loop_error_count(void);
+uint64_t get_main_loop_idle_count(void);
+
 extern time_t time_of_process_start;
 extern long stats_n_seconds_working;
 extern int quiet_level;

src/or/or.h

@@ -3972,6 +3972,8 @@ typedef struct {
 
   int HeartbeatPeriod; /**< Log heartbeat messages after this many seconds
                         * have passed. */
+  int MainloopStats; /**< Log main loop statistics as part of the
+                      * heartbeat messages. */
 
   char *HTTPProxy; /**< hostname[:port] to use as http proxy, if any. */
   tor_addr_t HTTPProxyAddr; /**< Parsed IPv4 addr for http proxy, if any. */

src/or/status.c

@@ -157,6 +157,20 @@ log_heartbeat(time_t now)
     tor_free(msg);
   }
 
+  if (options->MainloopStats) {
+    const uint64_t main_loop_success_count = get_main_loop_success_count();
+    const uint64_t main_loop_error_count = get_main_loop_error_count();
+    const uint64_t main_loop_idle_count = get_main_loop_idle_count();
+
+    log_fn(LOG_NOTICE, LD_HEARTBEAT, "Main event loop statistics: "
+         U64_FORMAT " succesful returns, "
+         U64_FORMAT " erroneous returns, and "
+         U64_FORMAT " idle returns.",
+         U64_PRINTF_ARG(main_loop_success_count),
+         U64_PRINTF_ARG(main_loop_error_count),
+         U64_PRINTF_ARG(main_loop_idle_count));
+  }
+
   tor_free(uptime);
   tor_free(bw_sent);
   tor_free(bw_rcvd);