Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands

[Karsten Blees <karsten.blees@gmail.com>]

Am 21.05.2014 18:55, schrieb Jeff King:
> On Tue, May 20, 2014 at 09:11:24PM +0200, Karsten Blees wrote:
> 
>> Add performance tracing to identify which git commands are called and how
>> long they execute. This is particularly useful to debug performance issues
>> of scripted commands.
>>
>> Usage example: > GIT_TRACE_PERFORMANCE=~/git-trace.log git stash list
>>
>> Creates a log file like this:
>> performance: at trace.c:319, time: 0.000303280 s: git command: 'git' 'rev-parse' '--git-dir'
>> performance: at trace.c:319, time: 0.000334409 s: git command: 'git' 'rev-parse' '--is-inside-work-tree'
>> performance: at trace.c:319, time: 0.000215243 s: git command: 'git' 'rev-parse' '--show-toplevel'
>> performance: at trace.c:319, time: 0.000410639 s: git command: 'git' 'config' '--get-colorbool' 'color.interactive'
>> performance: at trace.c:319, time: 0.000394077 s: git command: 'git' 'config' '--get-color' 'color.interactive.help' 'red bold'
>> performance: at trace.c:319, time: 0.000280701 s: git command: 'git' 'config' '--get-color' '' 'reset'
>> performance: at trace.c:319, time: 0.000908185 s: git command: 'git' 'rev-parse' '--verify' 'refs/stash'
>> performance: at trace.c:319, time: 0.028827774 s: git command: 'git' 'stash' 'list'
> 
> Neat. I actually wanted something like this just yesterday. It looks
> like you are mainly tracing the execution of programs. Would it make
> sense to just tie this to regular trace_* calls, and if
> GIT_TRACE_PERFORMANCE is set, add a timestamp to each line?
> 
> Then we would not need to add separate trace_command_performance calls,
> and other parts of the code that are already instrumented with GIT_TRACE
> would get the feature for free.
> 
> -Peff
> 

IMO printing timestamps in all trace output would be a useful feature on its own, but its not what I'm trying to achieve here. Timestamps only give you a broad overview of when things started, not how long they took. And calculating the durations from timestamps in the log output is tedious work, esp. if multiple processes and threads are involved (would need pid and thread-id as well).

The first patch helps calculating durations (without having to mess with struct timespec/timeval), and the second helps logging the results. Its basically a utility for manual profiling. Printing total command execution time (this patch) is just one possible use case.

E.g. if I'm interested in a particular code section, I throw in 2 lines of code (before and after the code section). This gives very accurate results, without significantly affecting overall performance. I can then push the changes to my Linux/Windows box and get comparable results there. No need to disable optimization. No worries that the profiling tool isn't available on the other platform. No analyzing megabytes of mostly irrelevant profiling data.

Does that make sense?

-- 
-- 
*** Please reply-to-all at all times ***
*** (do not pretend to know who is subscribed and who is not) ***
*** Please avoid top-posting. ***
The msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.

You received this message because you are subscribed to the Google
Groups "msysGit" group.
To post to this group, send email to msysgit@googlegroups.com
To unsubscribe from this group, send email to
msysgit+unsubscribe@googlegroups.com
For more options, and view previous threads, visit this group at
http://groups.google.com/group/msysgit?hl=en_US?hl=en

--- 
You received this message because you are subscribed to the Google Groups "msysGit" group.
To unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.