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

diff --git a/changes/bug24605 b/changes/bug24605
new file mode 100644 (file)
index 0000000..7ee292b
--- /dev/null
+++ b/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.

diff --git a/doc/tor.1.txt b/doc/tor.1.txt
index b2218e33cc8c9bc0e3b8266c20c4aea592c9c8c7..64114d6e6b50632e8728a1f4b9c31dd390100b2d 100644 (file)
--- a/doc/tor.1.txt
+++ b/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).

diff --git a/src/or/config.c b/src/or/config.c
index fa80dad57642b150b0a968c0e10c4b89698a577d..3ae3af55a3492306da99036dc458ff4054b92a55 100644 (file)
--- a/src/or/config.c
+++ b/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. */

diff --git a/src/or/main.c b/src/or/main.c
index aae98dd8abde25fb7f03d2148a5ca01496a6780f..7c6ab545f0926f4c73f83cefd2d7b3131705732e 100644 (file)
--- a/src/or/main.c
+++ b/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. */

diff --git a/src/or/main.h b/src/or/main.h
index 8eb977575ecb9c7d451de9bac122c988f9f942d8..f6346b65d1efb1873f41b985360c202a932fb58c 100644 (file)
--- a/src/or/main.h
+++ b/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;

diff --git a/src/or/or.h b/src/or/or.h
index aff43f195bc9aaf72c8b0dbe298c6b024d53111c..69f46cede27e4036ed4f525f0b2117b7dd5dec5a 100644 (file)
--- a/src/or/or.h
+++ b/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. */

diff --git a/src/or/status.c b/src/or/status.c
index f7be41e412578dfd8113e04278f2aa52a562a920..1a8885e83ea6d3655a68ba213261eaeb6174171a 100644 (file)
--- a/src/or/status.c
+++ b/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);