add high resolution timer function to debug performance issues
PATCH v4 1/3 add high resolution timer function to debug performance issues
In reply to a message not in the archiveAdd a getnanotime() function that returns nanoseconds since 01/01/1970 as unsigned 64-bit integer (i.e. overflows in july 2554). This is easier to work with than e.g. struct timeval or struct timespec.
The implementation uses gettimeofday() by default; supports high precision time sources on the following platforms:
* Linux: using clock_gettime(CLOCK_MONOTONIC)
* Windows: using QueryPerformanceCounter()
Todo:
* enable clock_gettime() on more platforms
* implement Mac OSX version using mach_absolute_time
--- Makefile | 7 +++++ cache.h | 1 + config.mak.uname | 1 + trace.c | 82 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 4 files changed, 91 insertions(+)
Makefile +7 -0
@@ -341,6 +341,8 @@ all:: # # Define GMTIME_UNRELIABLE_ERRORS if your gmtime() function does not # return NULL when it receives a bogus time_t. +# +# Define HAVE_CLOCK_GETTIME if your platform has clock_gettime in librt. GIT-VERSION-FILE: FORCE @$(SHELL_PATH) ./GIT-VERSION-GEN
@@ -1497,6 +1499,11 @@ ifdef GMTIME_UNRELIABLE_ERRORS BASIC_CFLAGS += -DGMTIME_UNRELIABLE_ERRORS endif +ifdef HAVE_CLOCK_GETTIME + BASIC_CFLAGS += -DHAVE_CLOCK_GETTIME + EXTLIBS += -lrt +endif + ifeq ($(TCLTK_PATH),) NO_TCLTK = NoThanks endif
cache.h +1 -0
@@ -1362,6 +1362,7 @@ extern int trace_want(const char *key); __attribute__((format (printf,2 ,3 )))extern void trace_printf_key (const char *key,const char *fmt, ...);extern void trace_strbuf (const char *key,const struct strbuf *buf); +extern uint64_t getnanotime (void );void packet_trace_identity (const char *prog);
config.mak.uname +1 -0
@@ -33,6 +33,7 @@ ifeq ($(uname_S),Linux) HAVE_PATHS_H = YesPlease LIBC_CONTAINS_LIBINTL = YesPlease HAVE_DEV_TTY = YesPlease + HAVE_CLOCK_GETTIME = YesPlease endif ifeq ($(uname_S),GNU/kFreeBSD) NO_STRLCPY = YesPlease
trace.c +82 -0
85 lines not on this page · raw message
Signature · 21 lines
1.9.2.msysgit.0.493.g47a82c3 -- -- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
Quoted 3 lines · Karsten Blees
* implement Mac OSX version using
mach_absolute_time
Note that unlike the Windows and Linux APIs, mach_absolute_time does not do correction for frequency-scaling and cross-CPU synchronization with the TSC.
I'm not aware of anything else that you could use on MacOS, so your best bet is probably just to use mach_absolute_time and document it's shortcomings.
Regards, Noel.
Disclaimer: http://www.peralex.com/disclaimer.html
Am 21.05.2014 09:31, schrieb Noel Grandin:
Quoted 7 lines · Karsten Blees
Quoted 3 lines
* implement Mac OSX version using
mach_absolute_timeNote that unlike the Windows and Linux APIs,
mach_absolute_timedoes not do correction for frequency-scaling
I don't have a MAC so I can't test any of this, but supposedly mach_timebase_info() returns the frequency of mach_absolute_time(), so you could do similar frequency-scaling as I do for Windows with QueryPerformanceFrequency().
Quoted 2 lines
and cross-CPU synchronization with the TSC.
The TSC is synchronized across cores and sockets on modern x86 hardware [1] (at least since Intel Nehalem, i.e. all Core i[357] processors). On older machines, I would expect the OS API to choose a more appropriate time source, e.g. the HPET. I'm not proposing to use asm("rdtsc") or anything like that...
[1] https://software.intel.com/en-us/articles/best-timing-function-for-measuring-ipp-api-timing
Signature · 18 lines
-- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
PATCH v4 2/3 add trace_performance facility to debug performance issues
In reply to a message not in the archiveAdd trace_performance and trace_performance_since macros that print file name, line number, time and an optional printf-formatted text to the file specified in environment variable GIT_TRACE_PERFORMANCE.
Unless enabled via GIT_TRACE_PERFORMANCE, these macros have no noticeable impact on performance, so that test code may be shipped in release builds.
MSVC: variadic macros (__VA_ARGS__) require VC++ 2005 or newer.
Simple use case (measure one code section):
uint64_t start = getnanotime(); /* code section to measure */ trace_performance_since(start, "foobar");
Medium use case (measure consecutive code sections):
uint64_t start = getnanotime(); /* first code section to measure */ start = trace_performance_since(start, "first foobar"); /* second code section to measure */ trace_performance_since(start, "second foobar");
Complex use case (measure repetitive code sections):
uint64_t t = 0;
for (;;) {
/* ignore */
t -= getnanotime();
/* code section to measure */
t += getnanotime();
/* ignore */
}
trace_performance(t, "frotz");--- cache.h | 18 ++++++++++++++++++ trace.c | 40 ++++++++++++++++++++++++++++++++++++++++ 2 files changed, 58 insertions(+)
cache.h +18 -0
@@ -1363,6 +1363,24 @@ __attribute__((format (printf, 2, 3)))extern void trace_printf_key (const char *key,const char *fmt, ...);extern void trace_strbuf (const char *key,const struct strbuf *buf);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, ...); + +/* +* Prints specified time (in nanoseconds) if GIT_TRACE_PERFORMANCE is enabled. +* Returns current time in nanoseconds. +*/ +#define trace_performance (nanos, ...) \ + trace_performance_file_line(__FILE__, __LINE__, nanos, __VA_ARGS__) + +/* +* Prints time since 'start' if GIT_TRACE_PERFORMANCE is enabled. +* Returns current time in nanoseconds. +*/ +#define trace_performance_since (start, ...) \ + trace_performance_file_line(__FILE__, __LINE__, \ + getnanotime() - (start), __VA_ARGS__)void packet_trace_identity (const char *prog);
trace.c +40 -0
@@ -269,3 +269,43 @@ inline uint64_t getnanotime(void)return now; } } + +static const char *GIT_TRACE_PERFORMANCE ="GIT_TRACE_PERFORMANCE" ; + +static inline int trace_want_performance (void ) +{ +static int enabled =-1 ; +if (enabled <0 ) + enabled =trace_want (GIT_TRACE_PERFORMANCE ); +return enabled; +} + +/* +* Prints performance data if environment variable GIT_TRACE_PERFORMANCE is +* set, otherwise a NOOP. Returns the current time in nanoseconds. +*/ +__attribute__((format (printf,4 ,5 ))) +uint64_t trace_performance_file_line (const char *file,int lineno, +uint64_t nanos,const char *fmt, ...) +{ +struct strbuf buf =STRBUF_INIT ; +va_list args; + +if (!trace_want_performance ()) +return 0 ; + +strbuf_addf (&buf,"performance: at %s:%i, time: %.9f s" , file, lineno, + (double ) nanos /1000000000 ); + +if (fmt && *fmt) { +strbuf_addstr (&buf,": " ); +va_start (args, fmt); +strbuf_vaddf (&buf, fmt, args); +va_end (args); + } +strbuf_addch (&buf,'\n' ); + +trace_strbuf (GIT_TRACE_PERFORMANCE , &buf); +strbuf_release (&buf); +return getnanotime (); +}
Signature · 21 lines
1.9.2.msysgit.0.493.g47a82c3 -- -- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
PATCH v4 3/3 add command performance tracing to debug scripted commands
In reply to a message not in the archiveAdd 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'
--- cache.h | 1 + git.c | 2 ++ trace.c | 22 ++++++++++++++++++++++ 3 files changed, 25 insertions(+)
cache.h +1 -0
@@ -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.
git.c +2 -0
@@ -568,6 +568,8 @@ int main(int argc, char **av)git_setup_gettext (); +trace_command_performance (argv); +/* * "git-xxxx" is the same as "git xxxx", but we obviously: *
trace.c +22 -0
@@ -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 (); +}
Signature · 21 lines
1.9.2.msysgit.0.493.g47a82c3 -- -- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
Quoted 2 lines · Karsten Blees
Add a
getnanotime()function that returns nanoseconds since 01/01/1970 as unsigned 64-bit integer (i.e. overflows in july 2554).
Must it be relative to epoch? If it was relative to system boot (like the NetBSD kernel's nanouptime() function), then you wouldn't have to worry about clock adjustments messing with performance stats and you might have more options for implementing getnanotime() on various platforms.
-Richard
Quoted 6 lines · Richard Hansen
Quoted 2 lines · Karsten Blees
Add a
getnanotime()function that returns nanoseconds since 01/01/1970 as unsigned 64-bit integer (i.e. overflows in july 2554).Must it be relative to epoch? If it was relative to system boot (like the NetBSD kernel's
nanouptime()function),
or relative to some other arbitrary reference point
Quoted 5 lines
then you wouldn't have to
worry about clock adjustments messing with performance stats and you might have more options for implementinggetnanotime()on various platforms.-Richard
Am 22.05.2014 00:14, schrieb Richard Hansen:
Quoted 11 lines · Karsten Blees
Quoted 2 lines
Add a
getnanotime()function that returns nanoseconds since 01/01/1970 as unsigned 64-bit integer (i.e. overflows in july 2554).Must it be relative to epoch? If it was relative to system boot (like the NetBSD kernel's
nanouptime()function), then you wouldn't have to worry about clock adjustments messing with performance stats and you might have more options for implementinggetnanotime()on various platforms.-Richard
Normalizing to the epoch adds the ability to use the same timestamps (div 10e9) in other time-related functions (e.g. gmtime, ctime etc.), with very little overhead (one 64-bit integer addition per call).
The getnanotime() implementation is actually platform independent and can be backed by any time source that returns nanoseconds relative to anything. Getnanotime() is synced to the system clock only once on startup, so if your time source is monotonic (which I think NetBSD's nanouptime() is), you don't have to worry about clock adjustments.
Signature · 18 lines
-- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
Re: [RFC/PATCH v4 2/3] add trace_performance facility to debug performance issues
In reply to Karsten BleesQuoted 8 lines · Karsten Blees
Add
trace_performanceandtrace_performance_sincemacros that print file name, line number, time and an optional printf-formatted text to the file specified in environment variableGIT_TRACE_PERFORMANCE.Unless enabled via
GIT_TRACE_PERFORMANCE, these macros have no noticeable impact on performance, so that test code may be shipped in release builds.MSVC: variadic macros (
__VA_ARGS__) require VC++ 2005 or newer.
I think we still have some Unix compilers that do not do variadic macros, either. For a while, people were compiling with antique stuff like SUNWspro and MIPSpro. I don't know if they still do, if they use gcc on such systems now, or if those systems have finally been decomissioned.
But either we need to change our stance on variadic macros, or this feature needs to be able to be compiled conditionally.
-Peff
Signature · 18 lines
-- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
Re: [RFC/PATCH v4 2/3] add trace_performance facility to debug performance issues
Am 21.05.2014 18:58, schrieb Jeff King:
Quoted 17 lines · Karsten Blees
Quoted 9 lines
Add
trace_performanceandtrace_performance_sincemacros that print file name, line number, time and an optional printf-formatted text to the file specified in environment variableGIT_TRACE_PERFORMANCE.Unless enabled via
GIT_TRACE_PERFORMANCE, these macros have no noticeable impact on performance, so that test code may be shipped in release builds.MSVC: variadic macros (
__VA_ARGS__) require VC++ 2005 or newer.I think we still have some Unix compilers that do not do variadic macros, either. For a while, people were compiling with antique stuff like SUNWspro and MIPSpro. I don't know if they still do, if they use gcc on such systems now, or if those systems have finally been decomissioned.
Quoted 5 lines
But either we need to change our stance on variadic macros, or this feature needs to be able to be compiled conditionally.
-Peff
Macros are mainly used to supply __FILE__ and __LINE__, so that lazy people don't need to think of a unique message for each use of trace_performance_*. Without __FILE__, __LINE__ and message, the output would be pretty useless (i.e. just the time without any additional info).
If there's platforms that don't support variadic macros, I'd suggest to drop the __FILE__ __LINE__ feature completely and make message mandatory (with the added benefit that manually provided messages don't change if the code is moved, i.e. trace logs would become somewhat comparable across versions).
(adding cc: Dscho as IIRC the __FILE__ __LINE__ idea was originally his).
Signature · 18 lines
-- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
Re: [RFC/PATCH v4 2/3] add trace_performance facility to debug performance issues
Quoted 11 lines · Karsten Blees
Macros are mainly used to supply
__FILE__and__LINE__, so that lazy people don't need to think of a unique message for each use of trace_performance_*. Without__FILE__,__LINE__and message, the output would be pretty useless (i.e. just the time without any additional info).If there's platforms that don't support variadic macros, I'd suggest to drop the
__FILE____LINE__feature completely and make message mandatory (with the added benefit that manually provided messages don't change if the code is moved, i.e. trace logs would become somewhat comparable across versions).
I do think __FILE__ and __LINE__ can be useful, and it would not be the end of the world to simply omit them on platforms that can't do the variadic macros (there shouldn't be many these days, and I think they are used to living with reduced functionality in some cases).
But if this were attached to trace_printf, we would always have a message anyway, no?
-Peff
Signature · 18 lines
-- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
In reply to Karsten BleesQuoted 6 lines · Karsten Blees
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
Quoted 9 lines
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
Signature · 18 lines
-- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
Am 21.05.2014 18:55, schrieb Jeff King:
Quoted 23 lines · Karsten Blees
Quoted 7 lines
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
Quoted 9 lines
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_PERFORMANCEis set, add a timestamp to each line?
Quoted 6 lines
Then we would not need to add separate
trace_command_performancecalls, and other parts of the code that are already instrumented withGIT_TRACEwould 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?
Signature · 18 lines
-- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
Quoted 9 lines · Karsten Blees
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
Signature · 18 lines
-- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
In reply to Jeff KingQuoted 18 lines · Jeff King
Quoted 6 lines · Karsten Blees
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
Quoted 9 lines
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'
Quoted 4 lines
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_PERFORMANCEis 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.
Quoted 7 lines
Then we would not need to add separate
trace_command_performancecalls, and other parts of the code that are already instrumented withGIT_TRACEwould get the feature for free.-Peff
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
In reply to Jeff KingAm 22.05.2014 11:59, schrieb Jeff King:
Quoted 14 lines · Karsten Blees
Quoted 10 lines
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.
Quoted 8 lines
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...
Signature · 18 lines
-- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.
Re: [RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands
Quoted 5 lines · Karsten Blees
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 newtrace.h
* improve commit messages of existing patches to clarify the issues discussed so far
Thanks, that all sounds reasonable.
Quoted 1 line
I'm on holiday next week , so please be patient...
No hurry. :)
-Peff
Signature · 18 lines
-- *** 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 [email protected] To unsubscribe from this group, send email to [email protected] 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 [email protected]. For more options, visit https://groups.google.com/d/optout.