From: Ben Pfaff Date: Tue, 24 May 2011 19:23:42 +0000 (-0700) Subject: poll-loop: Automatically log reason for wakeup when CPU usage spikes. X-Git-Url: https://pintos-os.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=959ec62e324d88e47930379d3f0d196119595de9;p=openvswitch 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.) --- 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); } diff --git a/lib/timeval.c b/lib/timeval.c index 099730e8..88a6679e 100644 --- a/lib/timeval.c +++ b/lib/timeval.c @@ -59,8 +59,9 @@ static void refresh_monotonic_if_ticked(void); static time_t time_add(time_t, time_t); static void block_sigalrm(sigset_t *); static void unblock_sigalrm(const sigset_t *); -static void log_poll_interval(long long int last_wakeup, - const struct rusage *last_rusage); +static void log_poll_interval(long long int last_wakeup); +static struct rusage *get_recent_rusage(void); +static void refresh_rusage(void); /* Initializes the timetracking module. * @@ -280,14 +281,13 @@ int time_poll(struct pollfd *pollfds, int n_pollfds, int timeout) { static long long int last_wakeup; - static struct rusage last_rusage; long long int start; sigset_t oldsigs; bool blocked; int retval; time_refresh(); - log_poll_interval(last_wakeup, &last_rusage); + log_poll_interval(last_wakeup); coverage_clear(); start = time_msec(); blocked = false; @@ -318,7 +318,7 @@ time_poll(struct pollfd *pollfds, int n_pollfds, int timeout) unblock_sigalrm(&oldsigs); } last_wakeup = time_msec(); - getrusage(RUSAGE_SELF, &last_rusage); + refresh_rusage(); return retval; } @@ -399,7 +399,7 @@ timeval_diff_msec(const struct timeval *a, const struct timeval *b) } static void -log_poll_interval(long long int last_wakeup, const struct rusage *last_rusage) +log_poll_interval(long long int last_wakeup) { static unsigned int mean_interval; /* In 16ths of a millisecond. */ static unsigned int n_samples; @@ -415,6 +415,7 @@ log_poll_interval(long long int last_wakeup, const struct rusage *last_rusage) /* Warn if we took too much time between polls: at least 50 ms and at least * 8X the mean interval. */ if (n_samples > 10 && interval > mean_interval * 8 && interval > 50 * 16) { + const struct rusage *last_rusage = get_recent_rusage(); struct rusage rusage; getrusage(RUSAGE_SELF, &rusage); @@ -460,3 +461,55 @@ log_poll_interval(long long int last_wakeup, const struct rusage *last_rusage) mean_interval = interval; } } + +/* CPU usage tracking. */ + +struct cpu_usage { + long long int when; /* Time that this sample was taken. */ + unsigned long long int cpu; /* Total user+system CPU usage when sampled. */ +}; + +static struct rusage recent_rusage; +static struct cpu_usage older = { LLONG_MIN, 0 }; +static struct cpu_usage newer = { LLONG_MIN, 0 }; +static int cpu_usage = -1; + +static struct rusage * +get_recent_rusage(void) +{ + return &recent_rusage; +} + +static void +refresh_rusage(void) +{ + long long int now; + + now = time_msec(); + getrusage(RUSAGE_SELF, &recent_rusage); + + if (now >= newer.when + 3 * 1000) { + older = newer; + newer.when = now; + newer.cpu = (timeval_to_msec(&recent_rusage.ru_utime) + + timeval_to_msec(&recent_rusage.ru_stime)); + + if (older.when != LLONG_MIN && newer.cpu > older.cpu) { + unsigned int dividend = newer.cpu - older.cpu; + unsigned int divisor = (newer.when - older.when) / 100; + cpu_usage = divisor > 0 ? dividend / divisor : -1; + } else { + cpu_usage = -1; + } + } +} + +/* Returns an estimate of this process's CPU usage, as a percentage, over the + * past few seconds of wall-clock time. Returns -1 if no estimate is available + * (which will happen if the process has not been running long enough to have + * an estimate, and can happen for other reasons as well). */ +int +get_cpu_usage(void) +{ + return cpu_usage; +} diff --git a/lib/timeval.h b/lib/timeval.h index 303461ad..517524c6 100644 --- a/lib/timeval.h +++ b/lib/timeval.h @@ -62,6 +62,8 @@ long long int timeval_to_msec(const struct timeval *); void xgettimeofday(struct timeval *); +int get_cpu_usage(void); + #ifdef __cplusplus } #endif