Re: [PATCH] Reduce performance penalty for turned off traces

2017-11-17 Thread Jeff King 
On Wed, Nov 15, 2017 at 11:14:20AM -0800, Stefan Beller wrote:

> > I did manually disable HAVE_VARIADIC_MACROS and confirmed that the
> > result builds and passes the test suite (though I suspect that GIT_TRACE
> > is not well exercised by the suite).
> 
> GIT_TRACE is exercised in the test suite (though I am not sure if it counts
> as well-exercised) in t7406-submodule-update.sh for example, which uses
> GIT_TRACE to obtain information about thread parallelism used by Git, as
> that is not observable otherwise, if we assume that performance tests in the
> standard test suite are not feasible.

Hmm, yeah, that might cover it. What I'm worried about is that we missed
some case where NULL needed to become &trace_default_key. But I did look
for that in my review of the patch and didn't notice any spots. And the
coverage in t7406 should help.

> > After your patch, the GIT_TRACE=1 time remains the same but GIT_TRACE=0
> > drops to 1ms.
> 
> So does that mean we can use a lot more tracing now?

Yep, that's the intent.

-Peff

Re: [PATCH] Reduce performance penalty for turned off traces

2017-11-17 Thread Jeff King 
On Sun, Nov 12, 2017 at 11:24:11PM +, Gennady Kupava wrote:

> In reality, gcc didn't do that and I saw 3 function calls. I am pretty
> sure that compiler of the distant bright future will do that, and only
> problem would be to eliminate that single function call. Hopefully
> with -flto it will also eliminate this single functions call, at it
> will be able to see through translation units. Given that I actually
> like current implementation as it hides all details in .c file.

Yeah, I agree with your analysis that we are really just overriding what
could eventually be figured out by the compiler during LTO.

I do think this is worth pursuing in the meantime, though, because it's
not _too_ much work, and we don't know when that magical optimizing
compiler will appear. :) So this frees us up in the meantime to worry
less about the cost of tracing.

> Now, implementation you suggesting moves extra things into .h, so it
> is imperfect in terms above, while things I suggested moves only
> necessary bit of checking the necessity to do anything, which is only
> (interesting) part should be executed while traces are off, and the
> only part we really want to be inlined.

I only meant to suggest moving the necessary checking into the .h file.
It's just that we have to make it a static inline for cases where we
don't have variadic macros. Anyway, I'm OK with your original notion of
leaving the non-variadic-macro systems on the "slow" path, so we can
just go with the pure-macro thing you have.

> > So it is measurable, and we might expect that tracing a really big loop
> > (say over all of the objects in the repository) would benefit. OTOH, a
> > real loop would actually be doing other stuff, so the speedup would be
> > less dramatic. Still, it seems like an easy win.
> 
> I actually quite familiar with performance analysis and know how to
> use perf and similar tools a bit -
> so if there is something more measurable in TODO, I could try. But I
> guess this is interesting to many devs so such tasks probably already
> all done and bottlenecks are identified in git =)

There are lots of bottlenecks still to be found, I'm sure. If you want
to have a go at finding some with perf, be my guest. :)

-Peff

Re: [PATCH] Reduce performance penalty for turned off traces

2017-11-15 Thread Stefan Beller 
On Sun, Nov 12, 2017 at 6:17 AM, Jeff King  wrote:
> On Sat, Nov 11, 2017 at 07:28:58PM +, gennady.kup...@gmail.com wrote:
>
>> From: Gennady Kupava 
>>
>> Signed-off-by: Gennady Kupava 
>
> Thanks, and welcome to the list.

Welcome to the list!

> I did manually disable HAVE_VARIADIC_MACROS and confirmed that the
> result builds and passes the test suite (though I suspect that GIT_TRACE
> is not well exercised by the suite).

GIT_TRACE is exercised in the test suite (though I am not sure if it counts
as well-exercised) in t7406-submodule-update.sh for example, which uses
GIT_TRACE to obtain information about thread parallelism used by Git, as
that is not observable otherwise, if we assume that performance tests in the
standard test suite are not feasible.

> I tried timing a simple loop like:
> 
> Without your patch, the times for GIT_TRACE=1 and GIT_TRACE=0 are about
> 500ms and 9ms respectively.
>
> After your patch, the GIT_TRACE=1 time remains the same but GIT_TRACE=0
> drops to 1ms.

So does that mean we can use a lot more tracing now?

Thanks,
Stefan

Re: [PATCH] Reduce performance penalty for turned off traces

2017-11-12 Thread Gennady Kupava 
Hi Jeff, thanks for such detailed review and additional testing.

Below are just some discussion related review comments,
Please expect patch itself on some evening during coming week.

On 12 November 2017 at 14:17, Jeff King  wrote:
>
> On Sat, Nov 11, 2017 at 07:28:58PM +, gennady.kup...@gmail.com wrote:
>
> > From: Gennady Kupava 
> >
> > Signed-off-by: Gennady Kupava 
>
> Thanks, and welcome to the list.
>
>
> > ---
> > One of the tasks siggested in scope of 'Git sprint weekend'.
> > Couple of chioces made here:
>
> These kinds of choices/caveats (along with the motivation for the patch)
> should go into the commit message so people running "git log" later can
> see them.

Will split into two patches.

>
> >  1. Use constant instead of NULL to indicate default trace level, this just
> > makes everything simpler.
>
> I think this makes sense, as we were translating NULL into this default
> struct behind the scenes already. As we discussed off-list, this does
> mean that you can no longer do:
>
>   trace_printf_key(NULL, "foo");
>
> to send to the default key, and instead must do:
>
>   trace_printf("foo");
>
> The second one has always been the preferred way of spelling it, but the
> first one happened to work. So the only fallout would be if somebody is
> using the non-preferred method, they'd now segfault. There aren't any
> such calls in the current code base, though, and I find it rather
> unlikely that there would be new instances in topics other people are
> working on.
>
> I think it may be worth splitting that out into a separate preparatory
> patch to make it more clear what's going on (especially if our
> assumption turns out wrong and somebody does end up tracing a problem
> back to it).


Logic which lead me to removing NULL:
_If_ we want to do some kind of trivial check before calling functions
from other
translation units (which is always real function call), we have to
have some kind
of status immediately available in .h file.
I saw two options here:
 - move whole 'normalization' procedure to .h
 - remove 'normalization' procedure

Reasons removal option was chosen:
 - I found no code which actually uses NULL as a parameter option.
 - Given the nature of the key parameter ( struct key* )
I was just really unable to find any reasonable use
case there caller really want to pass NULL, so it seemed to me that
best solution
is to remove it. I still can imagine something like dynamic trace
category coming from
some kind of configuration file. In such special case there caller
might need it,
he might just do check in calling code once or just simply add it.
 - Squash big more performance as we do not need to do this
normalization on every call.

I will elaborate on 'moving whole implementation later'

>
> >  2. Move just enough from implementation to header, to be able to do check
> > before calling actual functions.
>
> Makes sense.
>
> >  3. Most controversail: do not support optimization for older
> > compilers not supporting variadic templates in macroses. Problem
> > is that theoretically someone may write some complicated trace
> > while would work in 'modern' compiler and be too slow in more
> > 'classic' compilers, however expectation is that risk of that is
> > quite low and 'classic' compilers will go away eventually.
>
> I think this is probably acceptable. I know we've discussed elsewhere
> recently how common such compilers actually are, and whether we could
> give up on them altogether.
>
> If we wanted to, we could support that case by using inline functions in
> the header (though it does make me wonder if compilers that old also do
> not actually end up inlining).
>
> I did manually disable HAVE_VARIADIC_MACROS and confirmed that the
> result builds and passes the test suite (though I suspect that GIT_TRACE
> is not well exercised by the suite).
>

Good.

>
> > diff --git a/trace.c b/trace.c
> > index 7508aea02..180ee3b00 100644
> > --- a/trace.c
> > +++ b/trace.c
> > @@ -25,26 +25,14 @@
> >  #include "cache.h"
> >  #include "quote.h"
> >
> > -/*
> > - * "Normalize" a key argument by converting NULL to our trace_default,
> > - * and otherwise passing through the value. All caller-facing functions
> > - * should normalize their inputs in this way, though most get it
> > - * for free by calling get_trace_fd() (directly or indirectly).
> > - */
> > -static void normalize_trace_key(struct trace_key **key)
> > -{
> > - static struct trace_key trace_default = { "GIT_TRACE" };
> > - if (!*key)
> > - *key = &trace_default;
> > -}
> > +struct trace_key trace_default_key = { TRACE_KEY_PREFIX, 0, 0, 0 };
>
> Makes sense. We no longer auto-normalize, but just expect the
> appropriate functions to pass a pointer to the default key themselves.

This is again (more details below) choice of how much implementation details we
want to move into header file.

>
>
> > +struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
>
> This change was unex

Re: [PATCH] Reduce performance penalty for turned off traces

2017-11-12 Thread Jeff King 
On Sat, Nov 11, 2017 at 07:28:58PM +, gennady.kup...@gmail.com wrote:

> From: Gennady Kupava 
> 
> Signed-off-by: Gennady Kupava 

Thanks, and welcome to the list.

> ---
> One of the tasks siggested in scope of 'Git sprint weekend'.
> Couple of chioces made here:

These kinds of choices/caveats (along with the motivation for the patch)
should go into the commit message so people running "git log" later can
see them.

>  1. Use constant instead of NULL to indicate default trace level, this just
> makes everything simpler.

I think this makes sense, as we were translating NULL into this default
struct behind the scenes already. As we discussed off-list, this does
mean that you can no longer do:

  trace_printf_key(NULL, "foo");

to send to the default key, and instead must do:

  trace_printf("foo");

The second one has always been the preferred way of spelling it, but the
first one happened to work. So the only fallout would be if somebody is
using the non-preferred method, they'd now segfault. There aren't any
such calls in the current code base, though, and I find it rather
unlikely that there would be new instances in topics other people are
working on.

I think it may be worth splitting that out into a separate preparatory
patch to make it more clear what's going on (especially if our
assumption turns out wrong and somebody does end up tracing a problem
back to it).

>  2. Move just enough from implementation to header, to be able to do check
> before calling actual functions.

Makes sense.

>  3. Most controversail: do not support optimization for older
> compilers not supporting variadic templates in macroses. Problem
> is that theoretically someone may write some complicated trace
> while would work in 'modern' compiler and be too slow in more
> 'classic' compilers, however expectation is that risk of that is
> quite low and 'classic' compilers will go away eventually.

I think this is probably acceptable. I know we've discussed elsewhere
recently how common such compilers actually are, and whether we could
give up on them altogether.

If we wanted to, we could support that case by using inline functions in
the header (though it does make me wonder if compilers that old also do
not actually end up inlining).

I did manually disable HAVE_VARIADIC_MACROS and confirmed that the
result builds and passes the test suite (though I suspect that GIT_TRACE
is not well exercised by the suite).

> diff --git a/trace.c b/trace.c
> index 7508aea02..180ee3b00 100644
> --- a/trace.c
> +++ b/trace.c
> @@ -25,26 +25,14 @@
>  #include "cache.h"
>  #include "quote.h"
>  
> -/*
> - * "Normalize" a key argument by converting NULL to our trace_default,
> - * and otherwise passing through the value. All caller-facing functions
> - * should normalize their inputs in this way, though most get it
> - * for free by calling get_trace_fd() (directly or indirectly).
> - */
> -static void normalize_trace_key(struct trace_key **key)
> -{
> - static struct trace_key trace_default = { "GIT_TRACE" };
> - if (!*key)
> - *key = &trace_default;
> -}
> +struct trace_key trace_default_key = { TRACE_KEY_PREFIX, 0, 0, 0 };

Makes sense. We no longer auto-normalize, but just expect the
appropriate functions to pass a pointer to the default key themselves.

> +struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);

This change was unexpected, but I think you just moved this up to keep
all the pre-declared structs together. Makes sense.

>  /* Get a trace file descriptor from "key" env variable. */
>  static int get_trace_fd(struct trace_key *key)
>  {
>   const char *trace;
>  
> - normalize_trace_key(&key);
> -
>   /* don't open twice */
>   if (key->initialized)
>   return key->fd;

And this and similar changes to drop normalize_trace_key() all make
sense with the earlier hunk. Good.

> @@ -341,7 +324,7 @@ void trace_repo_setup(const char *prefix)
>  
>  int trace_want(struct trace_key *key)
>  {
> - return !!get_trace_fd(key);
> +   return !!get_trace_fd(key);
>  }

This line accidentally swapped out the tab for spaces.

> diff --git a/trace.h b/trace.h
> index 179b249c5..64326573a 100644
> --- a/trace.h
> +++ b/trace.h
> @@ -4,6 +4,8 @@
>  #include "git-compat-util.h"
>  #include "strbuf.h"
>  
> +#define TRACE_KEY_PREFIX "GIT_TRACE"
> [..]
> -#define TRACE_KEY_INIT(name) { "GIT_TRACE_" #name, 0, 0, 0 }
> +#define TRACE_KEY_INIT(name) { TRACE_KEY_PREFIX "_" #name, 0, 0, 0 }

I see you pulled this out so you could use TRACE_KEY_PREFIX elsewhere
for the default key. Yes, the default key and the prefix do happen to be
related in that way, but I actually think it was a bit less obfuscated
the original way, even it repeated the string "GIT_TRACE" twice.

> +#define trace_pass(key) ((key)->fd || !(key)->initialized)

Factoring this out makes sense, since we have to repeat it in each
macro.

Speaking of macros, one side effect of this whole patch is that the

[PATCH] Reduce performance penalty for turned off traces

2017-11-11 Thread gennady . kupava 
From: Gennady Kupava 

Signed-off-by: Gennady Kupava 
---
One of the tasks siggested in scope of 'Git sprint weekend'.
Couple of chioces made here:
 1. Use constant instead of NULL to indicate default trace level, this just
makes everything simpler.
 2. Move just enough from implementation to header, to be able to do check
before calling actual functions.
 3. Most controversail: do not support optimization for older compilers not
supporting variadic templates in macroses. Problem is that theoretically
someone may write some complicated trace while would work in 'modern' compiler 
and be too slow in more 'classic' compilers, however expectation is that risk 
of that is quite low and 'classic' compilers will go away eventually.

Passes test suite locally on Linux/amd64.

 trace.c | 29 ++--
 trace.h | 68 +++--
 2 files changed, 55 insertions(+), 42 deletions(-)

diff --git a/trace.c b/trace.c
index 7508aea02..180ee3b00 100644
--- a/trace.c
+++ b/trace.c
@@ -25,26 +25,14 @@
 #include "cache.h"
 #include "quote.h"
 
-/*
- * "Normalize" a key argument by converting NULL to our trace_default,
- * and otherwise passing through the value. All caller-facing functions
- * should normalize their inputs in this way, though most get it
- * for free by calling get_trace_fd() (directly or indirectly).
- */
-static void normalize_trace_key(struct trace_key **key)
-{
-   static struct trace_key trace_default = { "GIT_TRACE" };
-   if (!*key)
-   *key = &trace_default;
-}
+struct trace_key trace_default_key = { TRACE_KEY_PREFIX, 0, 0, 0 };
+struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
 
 /* Get a trace file descriptor from "key" env variable. */
 static int get_trace_fd(struct trace_key *key)
 {
const char *trace;
 
-   normalize_trace_key(&key);
-
/* don't open twice */
if (key->initialized)
return key->fd;
@@ -82,8 +70,6 @@ static int get_trace_fd(struct trace_key *key)
 
 void trace_disable(struct trace_key *key)
 {
-   normalize_trace_key(&key);
-
if (key->need_close)
close(key->fd);
key->fd = 0;
@@ -129,7 +115,6 @@ static int prepare_trace_line(const char *file, int line,
 static void trace_write(struct trace_key *key, const void *buf, unsigned len)
 {
if (write_in_full(get_trace_fd(key), buf, len) < 0) {
-   normalize_trace_key(&key);
warning("unable to write trace for %s: %s",
key->key, strerror(errno));
trace_disable(key);
@@ -168,13 +153,13 @@ static void trace_argv_vprintf_fl(const char *file, int 
line,
 {
struct strbuf buf = STRBUF_INIT;
 
-   if (!prepare_trace_line(file, line, NULL, &buf))
+   if (!prepare_trace_line(file, line, &trace_default_key, &buf))
return;
 
strbuf_vaddf(&buf, format, ap);
 
sq_quote_argv(&buf, argv, 0);
-   print_trace_line(NULL, &buf);
+   print_trace_line(&trace_default_key, &buf);
 }
 
 void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
@@ -189,8 +174,6 @@ void trace_strbuf_fl(const char *file, int line, struct 
trace_key *key,
print_trace_line(key, &buf);
 }
 
-static struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
-
 static void trace_performance_vprintf_fl(const char *file, int line,
 uint64_t nanos, const char *format,
 va_list ap)
@@ -216,7 +199,7 @@ void trace_printf(const char *format, ...)
 {
va_list ap;
va_start(ap, format);
-   trace_vprintf_fl(NULL, 0, NULL, format, ap);
+   trace_vprintf_fl(NULL, 0, &trace_default_key, format, ap);
va_end(ap);
 }
 
@@ -341,7 +324,7 @@ void trace_repo_setup(const char *prefix)
 
 int trace_want(struct trace_key *key)
 {
-   return !!get_trace_fd(key);
+   return !!get_trace_fd(key);
 }
 
 #if defined(HAVE_CLOCK_GETTIME) && defined(HAVE_CLOCK_MONOTONIC)
diff --git a/trace.h b/trace.h
index 179b249c5..64326573a 100644
--- a/trace.h
+++ b/trace.h
@@ -4,6 +4,8 @@
 #include "git-compat-util.h"
 #include "strbuf.h"
 
+#define TRACE_KEY_PREFIX "GIT_TRACE"
+
 struct trace_key {
const char * const key;
int fd;
@@ -11,7 +13,10 @@ struct trace_key {
unsigned int  need_close : 1;
 };
 
-#define TRACE_KEY_INIT(name) { "GIT_TRACE_" #name, 0, 0, 0 }
+#define TRACE_KEY_INIT(name) { TRACE_KEY_PREFIX "_" #name, 0, 0, 0 }
+
+extern struct trace_key trace_default_key;
+extern struct trace_key trace_perf_key;
 
 extern void trace_repo_setup(const char *prefix);
 extern int trace_want(struct trace_key *key);
@@ -77,24 +82,49 @@ extern void trace_performance_since(uint64_t start, const 
char *format, ...);
  * comma, but this is non-standard.
  */
 
-#define trace_printf(...) \
-   trace_printf_key_fl(TRACE_CONTEXT, __LINE__, NULL, __VA_ARGS__)
-