summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorajs <ajs>2005-04-28 01:31:13 +0000
committerajs <ajs>2005-04-28 01:31:13 +0000
commit8b70d0b04f6bba2f30827d71084dd74fd00808b3 (patch)
tree245969be7b29246bcb5ca39fc6661f0aeea7dd75
parent3df537822f594ffefe4d5e121c0b2430c9c12806 (diff)
2005-04-27 Andrew J. Schorr <ajschorr@alumni.princeton.edu>
Add wall-clock timing statistics to 'show thread cpu' output. * thread.h: Define struct rusage_t to contain wall-clock time and cpu time. Change GETRUSAGE macro to collect both pieces of data. Make appropriate changes to struct cpu_thread_history to track CPU time and real time. Change proto for thread_consumed_time to return real and cpu time elapsed. And declare a new global variable 'struct timeval recent_time'. * thread.c (struct timeval recent_time): New global timestamp variable. (timeval_adjust): If timeout is negative, set to 0 (not 10 microseconds). And remove upper bound of 1,000,000 seconds, since this does not seem to make any sense (and it breaks funcname_thread_add_timer_timeval). (timeval_cmp): Should return long, not int. (vty_out_cpu_thread_history): Show CPU time and real time. (cpu_record_hash_print): Calculate totals for CPU and real time. (cpu_record_print): Change 'show thread cpu' title to show CPU and real time. (thread_timer_remain_second): Put current time in global recent_time. (funcname_thread_add_timer_timeval): Fix assert. Replace 2-case switch assignment with a ternary expression. Use global recent_time variable. Fix use of timeval_adjust (previously, the value was not actually being adjusted). (thread_cancel): Add missing "break" statement in case THREAD_BACKGROUND. (thread_timer_wait): Use global recent_time value instead of calling gettimeofday. And there's no need to check for negative timeouts, since timeval_subtract already sets these to zero. (thread_timer_process): Timers are sorted, so bail out once we encounter a timer that has not yet popped. And remove some extraneous asserts. (thread_fetch): Do not process foreground timers before calling select. Instead, add them to the ready list just after the select. Also, no need to maintain a count of the number of ready threads, since we don't care how many there are, just whether there's one at the head of the ready list (which is easily checked). Stick current time in global variable recent_time to reduce the number of calls to gettimeofday. Tighten logic for calculating the select timeout. (thread_consumed_time): Now returns real time and puts the elapsed cpu time in an additional argument. (thread_should_yield): Use real (wall-clock) time to decide whether to yield. (thread_call): Maintain CPU and real time statistics. * vty.c (vty_command): For slow commands, show real and cpu time.
-rw-r--r--lib/ChangeLog47
-rw-r--r--lib/thread.c239
-rw-r--r--lib/thread.h38
-rw-r--r--lib/vty.c8
4 files changed, 199 insertions, 133 deletions
diff --git a/lib/ChangeLog b/lib/ChangeLog
index 65abfd03..8da9870e 100644
--- a/lib/ChangeLog
+++ b/lib/ChangeLog
@@ -1,5 +1,52 @@
2005-04-27 Andrew J. Schorr <ajschorr@alumni.princeton.edu>
+ Add wall-clock timing statistics to 'show thread cpu' output.
+ * thread.h: Define struct rusage_t to contain wall-clock time
+ and cpu time. Change GETRUSAGE macro to collect both pieces
+ of data. Make appropriate changes to struct cpu_thread_history
+ to track CPU time and real time. Change proto for
+ thread_consumed_time to return real and cpu time elapsed.
+ And declare a new global variable 'struct timeval recent_time'.
+ * thread.c (struct timeval recent_time): New global timestamp variable.
+ (timeval_adjust): If timeout is negative, set to 0 (not 10
+ microseconds). And remove upper bound of 1,000,000 seconds, since
+ this does not seem to make any sense (and it breaks
+ funcname_thread_add_timer_timeval).
+ (timeval_cmp): Should return long, not int.
+ (vty_out_cpu_thread_history): Show CPU time and real time.
+ (cpu_record_hash_print): Calculate totals for CPU and real time.
+ (cpu_record_print): Change 'show thread cpu' title to show CPU and
+ real time.
+ (thread_timer_remain_second): Put current time in global recent_time.
+ (funcname_thread_add_timer_timeval): Fix assert. Replace 2-case
+ switch assignment with a ternary expression. Use global recent_time
+ variable. Fix use of timeval_adjust (previously, the value was not
+ actually being adjusted).
+ (thread_cancel): Add missing "break" statement in case
+ THREAD_BACKGROUND.
+ (thread_timer_wait): Use global recent_time value instead of calling
+ gettimeofday. And there's no need to check for negative timeouts,
+ since timeval_subtract already sets these to zero.
+ (thread_timer_process): Timers are sorted, so bail out once we
+ encounter a timer that has not yet popped. And remove some
+ extraneous asserts.
+ (thread_fetch): Do not process foreground timers before calling
+ select. Instead, add them to the ready list just after the select.
+ Also, no need to maintain a count of the number of ready threads,
+ since we don't care how many there are, just whether there's
+ one at the head of the ready list (which is easily checked).
+ Stick current time in global variable recent_time to reduce
+ the number of calls to gettimeofday. Tighten logic for
+ calculating the select timeout.
+ (thread_consumed_time): Now returns real time and puts the elapsed
+ cpu time in an additional argument.
+ (thread_should_yield): Use real (wall-clock) time to decide whether
+ to yield.
+ (thread_call): Maintain CPU and real time statistics.
+ * vty.c (vty_command): For slow commands, show real and cpu time.
+
+2005-04-27 Andrew J. Schorr <ajschorr@alumni.princeton.edu>
+
* workqueue.c (show_work_queues): Remove unused gettimeofday call.
2005-04-27 Paul Jakma <paul.jakma@sun.com>
diff --git a/lib/thread.c b/lib/thread.c
index 96ec50d0..2e1dd245 100644
--- a/lib/thread.c
+++ b/lib/thread.c
@@ -30,11 +30,14 @@
#include "command.h"
#include "sigevent.h"
+struct timeval recent_time;
static struct hash *cpu_record = NULL;
/* Struct timeval's tv_usec one second value. */
#define TIMER_SECOND_MICRO 1000000L
+/* Adjust so that tv_usec is in the range [0,TIMER_SECOND_MICRO).
+ And change negative values to 0. */
static struct timeval
timeval_adjust (struct timeval a)
{
@@ -51,13 +54,8 @@ timeval_adjust (struct timeval a)
}
if (a.tv_sec < 0)
- {
- a.tv_sec = 0;
- a.tv_usec = 10;
- }
-
- if (a.tv_sec > TIMER_SECOND_MICRO)
- a.tv_sec = TIMER_SECOND_MICRO;
+ /* Change negative timeouts to 0. */
+ a.tv_sec = a.tv_usec = 0;
return a;
}
@@ -73,7 +71,7 @@ timeval_subtract (struct timeval a, struct timeval b)
return timeval_adjust (ret);
}
-static int
+static long
timeval_cmp (struct timeval a, struct timeval b)
{
return (a.tv_sec == b.tv_sec
@@ -114,9 +112,17 @@ static inline void
vty_out_cpu_thread_history(struct vty* vty,
struct cpu_thread_history *a)
{
- vty_out(vty, " %7ld.%03ld %9d %8ld %10ld %c%c%c%c%c%c %s%s",
- a->total/1000, a->total%1000, a->total_calls,
- a->total/a->total_calls, a->max,
+#ifdef HAVE_RUSAGE
+ vty_out(vty, "%7ld.%03ld %9d %8ld %9ld %8ld %9ld",
+ a->cpu.total/1000, a->cpu.total%1000, a->total_calls,
+ a->cpu.total/a->total_calls, a->cpu.max,
+ a->real.total/a->total_calls, a->real.max);
+#else
+ vty_out(vty, "%7ld.%03ld %9d %8ld %9ld",
+ a->real.total/1000, a->real.total%1000, a->total_calls,
+ a->real.total/a->total_calls, a->real.max);
+#endif
+ vty_out(vty, " %c%c%c%c%c%c %s%s",
a->types & (1 << THREAD_READ) ? 'R':' ',
a->types & (1 << THREAD_WRITE) ? 'W':' ',
a->types & (1 << THREAD_TIMER) ? 'T':' ',
@@ -139,10 +145,15 @@ cpu_record_hash_print(struct hash_backet *bucket,
if ( !(a->types & *filter) )
return;
vty_out_cpu_thread_history(vty,a);
- totals->total += a->total;
totals->total_calls += a->total_calls;
- if (totals->max < a->max)
- totals->max = a->max;
+ totals->real.total += a->real.total;
+ if (totals->real.max < a->real.max)
+ totals->real.max = a->real.max;
+#ifdef HAVE_RUSAGE
+ totals->cpu.total += a->cpu.total;
+ if (totals->cpu.max < a->cpu.max)
+ totals->cpu.max = a->cpu.max;
+#endif
}
static void
@@ -155,9 +166,15 @@ cpu_record_print(struct vty *vty, unsigned char filter)
tmp.funcname = "TOTAL";
tmp.types = filter;
- vty_out(vty,
- " Runtime(ms) Invoked Avg uSecs Max uSecs Type Thread%s",
- VTY_NEWLINE);
+#ifdef HAVE_RUSAGE
+ vty_out(vty, "%21s %18s %18s%s",
+ "", "CPU (user+system):", "Real (wall-clock):", VTY_NEWLINE);
+#endif
+ vty_out(vty, "Runtime(ms) Invoked Avg uSec Max uSecs");
+#ifdef HAVE_RUSAGE
+ vty_out(vty, " Avg uSec Max uSecs");
+#endif
+ vty_out(vty, " Type Thread%s", VTY_NEWLINE);
hash_iterate(cpu_record,
(void(*)(struct hash_backet*,void*))cpu_record_hash_print,
args);
@@ -378,12 +395,10 @@ thread_empty (struct thread_list *list)
unsigned long
thread_timer_remain_second (struct thread *thread)
{
- struct timeval timer_now;
+ gettimeofday (&recent_time, NULL);
- gettimeofday (&timer_now, NULL);
-
- if (thread->u.sands.tv_sec - timer_now.tv_sec > 0)
- return thread->u.sands.tv_sec - timer_now.tv_sec;
+ if (thread->u.sands.tv_sec - recent_time.tv_sec > 0)
+ return thread->u.sands.tv_sec - recent_time.tv_sec;
else
return 0;
}
@@ -499,35 +514,23 @@ funcname_thread_add_timer_timeval (struct thread_master *m,
const char* funcname)
{
struct thread *thread;
- struct timeval timer_now;
+ struct timeval alarm_time;
struct thread_list *list;
struct thread *tt;
assert (m != NULL);
- assert (type == THREAD_TIMER || THREAD_BACKGROUND);
+ assert (type == THREAD_TIMER || type == THREAD_BACKGROUND);
assert (time_relative);
- switch (type)
- {
- case THREAD_TIMER:
- list = &m->timer;
- break;
- case THREAD_BACKGROUND:
- list = &m->background;
- break;
- default:
- return NULL;
- }
-
+ list = ((type == THREAD_TIMER) ? &m->timer : &m->background);
thread = thread_get (m, type, func, arg, funcname);
/* Do we need jitter here? */
- gettimeofday (&timer_now, NULL);
- timer_now.tv_sec += time_relative->tv_sec;
- timer_now.tv_usec += time_relative->tv_usec;
- timeval_adjust (timer_now);
- thread->u.sands = timer_now;
+ gettimeofday (&recent_time, NULL);
+ alarm_time.tv_sec = recent_time.tv_sec + time_relative->tv_sec;
+ alarm_time.tv_usec = recent_time.tv_usec + time_relative->tv_usec;
+ thread->u.sands = timeval_adjust(alarm_time);
/* Sort by timeval. */
for (tt = list->head; tt; tt = tt->next)
@@ -648,6 +651,7 @@ thread_cancel (struct thread *thread)
break;
case THREAD_BACKGROUND:
list = &thread->master->background;
+ break;
default:
return;
break;
@@ -683,20 +687,9 @@ thread_cancel_event (struct thread_master *m, void *arg)
static struct timeval *
thread_timer_wait (struct thread_list *tlist, struct timeval *timer_val)
{
- struct timeval timer_now;
- struct timeval timer_min;
-
if (tlist->head)
{
- gettimeofday (&timer_now, NULL);
- timer_min = tlist->head->u.sands;
- timer_min = timeval_subtract (timer_min, timer_now);
- if (timer_min.tv_sec < 0)
- {
- timer_min.tv_sec = 0;
- timer_min.tv_usec = 10;
- }
- *timer_val = timer_min;
+ *timer_val = timeval_subtract (tlist->head->u.sands, recent_time);
return timer_val;
}
return NULL;
@@ -738,25 +731,22 @@ thread_process_fd (struct thread_list *list, fd_set *fdset, fd_set *mfdset)
return ready;
}
-/* fetch next timer-like thread thread from the list and return it */
+/* Add all timers that have popped to the ready list. */
static unsigned int
thread_timer_process (struct thread_list *list, struct timeval *timenow)
{
struct thread *thread;
unsigned int ready = 0;
- assert (list && timenow);
-
for (thread = list->head; thread; thread = thread->next)
- if (timeval_cmp (*timenow, thread->u.sands) >= 0)
- {
- thread_list_delete (list, thread);
- assert (thread->next == thread->prev && thread->next == NULL);
- thread->next = thread->prev = NULL;
- thread->type = THREAD_READY;
- thread_list_add (&thread->master->ready, thread);
- ready++;
- }
+ {
+ if (timeval_cmp (*timenow, thread->u.sands) < 0)
+ return ready;
+ thread_list_delete (list, thread);
+ thread->type = THREAD_READY;
+ thread_list_add (&thread->master->ready, thread);
+ ready++;
+ }
return ready;
}
@@ -768,7 +758,6 @@ thread_fetch (struct thread_master *m, struct thread *fetch)
fd_set readfd;
fd_set writefd;
fd_set exceptfd;
- struct timeval timer_now;
struct timeval timer_val;
struct timeval timer_val_bg;
struct timeval *timer_wait;
@@ -777,7 +766,6 @@ thread_fetch (struct thread_master *m, struct thread *fetch)
while (1)
{
int num = 0;
- int ready = m->ready.count;
/* Signals are highest priority */
quagga_sigevent_process ();
@@ -786,12 +774,6 @@ thread_fetch (struct thread_master *m, struct thread *fetch)
if ((thread = thread_trim_head (&m->event)) != NULL)
return thread_run (m, thread, fetch);
- /* Execute timer. */
- gettimeofday (&timer_now, NULL);
-
- /* Timer threads */
- ready += thread_timer_process (&m->timer, &timer_now);
-
/* If there are any ready threads from previous scheduler runs,
* process top of them.
*/
@@ -804,22 +786,13 @@ thread_fetch (struct thread_master *m, struct thread *fetch)
exceptfd = m->exceptfd;
/* Calculate select wait timer if nothing else to do */
- if (ready == 0)
- {
- timer_wait = thread_timer_wait (&m->timer, &timer_val);
- timer_wait_bg = thread_timer_wait (&m->background, &timer_val_bg);
-
- if (timer_wait && timer_wait_bg &&
- (timeval_cmp (*timer_wait, *timer_wait_bg) > 0))
- timer_wait = timer_wait_bg;
- else if (!timer_wait && timer_wait_bg)
- timer_wait = timer_wait_bg;
- }
- else
- {
- timer_val.tv_sec = timer_val.tv_usec = 0;
- timer_wait = &timer_val;
- }
+ gettimeofday (&recent_time, NULL);
+ timer_wait = thread_timer_wait (&m->timer, &timer_val);
+ timer_wait_bg = thread_timer_wait (&m->background, &timer_val_bg);
+
+ if (timer_wait_bg &&
+ (!timer_wait || (timeval_cmp (*timer_wait, *timer_wait_bg) > 0)))
+ timer_wait = timer_wait_bg;
num = select (FD_SETSIZE, &readfd, &writefd, &exceptfd, timer_wait);
@@ -831,61 +804,76 @@ thread_fetch (struct thread_master *m, struct thread *fetch)
zlog_warn ("select() error: %s", safe_strerror (errno));
return NULL;
}
+
+ /* Check foreground timers. Historically, they have had higher
+ priority than I/O threads, so let's push them onto the ready
+ list in front of the I/O threads. */
+ gettimeofday (&recent_time, NULL);
+ thread_timer_process (&m->timer, &recent_time);
/* Got IO, process it */
if (num > 0)
{
/* Normal priority read thead. */
- ready += thread_process_fd (&m->read, &readfd, &m->readfd);
+ thread_process_fd (&m->read, &readfd, &m->readfd);
/* Write thead. */
- ready += thread_process_fd (&m->write, &writefd, &m->writefd);
+ thread_process_fd (&m->write, &writefd, &m->writefd);
}
-
+
+#if 0
+ /* If any threads were made ready above (I/O or foreground timer),
+ perhaps we should avoid adding background timers to the ready
+ list at this time. If this is code is uncommented, then background
+ timer threads will not run unless there is nothing else to do. */
+ if ((thread = thread_trim_head (&m->ready)) != NULL)
+ return thread_run (m, thread, fetch);
+#endif
+
/* Background timer/events, lowest priority */
- ready += thread_timer_process (&m->background, &timer_now);
+ thread_timer_process (&m->background, &recent_time);
- /* if any threads were made ready above.. */
- if ((ready > 0) && (thread = thread_trim_head (&m->ready)) != NULL)
+ if ((thread = thread_trim_head (&m->ready)) != NULL)
return thread_run (m, thread, fetch);
}
}
unsigned long
-thread_consumed_time (RUSAGE_T *now, RUSAGE_T *start)
+thread_consumed_time (RUSAGE_T *now, RUSAGE_T *start, unsigned long *cputime)
{
- unsigned long thread_time;
-
#ifdef HAVE_RUSAGE
/* This is 'user + sys' time. */
- thread_time = timeval_elapsed (now->ru_utime, start->ru_utime);
- thread_time += timeval_elapsed (now->ru_stime, start->ru_stime);
+ *cputime = timeval_elapsed (now->cpu.ru_utime, start->cpu.ru_utime) +
+ timeval_elapsed (now->cpu.ru_stime, start->cpu.ru_stime);
#else
- /* When rusage is not available, simple elapsed time is used. */
- thread_time = timeval_elapsed (*now, *start);
+ *cputime = 0;
#endif /* HAVE_RUSAGE */
-
- return thread_time;
-}
-
-/* We should aim to yield after THREAD_YIELD_TIME_SLOT
- milliseconds. */
+ return timeval_elapsed (now->real, start->real);
+}
+
+/* We should aim to yield after THREAD_YIELD_TIME_SLOT milliseconds.
+ Note: we are using real (wall clock) time for this calculation.
+ It could be argued that CPU time may make more sense in certain
+ contexts. The things to consider are whether the thread may have
+ blocked (in which case wall time increases, but CPU time does not),
+ or whether the system is heavily loaded with other processes competing
+ for CPU time. On balance, wall clock time seems to make sense.
+ Plus it has the added benefit that gettimeofday should be faster
+ than calling getrusage. */
int
thread_should_yield (struct thread *thread)
{
- RUSAGE_T ru;
-
- GETRUSAGE (&ru);
-
- return (thread_consumed_time (&ru, &thread->ru) > THREAD_YIELD_TIME_SLOT);
+ gettimeofday(&recent_time, NULL);
+ return (timeval_elapsed(recent_time, thread->ru.real) >
+ THREAD_YIELD_TIME_SLOT);
}
/* We check thread consumed time. If the system has getrusage, we'll
- use that to get indepth stats on the performance of the thread. If
- not - we'll use gettimeofday for some guestimation. */
+ use that to get in-depth stats on the performance of the thread in addition
+ to wall clock time stats from gettimeofday. */
void
thread_call (struct thread *thread)
{
- unsigned long thread_time;
+ unsigned long realtime, cputime;
RUSAGE_T ru;
struct cpu_thread_history tmp, *cpu;
@@ -899,26 +887,31 @@ thread_call (struct thread *thread)
GETRUSAGE (&ru);
- thread_time = thread_consumed_time (&ru, &thread->ru);
- cpu->total += thread_time;
- if (cpu->max < thread_time)
- cpu->max = thread_time;
+ realtime = thread_consumed_time (&ru, &thread->ru, &cputime);
+ cpu->real.total += realtime;
+ if (cpu->real.max < realtime)
+ cpu->real.max = realtime;
+#ifdef HAVE_RUSAGE
+ cpu->cpu.total += cputime;
+ if (cpu->cpu.max < cputime)
+ cpu->cpu.max = cputime;
+#endif
++cpu->total_calls;
cpu->types |= (1 << thread->add_type);
#ifdef CONSUMED_TIME_CHECK
- if (thread_time > CONSUMED_TIME_CHECK)
+ if (realtime > CONSUMED_TIME_CHECK)
{
/*
* We have a CPU Hog on our hands.
* Whinge about it now, so we're aware this is yet another task
* to fix.
*/
- zlog_warn ("CPU HOG: task %s (%lx) ran for %ldms",
+ zlog_warn ("SLOW THREAD: task %s (%lx) ran for %lums (cpu time %lums)",
thread->funcname,
(unsigned long) thread->func,
- thread_time / 1000L);
+ realtime/1000, cputime/1000);
}
#endif /* CONSUMED_TIME_CHECK */
}
diff --git a/lib/thread.h b/lib/thread.h
index aef9df79..0d84cfc5 100644
--- a/lib/thread.h
+++ b/lib/thread.h
@@ -22,12 +22,22 @@
#ifndef _ZEBRA_THREAD_H
#define _ZEBRA_THREAD_H
+struct rusage_t
+{
+#ifdef HAVE_RUSAGE
+ struct rusage cpu;
+#endif
+ struct timeval real;
+};
+#define RUSAGE_T struct rusage_t
+
#ifdef HAVE_RUSAGE
-#define RUSAGE_T struct rusage
-#define GETRUSAGE(X) getrusage (RUSAGE_SELF, X);
+#define GETRUSAGE(X) \
+ getrusage(RUSAGE_SELF, &((X)->cpu)); \
+ gettimeofday(&recent_time, NULL); (X)->real = recent_time
#else
-#define RUSAGE_T struct timeval
-#define GETRUSAGE(X) gettimeofday (X, NULL);
+#define GETRUSAGE(X) \
+ gettimeofday(&recent_time, NULL); (X)->real = recent_time
#endif /* HAVE_RUSAGE */
/* Linked list of thread. */
@@ -73,11 +83,18 @@ struct thread
char* funcname;
};
-struct cpu_thread_history {
+struct cpu_thread_history
+{
int (*func)(struct thread *);
const char *funcname;
unsigned int total_calls;
- unsigned long total, max;
+ struct time_stats
+ {
+ unsigned long total, max;
+ } real;
+#ifdef HAVE_RUSAGE
+ struct time_stats cpu;
+#endif
unsigned char types;
};
@@ -170,6 +187,13 @@ int thread_should_yield (struct thread *);
extern struct cmd_element show_thread_cpu_cmd;
-extern unsigned long thread_consumed_time(RUSAGE_T *after, RUSAGE_T *before);
+/* Returns elapsed real (wall clock) time. */
+extern unsigned long thread_consumed_time(RUSAGE_T *after, RUSAGE_T *before,
+ unsigned long *cpu_time_elapsed);
+
+/* Global variable containing a recent result from gettimeofday. This can
+ be used instead of calling gettimeofday if a recent value is sufficient.
+ This is guaranteed to be refreshed before a thread is called. */
+extern struct timeval recent_time;
#endif /* _ZEBRA_THREAD_H */
diff --git a/lib/vty.c b/lib/vty.c
index ea74172c..e429ef17 100644
--- a/lib/vty.c
+++ b/lib/vty.c
@@ -399,7 +399,7 @@ vty_command (struct vty *vty, char *buf)
{
RUSAGE_T before;
RUSAGE_T after;
- unsigned long cmdtime;
+ unsigned long realtime, cputime;
GETRUSAGE(&before);
#endif /* CONSUMED_TIME_CHECK */
@@ -408,9 +408,11 @@ vty_command (struct vty *vty, char *buf)
#ifdef CONSUMED_TIME_CHECK
GETRUSAGE(&after);
- if ((cmdtime = thread_consumed_time(&after, &before)) > CONSUMED_TIME_CHECK)
+ if ((realtime = thread_consumed_time(&after, &before, &cputime)) >
+ CONSUMED_TIME_CHECK)
/* Warn about CPU hog that must be fixed. */
- zlog_warn("CPU HOG: command took %lums: %s", cmdtime/1000, buf);
+ zlog_warn("SLOW COMMAND: command took %lums (cpu time %lums): %s",
+ realtime/1000, cputime/1000, buf);
}
#endif /* CONSUMED_TIME_CHECK */