[RFC/PATCH v4 1/3] add high resolution timer function to debug performance issues

[RFC/PATCH v4 1/3] add high resolution timer function to debug performance issues

[Karsten Blees]

Add 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

Signed-off-by: Karsten Blees <blees@dcon.de>
---
 Makefile         |  7 +++++
 cache.h          |  1 +
 config.mak.uname |  1 +
 trace.c          | 82 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 4 files changed, 91 insertions(+)

diff --git a/Makefile b/Makefile
index a53f3a8..3c05f8c 100644
--- a/Makefile
+++ b/Makefile
@@ -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
diff --git a/cache.h b/cache.h
index 107ac61..48fc616 100644
--- a/cache.h
+++ b/cache.h
@@ -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);
 
diff --git a/config.mak.uname b/config.mak.uname
index 23a8803..5e3b1dd 100644
--- a/config.mak.uname
+++ b/config.mak.uname
@@ -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
diff --git a/trace.c b/trace.c
index 08180a9..3d72084 100644
--- a/trace.c
+++ b/trace.c
@@ -187,3 +187,85 @@ int trace_want(const char *key)
 		return 0;
 	return 1;
 }
+
+#ifdef HAVE_CLOCK_GETTIME
+
+static inline uint64_t highres_nanos(void)
+{
+	struct timespec ts;
+	if (clock_gettime(CLOCK_MONOTONIC, &ts))
+		return 0;
+	return (uint64_t) ts.tv_sec * 1000000000 + ts.tv_nsec;
+}
+
+#elif defined (GIT_WINDOWS_NATIVE)
+
+static inline uint64_t highres_nanos(void)
+{
+	static uint64_t high_ns, scaled_low_ns;
+	static int scale;
+	LARGE_INTEGER cnt;
+
+	if (!scale) {
+		if (!QueryPerformanceFrequency(&cnt))
+			return 0;
+
+		/* high_ns = number of ns per cnt.HighPart */
+		high_ns = (1000000000LL << 32) / (uint64_t) cnt.QuadPart;
+
+		/*
+		 * Number of ns per cnt.LowPart is 10^9 / frequency (or
+		 * high_ns >> 32). For maximum precision, we scale this factor
+		 * so that it just fits within 32 bit (i.e. won't overflow if
+		 * multiplied with cnt.LowPart).
+		 */
+		scaled_low_ns = high_ns;
+		scale = 32;
+		while (scaled_low_ns >= 0x100000000LL) {
+			scaled_low_ns >>= 1;
+			scale--;
+		}
+	}
+
+	/* if QPF worked on initialization, we expect QPC to work as well */
+	QueryPerformanceCounter(&cnt);
+
+	return (high_ns * cnt.HighPart) +
+	       ((scaled_low_ns * cnt.LowPart) >> scale);
+}
+
+#else
+# define highres_nanos() 0
+#endif
+
+static inline uint64_t gettimeofday_nanos(void)
+{
+	struct timeval tv;
+	gettimeofday(&tv, NULL);
+	return (uint64_t) tv.tv_sec * 1000000000 + tv.tv_usec * 1000;
+}
+
+/*
+ * Returns nanoseconds since the epoch (01/01/1970), for performance tracing
+ * (i.e. favoring high precision over wall clock time accuracy).
+ */
+inline uint64_t getnanotime(void)
+{
+	static uint64_t offset;
+	if (offset > 1) {
+		/* initialization succeeded, return offset + high res time */
+		return offset + highres_nanos();
+	} else if (offset == 1) {
+		/* initialization failed, fall back to gettimeofday */
+		return gettimeofday_nanos();
+	} else {
+		/* initialize offset if high resolution timer works */
+		uint64_t now = gettimeofday_nanos();
+		uint64_t highres = highres_nanos();
+		if (highres)
+			offset = now - highres;
+		else
+			offset = 1;
+		return now;
+	}
+}
-- 
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 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.

Re: [RFC/PATCH v4 1/3] add high resolution timer function to debug performance issues

[Noel Grandin]

On 2014-05-20 21:11, Karsten Blees wrote:
>   * 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

Re: [RFC/PATCH v4 1/3] add high resolution timer function to debug performance issues

[Karsten Blees]

Am 21.05.2014 09:31, schrieb Noel Grandin:
> On 2014-05-20 21:11, Karsten Blees wrote:
>>   * 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

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().

> 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

-- 
-- 
*** 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.

Re: [RFC/PATCH v4 1/3] add high resolution timer function to debug performance issues

[Richard Hansen]

On 2014-05-20 15:11, Karsten Blees wrote:
> 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

Re: [RFC/PATCH v4 1/3] add high resolution timer function to debug performance issues

[Richard Hansen]

On 2014-05-21 18:14, Richard Hansen wrote:
> On 2014-05-20 15:11, Karsten Blees wrote:
>> 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

> 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

Re: [RFC/PATCH v4 1/3] add high resolution timer function to debug performance issues

[Karsten Blees]

Am 22.05.2014 00:14, schrieb Richard Hansen:
> On 2014-05-20 15:11, Karsten Blees wrote:
>> 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
> 

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.

-- 
-- 
*** 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.

[RFC/PATCH v4 2/3] add trace_performance facility to debug performance issues

[Karsten Blees]

Add 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");

Signed-off-by: Karsten Blees <blees@dcon.de>
---
 cache.h | 18 ++++++++++++++++++
 trace.c | 40 ++++++++++++++++++++++++++++++++++++++++
 2 files changed, 58 insertions(+)

diff --git a/cache.h b/cache.h
index 48fc616..cb856d9 100644
--- a/cache.h
+++ b/cache.h
@@ -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);
 
diff --git a/trace.c b/trace.c
index 3d72084..1b1903b 100644
--- a/trace.c
+++ b/trace.c
@@ -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();
+}
-- 
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 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.

Re: [RFC/PATCH v4 2/3] add trace_performance facility to debug performance issues

[Jeff King]

On Tue, May 20, 2014 at 09:11:19PM +0200, Karsten Blees wrote:

> Add 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.

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

-- 
-- 
*** 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.

Re: [RFC/PATCH v4 2/3] add trace_performance facility to debug performance issues

[Karsten Blees]

Am 21.05.2014 18:58, schrieb Jeff King:
> On Tue, May 20, 2014 at 09:11:19PM +0200, Karsten Blees wrote:
> 
>> Add 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.
> 
> 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
> 

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).

-- 
-- 
*** 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.

Re: [RFC/PATCH v4 2/3] add trace_performance facility to debug performance issues

[Jeff King]

On Wed, May 21, 2014 at 08:34:47PM +0200, Karsten Blees wrote:

> 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

-- 
-- 
*** 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.

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

[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

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 <blees@dcon.de>
---
 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-xxxx" is the same as "git xxxx", 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

-- 
-- 
*** 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.

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

[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

-- 
-- 
*** 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.

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

[Junio C Hamano]

Jeff King <peff@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
>
> -- 

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

[Karsten Blees]

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.

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

[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

-- 
-- 
*** 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.

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

[Karsten Blees]

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...

-- 
-- 
*** 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.

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

[Jeff King]

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

-- 
-- 
*** 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.