From b0224bf7282f2ec968a46e35a2a8dab1ddaf0667 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Tue, 1 May 2018 10:05:22 -0400 Subject: [PATCH 1/3] Add a mechanism for the logging system to report queued callbacks Sometimes the logging system will queue a log message for later. When it does this, the callback will either get flushed at the next safe time, or from the second-elapsed callback. But we're trying to eliminate the second-elapsed callback, so let's make a way for the log system to tell its users about this. --- src/common/log.c | 25 +++++++++++++++++++++++++ src/common/torlog.h | 2 ++ 2 files changed, 27 insertions(+) diff --git a/src/common/log.c b/src/common/log.c index 922e9dd38..ebd50f62d 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -170,6 +170,9 @@ typedef struct pending_log_message_t { /** Log messages waiting to be replayed onto callback-based logs */ static smartlist_t *pending_cb_messages = NULL; +/** Callback to invoke when pending_cb_messages becomes nonempty. */ +static pending_callback_callback pending_cb_cb = NULL; + /** Log messages waiting to be replayed once the logging system is initialized. */ static smartlist_t *pending_startup_messages = NULL; @@ -538,6 +541,9 @@ logfile_deliver(logfile_t *lf, const char *buf, size_t msg_len, smartlist_add(pending_cb_messages, pending_log_message_new(severity,domain,NULL,msg_after_prefix)); *callbacks_deferred = 1; + if (smartlist_len(pending_cb_messages) == 1 && pending_cb_cb) { + pending_cb_cb(); + } } } else { lf->callback(severity, domain, msg_after_prefix); @@ -825,6 +831,7 @@ logs_free_all(void) logfiles = NULL; messages = pending_cb_messages; pending_cb_messages = NULL; + pending_cb_cb = NULL; messages2 = pending_startup_messages; pending_startup_messages = NULL; UNLOCK_LOGS(); @@ -987,6 +994,24 @@ add_temp_log(int min_severity) UNLOCK_LOGS(); } +/** + * Register "cb" as the callback to call when there are new pending log + * callbacks to be flushed with flush_pending_log_callbacks(). + * + * Note that this callback, if present, can be invoked from any thread. + * + * This callback must not log. + * + * It is intentional that this function contains the name "callback" twice: it + * sets a "callback" to be called on the condition that there is a "pending + * callback". + **/ +void +logs_set_pending_callback_callback(pending_callback_callback cb) +{ + pending_cb_cb = cb; +} + /** * Add a log handler to send messages in severity * to the function cb. diff --git a/src/common/torlog.h b/src/common/torlog.h index ac632ff52..de389883c 100644 --- a/src/common/torlog.h +++ b/src/common/torlog.h @@ -154,6 +154,8 @@ int add_android_log(const log_severity_list_t *severity, const char *android_identity_tag); #endif // HAVE_ANDROID_LOG_H. int add_callback_log(const log_severity_list_t *severity, log_callback cb); +typedef void (*pending_callback_callback)(void); +void logs_set_pending_callback_callback(pending_callback_callback cb); void logs_set_domain_logging(int enabled); int get_min_log_level(void); void switch_logs_debug(void); From 0d8604c76306ea95e7918af67cf268d630aea941 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Tue, 1 May 2018 10:26:04 -0400 Subject: [PATCH 2/3] Give queued_events_flush_all() responsibility for flushing log cbs This requires that when a log cb happens, the event for flushing queued events is scheduled, so we also add the necessary machinery to have that happen. Note that this doesn't actually help with logs from outside the main thread, but those were already suppressed: see #25987 for a ticket tracking that issue. --- src/or/config.c | 1 + src/or/control.c | 22 +++++++++++++++++++++- src/or/control.h | 1 + 3 files changed, 23 insertions(+), 1 deletion(-) diff --git a/src/or/config.c b/src/or/config.c index 54f3930fc..208680060 100644 --- a/src/or/config.c +++ b/src/or/config.c @@ -1547,6 +1547,7 @@ options_act_reversible(const or_options_t *old_options, char **msg) tor_malloc_zero(sizeof(log_severity_list_t)); close_temp_logs(); add_callback_log(severity, control_event_logmsg); + logs_set_pending_callback_callback(control_event_logmsg_pending); control_adjust_event_log_severity(); tor_free(severity); tor_log_update_sigsafe_err_fds(); diff --git a/src/or/control.c b/src/or/control.c index dda887218..7ad9460cc 100644 --- a/src/or/control.c +++ b/src/or/control.c @@ -803,6 +803,9 @@ queued_event_free_(queued_event_t *ev) static void queued_events_flush_all(int force) { + /* Make sure that we get all the pending log events, if there are any. */ + flush_pending_log_callbacks(); + if (PREDICT_UNLIKELY(queued_control_events == NULL)) { return; } @@ -6186,7 +6189,7 @@ control_event_logmsg(int severity, uint32_t domain, const char *msg) int event; /* Don't even think of trying to add stuff to a buffer from a cpuworker - * thread. */ + * thread. (See #25987 for plan to fix.) */ if (! in_main_thread()) return; @@ -6232,6 +6235,23 @@ control_event_logmsg(int severity, uint32_t domain, const char *msg) } } +/** + * Logging callback: called when there is a queued pending log callback. + */ +void +control_event_logmsg_pending(void) +{ + if (! in_main_thread()) { + /* We can't handle this case yet, since we're using a + * mainloop_event_t to invoke queued_events_flush_all. We ought to + * use a different mechanism instead: see #25987. + **/ + return; + } + tor_assert(flush_queued_events_event); + mainloop_event_activate(flush_queued_events_event); +} + /** Called whenever we receive new router descriptors: tell any * interested control connections. routers is a list of * routerinfo_t's. diff --git a/src/or/control.h b/src/or/control.h index 2f312a663..7f8a0bdb5 100644 --- a/src/or/control.h +++ b/src/or/control.h @@ -60,6 +60,7 @@ int control_event_conn_bandwidth(connection_t *conn); int control_event_conn_bandwidth_used(void); int control_event_circuit_cell_stats(void); void control_event_logmsg(int severity, uint32_t domain, const char *msg); +void control_event_logmsg_pending(void); int control_event_descriptors_changed(smartlist_t *routers); int control_event_address_mapped(const char *from, const char *to, time_t expires, const char *error, From 77b7eb2795208ad5c5f66a5626a89b14b03de6f2 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Tue, 1 May 2018 10:38:46 -0400 Subject: [PATCH 3/3] Remove responsibility for flushing log cbs from mainloop This is now handled as-needed as the control module is flushing its own callbacks. Closes ticket 25951. --- changes/ticket25951 | 9 +++++++++ src/or/main.c | 3 --- 2 files changed, 9 insertions(+), 3 deletions(-) create mode 100644 changes/ticket25951 diff --git a/changes/ticket25951 b/changes/ticket25951 new file mode 100644 index 000000000..b6cfc2091 --- /dev/null +++ b/changes/ticket25951 @@ -0,0 +1,9 @@ + o Minor features (mainloop): + - Move responsibility for + flushing log callbacks + from a once-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 + 25951. + diff --git a/src/or/main.c b/src/or/main.c index f1b830830..e68f72d1e 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -1701,9 +1701,6 @@ run_scheduled_events(time_t now) signewnym_impl(now); } - /* 0c. If we've deferred log messages for the controller, handle them now */ - flush_pending_log_callbacks(); - /* Maybe enough time elapsed for us to reconsider a circuit. */ circuit_upgrade_circuits_from_guard_wait();