From bf80e2df3fe48f81c69bb68887376b02ab247e5f Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Thu, 18 Dec 2008 17:19:04 +0000 Subject: [PATCH] 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 | 3 +++ doc/TODO.021 | 2 +- src/common/util.c | 33 ++++++++++++++++++++++++++++++++- src/common/util.h | 10 ++++++++++ src/or/connection.c | 17 ++++++++--------- src/or/connection_edge.c | 2 +- src/or/main.c | 4 ++++ src/or/relay.c | 5 ++--- src/or/test.c | 1 + 9 files changed, 62 insertions(+), 15 deletions(-) diff --git a/ChangeLog b/ChangeLog index 933ed102d5..56efc89102 100644 --- a/ChangeLog +++ b/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 diff --git a/doc/TODO.021 b/doc/TODO.021 index b5e766b808..d8aa04084a 100644 --- a/doc/TODO.021 +++ b/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 diff --git a/src/common/util.c b/src/common/util.c index 2cb95a59a9..b00d26cba4 100644 --- a/src/common/util.c +++ b/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 diff --git a/src/common/util.h b/src/common/util.h index e8d78c9847..029cad9e3f 100644 --- a/src/common/util.h +++ b/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); diff --git a/src/or/connection.c b/src/or/connection.c index ca688052fc..23da915560 100644 --- a/src/or/connection.c +++ b/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, time(NULL)); + at_most = connection_bucket_read_limit(conn, approx_time()); } 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 diff --git a/src/or/connection_edge.c b/src/or/connection_edge.c index 3e2a43917e..620db73a62 100644 --- a/src/or/connection_edge.c +++ b/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. */ diff --git a/src/or/main.c b/src/or/main.c index 762e14f801..17cd6d2676 100644 --- a/src/or/main.c +++ b/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 diff --git a/src/or/relay.c b/src/or/relay.c index 2ced83acbd..5dbed49b4c 100644 --- a/src/or/relay.c +++ b/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 = time(NULL); + circ->n_conn->client_used = approx_time(); } 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()); } } diff --git a/src/or/test.c b/src/or/test.c index e621c70068..8b07ee536a 100644 --- a/src/or/test.c +++ b/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();