[ovs-dev] [PATCH] poll-loop: Automatically log reason for wakeup when CPU usage spikes.
Ethan Jackson
ethan at nicira.com
Mon May 23 21:11:04 UTC 2011
Looks Good.
log_wakeup() has complex enough arguments that it could possibly
benefit from a comment. Especially 'arg' which appears to have two
different meanings depending on 'fd'.
Ethan
On Thu, May 19, 2011 at 10:38, Ben Pfaff <blp at nicira.com> wrote:
> 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.)
> ---
> lib/poll-loop.c | 74 ++++++++++++++++++++++++++++++++++++------------------
> lib/timeval.c | 65 +++++++++++++++++++++++++++++++++++++++++++----
> lib/timeval.h | 2 +
> 3 files changed, 110 insertions(+), 31 deletions(-)
>
> diff --git a/lib/poll-loop.c b/lib/poll-loop.c
> index c944477..1d2a599 100644
> --- a/lib/poll-loop.c
> +++ b/lib/poll-loop.c
> @@ -146,23 +146,55 @@ 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, ...)
> +static void
> +log_wakeup(const char *where, int fd, int arg)
> {
> - 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 (fd < 0) {
> + ds_put_format(&s, "%d-ms timeout", arg);
> + } else {
> + char *description = describe_fd(fd);
> + if (arg & POLLIN) {
> + ds_put_cstr(&s, "[POLLIN]");
> + }
> + if (arg & POLLOUT) {
> + ds_put_cstr(&s, "[POLLOUT]");
> + }
> + if (arg & POLLERR) {
> + ds_put_cstr(&s, "[POLLERR]");
> + }
> + if (arg & POLLHUP) {
> + ds_put_cstr(&s, "[POLLHUP]");
> + }
> + if (arg & POLLNVAL) {
> + ds_put_cstr(&s, "[POLLNVAL]");
> + }
> + ds_put_format(&s, " on fd %d (%s)", fd, description);
> + free(description);
> + }
> 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 +235,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, -1, 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(timeout_where, pw->fd, pw->pollfd->revents);
> }
> poll_cancel(pw);
> }
> diff --git a/lib/timeval.c b/lib/timeval.c
> index 099730e..88a6679 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 303461a..517524c 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
> --
> 1.7.4.4
>
> _______________________________________________
> dev mailing list
> dev at openvswitch.org
> http://openvswitch.org/mailman/listinfo/dev
>
More information about the dev
mailing list