diff --git a/lib/command.c b/lib/command.c index 316971e..adfc843 100644 --- a/lib/command.c +++ b/lib/command.c @@ -3581,6 +3581,10 @@ cmd_init (int terminal) install_element (VIEW_NODE, &show_thread_cpu_cmd); install_element (ENABLE_NODE, &show_thread_cpu_cmd); +#ifdef HAVE_RUSAGE + install_element (VIEW_NODE, &show_system_rusage_cmd); + install_element (ENABLE_NODE, &show_system_rusage_cmd); +#endif install_element (VIEW_NODE, &show_work_queues_cmd); install_element (ENABLE_NODE, &show_work_queues_cmd); } diff --git a/lib/stream.c b/lib/stream.c diff --git a/lib/thread.c b/lib/thread.c index 32fc15e..f05fbe9 100644 --- a/lib/thread.c +++ b/lib/thread.c @@ -32,6 +32,9 @@ #include "sigevent.h" struct timeval recent_time; static struct hash *cpu_record = NULL; +#ifdef HAVE_RUSAGE +static struct rusage *master_ru = NULL; +#endif /* Struct timeval's tv_usec one second value. */ #define TIMER_SECOND_MICRO 1000000L @@ -113,13 +116,13 @@ vty_out_cpu_thread_history(struct vty* v struct cpu_thread_history *a) { #ifdef HAVE_RUSAGE - vty_out(vty, "%7ld.%03ld %9d %8ld %9ld %8ld %9ld", - a->cpu.total/1000, a->cpu.total%1000, a->total_calls, + vty_out(vty, "%7lu.%02lu %9u %8lu %9lu %8lu %9lu", + a->cpu.total/1000, a->cpu.total%1000/10, 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, + vty_out(vty, "%7lu.%02lu %9u %8lu %9lu", + a->real.total/1000, a->real.total%1000/10, a->total_calls, a->real.total/a->total_calls, a->real.max); #endif vty_out(vty, " %c%c%c%c%c%c %s%s", @@ -161,20 +164,27 @@ cpu_record_print(struct vty *vty, unsign { struct cpu_thread_history tmp; void *args[3] = {&tmp, vty, &filter}; - + static const char *times_header = " Avg uSec Max uSecs"; memset(&tmp, 0, sizeof tmp); tmp.funcname = "TOTAL"; tmp.types = filter; + #ifdef HAVE_RUSAGE - vty_out(vty, "%21s %18s %18s%s", - "", "CPU (user+system):", "Real (wall-clock):", VTY_NEWLINE); + vty_out(vty, "%10s %9s %18s %18s%s", + "Runtime ", "", "CPU (user+system):", "Real (wall-clock):", + VTY_NEWLINE); +#else + vty_out(vty, "%10s %9s %18s%s", + "Runtime ", "", "Real (wall-clock):", + VTY_NEWLINE); #endif - vty_out(vty, "Runtime(ms) Invoked Avg uSec Max uSecs"); + + vty_out(vty, "%10s %9s%s", "(ms) ", "Invoked", times_header); #ifdef HAVE_RUSAGE - vty_out(vty, " Avg uSec Max uSecs"); + vty_out(vty, "%s", times_header); #endif - vty_out(vty, " Type Thread%s", VTY_NEWLINE); + vty_out(vty, " %6s Thread%s", "Type", VTY_NEWLINE); hash_iterate(cpu_record, (void(*)(struct hash_backet*,void*))cpu_record_hash_print, args); @@ -242,6 +252,39 @@ DEFUN(show_thread_cpu, cpu_record_print(vty, filter); return CMD_SUCCESS; } + +#ifdef HAVE_RUSAGE +DEFUN(show_system_rusage, + show_system_rusage_cmd, + "show system rusage", + SHOW_STR + "System information\n" + "Resource usage (getrusage)\n") +{ + vty_out (vty, "CPU time (user) : %lu.%02lu s%s", + master_ru->ru_utime.tv_sec, + master_ru->ru_utime.tv_usec/10000, VTY_NEWLINE); + vty_out (vty, "CPU time (system): %lu.%02lu s%s", + master_ru->ru_stime.tv_sec, + master_ru->ru_stime.tv_usec/10000, VTY_NEWLINE); + vty_out (vty, "RSS : Maximum : %lu bytes%s", master_ru->ru_maxrss, VTY_NEWLINE); + vty_out (vty, " Shared : %lu bytes%s", master_ru->ru_ixrss, VTY_NEWLINE); + vty_out (vty, " Data : %lu bytes%s", master_ru->ru_idrss, VTY_NEWLINE); + vty_out (vty, " Stack : %lu bytes%s", master_ru->ru_isrss, VTY_NEWLINE); + vty_out (vty, "Page : Reclaims : %lu%s", master_ru->ru_minflt, VTY_NEWLINE); + vty_out (vty, " Faults : %lu%s", master_ru->ru_majflt, VTY_NEWLINE); + vty_out (vty, " Swaps : %lu%s", master_ru->ru_nswap, VTY_NEWLINE); + vty_out (vty, "Block: Input : %lu%s", master_ru->ru_inblock, VTY_NEWLINE); + vty_out (vty, " Output : %lu%s", master_ru->ru_oublock, VTY_NEWLINE); + vty_out (vty, "Msgs : Sent : %lu%s", master_ru->ru_msgsnd, VTY_NEWLINE); + vty_out (vty, " Received : %lu%s", master_ru->ru_msgrcv, VTY_NEWLINE); + vty_out (vty, "Signals Received : %lu%s", master_ru->ru_nsignals, VTY_NEWLINE); + vty_out (vty, "Ctxt Switch (vol): %lu%s", master_ru->ru_nvcsw, VTY_NEWLINE); + vty_out (vty, "Ctxt Switch (inv): %lu%s", master_ru->ru_nivcsw, VTY_NEWLINE); + + return CMD_SUCCESS; +} +#endif /* HAVE_RUSAGE */ /* List allocation and head/tail print out. */ static void @@ -276,13 +319,20 @@ thread_master_debug (struct thread_maste struct thread_master * thread_master_create () { + struct thread_master *master; if (cpu_record == NULL) cpu_record = hash_create_size (1011, (unsigned int (*) (void *))cpu_record_hash_key, (int (*) (void *, void *))cpu_record_hash_cmp); - - return (struct thread_master *) XCALLOC (MTYPE_THREAD_MASTER, - sizeof (struct thread_master)); + + master = XCALLOC (MTYPE_THREAD_MASTER, sizeof (struct thread_master)); + +#ifdef HAVE_RUSAGE + if (master) + master_ru = &master->ru.cpu; +#endif + + return master; } /* Add a new thread to the list. */ @@ -867,7 +917,7 @@ int thread_should_yield (struct thread *thread) { gettimeofday(&recent_time, NULL); - return (timeval_elapsed(recent_time, thread->ru.real) > + return (timeval_elapsed(recent_time, thread->master->ru.real) > THREAD_YIELD_TIME_SLOT); } @@ -879,31 +929,40 @@ thread_call (struct thread *thread) { unsigned long realtime, cputime; RUSAGE_T ru; - struct cpu_thread_history tmp, *cpu; + struct cpu_thread_history tmp; tmp.func = thread->func; tmp.funcname = thread->funcname; - cpu = hash_get (cpu_record, &tmp, - (void * (*) (void *))cpu_record_hash_alloc); - - GETRUSAGE (&thread->ru); - - (*thread->func) (thread); - + + /* Cache a pointer to the relevant cpu history thread, if the thread + * not have this yet. + * + * Callers submitting 'dummy threads' hence must take care that + * thread->cpu is NULLed. See thread_execute below. + */ + if (!thread->cpu) + thread->cpu = hash_get (cpu_record, &tmp, + (void * (*) (void *))cpu_record_hash_alloc); + + /* thread->master->ru should always be the most recent. + * as threads may be nested via thread_execute. + */ GETRUSAGE (&ru); + (*thread->func) (thread); + GETRUSAGE (&thread->master->ru); - realtime = thread_consumed_time (&ru, &thread->ru, &cputime); - cpu->real.total += realtime; - if (cpu->real.max < realtime) - cpu->real.max = realtime; + realtime = thread_consumed_time (&thread->master->ru, &ru, &cputime); + thread->cpu->real.total += realtime; + if (thread->cpu->real.max < realtime) + thread->cpu->real.max = realtime; #ifdef HAVE_RUSAGE - cpu->cpu.total += cputime; - if (cpu->cpu.max < cputime) - cpu->cpu.max = cputime; + thread->cpu->cpu.total += cputime; + if (thread->cpu->cpu.max < cputime) + thread->cpu->cpu.max = cputime; #endif - ++cpu->total_calls; - cpu->types |= (1 << thread->add_type); + ++(thread->cpu->total_calls); + thread->cpu->types |= (1 << thread->add_type); #ifdef CONSUMED_TIME_CHECK if (realtime > CONSUMED_TIME_CHECK) @@ -935,7 +994,7 @@ funcname_thread_execute (struct thread_m dummy.type = THREAD_EVENT; dummy.add_type = THREAD_EXECUTE; - dummy.master = NULL; + dummy.master = m; dummy.func = func; dummy.arg = arg; dummy.u.val = val; diff --git a/lib/thread.h b/lib/thread.h index f693ff5..8834fee 100644 --- a/lib/thread.h +++ b/lib/thread.h @@ -62,6 +62,7 @@ struct thread_master fd_set writefd; fd_set exceptfd; unsigned long alloc; + struct rusage_t ru; }; /* Thread itself. */ @@ -79,7 +80,9 @@ struct thread int fd; /* file descriptor in case of read/write. */ struct timeval sands; /* rest of time sands value. */ } u; - RUSAGE_T ru; /* Indepth usage info. */ + + /* Accounting */ + struct cpu_thread_history *cpu; char* funcname; }; @@ -191,7 +194,9 @@ extern void thread_call (struct thread * extern unsigned long thread_timer_remain_second (struct thread *); extern int thread_should_yield (struct thread *); +/* internal libzebra exports */ extern struct cmd_element show_thread_cpu_cmd; +extern struct cmd_element show_system_rusage_cmd; /* Returns elapsed real (wall clock) time. */ extern unsigned long thread_consumed_time(RUSAGE_T *after, RUSAGE_T *before,