diff options
| -rw-r--r-- | changes/ticket26009 | 9 | ||||
| -rw-r--r-- | src/or/circuitbuild.c | 30 | ||||
| -rw-r--r-- | src/or/circuitbuild.h | 2 | ||||
| -rw-r--r-- | src/or/connection.c | 3 | ||||
| -rw-r--r-- | src/or/main.c | 90 | ||||
| -rw-r--r-- | src/or/main.h | 2 | ||||
| -rw-r--r-- | src/or/periodic.c | 2 | ||||
| -rw-r--r-- | src/test/include.am | 1 | ||||
| -rw-r--r-- | src/test/test.c | 1 | ||||
| -rw-r--r-- | src/test/test.h | 1 | ||||
| -rw-r--r-- | src/test/test_mainloop.c | 142 |
11 files changed, 255 insertions, 28 deletions
diff --git a/changes/ticket26009 b/changes/ticket26009 new file mode 100644 index 0000000000..51ada15726 --- /dev/null +++ b/changes/ticket26009 @@ -0,0 +1,9 @@ + o Minor features (mainloop): + - Move responsibility for + keeping track of Tor's uptime + from a nce-per-second callback to a callback that is only scheduled as + needed. Once enough items are removed from our once-per-second + callback, we can eliminate it entirely to conserve CPU when idle. + Closes ticket + 26009. + diff --git a/src/or/circuitbuild.c b/src/or/circuitbuild.c index 6881e0ebb8..09102d0c4c 100644 --- a/src/or/circuitbuild.c +++ b/src/or/circuitbuild.c @@ -1130,19 +1130,29 @@ circuit_send_intermediate_onion_skin(origin_circuit_t *circ, return 0; } -/** Our clock just jumped by <b>seconds_elapsed</b>. Assume - * something has also gone wrong with our network: notify the user, - * and abandon all not-yet-used circuits. */ +/** Our clock just jumped by <b>seconds_elapsed</b>. If <b>was_idle</b> is + * true, then the monotonic time matches; otherwise it doesn't. Assume + * something has also gone wrong with our network: notify the user, and + * abandon all not-yet-used circuits. */ void -circuit_note_clock_jumped(int seconds_elapsed) +circuit_note_clock_jumped(int64_t seconds_elapsed, bool was_idle) { int severity = server_mode(get_options()) ? LOG_WARN : LOG_NOTICE; - tor_log(severity, LD_GENERAL, "Your system clock just jumped %d seconds %s; " - "assuming established circuits no longer work.", - seconds_elapsed >=0 ? seconds_elapsed : -seconds_elapsed, - seconds_elapsed >=0 ? "forward" : "backward"); - control_event_general_status(LOG_WARN, "CLOCK_JUMPED TIME=%d", - seconds_elapsed); + if (was_idle) { + tor_log(severity, LD_GENERAL, "Tor has been idle for "I64_FORMAT + " seconds; assuming established circuits no longer work.", + I64_PRINTF_ARG(seconds_elapsed)); + } else { + tor_log(severity, LD_GENERAL, + "Your system clock just jumped "I64_FORMAT" seconds %s; " + "assuming established circuits no longer work.", + I64_PRINTF_ARG( + seconds_elapsed >=0 ? seconds_elapsed : -seconds_elapsed), + seconds_elapsed >=0 ? "forward" : "backward"); + } + control_event_general_status(LOG_WARN, "CLOCK_JUMPED TIME="I64_FORMAT + " IDLE=%d", + I64_PRINTF_ARG(seconds_elapsed), was_idle?1:0); /* so we log when it works again */ note_that_we_maybe_cant_complete_circuits(); control_event_client_status(severity, "CIRCUIT_NOT_ESTABLISHED REASON=%s", diff --git a/src/or/circuitbuild.h b/src/or/circuitbuild.h index ae4aef768a..0184898e29 100644 --- a/src/or/circuitbuild.h +++ b/src/or/circuitbuild.h @@ -29,7 +29,7 @@ void circuit_n_chan_done(channel_t *chan, int status, int inform_testing_reachability(void); int circuit_timeout_want_to_count_circ(const origin_circuit_t *circ); int circuit_send_next_onion_skin(origin_circuit_t *circ); -void circuit_note_clock_jumped(int seconds_elapsed); +void circuit_note_clock_jumped(int64_t seconds_elapsed, bool was_idle); int circuit_extend(cell_t *cell, circuit_t *circ); int circuit_init_cpath_crypto(crypt_path_t *cpath, const char *key_data, size_t key_data_len, diff --git a/src/or/connection.c b/src/or/connection.c index 4361e1ca0c..1b15260801 100644 --- a/src/or/connection.c +++ b/src/or/connection.c @@ -3440,7 +3440,7 @@ int connection_handle_read(connection_t *conn) { int res; - + update_current_time(time(NULL)); res = connection_handle_read_impl(conn); return res; } @@ -3983,6 +3983,7 @@ int connection_handle_write(connection_t *conn, int force) { int res; + update_current_time(time(NULL)); conn->in_connection_handle_write = 1; res = connection_handle_write_impl(conn, force); conn->in_connection_handle_write = 0; diff --git a/src/or/main.c b/src/or/main.c index c3505a2d91..2497c277a2 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -2497,8 +2497,71 @@ hs_service_callback(time_t now, const or_options_t *options) static periodic_timer_t *second_timer = NULL; /** Number of libevent errors in the last second: we die if we get too many. */ static int n_libevent_errors = 0; -/** Last time that second_elapsed_callback was called. */ + +/** Last time that update_current_time was called. */ static time_t current_second = 0; +/** Last time that update_current_time updated current_second. */ +static monotime_coarse_t current_second_last_changed; + +/** + * Set the current time to "now", which should be the value returned by + * time(). Check for clock jumps and track the total number of seconds we + * have been running. + */ +void +update_current_time(time_t now) +{ + if (PREDICT_LIKELY(now == current_second)) { + /* We call this function a lot. Most frequently, the current second + * will not have changed, so we just return. */ + return; + } + + const time_t seconds_elapsed = current_second ? (now - current_second) : 0; + + /* Check the wall clock against the monotonic clock, so we can + * better tell idleness from clock jumps and/or other shenanigans. */ + monotime_coarse_t last_updated; + memcpy(&last_updated, ¤t_second_last_changed, sizeof(last_updated)); + monotime_coarse_get(¤t_second_last_changed); + + /** How much clock jumping do we tolerate? */ +#define NUM_JUMPED_SECONDS_BEFORE_WARN 100 + + /** How much idleness do we tolerate? */ +#define NUM_IDLE_SECONDS_BEFORE_WARN 3600 + + if (seconds_elapsed < -NUM_JUMPED_SECONDS_BEFORE_WARN) { + // moving back in time is always a bad sign. + circuit_note_clock_jumped(seconds_elapsed, false); + } else if (seconds_elapsed >= NUM_JUMPED_SECONDS_BEFORE_WARN) { + /* Compare the monotonic clock to the result of time(). */ + const int32_t monotime_msec_passed = + monotime_coarse_diff_msec32(&last_updated, + ¤t_second_last_changed); + const int monotime_sec_passed = monotime_msec_passed / 1000; + const int discrepancy = monotime_sec_passed - (int)seconds_elapsed; + /* If the monotonic clock deviates from time(NULL), we have a couple of + * possibilities. On some systems, this means we have been suspended or + * sleeping. Everywhere, it can mean that the wall-clock time has + * been changed -- for example, with settimeofday(). + * + * On the other hand, if the monotonic time matches with the wall-clock + * time, we've probably just been idle for a while, with no events firing. + * we tolerate much more of that. + */ + const bool clock_jumped = abs(discrepancy) > 2; + + if (clock_jumped || seconds_elapsed >= NUM_IDLE_SECONDS_BEFORE_WARN) { + circuit_note_clock_jumped(seconds_elapsed, ! clock_jumped); + } + } else if (seconds_elapsed > 0) { + stats_n_seconds_working += seconds_elapsed; + } + + update_approx_time(now); + current_second = now; +} /** Libevent callback: invoked once every second. */ static void @@ -2510,18 +2573,21 @@ second_elapsed_callback(periodic_timer_t *timer, void *arg) time_t now; size_t bytes_written; size_t bytes_read; - int seconds_elapsed; (void)timer; (void)arg; n_libevent_errors = 0; - /* log_notice(LD_GENERAL, "Tick."); */ now = time(NULL); - update_approx_time(now); + + /* We don't need to do this once-per-second any more: time-updating is + * only in this callback _because it is a callback_. It should be fine + * to disable this callback, and the time will still get updated. + */ + update_current_time(now); /* the second has rolled over. check more stuff. */ - seconds_elapsed = current_second ? (int)(now - current_second) : 0; + // remove this once it's unneeded bytes_read = (size_t)(stats_n_bytes_read - stats_prev_n_read); bytes_written = (size_t)(stats_n_bytes_written - stats_prev_n_written); stats_prev_n_read = stats_n_bytes_read; @@ -2533,18 +2599,7 @@ second_elapsed_callback(periodic_timer_t *timer, void *arg) control_event_circ_bandwidth_used(); control_event_circuit_cell_stats(); -/** If more than this many seconds have elapsed, probably the clock - * jumped: doesn't count. */ -#define NUM_JUMPED_SECONDS_BEFORE_WARN 100 - if (seconds_elapsed < -NUM_JUMPED_SECONDS_BEFORE_WARN || - seconds_elapsed >= NUM_JUMPED_SECONDS_BEFORE_WARN) { - circuit_note_clock_jumped(seconds_elapsed); - } else if (seconds_elapsed > 0) - stats_n_seconds_working += seconds_elapsed; - run_scheduled_events(now); - - current_second = now; /* remember which second it is, for next time */ } #ifdef HAVE_SYSTEMD_209 @@ -3029,6 +3084,7 @@ signal_callback(evutil_socket_t fd, short events, void *arg) (void)fd; (void)events; + update_current_time(time(NULL)); process_signal(sig); } @@ -3667,6 +3723,8 @@ tor_free_all(int postfork) heartbeat_callback_first_time = 1; n_libevent_errors = 0; current_second = 0; + memset(¤t_second_last_changed, 0, + sizeof(current_second_last_changed)); if (!postfork) { release_lockfile(); diff --git a/src/or/main.h b/src/or/main.h index a312b51e05..45d6b4478f 100644 --- a/src/or/main.h +++ b/src/or/main.h @@ -66,6 +66,8 @@ void reschedule_dirvote(const or_options_t *options); void mainloop_schedule_postloop_cleanup(void); void rescan_periodic_events(const or_options_t *options); +void update_current_time(time_t now); + MOCK_DECL(long,get_uptime,(void)); MOCK_DECL(void,reset_uptime,(void)); diff --git a/src/or/periodic.c b/src/or/periodic.c index 76aa418b35..92fa677f8f 100644 --- a/src/or/periodic.c +++ b/src/or/periodic.c @@ -14,6 +14,7 @@ #include "or.h" #include "compat_libevent.h" #include "config.h" +#include "main.h" #include "periodic.h" /** We disable any interval greater than this number of seconds, on the @@ -48,6 +49,7 @@ periodic_event_dispatch(mainloop_event_t *ev, void *data) } time_t now = time(NULL); + update_current_time(now); const or_options_t *options = get_options(); // log_debug(LD_GENERAL, "Dispatching %s", event->name); int r = event->fn(now, options); diff --git a/src/test/include.am b/src/test/include.am index 43eaf1e239..9543635c84 100644 --- a/src/test/include.am +++ b/src/test/include.am @@ -139,6 +139,7 @@ src_test_test_SOURCES = \ src/test/test_keypin.c \ src/test/test_link_handshake.c \ src/test/test_logging.c \ + src/test/test_mainloop.c \ src/test/test_microdesc.c \ src/test/test_nodelist.c \ src/test/test_oom.c \ diff --git a/src/test/test.c b/src/test/test.c index 0ad33ec0c0..f0e8b9b728 100644 --- a/src/test/test.c +++ b/src/test/test.c @@ -880,6 +880,7 @@ struct testgroup_t testgroups[] = { { "introduce/", introduce_tests }, { "keypin/", keypin_tests }, { "link-handshake/", link_handshake_tests }, + { "mainloop/", mainloop_tests }, { "nodelist/", nodelist_tests }, { "oom/", oom_tests }, { "oos/", oos_tests }, diff --git a/src/test/test.h b/src/test/test.h index 0cd0304629..3095d54e33 100644 --- a/src/test/test.h +++ b/src/test/test.h @@ -234,6 +234,7 @@ extern struct testcase_t introduce_tests[]; extern struct testcase_t keypin_tests[]; extern struct testcase_t link_handshake_tests[]; extern struct testcase_t logging_tests[]; +extern struct testcase_t mainloop_tests[]; extern struct testcase_t microdesc_tests[]; extern struct testcase_t nodelist_tests[]; extern struct testcase_t oom_tests[]; diff --git a/src/test/test_mainloop.c b/src/test/test_mainloop.c new file mode 100644 index 0000000000..9da8a039dd --- /dev/null +++ b/src/test/test_mainloop.c @@ -0,0 +1,142 @@ +/* Copyright (c) 2018, The Tor Project, Inc. */ +/* See LICENSE for licensing information */ + +/** + * \file test_mainloop.c + * \brief Tests for functions closely related to the Tor main loop + */ + +#include "test.h" +#include "log_test_helpers.h" + +#include "or.h" +#include "main.h" + +static const uint64_t BILLION = 1000000000; + +static void +test_mainloop_update_time_normal(void *arg) +{ + (void)arg; + + monotime_enable_test_mocking(); + /* This is arbitrary */ + uint64_t mt_now = U64_LITERAL(7493289274986); + /* This time is in the past as of when this test was written. */ + time_t now = 1525272090; + monotime_coarse_set_mock_time_nsec(mt_now); + reset_uptime(); + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 0); + + update_current_time(now); // Same time as before is a no-op. + tt_int_op(get_uptime(), OP_EQ, 0); + + now += 1; + mt_now += BILLION; + monotime_coarse_set_mock_time_nsec(mt_now); + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 1); + + now += 2; // two-second jump is unremarkable. + mt_now += 2*BILLION; + update_current_time(now); + monotime_coarse_set_mock_time_nsec(mt_now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 3); + + now -= 1; // a one-second hop backwards is also unremarkable. + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); // it changes the approx time... + tt_int_op(get_uptime(), OP_EQ, 3); // but it doesn't roll back our uptime + + done: + monotime_disable_test_mocking(); +} + +static void +test_mainloop_update_time_jumps(void *arg) +{ + (void)arg; + + monotime_enable_test_mocking(); + /* This is arbitrary */ + uint64_t mt_now = U64_LITERAL(7493289274986); + /* This time is in the past as of when this test was written. */ + time_t now = 220897152; + monotime_coarse_set_mock_time_nsec(mt_now); + reset_uptime(); + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 0); + + /* Put some uptime on the clock.. */ + now += 3; + mt_now += 3*BILLION; + monotime_coarse_set_mock_time_nsec(mt_now); + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 3); + + /* Now try jumping forward and backward, without updating the monotonic + * clock. */ + setup_capture_of_logs(LOG_NOTICE); + now += 1800; + update_current_time(now); + expect_single_log_msg_containing( + "Your system clock just jumped 1800 seconds forward"); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 3); // no uptime change. + mock_clean_saved_logs(); + + now -= 600; + update_current_time(now); + expect_single_log_msg_containing( + "Your system clock just jumped 600 seconds backward"); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 3); // no uptime change. + mock_clean_saved_logs(); + + /* uptime tracking should go normally now if the clock moves sensibly. */ + now += 2; + mt_now += 2*BILLION; + update_current_time(now); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 5); + + /* If we skip forward by a few minutes but the monotonic clock agrees, + * we've just been idle: that counts as not worth warning about. */ + now += 1800; + mt_now += 1800*BILLION; + monotime_coarse_set_mock_time_nsec(mt_now); + update_current_time(now); + expect_no_log_entry(); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 5); // this doesn't count to uptime, though. + + /* If we skip forward by a long time, even if the clock agrees, it's + * idnless that counts. */ + now += 4000; + mt_now += 4000*BILLION; + monotime_coarse_set_mock_time_nsec(mt_now); + update_current_time(now); + expect_single_log_msg_containing("Tor has been idle for 4000 seconds"); + tt_int_op(approx_time(), OP_EQ, now); + tt_int_op(get_uptime(), OP_EQ, 5); + + done: + teardown_capture_of_logs(); + monotime_disable_test_mocking(); +} + +#define MAINLOOP_TEST(name) \ + { #name, test_mainloop_## name , TT_FORK, NULL, NULL } + +struct testcase_t mainloop_tests[] = { + MAINLOOP_TEST(update_time_normal), + MAINLOOP_TEST(update_time_jumps), + END_OF_TESTCASES +}; + |