2005-04-16 Andrew J. Schorr <ajschorr@alumni.princeton.edu>

	* configure.ac: Added AC_ARG_ENABLE(time-check).  By default,
	  warning messages will now be printed for threads or commands that take
	  longer than 5 seconds, but this configure argument can be used
	  to disable the checks or change the threshold.
	* thread.h (thread_consumed_time): Declare new function to calculate
	  elapsed microseconds.
	* thread.c (thread_consumed_time): Must be global not static so we
	  can call it from lib/vty.c:vty_command.
	  (thread_should_yield): Surround with `#if 0' to make clear that this
	  function is not currently being used anywhere.
	  (thread_call): If CONSUMED_TIME_CHECK is defined, print a CPU HOG
	  warning message if the thread takes more than CONSUMED_TIME_CHECK
	  microseconds.
	* vty.c (vty_command): If CONSUMED_TIME_CHECK is defined, print a CPU
	  HOG warning message if the command takes more than CONSUMED_TIME_CHECK
	  microseconds.

6 files changed, 66 insertions, 9 deletions

diff --git a/ChangeLog b/ChangeLog
index 0b10293b..7966cc47 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,3 +1,10 @@
+2005-04-16 Andrew J. Schorr <ajschorr@alumni.princeton.edu>
+
+	* configure.ac: Added AC_ARG_ENABLE(time-check).  By default,
+	  warning messages will now be printed for threads or commands that take
+	  longer than 5 seconds, but this configure argument can be used
+	  to disable the checks or change the threshold.
+
 2005-04-16 Paul Jakma <paul.jakma@sun.com>
 
 	* configure.ac: check for gawk, needed to build memtypes.h
diff --git a/configure.ac b/configure.ac
index 08b5214f..cbc95212 100755
--- a/configure.ac
+++ b/configure.ac
@@ -5,7 +5,7 @@
 ##  Copyright (c) 1996, 97, 98, 99, 2000 Kunihiro Ishiguro <kunihiro@zebra.org>
 ##  Portions Copyright (c) 2003 Paul Jakma <paul@dishone.st>
 ##
-## $Id: configure.ac,v 1.103 2005/04/16 15:38:23 paul Exp $
+## $Id: configure.ac,v 1.104 2005/04/16 17:11:24 ajs Exp $
 AC_PREREQ(2.53)
 
 AC_INIT(Quagga, 0.99.0, [http://bugzilla.quagga.net])
@@ -195,6 +195,8 @@ AC_ARG_ENABLE(gcc_ultra_verbose,
 [  --enable-gcc-ultra-verbose    enable ultra verbose GCC warnings])
 AC_ARG_ENABLE(gcc-rdynamic,
 [  --enable-gcc-rdynamic   enable gcc linking with -rdynamic for better backtraces])
+AC_ARG_ENABLE(time-check,
+[  --disable-time-check          disable slow thread warning messages])
 
 if test x"${enable_gcc_ultra_verbose}" = x"yes" ; then
   CFLAGS="${CFLAGS} -W -Wcast-qual -Wstrict-prototypes"
@@ -207,6 +209,14 @@ if test x"${enable_gcc_rdynamic}" = x"yes" ; then
   LDFLAGS="${LDFLAGS} -rdynamic"
 fi
 
+if test x"${enable_time_check}" != x"no" ; then
+  if test x"${enable_time_check}" = x"yes" -o x"${enable_time_check}" = x ; then
+    AC_DEFINE(CONSUMED_TIME_CHECK,5000000,Consumed Time Check)
+  else
+    AC_DEFINE_UNQUOTED(CONSUMED_TIME_CHECK,$enable_time_check,Consumed Time Check)
+  fi
+fi
+
 if test "${enable_broken_aliases}" = "yes"; then
   if test "${enable_netlink}" = "yes"
   then
diff --git a/lib/ChangeLog b/lib/ChangeLog
index e5ee5494..d8328499 100644
--- a/lib/ChangeLog
+++ b/lib/ChangeLog
@@ -1,3 +1,18 @@
+2005-04-16 Andrew J. Schorr <ajschorr@alumni.princeton.edu>
+
+	* thread.h (thread_consumed_time): Declare new function to calculate
+	  elapsed microseconds.
+	* thread.c (thread_consumed_time): Must be global not static so we
+	  can call it from lib/vty.c:vty_command.
+	  (thread_should_yield): Surround with `#if 0' to make clear that this
+	  function is not currently being used anywhere.
+	  (thread_call): If CONSUMED_TIME_CHECK is defined, print a CPU HOG
+	  warning message if the thread takes more than CONSUMED_TIME_CHECK
+	  microseconds.
+	* vty.c (vty_command): If CONSUMED_TIME_CHECK is defined, print a CPU
+	  HOG warning message if the command takes more than CONSUMED_TIME_CHECK
+	  microseconds.
+
 2005-04-16 Paul Jakma <paul@dishone.st>
 
 	* memtypes.c: the comment about use of comments in the comments
diff --git a/lib/thread.c b/lib/thread.c
index 05212d85..d1c925c4 100644
--- a/lib/thread.c
+++ b/lib/thread.c
@@ -804,7 +804,7 @@ thread_fetch (struct thread_master *m, struct thread *fetch)
     }
 }
 
-static unsigned long
+unsigned long
 thread_consumed_time (RUSAGE_T *now, RUSAGE_T *start)
 {
   unsigned long thread_time;
@@ -821,6 +821,10 @@ thread_consumed_time (RUSAGE_T *now, RUSAGE_T *start)
   return thread_time;
 }
 
+#if 0
+
+/* This function is not currently used: threads never yield! */
+
 /* We should aim to yield after THREAD_YIELD_TIME_SLOT
    milliseconds.  */
 int
@@ -836,6 +840,8 @@ thread_should_yield (struct thread *thread)
     return 0;
 }
 
+#endif
+
 /* 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.  */
@@ -864,20 +870,20 @@ thread_call (struct thread *thread)
   ++cpu->total_calls;
   cpu->types |= (1 << thread->add_type);
 
-#ifdef THREAD_CONSUMED_TIME_CHECK
-  if (thread_time > 200000L)
+#ifdef CONSUMED_TIME_CHECK
+  if (thread_time > 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_err ("CPU HOG task %s (%lx) ran for %ldms",
-		thread->funcname,
-		(unsigned long) thread->func,
-		thread_time / 1000L);
+      zlog_warn ("CPU HOG: task %s (%lx) ran for %ldms",
+		 thread->funcname,
+		 (unsigned long) thread->func,
+		 thread_time / 1000L);
     }
-#endif /* THREAD_CONSUMED_TIME_CHECK */
+#endif /* CONSUMED_TIME_CHECK */
 }
 
 /* Execute thread */
diff --git a/lib/thread.h b/lib/thread.h
index 716a6a6c..4008ba72 100644
--- a/lib/thread.h
+++ b/lib/thread.h
@@ -158,4 +158,6 @@ unsigned long thread_timer_remain_second (struct thread *);
 
 extern struct cmd_element show_thread_cpu_cmd;
 
+extern unsigned long thread_consumed_time(RUSAGE_T *after, RUSAGE_T *before);
+
 #endif /* _ZEBRA_THREAD_H */
diff --git a/lib/vty.c b/lib/vty.c
index 600c9fd8..ea74172c 100644
--- a/lib/vty.c
+++ b/lib/vty.c
@@ -395,8 +395,25 @@ vty_command (struct vty *vty, char *buf)
   if (vline == NULL)
     return CMD_SUCCESS;
 
+#ifdef CONSUMED_TIME_CHECK
+  {
+    RUSAGE_T before;
+    RUSAGE_T after;
+    unsigned long cmdtime;
+
+    GETRUSAGE(&before);
+#endif /* CONSUMED_TIME_CHECK */
+
   ret = cmd_execute_command (vline, vty, NULL, 0);
 
+#ifdef CONSUMED_TIME_CHECK
+    GETRUSAGE(&after);
+    if ((cmdtime = thread_consumed_time(&after, &before)) > CONSUMED_TIME_CHECK)
+      /* Warn about CPU hog that must be fixed. */
+      zlog_warn("CPU HOG: command took %lums: %s", cmdtime/1000, buf);
+  }
+#endif /* CONSUMED_TIME_CHECK */
+
   if (ret != CMD_SUCCESS)
     switch (ret)
       {