From e04ab74d17b4f3456bd3eeefe2043584431b4ea2 Mon Sep 17 00:00:00 2001 From: paul Date: Fri, 17 Jan 2003 23:47:00 +0000 Subject: From havanna_moon@gmx.net Fri Jan 17 23:37:49 2003 Date: Sat, 11 Jan 2003 23:26:28 +0100 (CET) From: Yon Uriarte To: "the list(tm) Zebra" Subject: [zebra 17217] [PATCH] show thread CPU Hi, a little patch from the 'stupid preprocessor tricks' collection to record thread statistics. Usage: "show thread cpu [r][w][t][e][x]" Output Fields: self explaining I hope. Type is one of RWTEX for: Read, Write (fd threads), Timer, Event, Execute. Overhead vs. vanilla zebra: almost nothing. Vanilla CVS zebra already collects thread run times. Caveats: Under linux getrusage has a granularity of 10ms, which is almost useless in this case. Run ./configure, edit config.h and comment out "#define HAVE_RUSAGE", this way it will use getimeofday which has a much better granularity. IMHO this is better, as cooperative threads are effectively running during all that wall time (dont care if CPU utilization was 3% or 99% during the time the thread was running (an effective rusage combined with getimeofday could give that info)). Maybe someone can give tips for other platforms on API granularity. TODO: change some of the calls to thread_add_$KIND to funcname_thread_add_$KIND with a meaningfull funcname, so users will get a better idea of what's going on. F.ex. (AFAIK): ospf_spf_calculate_timer -> "Routes Step 1, areas SPF" ospf_ase_calculate_timer -> "Routes Step 2, externals" Could this be added to the unofficial patch collection? Could someone with BGP keepalive problems run their bgpd with this patch and post the results? TIA, HTH, HAND, regards yon Example output: -------------------------------- ospfd# show thread cpu Runtime(ms) Invoked Avg uSecs Max uSecs Type Thread 14.829 31 478 585 T ospf_ase_calculate_timer 82.132 9838 8 291 EX ospf_nsm_event 0.029 1 29 29 E ospf_default_originate_timer 0.254 9 28 34 T ospf_db_desc_timer 0.026 7 3 11 T ospf_wait_timer 669.015 523 1279 490696 R vty_read 4.415 45 98 173 TE ospf_network_lsa_refresh_timer 15.026 31 484 588 T ospf_spf_calculate_timer 29.478 1593 18 122 E ospf_ls_upd_send_queue_event 0.173 1 173 173 T vty_timeout 4.173 242 17 58 E ospf_ls_ack_send_event 637.767 121223 5 55 T ospf_ls_ack_timer 39.373 244 161 2691 R zclient_read 12.169 98 124 726 EX ospf_ism_event 0.226 2 113 125 R vty_accept 537.776 14256 37 3813 W ospf_write 4.967 41 121 250 T ospf_router_lsa_timer 0.672 1 672 672 E zclient_connect 7.901 1658 4 26 T ospf_ls_req_timer 0.459 2 229 266 E ospf_external_lsa_originate_timer 3.203 60 53 305 T ospf_maxage_lsa_remover 108.341 9772 11 65 T ospf_ls_upd_timer 33.302 525 63 8628 W vty_flush 0.101 1 101 101 T ospf_router_lsa_update_timer 0.016 1 16 16 T ospf_router_id_update_timer 26.970 407 66 176 T ospf_lsa_maxage_walker 381.949 12244 31 69 T ospf_hello_timer 0.114 22 5 14 T ospf_inactivity_timer 34.290 1223 28 310 T ospf_lsa_refresh_walker 470.645 6592 71 665 R ospf_read 3119.791 180693 17 490696 RWTEX TOTAL ospfd# bgpd# sh t c TeX Runtime(ms) Invoked Avg uSecs Max uSecs Type Thread 21.504 476 45 71 T bgp_keepalive_timer 17.784 1157 15 131 T bgp_reuse_timer 29.080 193 150 249 T bgp_scan 23.606 995 23 420 E bgp_event 317.734 28572 11 69 T bgp_routeadv_timer 0.084 1 84 84 E zlookup_connect 0.526 1 526 526 E zclient_connect 1.348 13 103 147 T bgp_start_timer 19.443 142 136 420 T bgp_connect_timer 16.032 772 20 27 T bgp_import 447.141 32322 13 526 TEX TOTAL bgpd# bgpd# show thread cpu rw Runtime(ms) Invoked Avg uSecs Max uSecs Type Thread 155.043 7 22149 150659 R bgp_accept 129.638 180 720 53844 R vty_read 1.734 56 30 129 R zclient_read 0.255 2 127 148 R vty_accept 58.483 983 59 340 R bgp_read 171.495 29190 5 245 W bgp_write 13.884 181 76 2542 W vty_flush 530.532 30599 17 150659 RW TOTAL bgpd# -------------------------------- --- lib/thread.c | 221 ++++++++++++++++++++++++++++++++++++++++++++++++++++++----- lib/thread.h | 39 ++++++++--- 2 files changed, 233 insertions(+), 27 deletions(-) (limited to 'lib') diff --git a/lib/thread.c b/lib/thread.c index 31bbcd77..ff8f739d 100644 --- a/lib/thread.c +++ b/lib/thread.c @@ -26,6 +26,10 @@ #include "thread.h" #include "memory.h" #include "log.h" +#include "hash.h" +#include "command.h" + +static struct hash *cpu_record = NULL; /* Struct timeval's tv_usec one second value. */ #define TIMER_SECOND_MICRO 1000000L @@ -82,6 +86,141 @@ timeval_elapsed (struct timeval a, struct timeval b) + (a.tv_usec - b.tv_usec)); } +static unsigned int +cpu_record_hash_key (struct cpu_thread_history *a) +{ + return (unsigned int) a->func; +} + +static int +cpu_record_hash_cmp (struct cpu_thread_history *a, + struct cpu_thread_history *b) +{ + return a->func == b->func; +} + +static void* +cpu_record_hash_alloc (struct cpu_thread_history *a) +{ + struct cpu_thread_history *new; + new = XMALLOC( MTYPE_TMP/*XXX*/, sizeof *new); + memset(new, 0, sizeof *new); + new->func = a->func; + new->funcname = XSTRDUP(MTYPE_TMP/*XXX*/,a->funcname); + return new; +} + +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 %s%s", + a->total/1000, a->total%1000, a->total_calls, + a->total/a->total_calls, a->max, + a->types & (1 << THREAD_READ) ? 'R':' ', + a->types & (1 << THREAD_WRITE) ? 'W':' ', + a->types & (1 << THREAD_TIMER) ? 'T':' ', + a->types & (1 << THREAD_EVENT) ? 'E':' ', + a->types & (1 << THREAD_EXECUTE) ? 'X':' ', + a->funcname, VTY_NEWLINE); +} + +static void +cpu_record_hash_print(struct hash_backet *bucket, + void *args[]) +{ + struct cpu_thread_history *totals = args[0]; + struct vty *vty = args[1]; + unsigned char *filter = args[2]; + struct cpu_thread_history *a = bucket->data; + + + a = bucket->data; + 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; +} + +static void +cpu_record_print(struct vty *vty, unsigned char filter) +{ + struct cpu_thread_history tmp; + void *args[3] = {&tmp, vty, &filter}; + + memset(&tmp, 0, sizeof tmp); + tmp.funcname = "TOTAL"; + tmp.types = filter; + + vty_out(vty, + " Runtime(ms) Invoked Avg uSecs Max uSecs Type Thread%s", + VTY_NEWLINE); + hash_iterate(cpu_record, + (void(*)(struct hash_backet*,void*))cpu_record_hash_print, + args); + + if (tmp.total_calls > 0) + vty_out_cpu_thread_history(vty, &tmp); +} + +DEFUN(show_thread_cpu, + show_thread_cpu_cmd, + "show thread cpu [FILTER]", + SHOW_STR + "Thread information\n" + "Thread CPU usage\n" + "Display filter (rwtex)\n") +{ + int i = 0; + unsigned char filter = 0xff; + + if (argc > 0) + { + filter = 0; + while (argv[0][i] != '\0') + { + switch ( argv[0][i] ) + { + case 'r': + case 'R': + filter |= (1 << THREAD_READ); + break; + case 'w': + case 'W': + filter |= (1 << THREAD_WRITE); + break; + case 't': + case 'T': + filter |= (1 << THREAD_TIMER); + break; + case 'e': + case 'E': + filter |= (1 << THREAD_EVENT); + break; + case 'x': + case 'X': + filter |= (1 << THREAD_EXECUTE); + break; + default: + break; + } + ++i; + } + if (filter == 0) + { + vty_out(vty, "Invalid filter \"%s\" specified, must contain at least one of 'RWTEX'%s", + argv[0], VTY_NEWLINE); + return CMD_WARNING; + } + } + + cpu_record_print(vty, filter); + return CMD_SUCCESS; +} + /* List allocation and head/tail print out. */ static void thread_list_debug (struct thread_list *list) @@ -113,6 +252,10 @@ thread_master_debug (struct thread_master *m) struct thread_master * thread_master_create () { + if (cpu_record == NULL) + { + cpu_record = hash_create_size( 1011, cpu_record_hash_key, cpu_record_hash_cmp); + } return (struct thread_master *) XCALLOC (MTYPE_THREAD_MASTER, sizeof (struct thread_master)); } @@ -235,10 +378,37 @@ thread_timer_remain_second (struct thread *thread) return 0; } +/* Trim blankspace and "()"s */ +static char * +strip_funcname (char *funcname) +{ + char buff[100]; + char tmp, *ret, *e, *b = buff; + + strncpy(buff, funcname, sizeof(buff)); + buff[ sizeof(buff) -1] = '\0'; + e = buff +strlen(buff) -1; + + /* Wont work for funcname == "Word (explanation)" */ + + while (*b == ' ' || *b == '(') + ++b; + while (*e == ' ' || *e == ')') + --e; + e++; + + tmp = *e; + *e = '\0'; + ret = XSTRDUP (MTYPE_TMP, b); + *e = tmp; + + return ret; +} + /* Get new thread. */ static struct thread * thread_get (struct thread_master *m, u_char type, - int (*func) (struct thread *), void *arg) + int (*func) (struct thread *), void *arg, char* funcname) { struct thread *thread; @@ -250,17 +420,20 @@ thread_get (struct thread_master *m, u_char type, m->alloc++; } thread->type = type; + thread->add_type = type; thread->master = m; thread->func = func; thread->arg = arg; + thread->funcname = strip_funcname(funcname); + return thread; } /* Add new read thread. */ struct thread * -thread_add_read (struct thread_master *m, - int (*func) (struct thread *), void *arg, int fd) +funcname_thread_add_read (struct thread_master *m, + int (*func) (struct thread *), void *arg, int fd, char* funcname) { struct thread *thread; @@ -272,7 +445,7 @@ thread_add_read (struct thread_master *m, return NULL; } - thread = thread_get (m, THREAD_READ, func, arg); + thread = thread_get (m, THREAD_READ, func, arg, funcname); FD_SET (fd, &m->readfd); thread->u.fd = fd; thread_list_add (&m->read, thread); @@ -282,8 +455,8 @@ thread_add_read (struct thread_master *m, /* Add new write thread. */ struct thread * -thread_add_write (struct thread_master *m, - int (*func) (struct thread *), void *arg, int fd) +funcname_thread_add_write (struct thread_master *m, + int (*func) (struct thread *), void *arg, int fd, char* funcname) { struct thread *thread; @@ -295,7 +468,7 @@ thread_add_write (struct thread_master *m, return NULL; } - thread = thread_get (m, THREAD_WRITE, func, arg); + thread = thread_get (m, THREAD_WRITE, func, arg, funcname); FD_SET (fd, &m->writefd); thread->u.fd = fd; thread_list_add (&m->write, thread); @@ -305,8 +478,8 @@ thread_add_write (struct thread_master *m, /* Add timer event thread. */ struct thread * -thread_add_timer (struct thread_master *m, - int (*func) (struct thread *), void *arg, long timer) +funcname_thread_add_timer (struct thread_master *m, + int (*func) (struct thread *), void *arg, long timer, char* funcname) { struct timeval timer_now; struct thread *thread; @@ -316,7 +489,7 @@ thread_add_timer (struct thread_master *m, assert (m != NULL); - thread = thread_get (m, THREAD_TIMER, func, arg); + thread = thread_get (m, THREAD_TIMER, func, arg, funcname); /* Do we need jitter here? */ gettimeofday (&timer_now, NULL); @@ -342,14 +515,14 @@ thread_add_timer (struct thread_master *m, /* Add simple event thread. */ struct thread * -thread_add_event (struct thread_master *m, - int (*func) (struct thread *), void *arg, int val) +funcname_thread_add_event (struct thread_master *m, + int (*func) (struct thread *), void *arg, int val, char* funcname) { struct thread *thread; assert (m != NULL); - thread = thread_get (m, THREAD_EVENT, func, arg); + thread = thread_get (m, THREAD_EVENT, func, arg, funcname); thread->u.val = val; thread_list_add (&m->event, thread); @@ -621,6 +794,11 @@ thread_call (struct thread *thread) { unsigned long thread_time; RUSAGE_T ru; + struct cpu_thread_history tmp, *cpu; + + tmp.func = thread->func; + tmp.funcname = thread->funcname; + cpu = hash_get(cpu_record, &tmp, cpu_record_hash_alloc); GETRUSAGE (&thread->ru); @@ -629,6 +807,12 @@ 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; + + ++cpu->total_calls; + cpu->types |= (1 << thread->add_type); #ifdef THREAD_CONSUMED_TIME_CHECK if (thread_time > 200000L) @@ -638,8 +822,8 @@ thread_call (struct thread *thread) * Whinge about it now, so we're aware this is yet another task * to fix. */ - zlog_err ("CPU HOG task %lx ran for %ldms", - /* FIXME: report the name of the function somehow */ + zlog_err ("CPU HOG task %s (%lx) ran for %ldms", + thread->funcname, (unsigned long) thread->func, thread_time / 1000L); } @@ -648,20 +832,23 @@ thread_call (struct thread *thread) /* Execute thread */ struct thread * -thread_execute (struct thread_master *m, +funcname_thread_execute (struct thread_master *m, int (*func)(struct thread *), void *arg, - int val) + int val, + char* funcname) { struct thread dummy; memset (&dummy, 0, sizeof (struct thread)); dummy.type = THREAD_EVENT; + dummy.add_type = THREAD_EXECUTE; dummy.master = NULL; dummy.func = func; dummy.arg = arg; dummy.u.val = val; + dummy.funcname = strip_funcname (funcname); thread_call (&dummy); return NULL; diff --git a/lib/thread.h b/lib/thread.h index 9de62cdd..0a45d8f3 100644 --- a/lib/thread.h +++ b/lib/thread.h @@ -57,6 +57,7 @@ struct thread_master struct thread { unsigned char type; /* thread type */ + unsigned char add_type; /* thread type */ struct thread *next; /* next pointer of the thread */ struct thread *prev; /* previous pointer of the thread */ struct thread_master *master; /* pointer to the struct thread_master. */ @@ -68,6 +69,15 @@ struct thread struct timeval sands; /* rest of time sands value. */ } u; RUSAGE_T ru; /* Indepth usage info. */ + char* funcname; +}; + +struct cpu_thread_history { + int (*func)(struct thread *); + char *funcname; + unsigned int total_calls; + unsigned long total, max; + unsigned char types; }; /* Thread types. */ @@ -77,6 +87,7 @@ struct thread #define THREAD_EVENT 3 #define THREAD_READY 4 #define THREAD_UNUSED 5 +#define THREAD_EXECUTE 6 /* Thread yield time. */ #define THREAD_YIELD_TIME_SLOT 100 * 1000L /* 100ms */ @@ -117,23 +128,31 @@ struct thread #define THREAD_WRITE_OFF(thread) THREAD_OFF(thread) #define THREAD_TIMER_OFF(thread) THREAD_OFF(thread) +#define thread_add_read(m,f,a,v) funcname_thread_add_read(m,f,a,v,#f) +#define thread_add_write(m,f,a,v) funcname_thread_add_write(m,f,a,v,#f) +#define thread_add_timer(m,f,a,v) funcname_thread_add_timer(m,f,a,v,#f) +#define thread_add_event(m,f,a,v) funcname_thread_add_event(m,f,a,v,#f) +#define thread_execute(m,f,a,v) funcname_thread_execute(m,f,a,v,#f) + /* Prototypes. */ struct thread_master *thread_master_create (); -struct thread *thread_add_read (struct thread_master *, - int (*)(struct thread *), void *, int); -struct thread *thread_add_write (struct thread_master *, - int (*)(struct thread *), void *, int); -struct thread *thread_add_timer (struct thread_master *, - int (*)(struct thread *), void *, long); -struct thread *thread_add_event (struct thread_master *, - int (*)(struct thread *), void *, int ); +struct thread *funcname_thread_add_read (struct thread_master *, + int (*)(struct thread *), void *, int, char*); +struct thread *funcname_thread_add_write (struct thread_master *, + int (*)(struct thread *), void *, int, char*); +struct thread *funcname_thread_add_timer (struct thread_master *, + int (*)(struct thread *), void *, long, char*); +struct thread *funcname_thread_add_event (struct thread_master *, + int (*)(struct thread *), void *, int, char*); void thread_cancel (struct thread *); void thread_cancel_event (struct thread_master *, void *); struct thread *thread_fetch (struct thread_master *, struct thread *); -struct thread *thread_execute (struct thread_master *, - int (*)(struct thread *), void *, int); +struct thread *funcname_thread_execute (struct thread_master *, + int (*)(struct thread *), void *, int, char *); void thread_call (struct thread *); unsigned long thread_timer_remain_second (struct thread *); +extern struct cmd_element show_thread_cpu_cmd; + #endif /* _ZEBRA_THREAD_H */ -- cgit v1.2.1