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
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 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
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
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
Jeff King 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
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
[RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
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'
Signed-off-by: Karsten Blees
---
cache.h | 1 +
git.c | 2 ++
trace.c | 22 ++
3 files changed, 25 insertions(+)
diff --git a/cache.h b/cache.h
index cb856d9..289e8fd 100644
--- a/cache.h
+++ b/cache.h
@@ -1366,6 +1366,7 @@ extern uint64_t getnanotime(void);
__attribute__((format (printf, 4, 5)))
extern uint64_t trace_performance_file_line(const char *file, int lineno,
uint64_t nanos, const char *fmt, ...);
+extern void trace_command_performance(const char **argv);
/*
* Prints specified time (in nanoseconds) if GIT_TRACE_PERFORMANCE is enabled.
diff --git a/git.c b/git.c
index 9efd1a3..2ea65b1 100644
--- a/git.c
+++ b/git.c
@@ -568,6 +568,8 @@ int main(int argc, char **av)
git_setup_gettext();
+ trace_command_performance(argv);
+
/*
* "git-" is the same as "git ", but we obviously:
*
diff --git a/trace.c b/trace.c
index 1b1903b..9edcb59 100644
--- a/trace.c
+++ b/trace.c
@@ -309,3 +309,25 @@ uint64_t trace_performance_file_line(const char *file, int
lineno,
strbuf_release(&buf);
return getnanotime();
}
+
+static uint64_t command_start_time;
+static struct strbuf command_line = STRBUF_INIT;
+
+static void print_command_performance_atexit(void)
+{
+ trace_performance_since(command_start_time, "git command:%s",
+ command_line.buf);
+}
+
+void trace_command_performance(const char **argv)
+{
+ if (!trace_want_performance())
+ return;
+
+ if (!command_start_time)
+ atexit(print_command_performance_atexit);
+
+ strbuf_reset(&command_line);
+ sq_quote_argv(&command_line, argv, 0);
+ command_start_time = getnanotime();
+}
--
1.9.2.msysgit.0.493.g47a82c3
--
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
