If configured, write cell statistics to disk periodically.

ChangeLog

@@ -21,6 +21,10 @@ Changes in version 0.2.2.1-alpha - 2009-??-??
       transferred bytes per port to disk every 24 hours.  To enable this,
       run configure with the --enable-exit-stats option, and set
       "ExitPortStatistics 1" in your torrc.
+    - Relays write statistics on how long cells spend in their circuit
+      queues to disk every 24 hours. To enable this, run configure with
+      the --enable-buffer-stats option, and set "CellStatistics 1" in your
+      torrc.
 
   o Minor bugfixes
     - Hidden service clients didn't use a cached service descriptor that

configure.in

@@ -99,6 +99,13 @@ if test "$enable_geoip_stats" = "yes"; then
   AC_DEFINE(ENABLE_GEOIP_STATS, 1, [Defined if we try to collect per-country statistics])
 fi
 
+AC_ARG_ENABLE(buffer-stats,
+     AS_HELP_STRING(--enable-buffer-stats, enable code for relays to collect buffer statistics))
+
+if test "$enable_buffer_stats" = "yes"; then
+  AC_DEFINE(ENABLE_BUFFER_STATS, 1, [Defined if we try to collect buffer statistics])
+fi
+
 AC_ARG_ENABLE(gcc-warnings,
      AS_HELP_STRING(--enable-gcc-warnings, enable verbose warnings))
 

src/or/circuitlist.c

@@ -447,6 +447,11 @@ circuit_free(circuit_t *circ)
       rend_data_free(ocirc->rend_data);
   } else {
     or_circuit_t *ocirc = TO_OR_CIRCUIT(circ);
+#ifdef ENABLE_BUFFER_STATS
+    /* Remember cell statistics for this circuit before deallocating. */
+    if (get_options()->CellStatistics)
+      add_circ_to_buffer_stats(circ, time(NULL));
+#endif
     mem = ocirc;
     memlen = sizeof(or_circuit_t);
     tor_assert(circ->magic == OR_CIRCUIT_MAGIC);

src/or/config.c

@@ -162,6 +162,7 @@ static config_var_t _option_vars[] = {
   V(BridgePassword,              STRING,   NULL),
   V(BridgeRecordUsageByCountry,  BOOL,     "1"),
   V(BridgeRelay,                 BOOL,     "0"),
+  V(CellStatistics,              BOOL,     "0"),
   V(CircuitBuildTimeout,         INTERVAL, "1 minute"),
   V(CircuitIdleTimeout,          INTERVAL, "1 hour"),
   V(ClientDNSRejectInternalAddresses, BOOL,"1"),
@@ -1394,6 +1395,16 @@ options_act(or_options_t *old_options)
   if (options->ExitPortStatistics)
     log_warn(LD_CONFIG, "ExitPortStatistics enabled, but Tor was built "
              "without port statistics support.");
+#endif
+#ifdef ENABLE_BUFFER_STATS
+  if (options->CellStatistics)
+    log_notice(LD_CONFIG, "Configured to measure cell statistics. Look "
+               "for the buffer-stats file that will first be written to "
+               "the data directory in 24 hours from now.");
+#else
+  if (options->CellStatistics)
+    log_warn(LD_CONFIG, "CellStatistics enabled, but Tor was built "
+             "without cell statistics support.");
 #endif
   /* Check if we need to parse and add the EntryNodes config option. */
   if (options->EntryNodes &&

src/or/main.c

@@ -830,6 +830,9 @@ run_scheduled_events(time_t now)
   static time_t time_to_clean_caches = 0;
   static time_t time_to_recheck_bandwidth = 0;
   static time_t time_to_check_for_expired_networkstatus = 0;
+#ifdef ENABLE_BUFFER_STATS
+  static time_t time_to_dump_buffer_stats = 0;
+#endif
   static time_t time_to_retry_dns_init = 0;
   or_options_t *options = get_options();
   int i;
@@ -957,6 +960,14 @@ run_scheduled_events(time_t now)
     time_to_check_for_expired_networkstatus = now + CHECK_EXPIRED_NS_INTERVAL;
   }
 
+#ifdef ENABLE_BUFFER_STATS
+  if (time_to_dump_buffer_stats < now) {
+    if (get_options()->CellStatistics && time_to_dump_buffer_stats)
+      dump_buffer_stats();
+    time_to_dump_buffer_stats = now + DUMP_BUFFER_STATS_INTERVAL;
+  }
+#endif
+
   /* Remove old information from rephist and the rend cache. */
   if (time_to_clean_caches < now) {
     rep_history_clean(now - options->RephistTrackTime);

src/or/or.h

@@ -23,6 +23,9 @@
 #ifndef ENABLE_GEOIP_STATS
 #define ENABLE_GEOIP_STATS 1
 #endif
+#ifndef ENABLE_BUFFER_STATS
+#define ENABLE_BUFFER_STATS 1
+#endif
 #endif
 
 #ifdef MS_WINDOWS
@@ -833,6 +836,9 @@ typedef struct var_cell_t {
 typedef struct packed_cell_t {
   struct packed_cell_t *next; /**< Next cell queued on this circuit. */
   char body[CELL_NETWORK_SIZE]; /**< Cell as packed for network. */
+#ifdef ENABLE_BUFFER_STATS
+  struct timeval packed_timeval; /**< When was this cell packed? */
+#endif
 } packed_cell_t;
 
 /** A queue of cells on a circuit, waiting to be added to the
@@ -2072,6 +2078,17 @@ typedef struct or_circuit_t {
 
   /** True iff this circuit was made with a CREATE_FAST cell. */
   unsigned int is_first_hop : 1;
+
+#ifdef ENABLE_BUFFER_STATS
+  /** Number of cells that were removed from circuit queue; reset every
+   * time when writing buffer stats to disk. */
+  uint32_t processed_cells;
+
+  /** Total time in milliseconds that cells spent in both app-ward and
+   * exit-ward queues of this circuit; reset every time when writing
+   * buffer stats to disk. */
+  uint64_t total_cell_waiting_time;
+#endif
 } or_circuit_t;
 
 /** Convert a circuit subtype to a circuit_t.*/
@@ -2478,6 +2495,9 @@ typedef struct {
   /** If true, the user wants us to collect statistics on port usage. */
   int ExitPortStatistics;
 
+  /** If true, the user wants us to collect cell statistics. */
+  int CellStatistics;
+
   /** If true, do not believe anybody who tells us that a domain resolves
    * to an internal address, or that an internal address has a PTR mapping.
    * Helps avoid some cross-site attacks. */
@@ -4026,6 +4046,12 @@ void hs_usage_note_fetch_successful(const char *service_id, time_t now);
 void hs_usage_write_statistics_to_file(time_t now);
 void hs_usage_free_all(void);
 
+#ifdef ENABLE_BUFFER_STATS
+#define DUMP_BUFFER_STATS_INTERVAL (24*60*60)
+void add_circ_to_buffer_stats(circuit_t *circ, time_t end_of_interval);
+void dump_buffer_stats(void);
+#endif
+
 /********************************* rendclient.c ***************************/
 
 void rend_client_introcirc_has_opened(origin_circuit_t *circ);

src/or/relay.c

@@ -1592,7 +1592,13 @@ cell_queue_append(cell_queue_t *queue, packed_cell_t *cell)
 void
 cell_queue_append_packed_copy(cell_queue_t *queue, const cell_t *cell)
 {
-  cell_queue_append(queue, packed_cell_copy(cell));
+  packed_cell_t *copy = packed_cell_copy(cell);
+#ifdef ENABLE_BUFFER_STATS
+  /* Remember the exact time when this cell was put in the queue. */
+  if (get_options()->CellStatistics)
+    tor_gettimeofday(&copy->packed_timeval);
+#endif
+  cell_queue_append(queue, copy);
 }
 
 /** Remove and free every cell in <b>queue</b>. */
@@ -1801,6 +1807,19 @@ connection_or_flush_from_first_active_circuit(or_connection_t *conn, int max,
     packed_cell_t *cell = cell_queue_pop(queue);
     tor_assert(*next_circ_on_conn_p(circ,conn));
 
+#ifdef ENABLE_BUFFER_STATS
+    /* Calculate the exact time that this cell has spent in the queue. */
+    if (get_options()->CellStatistics && !CIRCUIT_IS_ORIGIN(circ)) {
+      struct timeval flushed_from_queue;
+      uint32_t cell_waiting_time;
+      or_circuit_t *orcirc = TO_OR_CIRCUIT(circ);
+      tor_gettimeofday(&flushed_from_queue);
+      cell_waiting_time = (uint32_t)
+            (tv_udiff(&cell->packed_timeval, &flushed_from_queue) / 1000);
+      orcirc->total_cell_waiting_time += cell_waiting_time;
+      orcirc->processed_cells++;
+    }
+#endif
     connection_write_to_buf(cell->body, CELL_NETWORK_SIZE, TO_CONN(conn));
 
     packed_cell_free(cell);

src/or/rephist.c

@@ -2576,3 +2576,174 @@ hs_usage_write_statistics_to_file(time_t now)
   tor_free(fname);
 }
 
+/*** cell statistics ***/
+
+#ifdef ENABLE_BUFFER_STATS
+/** Start of the current buffer stats interval. */
+time_t start_of_buffer_stats_interval;
+
+typedef struct circ_buffer_stats_t {
+  uint32_t processed_cells;
+  double mean_num_cells_in_queue;
+  double mean_time_cells_in_queue;
+  uint32_t local_circ_id;
+} circ_buffer_stats_t;
+
+/** Holds stats. */
+smartlist_t *circuits_for_buffer_stats = NULL;
+
+/** Remember cell statistics for circuit <b>circ</b> at time
+ * <b>end_of_interval</b> and reset cell counters in case the circuit
+ * remains open in the next measurement interval. */
+void
+add_circ_to_buffer_stats(circuit_t *circ, time_t end_of_interval)
+{
+  circ_buffer_stats_t *stat;
+  time_t start_of_interval;
+  int interval_length;
+  or_circuit_t *orcirc;
+  if (CIRCUIT_IS_ORIGIN(circ))
+    return;
+  orcirc = TO_OR_CIRCUIT(circ);
+  if (!orcirc->processed_cells)
+    return;
+  if (!circuits_for_buffer_stats)
+    circuits_for_buffer_stats = smartlist_create();
+  start_of_interval = circ->timestamp_created >
+      start_of_buffer_stats_interval ?
+        circ->timestamp_created :
+        start_of_buffer_stats_interval;
+  interval_length = (int) (end_of_interval - start_of_interval);
+  stat = tor_malloc_zero(sizeof(circ_buffer_stats_t));
+  stat->processed_cells = orcirc->processed_cells;
+  /* 1000.0 for s -> ms; 2.0 because of app-ward and exit-ward queues */
+  stat->mean_num_cells_in_queue = interval_length == 0 ? 0.0 :
+      (double) orcirc->total_cell_waiting_time /
+      (double) interval_length / 1000.0 / 2.0;
+  stat->mean_time_cells_in_queue =
+      (double) orcirc->total_cell_waiting_time /
+      (double) orcirc->processed_cells;
+  smartlist_add(circuits_for_buffer_stats, stat);
+  orcirc->total_cell_waiting_time = 0;
+  orcirc->processed_cells = 0;
+}
+
+/** Sorting helper: return -1, 1, or 0 based on comparison of two
+ * circ_buffer_stats_t */
+static int
+_buffer_stats_compare_entries(const void **_a, const void **_b)
+{
+  const circ_buffer_stats_t *a = *_a, *b = *_b;
+  if (a->processed_cells < b->processed_cells)
+    return 1;
+  else if (a->processed_cells > b->processed_cells)
+    return -1;
+  else
+    return 0;
+}
+
+/** Append buffer statistics to local file. */
+void
+dump_buffer_stats(void)
+{
+  time_t now = time(NULL);
+  char *filename;
+  char written[ISO_TIME_LEN+1];
+  open_file_t *open_file = NULL;
+  FILE *out;
+#define SHARES 10
+  int processed_cells[SHARES], circs_in_share[SHARES],
+      number_of_circuits, i;
+  double queued_cells[SHARES], time_in_queue[SHARES];
+  smartlist_t *str_build = smartlist_create();
+  char *str = NULL;
+  char buf[32];
+  circuit_t *circ;
+  /* add current circuits to stats */
+  for (circ = _circuit_get_global_list(); circ; circ = circ->next)
+    add_circ_to_buffer_stats(circ, now);
+  /* calculate deciles */
+  memset(processed_cells, 0, SHARES * sizeof(int));
+  memset(circs_in_share, 0, SHARES * sizeof(int));
+  memset(queued_cells, 0, SHARES * sizeof(double));
+  memset(time_in_queue, 0, SHARES * sizeof(double));
+  smartlist_sort(circuits_for_buffer_stats,
+                 _buffer_stats_compare_entries);
+  number_of_circuits = smartlist_len(circuits_for_buffer_stats);
+  i = 0;
+  SMARTLIST_FOREACH_BEGIN(circuits_for_buffer_stats,
+                          circ_buffer_stats_t *, stat)
+  {
+    int share = i++ * SHARES / number_of_circuits;
+    processed_cells[share] += stat->processed_cells;
+    queued_cells[share] += stat->mean_num_cells_in_queue;
+    time_in_queue[share] += stat->mean_time_cells_in_queue;
+    circs_in_share[share]++;
+  }
+  SMARTLIST_FOREACH_END(stat);
+  /* clear buffer stats history */
+  SMARTLIST_FOREACH(circuits_for_buffer_stats, circ_buffer_stats_t *,
+      stat, tor_free(stat));
+  smartlist_clear(circuits_for_buffer_stats);
+  /* write to file */
+  filename = get_datadir_fname("buffer-stats");
+  out = start_writing_to_stdio_file(filename, OPEN_FLAGS_APPEND,
+                                    0600, &open_file);
+  if (!out)
+    goto done;
+  format_iso_time(written, now);
+  if (fprintf(out, "written %s (%d s)\n", written,
+              DUMP_BUFFER_STATS_INTERVAL) < 0)
+    goto done;
+  for (i = 0; i < SHARES; i++) {
+    tor_snprintf(buf, sizeof(buf), "%d", !circs_in_share[i] ? 0 :
+                 processed_cells[i] / circs_in_share[i]);
+    smartlist_add(str_build, tor_strdup(buf));
+  }
+  str = smartlist_join_strings(str_build, ",", 0, NULL);
+  if (fprintf(out, "processed-cells %s\n", str) < 0)
+    goto done;
+  tor_free(str);
+  SMARTLIST_FOREACH(str_build, char *, c, tor_free(c));
+  smartlist_clear(str_build);
+  for (i = 0; i < SHARES; i++) {
+    tor_snprintf(buf, sizeof(buf), "%.2f", circs_in_share[i] == 0 ? 0.0 :
+                 queued_cells[i] / (double) circs_in_share[i]);
+    smartlist_add(str_build, tor_strdup(buf));
+  }
+  str = smartlist_join_strings(str_build, ",", 0, NULL);
+  if (fprintf(out, "queued-cells %s\n", str) < 0)
+    goto done;
+  tor_free(str);
+  SMARTLIST_FOREACH(str_build, char *, c, tor_free(c));
+  smartlist_clear(str_build);
+  for (i = 0; i < SHARES; i++) {
+    tor_snprintf(buf, sizeof(buf), "%.0f", circs_in_share[i] == 0 ? 0.0 :
+                 time_in_queue[i] / (double) circs_in_share[i]);
+    smartlist_add(str_build, tor_strdup(buf));
+  }
+  str = smartlist_join_strings(str_build, ",", 0, NULL);
+  if (fprintf(out, "time-in-queue %s\n", str) < 0)
+    goto done;
+  tor_free(str);
+  SMARTLIST_FOREACH(str_build, char *, c, tor_free(c));
+  smartlist_free(str_build);
+  str_build = NULL;
+  if (fprintf(out, "number-of-circuits-per-share %d\n",
+              (number_of_circuits + SHARES - 1) / SHARES) < 0)
+    goto done;
+  finish_writing_to_file(open_file);
+  open_file = NULL;
+ done:
+  if (open_file)
+    abort_writing_to_file(open_file);
+  tor_free(filename);
+  if (str_build) {
+    SMARTLIST_FOREACH(str_build, char *, c, tor_free(c));
+    smartlist_free(str_build);
+  }
+  tor_free(str);
+#undef SHARES
+}
+#endif
+