Replace calls to time(NULL) that occur on the order of once per read, one per write, or once per cell with calls to a function that looks at a cached value of time. This is tricksy to benchmark, since it will only help on systems where time() is a syscall and syscalls are relatively slow.

svn:r17690

ChangeLog

@@ -43,6 +43,9 @@ Changes in version 0.2.1.9-alpha - 2008-12-2?
     - On platforms with a maximum syslog string length, truncate syslog
       messages to that length ourselves, rather than relying on the
       system to do it for us.
+    - Optimize out calls to time(NULL) that occur for every IO operation, or
+      for every cell. On systems where time() is a slow syscalls, this will
+      be slightly helpful.
 
   o Minor features (controller):
     - New CONSENSUS_ARRIVED event to note when a new consensus has

doc/TODO.021

@@ -362,7 +362,7 @@ R   d Do we want to maintain our own set of entryguards that we use as
       "who can change what" in local_routerstatus explicit.  Make
       local_routerstatus (or equivalent) subsume all places to go for "what
       router is this?"
-    - Don't call time(NULL) so much; instead have a static time_t field
+    o Don't call time(NULL) so much; instead have a static time_t field
       that gets updated only a handful of times per second.
     - Refactor unit tests into multiple files
 

src/common/util.c

@@ -1284,9 +1284,40 @@ format_time_interval(char *out, size_t out_len, long interval)
   }
 }
 
+/* =====
+ * Cached time
+ * ===== */
+
+#ifndef TIME_IS_FAST
+/** Cached estimate of the currrent time.  Updated around once per second;
+ * may be a few seconds off if we are really busy.  This is a hack to avoid
+ * calling time(NULL) (which not everybody has optimized) on critical paths.
+ */
+static time_t cached_approx_time = 0;
+
+/** Return a cached estimate of the current time from when
+ * update_approx_time() was last called.  This is a hack to avoid calling
+ * time(NULL) on critical paths: please do not even think of calling it
+ * anywhere else. */
+time_t
+approx_time(void)
+{
+  return cached_approx_time;
+}
+
+/** Update the cached estimate of the current time.  This function SHOULD be
+ * called once per second, and MUST be called before the first call to
+ * get_approx_time. */
+void
+update_approx_time(time_t now)
+{
+  cached_approx_time = now;
+}
+#endif
+
 /* =====
  * Fuzzy time
- * XXXX022 Use this consistently or rip it out.
+ * XXXX022 Use this consistently or rip most of it out.
  * ===== */
 
 /* In a perfect world, everybody would run ntp, and ntp would be perfect, so

src/common/util.h

@@ -213,6 +213,16 @@ void format_iso_time(char *buf, time_t t);
 int parse_iso_time(const char *buf, time_t *t);
 int parse_http_time(const char *buf, struct tm *tm);
 int format_time_interval(char *out, size_t out_len, long interval);
+
+/* Cached time */
+#ifdef TIME_IS_FAST
+#define approx_time() time(NULL)
+#define update_approx_time(t) STMT_NIL
+#else
+time_t approx_time(void);
+void update_approx_time(time_t now);
+#endif
+
 /* Fuzzy time. */
 void ftime_set_maximum_sloppiness(int seconds);
 void ftime_set_estimated_skew(int seconds);

src/or/connection.c

@@ -1724,7 +1724,7 @@ connection_consider_empty_read_buckets(connection_t *conn)
 
   if (global_read_bucket <= 0) {
     reason = "global read bucket exhausted. Pausing.";
-  } else if (connection_counts_as_relayed_traffic(conn, time(NULL)) &&
+  } else if (connection_counts_as_relayed_traffic(conn, approx_time()) &&
              global_relayed_read_bucket <= 0) {
     reason = "global relayed read bucket exhausted. Pausing.";
   } else if (connection_speaks_cells(conn) &&
@@ -1748,7 +1748,7 @@ connection_consider_empty_write_buckets(connection_t *conn)
 
   if (global_write_bucket <= 0) {
     reason = "global write bucket exhausted. Pausing.";
-  } else if (connection_counts_as_relayed_traffic(conn, time(NULL)) &&
+  } else if (connection_counts_as_relayed_traffic(conn, approx_time()) &&
              global_relayed_write_bucket <= 0) {
     reason = "global relayed write bucket exhausted. Pausing.";
 #if 0
@@ -1928,7 +1928,7 @@ connection_handle_read(connection_t *conn)
   if (conn->marked_for_close)
     return 0; /* do nothing */
 
-  conn->timestamp_lastread = time(NULL);
+  conn->timestamp_lastread = approx_time();
 
   switch (conn->type) {
     case CONN_TYPE_OR_LISTENER:
@@ -1994,7 +1994,7 @@ loop_again:
 
     if (n_read) {
       /* Probably a no-op, but hey. */
-      connection_buckets_decrement(linked, time(NULL), 0, n_read);
+      connection_buckets_decrement(linked, approx_time(), 0, n_read);
 
       if (connection_flushed_some(linked) < 0)
         connection_mark_for_close(linked);
@@ -2034,8 +2034,7 @@ connection_read_to_buf(connection_t *conn, int *max_to_read, int *socket_error)
 
   if (at_most == -1) { /* we need to initialize it */
     /* how many bytes are we allowed to read? */
-    /* XXXX021 too many calls to time(). Do they hurt? */
+    at_most = connection_bucket_read_limit(conn, approx_time());
-    at_most = connection_bucket_read_limit(conn, time(NULL));
   }
 
   slack_in_buf = buf_slack(conn->inbuf);
@@ -2155,7 +2154,7 @@ connection_read_to_buf(connection_t *conn, int *max_to_read, int *socket_error)
     edge_conn->n_read += (int)n_read;
   }
 
-  connection_buckets_decrement(conn, time(NULL), n_read, n_written);
+  connection_buckets_decrement(conn, approx_time(), n_read, n_written);
 
   if (more_to_read && result == at_most) {
     slack_in_buf = buf_slack(conn->inbuf);
@@ -2223,7 +2222,7 @@ connection_handle_write(connection_t *conn, int force)
   socklen_t len=(socklen_t)sizeof(e);
   int result;
   ssize_t max_to_write;
-  time_t now = time(NULL);
+  time_t now = approx_time();
   size_t n_read = 0, n_written = 0;
 
   tor_assert(!connection_is_listener(conn));
@@ -2350,7 +2349,7 @@ connection_handle_write(connection_t *conn, int force)
     edge_conn->n_written += (int)n_written;
   }
 
-  connection_buckets_decrement(conn, time(NULL), n_read, n_written);
+  connection_buckets_decrement(conn, approx_time(), n_read, n_written);
 
   if (result > 0) {
     /* If we wrote any bytes from our buffer, then call the appropriate

src/or/connection_edge.c

@@ -2159,7 +2159,7 @@ connection_ap_handshake_send_resolve(edge_connection_t *ap_conn)
     uint32_t a;
     size_t len = strlen(ap_conn->socks_request->address);
     char c = 0;
-    /* XXXX021 This logic is a little ugly: we check for an in-addr.arpa ending
+    /* XXXX This logic is a little ugly: we check for an in-addr.arpa ending
      * on the address.  If we have one, the address is already in the right
      * order, so we'll leave it alone later.  Otherwise, we reverse it and
      * turn it into an in-addr.arpa address. */

src/or/main.c

@@ -1192,6 +1192,7 @@ second_elapsed_callback(int fd, short event, void *args)
 
   /* log_fn(LOG_NOTICE, "Tick."); */
   tor_gettimeofday(&now);
+  update_approx_time(now.tv_sec);
 
   /* the second has rolled over. check more stuff. */
   bytes_written = stats_prev_global_write_bucket - global_write_bucket;
@@ -1461,6 +1462,8 @@ do_main_loop(void)
                       event_active(conn->read_event, EV_READ, 1));
     called_loop_once = smartlist_len(active_linked_connection_lst) ? 1 : 0;
 
+    update_approx_time(time(NULL));
+
     /* poll until we have an event, or the second ends, or until we have
      * some active linked connections to trigger events for. */
     loop_result = event_loop(called_loop_once ? EVLOOP_ONCE : 0);
@@ -2059,6 +2062,7 @@ int
 tor_main(int argc, char *argv[])
 {
   int result = 0;
+  update_approx_time(time(NULL));
   tor_threads_init();
   init_logging();
 #ifdef USE_DMALLOC

src/or/relay.c

@@ -505,8 +505,7 @@ relay_send_command_from_edge(uint16_t stream_id, circuit_t *circ,
 
   if (cell_direction == CELL_DIRECTION_OUT && circ->n_conn) {
     /* if we're using relaybandwidthrate, this conn wants priority */
-    /* XXXX021 the call to time() seems little too frequent */
+    circ->n_conn->client_used = approx_time();
-    circ->n_conn->client_used = time(NULL);
   }
 
   if (cell_direction == CELL_DIRECTION_OUT) {
@@ -1840,7 +1839,7 @@ append_cell_to_circuit_queue(circuit_t *circ, or_connection_t *orconn,
      * get called, and we can start putting more data onto the buffer then.
      */
     log_debug(LD_GENERAL, "Primed a buffer.");
-    connection_or_flush_from_first_active_circuit(orconn, 1, time(NULL));
+    connection_or_flush_from_first_active_circuit(orconn, 1, approx_time());
   }
 }
 

src/or/test.c

@@ -4538,6 +4538,7 @@ main(int c, char**v)
   }
 #endif
 
+  update_approx_time(time(NULL));
   options = options_new();
   tor_threads_init();
   init_logging();