diff options
author | Ben Pfaff <blp@nicira.com> | 2011-05-24 12:23:42 -0700 |
---|---|---|
committer | Ben Pfaff <blp@nicira.com> | 2011-05-24 12:23:42 -0700 |
commit | 959ec62e324d88e47930379d3f0d196119595de9 (patch) | |
tree | 7dd66133666b6fc23ae701e2f2e3baa2b63455b6 /lib/poll-loop.c | |
parent | 3a88e544e07cd5c33b7eddac4e38a892897e5ed6 (diff) |
poll-loop: Automatically log reason for wakeup when CPU usage spikes.
For a long time, the poll-loop module has had the ability to log the reason
for wakeups, which is valuable for debugging excessive use of CPU time.
But I have to ask users to turn up the log level for the module, which
wastes their time and mine. This commit improves the situation by
automatically logging the reason for a wakeup whenever a process's
estimated CPU usage rises above 50%. (ovs-vswitchd often uses less than
1% CPU; more than 5% CPU is uncommon.)
Diffstat (limited to 'lib/poll-loop.c')
-rw-r--r-- | lib/poll-loop.c | 82 |
1 files changed, 58 insertions, 24 deletions
diff --git a/lib/poll-loop.c b/lib/poll-loop.c index c944477d..4e192f3a 100644 --- a/lib/poll-loop.c +++ b/lib/poll-loop.c @@ -146,23 +146,65 @@ poll_immediate_wake(const char *where) poll_timer_wait(0, where); } -static void PRINTF_FORMAT(2, 3) -log_wakeup(const char *where, const char *format, ...) +/* Logs, if appropriate, that the poll loop was awakened by an event + * registered at 'where' (typically a source file and line number). The other + * arguments have two possible interpretations: + * + * - If 'pollfd' is nonnull then it should be the "struct pollfd" that caused + * the wakeup. In this case, 'timeout' is ignored. + * + * - If 'pollfd' is nonnull then 'timeout' is the number of milliseconds + * after which the poll loop woke up. + */ +static void +log_wakeup(const char *where, const struct pollfd *pollfd, int timeout) { - struct ds ds; - va_list args; + static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(120, 120); + enum vlog_level level; + int cpu_usage; + struct ds s; - ds_init(&ds); - va_start(args, format); - ds_put_format_valist(&ds, format, args); - va_end(args); + cpu_usage = get_cpu_usage(); + if (VLOG_IS_DBG_ENABLED()) { + level = VLL_DBG; + } else if (cpu_usage > 50 && !VLOG_DROP_WARN(&rl)) { + level = VLL_WARN; + } else { + return; + } + ds_init(&s); + ds_put_cstr(&s, "wakeup due to "); + if (pollfd) { + char *description = describe_fd(pollfd->fd); + if (pollfd->revents & POLLIN) { + ds_put_cstr(&s, "[POLLIN]"); + } + if (pollfd->revents & POLLOUT) { + ds_put_cstr(&s, "[POLLOUT]"); + } + if (pollfd->revents & POLLERR) { + ds_put_cstr(&s, "[POLLERR]"); + } + if (pollfd->revents & POLLHUP) { + ds_put_cstr(&s, "[POLLHUP]"); + } + if (pollfd->revents & POLLNVAL) { + ds_put_cstr(&s, "[POLLNVAL]"); + } + ds_put_format(&s, " on fd %d (%s)", pollfd->fd, description); + free(description); + } else { + ds_put_format(&s, "%d-ms timeout", timeout); + } if (where) { - ds_put_format(&ds, " at %s", where); + ds_put_format(&s, " at %s", where); } - - VLOG_DBG("%s", ds_cstr(&ds)); - ds_destroy(&ds); + if (cpu_usage >= 0) { + ds_put_format(&s, " (%d%% CPU usage)", cpu_usage); + } + VLOG(level, "%s", ds_cstr(&s)); + ds_destroy(&s); } /* Blocks until one or more of the events registered with poll_fd_wait() @@ -203,21 +245,13 @@ poll_block(void) if (retval < 0) { static struct vlog_rate_limit rl = VLOG_RATE_LIMIT_INIT(1, 5); VLOG_ERR_RL(&rl, "poll: %s", strerror(-retval)); - } else if (!retval && VLOG_IS_DBG_ENABLED()) { - log_wakeup(timeout_where, "%d-ms timeout", timeout); + } else if (!retval) { + log_wakeup(timeout_where, NULL, timeout); } LIST_FOR_EACH_SAFE (pw, next, node, &waiters) { - if (pw->pollfd->revents && VLOG_IS_DBG_ENABLED()) { - char *description = describe_fd(pw->fd); - log_wakeup(pw->where, "%s%s%s%s%s on fd %d (%s)", - pw->pollfd->revents & POLLIN ? "[POLLIN]" : "", - pw->pollfd->revents & POLLOUT ? "[POLLOUT]" : "", - pw->pollfd->revents & POLLERR ? "[POLLERR]" : "", - pw->pollfd->revents & POLLHUP ? "[POLLHUP]" : "", - pw->pollfd->revents & POLLNVAL ? "[POLLNVAL]" : "", - pw->fd, description); - free(description); + if (pw->pollfd->revents) { + log_wakeup(pw->where, pw->pollfd, 0); } poll_cancel(pw); } |