This is a proposal for a small enhancement to Valgrind's debugging output. For long runs of Valgrind, I find it useful to have some rough indication as to how the run is progressing. This makes it possible, for example, to guess when approximately the program will reach some desired state. The attached patch adds a new command line flag, --progress-interval=number. This causes V to print a 1-line summary of progress every |number| seconds. For example, when starting Firefox with --progress-interval=10, I get lines like this --32411-- PROGRESS: U 110s, W 113s, 97.3% CPU, EvC 414.79M, TIn 616.7k, TOut 0.5k, #thr 67 --32411-- PROGRESS: U 120s, W 124s, 96.8% CPU, EvC 505.27M, TIn 636.6k, TOut 3.0k, #thr 64 --32411-- PROGRESS: U 130s, W 134s, 97.0% CPU, EvC 574.90M, TIn 657.5k, TOut 3.0k, #thr 63 --32411-- PROGRESS: U 140s, W 144s, 97.2% CPU, EvC 636.34M, TIn 659.9k, TOut 3.0k, #thr 62 --32411-- PROGRESS: U 150s, W 155s, 96.8% CPU, EvC 710.21M, TIn 664.0k, TOut 17.7k, #thr 61 --32411-- PROGRESS: U 160s, W 201s, 79.6% CPU, EvC 822.38M, TIn 669.9k, TOut 75.8k, #thr 60 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) I have found this very useful this past few months and would like to land it.
Created attachment 107830 [details] Implementation. This works on Linux. It should work on Solaris and OSX too, with the limitation that it always shows zero user time. This is because UInt VG_(get_user_milliseconds) isn't implemented on those targets and so just returns zero.
Thank you for the patch, Julian. I will implement VG_(get_user_milliseconds)() for Solaris, that's not a problem. However I wonder why allowed values for --progress-interval are only 1..3600? Why not 0, the default? Please also do something with comments around next_report_due_at, they look really scary. This is not the first static variable we have in Valgrind... What happens if a Valgrind'ed process with --progress-interval > 0 is suspended for several minutes? Is the logic in maybe_progress_report() able to cope with this? And the last nit - please use %u for "#thr" formatting instead of "%d". nThreads is UInt.
And also please add the line explanation somewhere. User manual, verbose output...
Created attachment 109872 [details] Addresses all review comments in comments 2 and 3. Addresses all review comments in comments 2 and 3. Ivo, if you are happy with it, could you please do the Solaris version of VG_(get_user_milliseconds) ? Note, this patch stores millisecond values in a UInt (unsigned 32 bit int) and so will overflow after 49.71 days. I don't consider this to be a big problem.
(In reply to Julian Seward from comment #4) > Addresses all review comments in comments 2 and 3. Ivo, if you are > happy with it, could you please do the Solaris version of > VG_(get_user_milliseconds)? Will do that, Julian.
Created attachment 109992 [details] Patch with Solaris implementation added
Hi Julian, patch with Solaris implementation is attached. The patch has been refreshed to apply cleanly to the latest git HEAD and a NEWS entry added. It is ready to be pushed - let me know if I should do it.
Ivo, thanks for the fix. Yes, if you are happy with it, please do push it.
Pushed as commit bd077baa71a40b60dcf0286b9fb89d803323fd93. https://sourceware.org/git/?p=valgrind.git;a=commit;h=bd077baa71a40b60dcf0286b9fb89d803323fd93
(In reply to Ivo Raisr from comment #9) > Pushed as commit bd077baa71a40b60dcf0286b9fb89d803323fd93. Thanks!