From: Ivo Raisr Date: Fri, 19 Jan 2018 16:12:34 +0000 (+0000) Subject: Add a simple progress-reporting facility. X-Git-Tag: VALGRIND_3_14_0~174 X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=bd077baa71a40b60dcf0286b9fb89d803323fd93;p=thirdparty%2Fvalgrind.git Add a simple progress-reporting facility. Fixes BZ#384633. Patch by: Julian Seward --- diff --git a/NEWS b/NEWS index 46c4db2c24..ac73ddee0b 100644 --- a/NEWS +++ b/NEWS @@ -72,6 +72,7 @@ where XXXXXX is the bug number as listed below. 384096 Mention AddrCheck at Memcheck's command line option --undef-value-errors=no 384526 reduce number of spill instructions generated by VEX register allocator v3 384584 Callee saved registers listed first for AMD64, X86, and PPC architectures +384633 Add a simple progress-reporting facility 384987 VEX register allocator: allocate caller-save registers for short lived vregs 385182 PPC64 is missing support for the DSCR 385207 PPC64, generate_store_FPRF() generates too many Iops diff --git a/coregrind/m_libcproc.c b/coregrind/m_libcproc.c index afcc11729d..97a4fc5347 100644 --- a/coregrind/m_libcproc.c +++ b/coregrind/m_libcproc.c @@ -958,6 +958,40 @@ Int VG_(gettimeofday)(struct vki_timeval *tv, struct vki_timezone *tz) return -1; } +UInt VG_(get_user_milliseconds)(void) +{ + UInt res = 0; +# if defined(VGO_linux) + { + struct vki_rusage ru; + VG_(memset)(&ru, 0, sizeof(ru)); + SysRes sr = VG_(do_syscall2)(__NR_getrusage, VKI_RUSAGE_SELF, (UWord)&ru); + if (!sr_isError(sr)) { + res = ru.ru_utime.tv_sec * 1000 + ru.ru_utime.tv_usec / 1000; + } + } + +# elif defined(VGO_solaris) + { + struct vki_rusage ru; + VG_(memset)(&ru, 0, sizeof(ru)); + SysRes sr = VG_(do_syscall2)(__NR_rusagesys, VKI__RUSAGESYS_GETRUSAGE, + (UWord) &ru); + if (!sr_isError(sr)) { + res = ru.ru_utime.tv_sec * 1000 + ru.ru_utime.tv_usec / 1000; + } + } + +# elif defined(VGO_darwin) + res = 0; + +# else +# error "Unknown OS" +# endif + + return res; +} + /* --------------------------------------------------------------------- atfork() diff --git a/coregrind/m_main.c b/coregrind/m_main.c index a7574c3e5b..bf4a712846 100644 --- a/coregrind/m_main.c +++ b/coregrind/m_main.c @@ -258,6 +258,8 @@ static void usage_NORETURN ( Bool debug_help ) " heap blocks allocated for Valgrind internal use (in bytes) [4]\n" " --wait-for-gdb=yes|no pause on startup to wait for gdb attach\n" " --sym-offsets=yes|no show syms in form 'name+offset'? [no]\n" +" --progress-interval= report progress every \n" +" CPU seconds [0, meaning disabled]\n" " --command-line-only=no|yes only use command line options [no]\n" "\n" " Vex options for all Valgrind tools:\n" @@ -671,6 +673,8 @@ void main_process_cmd_line_options( void ) else if VG_BOOL_CLO(arg, "--trace-syscalls", VG_(clo_trace_syscalls)) {} else if VG_BOOL_CLO(arg, "--wait-for-gdb", VG_(clo_wait_for_gdb)) {} else if VG_BOOL_CLO(arg, "--sym-offsets", VG_(clo_sym_offsets)) {} + else if VG_BINT_CLO(arg, "--progress-interval", + VG_(clo_progress_interval), 0, 3600) {} else if VG_BOOL_CLO(arg, "--read-inline-info", VG_(clo_read_inline_info)) {} else if VG_BOOL_CLO(arg, "--read-var-info", VG_(clo_read_var_info)) {} diff --git a/coregrind/m_options.c b/coregrind/m_options.c index 72173ddfa2..67eed342ba 100644 --- a/coregrind/m_options.c +++ b/coregrind/m_options.c @@ -110,6 +110,8 @@ enum FairSchedType VG_(clo_fair_sched) = disable_fair_sched; Bool VG_(clo_trace_sched) = False; Bool VG_(clo_profile_heap) = False; +UInt VG_(clo_progress_interval) = 0; /* in seconds, 1 .. 3600, + or 0 == disabled */ Int VG_(clo_core_redzone_size) = CORE_REDZONE_DEFAULT_SZB; // A value != -1 overrides the tool-specific value // VG_(needs_malloc_replacement).tool_client_redzone_szB diff --git a/coregrind/m_scheduler/scheduler.c b/coregrind/m_scheduler/scheduler.c index 54b8008d61..2ffcf4b866 100644 --- a/coregrind/m_scheduler/scheduler.c +++ b/coregrind/m_scheduler/scheduler.c @@ -172,6 +172,56 @@ static struct sched_lock *the_BigLock; Helper functions for the scheduler. ------------------------------------------------------------------ */ +static void maybe_progress_report ( UInt reporting_interval_seconds ) +{ + /* This is when the next report is due, in user cpu milliseconds since + process start. This is a global variable so this won't be thread-safe + if Valgrind is ever made multithreaded. For now it's fine. */ + static UInt next_report_due_at = 0; + + /* First of all, figure out whether another report is due. It + probably isn't. */ + UInt user_ms = VG_(get_user_milliseconds)(); + if (LIKELY(user_ms < next_report_due_at)) + return; + + Bool first_ever_call = next_report_due_at == 0; + + /* A report is due. First, though, set the time for the next report. */ + next_report_due_at += 1000 * reporting_interval_seconds; + + /* If it's been an excessively long time since the last check, we + might have gone more than one reporting interval forward. Guard + against that. */ + while (next_report_due_at <= user_ms) + next_report_due_at += 1000 * reporting_interval_seconds; + + /* Also we don't want to report anything on the first call, but we + have to wait till this point to leave, so that we set up the + next-call time correctly. */ + if (first_ever_call) + return; + + /* Print the report. */ + UInt user_cpu_seconds = user_ms / 1000; + UInt wallclock_seconds = VG_(read_millisecond_timer)() / 1000; + Double millionEvCs = ((Double)bbs_done) / 1000000.0; + Double thousandTIns = ((Double)VG_(get_bbs_translated)()) / 1000.0; + Double thousandTOuts = ((Double)VG_(get_bbs_discarded_or_dumped)()) / 1000.0; + UInt nThreads = VG_(count_living_threads)(); + + if (VG_(clo_verbosity) > 0) { + VG_(dmsg)("PROGRESS: U %'us, W %'us, %.1f%% CPU, EvC %.2fM, " + "TIn %.1fk, TOut %.1fk, #thr %u\n", + user_cpu_seconds, wallclock_seconds, + 100.0 + * (Double)(user_cpu_seconds) + / (Double)(wallclock_seconds == 0 ? 1 : wallclock_seconds), + millionEvCs, + thousandTIns, thousandTOuts, nThreads); + } +} + static void print_sched_event ( ThreadId tid, const HChar* what ) { @@ -1315,6 +1365,11 @@ VgSchedReturnCode VG_(scheduler) ( ThreadId tid ) scheduler_sanity(tid); VG_(sanity_check_general)(False); + /* Possibly make a progress report */ + if (UNLIKELY(VG_(clo_progress_interval) > 0)) { + maybe_progress_report( VG_(clo_progress_interval) ); + } + /* Look for any pending signals for this thread, and set them up for delivery */ VG_(poll_signals)(tid); diff --git a/coregrind/m_transtab.c b/coregrind/m_transtab.c index fa0a8683c5..6ef9ceae29 100644 --- a/coregrind/m_transtab.c +++ b/coregrind/m_transtab.c @@ -2565,6 +2565,11 @@ UInt VG_(get_bbs_translated) ( void ) return n_in_count; } +UInt VG_(get_bbs_discarded_or_dumped) ( void ) +{ + return n_disc_count + n_dump_count; +} + void VG_(print_tt_tc_stats) ( void ) { VG_(message)(Vg_DebugMsg, diff --git a/coregrind/pub_core_options.h b/coregrind/pub_core_options.h index cc6bb835c5..3bae7f3f19 100644 --- a/coregrind/pub_core_options.h +++ b/coregrind/pub_core_options.h @@ -201,6 +201,8 @@ extern enum FairSchedType VG_(clo_fair_sched); extern Bool VG_(clo_trace_sched); /* DEBUG: do heap profiling? default: NO */ extern Bool VG_(clo_profile_heap); +// DEBUG: report progress every N seconds (1 .. 3600) +extern UInt VG_(clo_progress_interval); #define MAX_REDZONE_SZB 128 // Maximum for the default values for core arenas and for client // arena given by the tool. diff --git a/docs/xml/manual-core.xml b/docs/xml/manual-core.xml index 6a038829ee..48321acd5b 100644 --- a/docs/xml/manual-core.xml +++ b/docs/xml/manual-core.xml @@ -2581,6 +2581,60 @@ need to use them. + + + + + + This is an enhancement to Valgrind's debugging output. It is + unlikely to be of interest to end users. + When number is set to a non-zero value, + Valgrind will print a one-line progress summary + every number seconds. Valid settings + for number are between 0 and 3600 + inclusive. Here's some example output + with number + set to 10: + + Each line shows: + + U: total user time + W: total wallclock time + CPU: overall average cpu use + EvC: number of event checks. An event + check is a backwards branch in the simulated program, so this is a + measure of forward progress of the program + TIn: number of code blocks instrumented + by the JIT + TOut: number of instrumented code + blocks that have been thrown away + #thr: number of threads in the + program + + From the progress of these, it is possible to observe: + + when the program is compute bound (TIn + rises slowly, EvC rises rapidly) + when the program is in a spinloop + (TIn/TOut + fixed, EvC rises rapidly) + when the program is JIT-bound (TIn + rises rapidly) + when the program is rapidly discarding code + (TOut rises rapidly) + when the program is about to achieve some expected state + (EvC arrives at some value you + expect) + when the program is idling (U rises + more slowly than W) + + + + diff --git a/include/pub_tool_libcproc.h b/include/pub_tool_libcproc.h index a3a186bc65..96b6d6838e 100644 --- a/include/pub_tool_libcproc.h +++ b/include/pub_tool_libcproc.h @@ -98,12 +98,17 @@ extern Int VG_(getegid) ( void ); Timing ------------------------------------------------------------------ */ -// Returns the number of milliseconds passed since the progam started +// Returns the number of milliseconds passed since the program started // (roughly; it gets initialised partway through Valgrind's initialisation -// steps). +// steps). This is wallclock time. extern UInt VG_(read_millisecond_timer) ( void ); + extern Int VG_(gettimeofday)(struct vki_timeval *tv, struct vki_timezone *tz); +// Returns the number of milliseconds of user cpu time we have used, +// as reported by 'getrusage'. +extern UInt VG_(get_user_milliseconds)(void); + /* --------------------------------------------------------------------- atfork ------------------------------------------------------------------ */ diff --git a/include/vki/vki-linux.h b/include/vki/vki-linux.h index 4840a53e29..faacf7fb37 100644 --- a/include/vki/vki-linux.h +++ b/include/vki/vki-linux.h @@ -971,6 +971,11 @@ struct vki_sctp_getaddrs { // From linux-2.6.8.1/include/linux/resource.h //---------------------------------------------------------------------- +#define VKI_RUSAGE_SELF 0 +#define VKI_RUSAGE_CHILDREN (-1) +#define VKI_RUSAGE_BOTH (-2) /* sys_wait4() uses this */ +#define VKI_RUSAGE_THREAD 1 /* only the calling thread */ + struct vki_rusage { struct vki_timeval ru_utime; /* user time used */ struct vki_timeval ru_stime; /* system time used */ diff --git a/none/tests/cmdline2.stdout.exp b/none/tests/cmdline2.stdout.exp index 2599a1b2f1..fb42abb49a 100644 --- a/none/tests/cmdline2.stdout.exp +++ b/none/tests/cmdline2.stdout.exp @@ -170,6 +170,8 @@ usage: valgrind [options] prog-and-args heap blocks allocated for Valgrind internal use (in bytes) [4] --wait-for-gdb=yes|no pause on startup to wait for gdb attach --sym-offsets=yes|no show syms in form 'name+offset'? [no] + --progress-interval= report progress every + CPU seconds [0, meaning disabled] --command-line-only=no|yes only use command line options [no] Vex options for all Valgrind tools: