Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
Am 22.05.2014 11:59, schrieb Jeff King: On Thu, May 22, 2014 at 02:40:48AM +0200, Karsten Blees wrote: 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? Ah, I see. I misunderstood from your example above. I do agree that automatically stamping with __FILE__ and __LINE__ is very helpful there. Could we maybe restrict that use of the variadic macros to a few known-good compilers (maybe #ifdef __GNUC__, which also hits clang, and something to catch MSVC)? On other systems it would become a compile-time noop, and they could live without the feature. -Peff Alright then. I've queued vor v5: * add __FILE__ __LINE__ for all trace output, if the compiler supports variadic macros * add timestamp for all trace output * perhaps move trace declarations to new trace.h * improve commit messages of existing patches to clarify the issues discussed so far I'm on holiday next week , so please be patient... -- To unsubscribe from this list: send the line unsubscribe git in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
On Fri, May 23, 2014 at 04:43:38PM +0200, Karsten Blees wrote: Alright then. I've queued vor v5: * add __FILE__ __LINE__ for all trace output, if the compiler supports variadic macros * add timestamp for all trace output * perhaps move trace declarations to new trace.h * improve commit messages of existing patches to clarify the issues discussed so far Thanks, that all sounds reasonable. I'm on holiday next week , so please be patient... No hurry. :) -Peff -- To unsubscribe from this list: send the line unsubscribe git in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
On Thu, May 22, 2014 at 02:40:48AM +0200, Karsten Blees wrote: 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? Ah, I see. I misunderstood from your example above. I do agree that automatically stamping with __FILE__ and __LINE__ is very helpful there. Could we maybe restrict that use of the variadic macros to a few known-good compilers (maybe #ifdef __GNUC__, which also hits clang, and something to catch MSVC)? On other systems it would become a compile-time noop, and they could live without the feature. -Peff -- To unsubscribe from this list: send the line unsubscribe git in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
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 -- To unsubscribe from this list: send the line unsubscribe git in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
Jeff King p...@peff.net writes: 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? Yeah, I very much like both, the output and your suggestion to hook it into the existing infrastructure. 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 -- -- To unsubscribe from this list: send the line unsubscribe git in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
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? -- To unsubscribe from this list: send the line unsubscribe git in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
