{"thread":{"id":"47172","subject":"[PATCH] Reduce performance penalty for turned off traces","startedAt":"2017-11-11T19:29:56Z","lastAt":"2017-11-27T10:12:22Z","messageCount":20,"participants":["gennady.kupava@gmail.com","Jeff King","Gennady Kupava","Stefan Beller","Junio C Hamano","Johannes Sixt"],"isPatch":true,"patchVersion":1,"patchTotal":null},"messages":[{"id":"332301","messageId":"20171111192858.27255-1-gennady.kupava@gmail.com","threadId":"47172","inReplyTo":null,"subject":"[PATCH] Reduce performance penalty for turned off traces","fromName":"","fromEmail":"gennady.kupava@gmail.com","sentAt":"2017-11-11T19:28:58Z","receivedAt":"2017-11-11T19:29:56Z","isPatch":true,"sender":{"key":"gennady.kupava@gmail.com","avatar":null},"body":"From: Gennady Kupava <gkupava@bloomberg.net>\n\nSigned-off-by: Gennady Kupava <gkupava@bloomberg.net>\n---\nOne of the tasks siggested in scope of 'Git sprint weekend'.\nCouple of chioces made here:\n 1. Use constant instead of NULL to indicate default trace level, this just\nmakes everything simpler.\n 2. Move just enough from implementation to header, to be able to do check\nbefore calling actual functions.\n 3. Most controversail: do not support optimization for older compilers not\nsupporting variadic templates in macroses. Problem is that theoretically\nsomeone 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.\n\nPasses test suite locally on Linux/amd64.\n\n trace.c | 29 ++++++----------------------\n trace.h | 68 +++++++++++++++++++++++++++++++++++++++++++++++------------------\n 2 files changed, 55 insertions(+), 42 deletions(-)\n\ndiff --git a/trace.c b/trace.c\nindex 7508aea02..180ee3b00 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -25,26 +25,14 @@\n #include \"cache.h\"\n #include \"quote.h\"\n \n-/*\n- * \"Normalize\" a key argument by converting NULL to our trace_default,\n- * and otherwise passing through the value. All caller-facing functions\n- * should normalize their inputs in this way, though most get it\n- * for free by calling get_trace_fd() (directly or indirectly).\n- */\n-static void normalize_trace_key(struct trace_key **key)\n-{\n-\tstatic struct trace_key trace_default = { \"GIT_TRACE\" };\n-\tif (!*key)\n-\t\t*key = &trace_default;\n-}\n+struct trace_key trace_default_key = { TRACE_KEY_PREFIX, 0, 0, 0 };\n+struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);\n \n /* Get a trace file descriptor from \"key\" env variable. */\n static int get_trace_fd(struct trace_key *key)\n {\n \tconst char *trace;\n \n-\tnormalize_trace_key(&key);\n-\n \t/* don't open twice */\n \tif (key->initialized)\n \t\treturn key->fd;\n@@ -82,8 +70,6 @@ static int get_trace_fd(struct trace_key *key)\n \n void trace_disable(struct trace_key *key)\n {\n-\tnormalize_trace_key(&key);\n-\n \tif (key->need_close)\n \t\tclose(key->fd);\n \tkey->fd = 0;\n@@ -129,7 +115,6 @@ static int prepare_trace_line(const char *file, int line,\n static void trace_write(struct trace_key *key, const void *buf, unsigned len)\n {\n \tif (write_in_full(get_trace_fd(key), buf, len) < 0) {\n-\t\tnormalize_trace_key(&key);\n \t\twarning(\"unable to write trace for %s: %s\",\n \t\t\tkey->key, strerror(errno));\n \t\ttrace_disable(key);\n@@ -168,13 +153,13 @@ static void trace_argv_vprintf_fl(const char *file, int line,\n {\n \tstruct strbuf buf = STRBUF_INIT;\n \n-\tif (!prepare_trace_line(file, line, NULL, &buf))\n+\tif (!prepare_trace_line(file, line, &trace_default_key, &buf))\n \t\treturn;\n \n \tstrbuf_vaddf(&buf, format, ap);\n \n \tsq_quote_argv(&buf, argv, 0);\n-\tprint_trace_line(NULL, &buf);\n+\tprint_trace_line(&trace_default_key, &buf);\n }\n \n void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n@@ -189,8 +174,6 @@ void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n \tprint_trace_line(key, &buf);\n }\n \n-static struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);\n-\n static void trace_performance_vprintf_fl(const char *file, int line,\n \t\t\t\t\t uint64_t nanos, const char *format,\n \t\t\t\t\t va_list ap)\n@@ -216,7 +199,7 @@ void trace_printf(const char *format, ...)\n {\n \tva_list ap;\n \tva_start(ap, format);\n-\ttrace_vprintf_fl(NULL, 0, NULL, format, ap);\n+\ttrace_vprintf_fl(NULL, 0, &trace_default_key, format, ap);\n \tva_end(ap);\n }\n \n@@ -341,7 +324,7 @@ void trace_repo_setup(const char *prefix)\n \n int trace_want(struct trace_key *key)\n {\n-\treturn !!get_trace_fd(key);\n+       return !!get_trace_fd(key);\n }\n \n #if defined(HAVE_CLOCK_GETTIME) && defined(HAVE_CLOCK_MONOTONIC)\ndiff --git a/trace.h b/trace.h\nindex 179b249c5..64326573a 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -4,6 +4,8 @@\n #include \"git-compat-util.h\"\n #include \"strbuf.h\"\n \n+#define TRACE_KEY_PREFIX \"GIT_TRACE\"\n+\n struct trace_key {\n \tconst char * const key;\n \tint fd;\n@@ -11,7 +13,10 @@ struct trace_key {\n \tunsigned int  need_close : 1;\n };\n \n-#define TRACE_KEY_INIT(name) { \"GIT_TRACE_\" #name, 0, 0, 0 }\n+#define TRACE_KEY_INIT(name) { TRACE_KEY_PREFIX \"_\" #name, 0, 0, 0 }\n+\n+extern struct trace_key trace_default_key;\n+extern struct trace_key trace_perf_key;\n \n extern void trace_repo_setup(const char *prefix);\n extern int trace_want(struct trace_key *key);\n@@ -77,24 +82,49 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);\n  * comma, but this is non-standard.\n  */\n \n-#define trace_printf(...) \\\n-\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, NULL, __VA_ARGS__)\n-\n-#define trace_printf_key(key, ...) \\\n-\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__)\n-\n-#define trace_argv_printf(argv, ...) \\\n-\ttrace_argv_printf_fl(TRACE_CONTEXT, __LINE__, argv, __VA_ARGS__)\n-\n-#define trace_strbuf(key, data) \\\n-\ttrace_strbuf_fl(TRACE_CONTEXT, __LINE__, key, data)\n-\n-#define trace_performance(nanos, ...) \\\n-\ttrace_performance_fl(TRACE_CONTEXT, __LINE__, nanos, __VA_ARGS__)\n-\n-#define trace_performance_since(start, ...) \\\n-\ttrace_performance_fl(TRACE_CONTEXT, __LINE__, getnanotime() - (start), \\\n-\t\t\t     __VA_ARGS__)\n+#define trace_pass(key) ((key)->fd || !(key)->initialized)\n+\n+#define trace_printf(...)\t\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass(&trace_default_key))\t\t\t    \\\n+\t\t\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__,        \\\n+\t\t\t\t\t    &trace_default_key,__VA_ARGS__);\\\n+\t} while(0)\n+\n+#define trace_printf_key(key, ...)\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass(key))\t\t\t\t\t    \\\n+\t\t\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, key,   \\\n+\t\t\t\t\t    __VA_ARGS__);\t\t    \\\n+\t} while(0)\n+\n+#define trace_argv_printf(argv, ...)\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass(&trace_default_key))\t\t\t    \\\n+\t\t       trace_argv_printf_fl(TRACE_CONTEXT, __LINE__,\t    \\\n+\t\t\t\t\t    argv, __VA_ARGS__);\t\t    \\\n+\t} while(0)\n+\n+#define trace_strbuf(key, data)\t\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass(key))\t\t\t\t\t    \\\n+\t\t\ttrace_strbuf_fl(TRACE_CONTEXT, __LINE__, key, data);\\\n+\t} while(0)\n+\n+#define trace_performance(nanos, ...)\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass(key))\t\t\t\t\t    \\\n+\t\t\ttrace_performance_fl(TRACE_CONTEXT, __LINE__, nanos,\\\n+\t\t\t\t\t     __VA_ARGS__);  \t\t    \\\n+\t} while(0)\n+\n+#define trace_performance_since(start, ...)\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass(&trace_perf_key))\t\t\t    \\\n+\t\t\ttrace_performance_fl(TRACE_CONTEXT, __LINE__,       \\\n+\t\t\t\t\t     getnanotime() - (start),\t    \\\n+\t\t\t\t\t     __VA_ARGS__);\t\t    \\\n+\t} while(0)\n \n /* backend functions, use non-*fl macros instead */\n __attribute__((format (printf, 4, 5)))\n-- \n2.14.1\n\n"},{"id":"332331","messageId":"20171112141737.nmnsygm4wrhtkqwb@sigill.intra.peff.net","threadId":"47172","inReplyTo":"20171111192858.27255-1-gennady.kupava@gmail.com","subject":"Re: [PATCH] Reduce performance penalty for turned off traces","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2017-11-12T14:17:38Z","receivedAt":"2017-11-12T14:17:46Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sat, Nov 11, 2017 at 07:28:58PM +0000, gennady.kupava@gmail.com wrote:\n\n> From: Gennady Kupava <gkupava@bloomberg.net>\n> \n> Signed-off-by: Gennady Kupava <gkupava@bloomberg.net>\n\nThanks, and welcome to the list.\n\n> ---\n> One of the tasks siggested in scope of 'Git sprint weekend'.\n> Couple of chioces made here:\n\nThese kinds of choices/caveats (along with the motivation for the patch)\nshould go into the commit message so people running \"git log\" later can\nsee them.\n\n>  1. Use constant instead of NULL to indicate default trace level, this just\n> makes everything simpler.\n\nI think this makes sense, as we were translating NULL into this default\nstruct behind the scenes already. As we discussed off-list, this does\nmean that you can no longer do:\n\n  trace_printf_key(NULL, \"foo\");\n\nto send to the default key, and instead must do:\n\n  trace_printf(\"foo\");\n\nThe second one has always been the preferred way of spelling it, but the\nfirst one happened to work. So the only fallout would be if somebody is\nusing the non-preferred method, they'd now segfault. There aren't any\nsuch calls in the current code base, though, and I find it rather\nunlikely that there would be new instances in topics other people are\nworking on.\n\nI think it may be worth splitting that out into a separate preparatory\npatch to make it more clear what's going on (especially if our\nassumption turns out wrong and somebody does end up tracing a problem\nback to it).\n\n>  2. Move just enough from implementation to header, to be able to do check\n> before calling actual functions.\n\nMakes sense.\n\n>  3. Most controversail: do not support optimization for older\n>     compilers not supporting variadic templates in macroses. Problem\n>     is that theoretically someone may write some complicated trace\n>     while would work in 'modern' compiler and be too slow in more\n>     'classic' compilers, however expectation is that risk of that is\n>     quite low and 'classic' compilers will go away eventually.\n\nI think this is probably acceptable. I know we've discussed elsewhere\nrecently how common such compilers actually are, and whether we could\ngive up on them altogether.\n\nIf we wanted to, we could support that case by using inline functions in\nthe header (though it does make me wonder if compilers that old also do\nnot actually end up inlining).\n\nI did manually disable HAVE_VARIADIC_MACROS and confirmed that the\nresult builds and passes the test suite (though I suspect that GIT_TRACE\nis not well exercised by the suite).\n\n> diff --git a/trace.c b/trace.c\n> index 7508aea02..180ee3b00 100644\n> --- a/trace.c\n> +++ b/trace.c\n> @@ -25,26 +25,14 @@\n>  #include \"cache.h\"\n>  #include \"quote.h\"\n>  \n> -/*\n> - * \"Normalize\" a key argument by converting NULL to our trace_default,\n> - * and otherwise passing through the value. All caller-facing functions\n> - * should normalize their inputs in this way, though most get it\n> - * for free by calling get_trace_fd() (directly or indirectly).\n> - */\n> -static void normalize_trace_key(struct trace_key **key)\n> -{\n> -\tstatic struct trace_key trace_default = { \"GIT_TRACE\" };\n> -\tif (!*key)\n> -\t\t*key = &trace_default;\n> -}\n> +struct trace_key trace_default_key = { TRACE_KEY_PREFIX, 0, 0, 0 };\n\nMakes sense. We no longer auto-normalize, but just expect the\nappropriate functions to pass a pointer to the default key themselves.\n\n> +struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);\n\nThis change was unexpected, but I think you just moved this up to keep\nall the pre-declared structs together. Makes sense.\n\n>  /* Get a trace file descriptor from \"key\" env variable. */\n>  static int get_trace_fd(struct trace_key *key)\n>  {\n>  \tconst char *trace;\n>  \n> -\tnormalize_trace_key(&key);\n> -\n>  \t/* don't open twice */\n>  \tif (key->initialized)\n>  \t\treturn key->fd;\n\nAnd this and similar changes to drop normalize_trace_key() all make\nsense with the earlier hunk. Good.\n\n> @@ -341,7 +324,7 @@ void trace_repo_setup(const char *prefix)\n>  \n>  int trace_want(struct trace_key *key)\n>  {\n> -\treturn !!get_trace_fd(key);\n> +       return !!get_trace_fd(key);\n>  }\n\nThis line accidentally swapped out the tab for spaces.\n\n> diff --git a/trace.h b/trace.h\n> index 179b249c5..64326573a 100644\n> --- a/trace.h\n> +++ b/trace.h\n> @@ -4,6 +4,8 @@\n>  #include \"git-compat-util.h\"\n>  #include \"strbuf.h\"\n>  \n> +#define TRACE_KEY_PREFIX \"GIT_TRACE\"\n> [..]\n> -#define TRACE_KEY_INIT(name) { \"GIT_TRACE_\" #name, 0, 0, 0 }\n> +#define TRACE_KEY_INIT(name) { TRACE_KEY_PREFIX \"_\" #name, 0, 0, 0 }\n\nI see you pulled this out so you could use TRACE_KEY_PREFIX elsewhere\nfor the default key. Yes, the default key and the prefix do happen to be\nrelated in that way, but I actually think it was a bit less obfuscated\nthe original way, even it repeated the string \"GIT_TRACE\" twice.\n\n> +#define trace_pass(key) ((key)->fd || !(key)->initialized)\n\nFactoring this out makes sense, since we have to repeat it in each\nmacro.\n\nSpeaking of macros, one side effect of this whole patch is that the\n\"key\" parmaeter is going to be evaluated multiple times. I think that's\nan acceptable tradeoff, as we'd basically always expect to pass the\naddress of a static struct here.\n\nIf that's a problem I think we _could_ do it with a combination of\nmacros and inline functions. The macro has to go in the outer layer in\norder to set __LINE__ properly. But something like:\n\n  static inline\n  void trace_printf_key_helper(const char *context, int line,\n                               struct trace_key *key,\n\t\t\t       const char *fmt, ...)\n  {\n\tif (trace_pass(key)) {\n\t\tva_list ap;\n\t\tva_start(ap, fmt);\n\t\ttrace_vprintf_key_fl(context, line, key, fmt, ap);\n\t\tva_end(ap);\n\t}\n  }\n\n  #define trace_printf_key(key, ...) \\\n\ttrace_printf_key_helper(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__);\n\nwould work, I think.\n\n> +#define trace_printf(...)\t\t\t\t\t\t    \\\n> +\tdo {\t\t\t\t\t\t\t\t    \\\n> +\t\tif (trace_pass(&trace_default_key))\t\t\t    \\\n> +\t\t\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__,        \\\n> +\t\t\t\t\t    &trace_default_key,__VA_ARGS__);\\\n> +\t} while(0)\n> +\n> +#define trace_printf_key(key, ...)\t\t\t\t\t    \\\n> +\tdo {\t\t\t\t\t\t\t\t    \\\n> +\t\tif (trace_pass(key))\t\t\t\t\t    \\\n> +\t\t\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, key,   \\\n> +\t\t\t\t\t    __VA_ARGS__);\t\t    \\\n> +\t} while(0)\n\nNow that these definitions are getting a bit more complex, I wonder if\nwe can implement them in terms of each other. I.e., could the first one\nbe:\n\n  #define trace_printf(...) trace_printf_key(&trace_default_key, __VA_ARGS__)\n\nI'm not sure if there are any gotchas with recursive variadic macros. If\nit's just this one macro that's not too big a deal, and it looks like\nmost of the rest of them end up having to call different functions and\ncan't nest like this. So it may not be worth troubling about.\n\n> +#define trace_argv_printf(argv, ...)\t\t\t\t\t    \\\n> [...]\n\nThe rest of this looks good.\n\nI tried timing a simple loop like:\n\ndiff --git a/git.c b/git.c\nindex 9e96dd4090..f3dbc15a99 100644\n--- a/git.c\n+++ b/git.c\n@@ -626,6 +626,11 @@ int cmd_main(int argc, const char **argv)\n {\n \tconst char *cmd;\n \tint done_help = 0;\n+\tint i;\n+\n+\tfor (i = 0; i < 1000000; i++)\n+\t\ttrace_printf(\"item %d\", i);\n+\treturn 0;\n \n \tcmd = argv[0];\n \tif (!cmd)\n\nWithout your patch, the times for GIT_TRACE=1 and GIT_TRACE=0 are about\n500ms and 9ms respectively.\n\nAfter your patch, the GIT_TRACE=1 time remains the same but GIT_TRACE=0\ndrops to 1ms.\n\nSo it is measurable, and we might expect that tracing a really big loop\n(say over all of the objects in the repository) would benefit. OTOH, a\nreal loop would actually be doing other stuff, so the speedup would be\nless dramatic. Still, it seems like an easy win.\n\n-Peff\n"},{"id":"332375","messageId":"CAPu-DQr0eRYiafF64=Mwm56xJgNPH0HVm+B4vKnzK0iAE4_xUg@mail.gmail.com","threadId":"47172","inReplyTo":"20171112141737.nmnsygm4wrhtkqwb@sigill.intra.peff.net","subject":"Re: [PATCH] Reduce performance penalty for turned off traces","fromName":"Gennady Kupava","fromEmail":"gennady.kupava@gmail.com","sentAt":"2017-11-12T23:24:11Z","receivedAt":"2017-11-12T23:24:19Z","isPatch":true,"sender":{"key":"gennady.kupava@gmail.com","avatar":null},"body":"Hi Jeff, thanks for such detailed review and additional testing.\n\nBelow are just some discussion related review comments,\nPlease expect patch itself on some evening during coming week.\n\nOn 12 November 2017 at 14:17, Jeff King <peff@peff.net> wrote:\n>\n> On Sat, Nov 11, 2017 at 07:28:58PM +0000, gennady.kupava@gmail.com wrote:\n>\n> > From: Gennady Kupava <gkupava@bloomberg.net>\n> >\n> > Signed-off-by: Gennady Kupava <gkupava@bloomberg.net>\n>\n> Thanks, and welcome to the list.\n>\n>\n> > ---\n> > One of the tasks siggested in scope of 'Git sprint weekend'.\n> > Couple of chioces made here:\n>\n> These kinds of choices/caveats (along with the motivation for the patch)\n> should go into the commit message so people running \"git log\" later can\n> see them.\n\nWill split into two patches.\n\n>\n> >  1. Use constant instead of NULL to indicate default trace level, this just\n> > makes everything simpler.\n>\n> I think this makes sense, as we were translating NULL into this default\n> struct behind the scenes already. As we discussed off-list, this does\n> mean that you can no longer do:\n>\n>   trace_printf_key(NULL, \"foo\");\n>\n> to send to the default key, and instead must do:\n>\n>   trace_printf(\"foo\");\n>\n> The second one has always been the preferred way of spelling it, but the\n> first one happened to work. So the only fallout would be if somebody is\n> using the non-preferred method, they'd now segfault. There aren't any\n> such calls in the current code base, though, and I find it rather\n> unlikely that there would be new instances in topics other people are\n> working on.\n>\n> I think it may be worth splitting that out into a separate preparatory\n> patch to make it more clear what's going on (especially if our\n> assumption turns out wrong and somebody does end up tracing a problem\n> back to it).\n\n\nLogic which lead me to removing NULL:\n_If_ we want to do some kind of trivial check before calling functions\nfrom other\ntranslation units (which is always real function call), we have to\nhave some kind\nof status immediately available in .h file.\nI saw two options here:\n - move whole 'normalization' procedure to .h\n - remove 'normalization' procedure\n\nReasons removal option was chosen:\n - I found no code which actually uses NULL as a parameter option.\n - Given the nature of the key parameter ( struct key* )\nI was just really unable to find any reasonable use\ncase there caller really want to pass NULL, so it seemed to me that\nbest solution\nis to remove it. I still can imagine something like dynamic trace\ncategory coming from\nsome kind of configuration file. In such special case there caller\nmight need it,\nhe might just do check in calling code once or just simply add it.\n - Squash big more performance as we do not need to do this\nnormalization on every call.\n\nI will elaborate on 'moving whole implementation later'\n\n>\n> >  2. Move just enough from implementation to header, to be able to do check\n> > before calling actual functions.\n>\n> Makes sense.\n>\n> >  3. Most controversail: do not support optimization for older\n> >     compilers not supporting variadic templates in macroses. Problem\n> >     is that theoretically someone may write some complicated trace\n> >     while would work in 'modern' compiler and be too slow in more\n> >     'classic' compilers, however expectation is that risk of that is\n> >     quite low and 'classic' compilers will go away eventually.\n>\n> I think this is probably acceptable. I know we've discussed elsewhere\n> recently how common such compilers actually are, and whether we could\n> give up on them altogether.\n>\n> If we wanted to, we could support that case by using inline functions in\n> the header (though it does make me wonder if compilers that old also do\n> not actually end up inlining).\n>\n> I did manually disable HAVE_VARIADIC_MACROS and confirmed that the\n> result builds and passes the test suite (though I suspect that GIT_TRACE\n> is not well exercised by the suite).\n>\n\nGood.\n\n>\n> > diff --git a/trace.c b/trace.c\n> > index 7508aea02..180ee3b00 100644\n> > --- a/trace.c\n> > +++ b/trace.c\n> > @@ -25,26 +25,14 @@\n> >  #include \"cache.h\"\n> >  #include \"quote.h\"\n> >\n> > -/*\n> > - * \"Normalize\" a key argument by converting NULL to our trace_default,\n> > - * and otherwise passing through the value. All caller-facing functions\n> > - * should normalize their inputs in this way, though most get it\n> > - * for free by calling get_trace_fd() (directly or indirectly).\n> > - */\n> > -static void normalize_trace_key(struct trace_key **key)\n> > -{\n> > -     static struct trace_key trace_default = { \"GIT_TRACE\" };\n> > -     if (!*key)\n> > -             *key = &trace_default;\n> > -}\n> > +struct trace_key trace_default_key = { TRACE_KEY_PREFIX, 0, 0, 0 };\n>\n> Makes sense. We no longer auto-normalize, but just expect the\n> appropriate functions to pass a pointer to the default key themselves.\n\nThis is again (more details below) choice of how much implementation details we\nwant to move into header file.\n\n>\n>\n> > +struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);\n>\n> This change was unexpected, but I think you just moved this up to keep\n> all the pre-declared structs together. Makes sense.\n>\n\nReason is that _if_ we want to cover trace_performance* macroses with\nour performance patch, we need to expose this implementation detail in\nheader file now.\nAnd I expect we do want, even if this interface is not used now.\n\n> >  /* Get a trace file descriptor from \"key\" env variable. */\n> >  static int get_trace_fd(struct trace_key *key)\n> >  {\n> >       const char *trace;\n> >\n> > -     normalize_trace_key(&key);\n> > -\n> >       /* don't open twice */\n> >       if (key->initialized)\n> >               return key->fd;\n>\n> And this and similar changes to drop normalize_trace_key() all make\n> sense with the earlier hunk. Good.\n>\n> > @@ -341,7 +324,7 @@ void trace_repo_setup(const char *prefix)\n> >\n> >  int trace_want(struct trace_key *key)\n> >  {\n> > -     return !!get_trace_fd(key);\n> > +       return !!get_trace_fd(key);\n> >  }\n>\n> This line accidentally swapped out the tab for spaces.\n\nWill fix that.\n\n>\n> > diff --git a/trace.h b/trace.h\n> > index 179b249c5..64326573a 100644\n> > --- a/trace.h\n> > +++ b/trace.h\n> > @@ -4,6 +4,8 @@\n> >  #include \"git-compat-util.h\"\n> >  #include \"strbuf.h\"\n> >\n> > +#define TRACE_KEY_PREFIX \"GIT_TRACE\"\n> > [..]\n> > -#define TRACE_KEY_INIT(name) { \"GIT_TRACE_\" #name, 0, 0, 0 }\n> > +#define TRACE_KEY_INIT(name) { TRACE_KEY_PREFIX \"_\" #name, 0, 0, 0 }\n>\n> I see you pulled this out so you could use TRACE_KEY_PREFIX elsewhere\n> for the default key. Yes, the default key and the prefix do happen to be\n> related in that way, but I actually think it was a bit less obfuscated\n> the original way, even it repeated the string \"GIT_TRACE\" twice.\n\nYeah, I thought for some time here as I don't like both approaches,\nslight duplication vs\nslight complication. Typically I choose slight complication, but now,\ngiving this another\nthought it seems like slight duplication is really better in this case.\n\n>\n> > +#define trace_pass(key) ((key)->fd || !(key)->initialized)\n>\n> Factoring this out makes sense, since we have to repeat it in each\n> macro.\n>\n> Speaking of macros, one side effect of this whole patch is that the\n> \"key\" parmaeter is going to be evaluated multiple times. I think that's\n> an acceptable tradeoff, as we'd basically always expect to pass the\n> address of a static struct here.\n\nYes, I though about this.\n\n>\n> If that's a problem I think we _could_ do it with a combination of\n> macros and inline functions.\n\nAgree. Actually there is solution to this specific problem\nwhich somehow didn't came to my mind yesterday. There is actually no\nreason for trace_pass to be a macro, it is better to make it an inline function.\n\n> The macro has to go in the outer layer in\n> order to set __LINE__ properly. But something like:\n>\n>   static inline\n>   void trace_printf_key_helper(const char *context, int line,\n>                                struct trace_key *key,\n>                                const char *fmt, ...)\n>   {\n>         if (trace_pass(key)) {\n>                 va_list ap;\n>                 va_start(ap, fmt);\n>                 trace_vprintf_key_fl(context, line, key, fmt, ap);\n>                 va_end(ap);\n>         }\n>   }\n>\n>   #define trace_printf_key(key, ...) \\\n>         trace_printf_key_helper(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__);\n>\n> would work, I think.\n\nIt would but...\n\nSo I think main question in this whole idea to optimize traces a bit is how much\nwe really want and need to move to header. All reasons here are quite marginal,\nbut whole task is quite marginal, so we have to operate in terms of\nmarginal reasons.\n\nSo, i took into what gcc actually generated in optimized assembly for this code\n(of course not in details, but just to find how much calls made). My expectation\nwas that gcc as one of best compilers optimize all that static\nfunctions into one, so we'll have\nsomething like one big function call to the functions which somewhere\non top will do\nthe check which is similar to trace_pass.\n\nIn reality, gcc didn't do that and I saw 3 function calls. I am pretty\nsure that compiler\nof the distant bright future will do that, and only problem would be\nto eliminate that\nsingle function call. Hopefully with -flto it will also eliminate this\nsingle functions call,\nat it will be able to see through translation units. Given that I\nactually like current\nimplementation as it hides all details in .c file.\n\nNoting on the side at this point that first theoretical conclusion\nhere is that even if we'll move whole\ntrace.c into trace.h we'll still have same 2-3 function calls.\n\nSo, now given the description above, what's the best way to improve performance,\nif we want?\nWe need to somehow do check in header, so gcc could inline that into\ncalling function.\nNow, how much of implementation details we want to move to header?\nI think it is good if we hide inside .c whatever we can.\nSo my solution was to keep all logic in implementation, move only\nnecessary things to header,\nso:\n - reader of header file would see as few implementation details as possible\n - compiler would not try to inline something which actually doesn't matter\n   (it only matters to inline something which checks if traces are\noff). As this trace.h is included\n   (indirectly) pretty much everywhere (287 object files out of 315),\nnot trying to re-compile and inline\n   things that many times will save some CPU cycles during build\nreducing build time and probably\n   even saving some non-binary trees =)\n\nNow, implementation you suggesting moves extra things into .h,\nso it is imperfect in terms above, while things I suggested moves only\nnecessary bit\nof checking the necessity to do anything, which is only (interesting) part\nshould be executed while traces are off, and the only part we really\nwant to be inlined.\n\nThat's the reasons, hopefully it makes sense, if not, I just don't see\nmuch difference\nand could implement it in different way.\n\n>\n> > +#define trace_printf(...)                                                \\\n> > +     do {                                                                \\\n> > +             if (trace_pass(&trace_default_key))                         \\\n> > +                     trace_printf_key_fl(TRACE_CONTEXT, __LINE__,        \\\n> > +                                         &trace_default_key,__VA_ARGS__);\\\n> > +     } while(0)\n> > +\n> > +#define trace_printf_key(key, ...)                                       \\\n> > +     do {                                                                \\\n> > +             if (trace_pass(key))                                        \\\n> > +                     trace_printf_key_fl(TRACE_CONTEXT, __LINE__, key,   \\\n> > +                                         __VA_ARGS__);                   \\\n> > +     } while(0)\n>\n> Now that these definitions are getting a bit more complex, I wonder if\n> we can implement them in terms of each other. I.e., could the first one\n> be:\n>\n>   #define trace_printf(...) trace_printf_key(&trace_default_key, __VA_ARGS__)\n>\n> I'm not sure if there are any gotchas with recursive variadic macros. If\n> it's just this one macro that's not too big a deal, and it looks like\n> most of the rest of them end up having to call different functions and\n> can't nest like this. So it may not be worth troubling about.\n\nI was not sure about variadic macro calling variadic macro as well, so\ndecided to not do that.\nNow I read that two lines in C99 standard related to __VA_ARGS__, it\nseems like nothing\npreventing that, so will do.\n\n>\n> > +#define trace_argv_printf(argv, ...)                                     \\\n> > [...]\n>\n> The rest of this looks good.\n>\n> I tried timing a simple loop like:\n>\n> diff --git a/git.c b/git.c\n> index 9e96dd4090..f3dbc15a99 100644\n> --- a/git.c\n> +++ b/git.c\n> @@ -626,6 +626,11 @@ int cmd_main(int argc, const char **argv)\n>  {\n>         const char *cmd;\n>         int done_help = 0;\n> +       int i;\n> +\n> +       for (i = 0; i < 1000000; i++)\n> +               trace_printf(\"item %d\", i);\n> +       return 0;\n>\n>         cmd = argv[0];\n>         if (!cmd)\n>\n> Without your patch, the times for GIT_TRACE=1 and GIT_TRACE=0 are about\n> 500ms and 9ms respectively.\n\nWell, still something measurable =) May be on some exotic hardware it\ncould be more...\n\n> After your patch, the GIT_TRACE=1 time remains the same but GIT_TRACE=0\n> drops to 1ms.\n>\n> So it is measurable, and we might expect that tracing a really big loop\n> (say over all of the objects in the repository) would benefit. OTOH, a\n> real loop would actually be doing other stuff, so the speedup would be\n> less dramatic. Still, it seems like an easy win.\n\nI actually quite familiar with performance analysis and know how to\nuse perf and similar tools a bit -\nso if there is something more measurable in TODO, I could try. But I\nguess this is\ninteresting to many devs so such tasks probably already all done and bottlenecks\nare identified in git =)\n\nWith best regards,\nGennady\n\nOn 12 November 2017 at 14:17, Jeff King <peff@peff.net> wrote:\n> On Sat, Nov 11, 2017 at 07:28:58PM +0000, gennady.kupava@gmail.com wrote:\n>\n>> From: Gennady Kupava <gkupava@bloomberg.net>\n>>\n>> Signed-off-by: Gennady Kupava <gkupava@bloomberg.net>\n>\n> Thanks, and welcome to the list.\n>\n>> ---\n>> One of the tasks siggested in scope of 'Git sprint weekend'.\n>> Couple of chioces made here:\n>\n> These kinds of choices/caveats (along with the motivation for the patch)\n> should go into the commit message so people running \"git log\" later can\n> see them.\n>\n>>  1. Use constant instead of NULL to indicate default trace level, this just\n>> makes everything simpler.\n>\n> I think this makes sense, as we were translating NULL into this default\n> struct behind the scenes already. As we discussed off-list, this does\n> mean that you can no longer do:\n>\n>   trace_printf_key(NULL, \"foo\");\n>\n> to send to the default key, and instead must do:\n>\n>   trace_printf(\"foo\");\n>\n> The second one has always been the preferred way of spelling it, but the\n> first one happened to work. So the only fallout would be if somebody is\n> using the non-preferred method, they'd now segfault. There aren't any\n> such calls in the current code base, though, and I find it rather\n> unlikely that there would be new instances in topics other people are\n> working on.\n>\n> I think it may be worth splitting that out into a separate preparatory\n> patch to make it more clear what's going on (especially if our\n> assumption turns out wrong and somebody does end up tracing a problem\n> back to it).\n>\n>>  2. Move just enough from implementation to header, to be able to do check\n>> before calling actual functions.\n>\n> Makes sense.\n>\n>>  3. Most controversail: do not support optimization for older\n>>     compilers not supporting variadic templates in macroses. Problem\n>>     is that theoretically someone may write some complicated trace\n>>     while would work in 'modern' compiler and be too slow in more\n>>     'classic' compilers, however expectation is that risk of that is\n>>     quite low and 'classic' compilers will go away eventually.\n>\n> I think this is probably acceptable. I know we've discussed elsewhere\n> recently how common such compilers actually are, and whether we could\n> give up on them altogether.\n>\n> If we wanted to, we could support that case by using inline functions in\n> the header (though it does make me wonder if compilers that old also do\n> not actually end up inlining).\n>\n> I did manually disable HAVE_VARIADIC_MACROS and confirmed that the\n> result builds and passes the test suite (though I suspect that GIT_TRACE\n> is not well exercised by the suite).\n>\n>> diff --git a/trace.c b/trace.c\n>> index 7508aea02..180ee3b00 100644\n>> --- a/trace.c\n>> +++ b/trace.c\n>> @@ -25,26 +25,14 @@\n>>  #include \"cache.h\"\n>>  #include \"quote.h\"\n>>\n>> -/*\n>> - * \"Normalize\" a key argument by converting NULL to our trace_default,\n>> - * and otherwise passing through the value. All caller-facing functions\n>> - * should normalize their inputs in this way, though most get it\n>> - * for free by calling get_trace_fd() (directly or indirectly).\n>> - */\n>> -static void normalize_trace_key(struct trace_key **key)\n>> -{\n>> -     static struct trace_key trace_default = { \"GIT_TRACE\" };\n>> -     if (!*key)\n>> -             *key = &trace_default;\n>> -}\n>> +struct trace_key trace_default_key = { TRACE_KEY_PREFIX, 0, 0, 0 };\n>\n> Makes sense. We no longer auto-normalize, but just expect the\n> appropriate functions to pass a pointer to the default key themselves.\n>\n>> +struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);\n>\n> This change was unexpected, but I think you just moved this up to keep\n> all the pre-declared structs together. Makes sense.\n>\n>>  /* Get a trace file descriptor from \"key\" env variable. */\n>>  static int get_trace_fd(struct trace_key *key)\n>>  {\n>>       const char *trace;\n>>\n>> -     normalize_trace_key(&key);\n>> -\n>>       /* don't open twice */\n>>       if (key->initialized)\n>>               return key->fd;\n>\n> And this and similar changes to drop normalize_trace_key() all make\n> sense with the earlier hunk. Good.\n>\n>> @@ -341,7 +324,7 @@ void trace_repo_setup(const char *prefix)\n>>\n>>  int trace_want(struct trace_key *key)\n>>  {\n>> -     return !!get_trace_fd(key);\n>> +       return !!get_trace_fd(key);\n>>  }\n>\n> This line accidentally swapped out the tab for spaces.\n>\n>> diff --git a/trace.h b/trace.h\n>> index 179b249c5..64326573a 100644\n>> --- a/trace.h\n>> +++ b/trace.h\n>> @@ -4,6 +4,8 @@\n>>  #include \"git-compat-util.h\"\n>>  #include \"strbuf.h\"\n>>\n>> +#define TRACE_KEY_PREFIX \"GIT_TRACE\"\n>> [..]\n>> -#define TRACE_KEY_INIT(name) { \"GIT_TRACE_\" #name, 0, 0, 0 }\n>> +#define TRACE_KEY_INIT(name) { TRACE_KEY_PREFIX \"_\" #name, 0, 0, 0 }\n>\n> I see you pulled this out so you could use TRACE_KEY_PREFIX elsewhere\n> for the default key. Yes, the default key and the prefix do happen to be\n> related in that way, but I actually think it was a bit less obfuscated\n> the original way, even it repeated the string \"GIT_TRACE\" twice.\n>\n>> +#define trace_pass(key) ((key)->fd || !(key)->initialized)\n>\n> Factoring this out makes sense, since we have to repeat it in each\n> macro.\n>\n> Speaking of macros, one side effect of this whole patch is that the\n> \"key\" parmaeter is going to be evaluated multiple times. I think that's\n> an acceptable tradeoff, as we'd basically always expect to pass the\n> address of a static struct here.\n>\n> If that's a problem I think we _could_ do it with a combination of\n> macros and inline functions. The macro has to go in the outer layer in\n> order to set __LINE__ properly. But something like:\n>\n>   static inline\n>   void trace_printf_key_helper(const char *context, int line,\n>                                struct trace_key *key,\n>                                const char *fmt, ...)\n>   {\n>         if (trace_pass(key)) {\n>                 va_list ap;\n>                 va_start(ap, fmt);\n>                 trace_vprintf_key_fl(context, line, key, fmt, ap);\n>                 va_end(ap);\n>         }\n>   }\n>\n>   #define trace_printf_key(key, ...) \\\n>         trace_printf_key_helper(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__);\n>\n> would work, I think.\n>\n>> +#define trace_printf(...)                                                \\\n>> +     do {                                                                \\\n>> +             if (trace_pass(&trace_default_key))                         \\\n>> +                     trace_printf_key_fl(TRACE_CONTEXT, __LINE__,        \\\n>> +                                         &trace_default_key,__VA_ARGS__);\\\n>> +     } while(0)\n>> +\n>> +#define trace_printf_key(key, ...)                                       \\\n>> +     do {                                                                \\\n>> +             if (trace_pass(key))                                        \\\n>> +                     trace_printf_key_fl(TRACE_CONTEXT, __LINE__, key,   \\\n>> +                                         __VA_ARGS__);                   \\\n>> +     } while(0)\n>\n> Now that these definitions are getting a bit more complex, I wonder if\n> we can implement them in terms of each other. I.e., could the first one\n> be:\n>\n>   #define trace_printf(...) trace_printf_key(&trace_default_key, __VA_ARGS__)\n>\n> I'm not sure if there are any gotchas with recursive variadic macros. If\n> it's just this one macro that's not too big a deal, and it looks like\n> most of the rest of them end up having to call different functions and\n> can't nest like this. So it may not be worth troubling about.\n>\n>> +#define trace_argv_printf(argv, ...)                                     \\\n>> [...]\n>\n> The rest of this looks good.\n>\n> I tried timing a simple loop like:\n>\n> diff --git a/git.c b/git.c\n> index 9e96dd4090..f3dbc15a99 100644\n> --- a/git.c\n> +++ b/git.c\n> @@ -626,6 +626,11 @@ int cmd_main(int argc, const char **argv)\n>  {\n>         const char *cmd;\n>         int done_help = 0;\n> +       int i;\n> +\n> +       for (i = 0; i < 1000000; i++)\n> +               trace_printf(\"item %d\", i);\n> +       return 0;\n>\n>         cmd = argv[0];\n>         if (!cmd)\n>\n> Without your patch, the times for GIT_TRACE=1 and GIT_TRACE=0 are about\n> 500ms and 9ms respectively.\n>\n> After your patch, the GIT_TRACE=1 time remains the same but GIT_TRACE=0\n> drops to 1ms.\n>\n> So it is measurable, and we might expect that tracing a really big loop\n> (say over all of the objects in the repository) would benefit. OTOH, a\n> real loop would actually be doing other stuff, so the speedup would be\n> less dramatic. Still, it seems like an easy win.\n>\n> -Peff\n"},{"id":"332615","messageId":"CAGZ79kb4Eo0AC4Z42_ks5_+Pcy4DrDCufNb=5J=g8L6pMnHd7A@mail.gmail.com","threadId":"47172","inReplyTo":"20171112141737.nmnsygm4wrhtkqwb@sigill.intra.peff.net","subject":"Re: [PATCH] Reduce performance penalty for turned off traces","fromName":"Stefan Beller","fromEmail":"sbeller@google.com","sentAt":"2017-11-15T19:14:20Z","receivedAt":"2017-11-15T19:14:42Z","isPatch":true,"sender":{"key":"stefanbeller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/455868?v=4"},"body":"On Sun, Nov 12, 2017 at 6:17 AM, Jeff King <peff@peff.net> wrote:\n> On Sat, Nov 11, 2017 at 07:28:58PM +0000, gennady.kupava@gmail.com wrote:\n>\n>> From: Gennady Kupava <gkupava@bloomberg.net>\n>>\n>> Signed-off-by: Gennady Kupava <gkupava@bloomberg.net>\n>\n> Thanks, and welcome to the list.\n\nWelcome to the list!\n\n> I did manually disable HAVE_VARIADIC_MACROS and confirmed that the\n> result builds and passes the test suite (though I suspect that GIT_TRACE\n> is not well exercised by the suite).\n\nGIT_TRACE is exercised in the test suite (though I am not sure if it counts\nas well-exercised) in t7406-submodule-update.sh for example, which uses\nGIT_TRACE to obtain information about thread parallelism used by Git, as\nthat is not observable otherwise, if we assume that performance tests in the\nstandard test suite are not feasible.\n\n> I tried timing a simple loop like:\n> ....\n> Without your patch, the times for GIT_TRACE=1 and GIT_TRACE=0 are about\n> 500ms and 9ms respectively.\n>\n> After your patch, the GIT_TRACE=1 time remains the same but GIT_TRACE=0\n> drops to 1ms.\n\nSo does that mean we can use a lot more tracing now?\n\nThanks,\nStefan\n"},{"id":"332778","messageId":"20171117221251.sku6lqbemcddvlky@sigill.intra.peff.net","threadId":"47172","inReplyTo":"CAPu-DQr0eRYiafF64=Mwm56xJgNPH0HVm+B4vKnzK0iAE4_xUg@mail.gmail.com","subject":"Re: [PATCH] Reduce performance penalty for turned off traces","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2017-11-17T22:12:51Z","receivedAt":"2017-11-17T22:12:58Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sun, Nov 12, 2017 at 11:24:11PM +0000, Gennady Kupava wrote:\n\n> In reality, gcc didn't do that and I saw 3 function calls. I am pretty\n> sure that compiler of the distant bright future will do that, and only\n> problem would be to eliminate that single function call. Hopefully\n> with -flto it will also eliminate this single functions call, at it\n> will be able to see through translation units. Given that I actually\n> like current implementation as it hides all details in .c file.\n\nYeah, I agree with your analysis that we are really just overriding what\ncould eventually be figured out by the compiler during LTO.\n\nI do think this is worth pursuing in the meantime, though, because it's\nnot _too_ much work, and we don't know when that magical optimizing\ncompiler will appear. :) So this frees us up in the meantime to worry\nless about the cost of tracing.\n\n> Now, implementation you suggesting moves extra things into .h, so it\n> is imperfect in terms above, while things I suggested moves only\n> necessary bit of checking the necessity to do anything, which is only\n> (interesting) part should be executed while traces are off, and the\n> only part we really want to be inlined.\n\nI only meant to suggest moving the necessary checking into the .h file.\nIt's just that we have to make it a static inline for cases where we\ndon't have variadic macros. Anyway, I'm OK with your original notion of\nleaving the non-variadic-macro systems on the \"slow\" path, so we can\njust go with the pure-macro thing you have.\n\n> > So it is measurable, and we might expect that tracing a really big loop\n> > (say over all of the objects in the repository) would benefit. OTOH, a\n> > real loop would actually be doing other stuff, so the speedup would be\n> > less dramatic. Still, it seems like an easy win.\n> \n> I actually quite familiar with performance analysis and know how to\n> use perf and similar tools a bit -\n> so if there is something more measurable in TODO, I could try. But I\n> guess this is interesting to many devs so such tasks probably already\n> all done and bottlenecks are identified in git =)\n\nThere are lots of bottlenecks still to be found, I'm sure. If you want\nto have a go at finding some with perf, be my guest. :)\n\n-Peff\n"},{"id":"332779","messageId":"20171117221631.x2xqeeqmf5xob3yv@sigill.intra.peff.net","threadId":"47172","inReplyTo":"CAGZ79kb4Eo0AC4Z42_ks5_+Pcy4DrDCufNb=5J=g8L6pMnHd7A@mail.gmail.com","subject":"Re: [PATCH] Reduce performance penalty for turned off traces","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2017-11-17T22:16:31Z","receivedAt":"2017-11-17T22:16:37Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Nov 15, 2017 at 11:14:20AM -0800, Stefan Beller wrote:\n\n> > I did manually disable HAVE_VARIADIC_MACROS and confirmed that the\n> > result builds and passes the test suite (though I suspect that GIT_TRACE\n> > is not well exercised by the suite).\n> \n> GIT_TRACE is exercised in the test suite (though I am not sure if it counts\n> as well-exercised) in t7406-submodule-update.sh for example, which uses\n> GIT_TRACE to obtain information about thread parallelism used by Git, as\n> that is not observable otherwise, if we assume that performance tests in the\n> standard test suite are not feasible.\n\nHmm, yeah, that might cover it. What I'm worried about is that we missed\nsome case where NULL needed to become &trace_default_key. But I did look\nfor that in my review of the patch and didn't notice any spots. And the\ncoverage in t7406 should help.\n\n> > After your patch, the GIT_TRACE=1 time remains the same but GIT_TRACE=0\n> > drops to 1ms.\n> \n> So does that mean we can use a lot more tracing now?\n\nYep, that's the intent.\n\n-Peff\n"},{"id":"332832","messageId":"20171119004247.22792-1-gennady.kupava@gmail.com","threadId":"47172","inReplyTo":"20171117221631.x2xqeeqmf5xob3yv@sigill.intra.peff.net","subject":"[PATCH 1/2] Simplify tracing code by removing trace key normalization concept","fromName":"","fromEmail":"gennady.kupava@gmail.com","sentAt":"2017-11-19T00:42:46Z","receivedAt":"2017-11-19T00:43:17Z","isPatch":true,"sender":{"key":"gennady.kupava@gmail.com","avatar":null},"body":"From: Gennady Kupava <gkupava@bloomberg.net>\n\n- to implement efficient traces with normalization, normalization\n  implementation should be moved to header. as it seems better to not\n  overload header file with this normalization logic, suggestion is\n  just to remove it\n- different macro exist specifically to handle traces with default key\n- there is no use of normalization in current code\n- it could be reintroduced if necessary\n\nSigned-off-by: Gennady Kupava <gkupava@bloomberg.net>\n---\n trace.c | 24 ++++--------------------\n trace.h |  4 +++-\n 2 files changed, 7 insertions(+), 21 deletions(-)\n\ndiff --git a/trace.c b/trace.c\nindex cb1293ed3..d47ea28e8 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -24,26 +24,13 @@\n #include \"cache.h\"\n #include \"quote.h\"\n \n-/*\n- * \"Normalize\" a key argument by converting NULL to our trace_default,\n- * and otherwise passing through the value. All caller-facing functions\n- * should normalize their inputs in this way, though most get it\n- * for free by calling get_trace_fd() (directly or indirectly).\n- */\n-static void normalize_trace_key(struct trace_key **key)\n-{\n-\tstatic struct trace_key trace_default = { \"GIT_TRACE\" };\n-\tif (!*key)\n-\t\t*key = &trace_default;\n-}\n+struct trace_key trace_default_key = { \"GIT_TRACE\", 0, 0, 0 };\n \n /* Get a trace file descriptor from \"key\" env variable. */\n static int get_trace_fd(struct trace_key *key)\n {\n \tconst char *trace;\n \n-\tnormalize_trace_key(&key);\n-\n \t/* don't open twice */\n \tif (key->initialized)\n \t\treturn key->fd;\n@@ -81,8 +68,6 @@ static int get_trace_fd(struct trace_key *key)\n \n void trace_disable(struct trace_key *key)\n {\n-\tnormalize_trace_key(&key);\n-\n \tif (key->need_close)\n \t\tclose(key->fd);\n \tkey->fd = 0;\n@@ -128,7 +113,6 @@ static int prepare_trace_line(const char *file, int line,\n static void trace_write(struct trace_key *key, const void *buf, unsigned len)\n {\n \tif (write_in_full(get_trace_fd(key), buf, len) < 0) {\n-\t\tnormalize_trace_key(&key);\n \t\twarning(\"unable to write trace for %s: %s\",\n \t\t\tkey->key, strerror(errno));\n \t\ttrace_disable(key);\n@@ -167,13 +151,13 @@ static void trace_argv_vprintf_fl(const char *file, int line,\n {\n \tstruct strbuf buf = STRBUF_INIT;\n \n-\tif (!prepare_trace_line(file, line, NULL, &buf))\n+\tif (!prepare_trace_line(file, line, &trace_default_key, &buf))\n \t\treturn;\n \n \tstrbuf_vaddf(&buf, format, ap);\n \n \tsq_quote_argv(&buf, argv, 0);\n-\tprint_trace_line(NULL, &buf);\n+\tprint_trace_line(&trace_default_key, &buf);\n }\n \n void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n@@ -215,7 +199,7 @@ void trace_printf(const char *format, ...)\n {\n \tva_list ap;\n \tva_start(ap, format);\n-\ttrace_vprintf_fl(NULL, 0, NULL, format, ap);\n+\ttrace_vprintf_fl(NULL, 0, &trace_default_key, format, ap);\n \tva_end(ap);\n }\n \ndiff --git a/trace.h b/trace.h\nindex 179b249c5..24b32f8f4 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -11,6 +11,8 @@ struct trace_key {\n \tunsigned int  need_close : 1;\n };\n \n+extern struct trace_key trace_default_key;\n+\n #define TRACE_KEY_INIT(name) { \"GIT_TRACE_\" #name, 0, 0, 0 }\n \n extern void trace_repo_setup(const char *prefix);\n@@ -78,7 +80,7 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);\n  */\n \n #define trace_printf(...) \\\n-\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, NULL, __VA_ARGS__)\n+\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, &trace_default_key, __VA_ARGS__)\n \n #define trace_printf_key(key, ...) \\\n \ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__)\n-- \n2.14.1\n\n"},{"id":"332833","messageId":"20171119004247.22792-2-gennady.kupava@gmail.com","threadId":"47172","inReplyTo":"20171119004247.22792-1-gennady.kupava@gmail.com","subject":"[PATCH 2/2] Reduce performance cost of the trace if trace category is disabled","fromName":"","fromEmail":"gennady.kupava@gmail.com","sentAt":"2017-11-19T00:42:47Z","receivedAt":"2017-11-19T00:43:35Z","isPatch":true,"sender":{"key":"gennady.kupava@gmail.com","avatar":null},"body":"From: Gennady Kupava <gkupava@bloomberg.net>\n\n- Do the check if the trace key is enabled sooner in call chain.\n- Move just enough code from trace.c into trace.h header so all code\n  necessary to determine that trace is disabled could be inlined to\n  calling functions.\n\nSigned-off-by: Gennady Kupava <gkupava@bloomberg.net>\n---\n trace.c |  3 +--\n trace.h | 58 ++++++++++++++++++++++++++++++++++++++++------------------\n 2 files changed, 41 insertions(+), 20 deletions(-)\n\ndiff --git a/trace.c b/trace.c\nindex d47ea28e8..b7530b51a 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -25,6 +25,7 @@\n #include \"quote.h\"\n \n struct trace_key trace_default_key = { \"GIT_TRACE\", 0, 0, 0 };\n+struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);\n \n /* Get a trace file descriptor from \"key\" env variable. */\n static int get_trace_fd(struct trace_key *key)\n@@ -172,8 +173,6 @@ void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n \tprint_trace_line(key, &buf);\n }\n \n-static struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);\n-\n static void trace_performance_vprintf_fl(const char *file, int line,\n \t\t\t\t\t uint64_t nanos, const char *format,\n \t\t\t\t\t va_list ap)\ndiff --git a/trace.h b/trace.h\nindex 24b32f8f4..cd9e280ba 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -14,6 +14,7 @@ struct trace_key {\n extern struct trace_key trace_default_key;\n \n #define TRACE_KEY_INIT(name) { \"GIT_TRACE_\" #name, 0, 0, 0 }\n+extern struct trace_key trace_perf_key;\n \n extern void trace_repo_setup(const char *prefix);\n extern int trace_want(struct trace_key *key);\n@@ -79,24 +80,42 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);\n  * comma, but this is non-standard.\n  */\n \n-#define trace_printf(...) \\\n-\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, &trace_default_key, __VA_ARGS__)\n-\n-#define trace_printf_key(key, ...) \\\n-\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__)\n-\n-#define trace_argv_printf(argv, ...) \\\n-\ttrace_argv_printf_fl(TRACE_CONTEXT, __LINE__, argv, __VA_ARGS__)\n-\n-#define trace_strbuf(key, data) \\\n-\ttrace_strbuf_fl(TRACE_CONTEXT, __LINE__, key, data)\n-\n-#define trace_performance(nanos, ...) \\\n-\ttrace_performance_fl(TRACE_CONTEXT, __LINE__, nanos, __VA_ARGS__)\n-\n-#define trace_performance_since(start, ...) \\\n-\ttrace_performance_fl(TRACE_CONTEXT, __LINE__, getnanotime() - (start), \\\n-\t\t\t     __VA_ARGS__)\n+#define trace_printf_key(key, ...)\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass_fl(key))\t\t\t\t\t    \\\n+\t\t\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, key,   \\\n+\t\t\t\t\t    __VA_ARGS__);\t\t    \\\n+\t} while(0)\n+\n+#define trace_printf(...) trace_printf_key(&trace_default_key, __VA_ARGS__);\n+\n+#define trace_argv_printf(argv, ...)\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass_fl(&trace_default_key))\t\t\t    \\\n+\t\t       trace_argv_printf_fl(TRACE_CONTEXT, __LINE__,\t    \\\n+\t\t\t\t\t    argv, __VA_ARGS__);\t\t    \\\n+\t} while(0)\n+\n+#define trace_strbuf(key, data)\t\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass_fl(key))\t\t\t\t\t    \\\n+\t\t\ttrace_strbuf_fl(TRACE_CONTEXT, __LINE__, key, data);\\\n+\t} while(0)\n+\n+#define trace_performance(nanos, ...)\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass_fl(key))\t\t\t\t\t    \\\n+\t\t\ttrace_performance_fl(TRACE_CONTEXT, __LINE__, nanos,\\\n+\t\t\t\t\t     __VA_ARGS__);  \t\t    \\\n+\t} while(0)\n+\n+#define trace_performance_since(start, ...)\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass_fl(&trace_perf_key))\t\t\t    \\\n+\t\t\ttrace_performance_fl(TRACE_CONTEXT, __LINE__,       \\\n+\t\t\t\t\t     getnanotime() - (start),\t    \\\n+\t\t\t\t\t     __VA_ARGS__);\t\t    \\\n+\t} while(0)\n \n /* backend functions, use non-*fl macros instead */\n __attribute__((format (printf, 4, 5)))\n@@ -110,6 +129,9 @@ extern void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n __attribute__((format (printf, 4, 5)))\n extern void trace_performance_fl(const char *file, int line,\n \t\t\t\t uint64_t nanos, const char *fmt, ...);\n+inline int trace_pass_fl(struct trace_key *key) {\n+\treturn key->fd || !key->initialized;\n+}\n \n #endif /* HAVE_VARIADIC_MACROS */\n \n-- \n2.14.1\n\n"},{"id":"332840","messageId":"xmqqzi7jnh6a.fsf@gitster.mtv.corp.google.com","threadId":"47172","inReplyTo":"20171119004247.22792-1-gennady.kupava@gmail.com","subject":"Re: [PATCH 1/2] Simplify tracing code by removing trace key normalization concept","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2017-11-19T02:19:57Z","receivedAt":"2017-11-19T02:20:06Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"gennady.kupava@gmail.com writes:\n\n> Subject: Re: [PATCH 1/2] Simplify tracing code by removing trace key normalization concept\n\nThe usual style comment on the subject applies here.\n\n> From: Gennady Kupava <gkupava@bloomberg.net>\n>\n> - to implement efficient traces with normalization, normalization\n>   implementation should be moved to header. as it seems better to not\n>   overload header file with this normalization logic, suggestion is\n>   just to remove it\n> - different macro exist specifically to handle traces with default key\n> - there is no use of normalization in current code\n> - it could be reintroduced if necessary\n\nI cannot quite tell what it is trying to achive to make it a\nbulleted list.  It's not like four things at the same conceptual\nlevel is enumerated; instead it just has four sentences that talk\nabout random things.\n\nMore importantly, I am not sure I understand what these sentences\nare trying to say.  \"Should be moved to header\"---so?  Does that\nmove something from the source to the header?  It seems to me that\nthe patch removes a helper function from trace.c but does not add\nanything to the header.\n\nOr am I wasting everybody's time by commenting on a stale comment\nthat used to describe an ancient iteration of this code?\n\nPuzzled.\n"},{"id":"332842","messageId":"d9076fef-c90c-63f2-5e0e-37293810e3d9@kdbg.org","threadId":"47172","inReplyTo":"20171119004247.22792-2-gennady.kupava@gmail.com","subject":"Re: [PATCH 2/2] Reduce performance cost of the trace if trace category is disabled","fromName":"Johannes Sixt","fromEmail":"j6t@kdbg.org","sentAt":"2017-11-19T08:27:03Z","receivedAt":"2017-11-19T08:27:11Z","isPatch":true,"sender":{"key":"j6t@kdbg.org","avatar":"https://avatars.githubusercontent.com/u/14810926?v=4"},"body":"Am 19.11.2017 um 01:42 schrieb gennady.kupava@gmail.com:\n> +#define trace_printf_key(key, ...)\t\t\t\t\t    \\\n> +\tdo {\t\t\t\t\t\t\t\t    \\\n> +\t\tif (trace_pass_fl(key))\t\t\t\t\t    \\\n> +\t\t\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, key,   \\\n> +\t\t\t\t\t    __VA_ARGS__);\t\t    \\\n> +\t} while(0)\n> +\n> +#define trace_printf(...) trace_printf_key(&trace_default_key, __VA_ARGS__);\n> +\n> +#define trace_argv_printf(argv, ...)\t\t\t\t\t    \\\n> +\tdo {\t\t\t\t\t\t\t\t    \\\n> +\t\tif (trace_pass_fl(&trace_default_key))\t\t\t    \\\n> +\t\t       trace_argv_printf_fl(TRACE_CONTEXT, __LINE__,\t    \\\n> +\t\t\t\t\t    argv, __VA_ARGS__);\t\t    \\\n> +\t} while(0)\n> +\n> +#define trace_strbuf(key, data)\t\t\t\t\t\t    \\\n> +\tdo {\t\t\t\t\t\t\t\t    \\\n> +\t\tif (trace_pass_fl(key))\t\t\t\t\t    \\\n> +\t\t\ttrace_strbuf_fl(TRACE_CONTEXT, __LINE__, key, data);\\\n> +\t} while(0)\n> +\n> +#define trace_performance(nanos, ...)\t\t\t\t\t    \\\n> +\tdo {\t\t\t\t\t\t\t\t    \\\n> +\t\tif (trace_pass_fl(key))\t\t\t\t\t    \\\n\nThe token \"key\" here looks suspicious. Did you mean &trace_perf_key?\n\n> +\t\t\ttrace_performance_fl(TRACE_CONTEXT, __LINE__, nanos,\\\n> +\t\t\t\t\t     __VA_ARGS__);  \t\t    \\\n> +\t} while(0)\n> +\n> +#define trace_performance_since(start, ...)\t\t\t\t    \\\n> +\tdo {\t\t\t\t\t\t\t\t    \\\n> +\t\tif (trace_pass_fl(&trace_perf_key))\t\t\t    \\\n> +\t\t\ttrace_performance_fl(TRACE_CONTEXT, __LINE__,       \\\n> +\t\t\t\t\t     getnanotime() - (start),\t    \\\n> +\t\t\t\t\t     __VA_ARGS__);\t\t    \\\n> +\t} while(0)\n>   \n>   /* backend functions, use non-*fl macros instead */\n>   __attribute__((format (printf, 4, 5)))\n\n-- Hannes\n"},{"id":"332847","messageId":"CAPu-DQoapb=cgxYEOEVcpZ4nQeh+FuOE6VF=m3NaqRcr2p8Nrg@mail.gmail.com","threadId":"47172","inReplyTo":"xmqqzi7jnh6a.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH 1/2] Simplify tracing code by removing trace key normalization concept","fromName":"Gennady Kupava","fromEmail":"gennady.kupava@gmail.com","sentAt":"2017-11-19T13:16:04Z","receivedAt":"2017-11-19T13:24:10Z","isPatch":true,"sender":{"key":"gennady.kupava@gmail.com","avatar":null},"body":"> The usual style comment on the subject applies here.\n\nOh sure, 50 characters. 'Remove trace key normalization concept' would\nbe better?\n\n> I cannot quite tell what it is trying to achive to make it a\nbulleted list.  It's not like four things at the same conceptual\nlevel is enumerated; instead it just has four sentences that talk\nabout random things.\n\nWith these four sentences I am describing the reasons why we need this\npatch. In my previous iteration I had similar  description outside of\ngit comment and was told to move it into git description. So it is in\ncomments. Hot sure if I understand what is the problem here. I can\nremove bulleted list and make it four sentences. I can remove it\naltogether. I can add some text so it will be easier to understand\nthis without context of previous patch. What would be the best?\n\nI reread relevant parts of\nhttps://github.com/git/git/blob/master/Documentation/SubmittingPatches\nand it seems description of the reasons and alternative discarded\nsolutions fits into description. So could please help me a bit to\nunderstand what is wrong.\n\n> More importantly, I am not sure I understand what these sentences\nare trying to say.  \"Should be moved to header\"---so?  Does that\nmove something from the source to the header?  It seems to me that\nthe patch removes a helper function from trace.c but does not add\nanything to the header.\n\nI was told to split the patch and do removal for the normalization as\nseparate commit. As it is separate commit, it needs to do separate\ndescription with the own reasons why etc. Yes it doesn't but it is\nneeded for the second patch in the series.\n\nSo comments explaining that, while implementing trace optimization, I\nsaw two options:\n1. Move normalization function from .c file to .h file\n2. Remove it\n\nAnd why I choose removal - not used, would complicate header without\nany benefit, and actually I didn't mention minor benefit of\ncompilation speed. This trace.h included and used in lots of places so\nit will take compiler some time to actually eliminate the code.\n\n> Puzzled.\n\nDoes it make more sense now?\n\nGennady\n\n\nOn 19 November 2017 at 02:19, Junio C Hamano <gitster@pobox.com> wrote:\n> gennady.kupava@gmail.com writes:\n>\n>> Subject: Re: [PATCH 1/2] Simplify tracing code by removing trace key normalization concept\n>\n> The usual style comment on the subject applies here.\n>\n>> From: Gennady Kupava <gkupava@bloomberg.net>\n>>\n>> - to implement efficient traces with normalization, normalization\n>>   implementation should be moved to header. as it seems better to not\n>>   overload header file with this normalization logic, suggestion is\n>>   just to remove it\n>> - different macro exist specifically to handle traces with default key\n>> - there is no use of normalization in current code\n>> - it could be reintroduced if necessary\n>\n> I cannot quite tell what it is trying to achive to make it a\n> bulleted list.  It's not like four things at the same conceptual\n> level is enumerated; instead it just has four sentences that talk\n> about random things.\n>\n> More importantly, I am not sure I understand what these sentences\n> are trying to say.  \"Should be moved to header\"---so?  Does that\n> move something from the source to the header?  It seems to me that\n> the patch removes a helper function from trace.c but does not add\n> anything to the header.\n>\n> Or am I wasting everybody's time by commenting on a stale comment\n> that used to describe an ancient iteration of this code?\n>\n> Puzzled.\n"},{"id":"332848","messageId":"CAPu-DQqO5gfr3H_vHu3JBeJrkCmh6qQ=vs=GOkLKjtE9=tDgcg@mail.gmail.com","threadId":"47172","inReplyTo":"d9076fef-c90c-63f2-5e0e-37293810e3d9@kdbg.org","subject":"Re: [PATCH 2/2] Reduce performance cost of the trace if trace category is disabled","fromName":"Gennady Kupava","fromEmail":"gennady.kupava@gmail.com","sentAt":"2017-11-19T13:18:31Z","receivedAt":"2017-11-19T13:24:13Z","isPatch":true,"sender":{"key":"gennady.kupava@gmail.com","avatar":null},"body":"Right, this trace is actually not used anywhere, so only check was\ncompilation. Will fix that.\n\nOn 19 November 2017 at 08:27, Johannes Sixt <j6t@kdbg.org> wrote:\n> Am 19.11.2017 um 01:42 schrieb gennady.kupava@gmail.com:\n>>\n>> +#define trace_printf_key(key, ...)\n>> \\\n>> +       do {\n>> \\\n>> +               if (trace_pass_fl(key))\n>> \\\n>> +                       trace_printf_key_fl(TRACE_CONTEXT, __LINE__, key,\n>> \\\n>> +                                           __VA_ARGS__);\n>> \\\n>> +       } while(0)\n>> +\n>> +#define trace_printf(...) trace_printf_key(&trace_default_key,\n>> __VA_ARGS__);\n>> +\n>> +#define trace_argv_printf(argv, ...)\n>> \\\n>> +       do {\n>> \\\n>> +               if (trace_pass_fl(&trace_default_key))\n>> \\\n>> +                      trace_argv_printf_fl(TRACE_CONTEXT, __LINE__,\n>> \\\n>> +                                           argv, __VA_ARGS__);\n>> \\\n>> +       } while(0)\n>> +\n>> +#define trace_strbuf(key, data)\n>> \\\n>> +       do {\n>> \\\n>> +               if (trace_pass_fl(key))\n>> \\\n>> +                       trace_strbuf_fl(TRACE_CONTEXT, __LINE__, key,\n>> data);\\\n>> +       } while(0)\n>> +\n>> +#define trace_performance(nanos, ...)\n>> \\\n>> +       do {\n>> \\\n>> +               if (trace_pass_fl(key))\n>> \\\n>\n>\n> The token \"key\" here looks suspicious. Did you mean &trace_perf_key?\n>\n>> +                       trace_performance_fl(TRACE_CONTEXT, __LINE__,\n>> nanos,\\\n>> +                                            __VA_ARGS__);\n>> \\\n>> +       } while(0)\n>> +\n>> +#define trace_performance_since(start, ...)\n>> \\\n>> +       do {\n>> \\\n>> +               if (trace_pass_fl(&trace_perf_key))\n>> \\\n>> +                       trace_performance_fl(TRACE_CONTEXT, __LINE__,\n>> \\\n>> +                                            getnanotime() - (start),\n>> \\\n>> +                                            __VA_ARGS__);\n>> \\\n>> +       } while(0)\n>>     /* backend functions, use non-*fl macros instead */\n>>   __attribute__((format (printf, 4, 5)))\n>\n>\n> -- Hannes\n"},{"id":"332881","messageId":"xmqqr2stokzd.fsf@gitster.mtv.corp.google.com","threadId":"47172","inReplyTo":"CAPu-DQoapb=cgxYEOEVcpZ4nQeh+FuOE6VF=m3NaqRcr2p8Nrg@mail.gmail.com","subject":"Re: [PATCH 1/2] Simplify tracing code by removing trace key normalization concept","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2017-11-20T00:24:38Z","receivedAt":"2017-11-20T00:24:47Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Gennady Kupava <gennady.kupava@gmail.com> writes:\n\n>> The usual style comment on the subject applies here.\n>\n> Oh sure, 50 characters. 'Remove trace key normalization concept' would\n> be better?\n\nI was referring to #summary-section of Documentation/SubmittingPatches\n\n    The first line of the commit message should be a short description (50\n    characters is the soft limit, see DISCUSSION in linkgit:git-commit[1]),\n    and should skip the full stop.  It is also conventional in most cases to\n    prefix the first line with \"area: \" where the area is a filename or\n    identifier for the general area of the code being modified, e.g.\n\n    * doc: clarify distinction between sign-off and pgp-signing\n    * githooks.txt: improve the intro section\n\n    If in doubt which identifier to use, run `git log --no-merges` on the\n    files you are modifying to see the current conventions.\n\n    [[summary-section]]\n    It's customary to start the remainder of the first line after \"area: \"\n    with a lower-case letter. E.g. \"doc: clarify...\", not \"doc:\n    Clarify...\", or \"githooks.txt: improve...\", not \"githooks.txt:\n    Improve...\".\n\n> So comments explaining that, while implementing trace optimization, I\n> saw two options:\n> 1. Move normalization function from .c file to .h file\n> 2. Remove it\n>\n> And why I choose removal - not used, would complicate header without\n> any benefit, and actually I didn't mention minor benefit of\n> compilation speed. This trace.h included and used in lots of places so\n> it will take compiler some time to actually eliminate the code.\n>\n>> Puzzled.\n>\n> Does it make more sense now?\n\nThe thought behind the change flows much better in the above\nexplanation than your four-bullet list (which a reader would often\nassume are parallel and orthogonal).  \"Remove this, because it is\nnot used\" is the primary thing for this step, and the fact that the\nlater step benefit from that change, while it may be more important\nto the person who want to see that later change, is incidental to\nsee if this change makes sense as a standalone patch.\n\nAnd that primary thing, \"remove this, because it is not used and\nonly complicates the code\" is what we want to start the log message\nwith.  The first sentence (\"this needs to be moved there\") saying\nwhat the patch chose not to was the source of the confusion.\n\n\n"},{"id":"332894","messageId":"xmqqvai5lf4a.fsf@gitster.mtv.corp.google.com","threadId":"47172","inReplyTo":"xmqqr2stokzd.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH 1/2] Simplify tracing code by removing trace key normalization concept","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2017-11-20T04:59:33Z","receivedAt":"2017-11-20T04:59:41Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Junio C Hamano <gitster@pobox.com> writes:\n\n> The thought behind the change flows much better in the above\n> explanation than your four-bullet list (which a reader would often\n> assume are parallel and orthogonal).  \"Remove this, because it is\n> not used\" is the primary thing for this step, and the fact that the\n\nMake that \"because it is not strictly necessary\", as that seems to\nbe much closer to what is going on, and I agree that it is a good\nchange to remove such \"convenience for callers\" feature from\ncodepaths that could be performance critical.  The callers can pass\nthe \"&default\" thing themselves just as easily as they pass NULL\nand have the library code to do the defaulting, and that will remove\nthe need to incur extra cost for a subroutine call.\n"},{"id":"333546","messageId":"20171126201119.24313-1-gennady.kupava@gmail.com","threadId":"47172","inReplyTo":"xmqqvai5lf4a.fsf@gitster.mtv.corp.google.com","subject":"[PATCH 1/2] trace: remove trace key normalization","fromName":"","fromEmail":"gennady.kupava@gmail.com","sentAt":"2017-11-26T20:11:18Z","receivedAt":"2017-11-26T20:11:35Z","isPatch":true,"sender":{"key":"gennady.kupava@gmail.com","avatar":null},"body":"From: Gennady Kupava <gkupava@bloomberg.net>\n\nTrace key normalization is not used, not strictly necessary,\ncomplicates the code and would negatively affect compilation speed if\nmoved to header.\n\nNew trace_default_key key or existing separate marco could be used\ninstead of passing NULL as a key.\n\nSigned-off-by: Gennady Kupava <gkupava@bloomberg.net>\n---\n trace.c | 24 ++++--------------------\n trace.h |  4 +++-\n 2 files changed, 7 insertions(+), 21 deletions(-)\n\ndiff --git a/trace.c b/trace.c\nindex cb1293ed3..d47ea28e8 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -24,26 +24,13 @@\n #include \"cache.h\"\n #include \"quote.h\"\n \n-/*\n- * \"Normalize\" a key argument by converting NULL to our trace_default,\n- * and otherwise passing through the value. All caller-facing functions\n- * should normalize their inputs in this way, though most get it\n- * for free by calling get_trace_fd() (directly or indirectly).\n- */\n-static void normalize_trace_key(struct trace_key **key)\n-{\n-\tstatic struct trace_key trace_default = { \"GIT_TRACE\" };\n-\tif (!*key)\n-\t\t*key = &trace_default;\n-}\n+struct trace_key trace_default_key = { \"GIT_TRACE\", 0, 0, 0 };\n \n /* Get a trace file descriptor from \"key\" env variable. */\n static int get_trace_fd(struct trace_key *key)\n {\n \tconst char *trace;\n \n-\tnormalize_trace_key(&key);\n-\n \t/* don't open twice */\n \tif (key->initialized)\n \t\treturn key->fd;\n@@ -81,8 +68,6 @@ static int get_trace_fd(struct trace_key *key)\n \n void trace_disable(struct trace_key *key)\n {\n-\tnormalize_trace_key(&key);\n-\n \tif (key->need_close)\n \t\tclose(key->fd);\n \tkey->fd = 0;\n@@ -128,7 +113,6 @@ static int prepare_trace_line(const char *file, int line,\n static void trace_write(struct trace_key *key, const void *buf, unsigned len)\n {\n \tif (write_in_full(get_trace_fd(key), buf, len) < 0) {\n-\t\tnormalize_trace_key(&key);\n \t\twarning(\"unable to write trace for %s: %s\",\n \t\t\tkey->key, strerror(errno));\n \t\ttrace_disable(key);\n@@ -167,13 +151,13 @@ static void trace_argv_vprintf_fl(const char *file, int line,\n {\n \tstruct strbuf buf = STRBUF_INIT;\n \n-\tif (!prepare_trace_line(file, line, NULL, &buf))\n+\tif (!prepare_trace_line(file, line, &trace_default_key, &buf))\n \t\treturn;\n \n \tstrbuf_vaddf(&buf, format, ap);\n \n \tsq_quote_argv(&buf, argv, 0);\n-\tprint_trace_line(NULL, &buf);\n+\tprint_trace_line(&trace_default_key, &buf);\n }\n \n void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n@@ -215,7 +199,7 @@ void trace_printf(const char *format, ...)\n {\n \tva_list ap;\n \tva_start(ap, format);\n-\ttrace_vprintf_fl(NULL, 0, NULL, format, ap);\n+\ttrace_vprintf_fl(NULL, 0, &trace_default_key, format, ap);\n \tva_end(ap);\n }\n \ndiff --git a/trace.h b/trace.h\nindex 179b249c5..24b32f8f4 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -11,6 +11,8 @@ struct trace_key {\n \tunsigned int  need_close : 1;\n };\n \n+extern struct trace_key trace_default_key;\n+\n #define TRACE_KEY_INIT(name) { \"GIT_TRACE_\" #name, 0, 0, 0 }\n \n extern void trace_repo_setup(const char *prefix);\n@@ -78,7 +80,7 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);\n  */\n \n #define trace_printf(...) \\\n-\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, NULL, __VA_ARGS__)\n+\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, &trace_default_key, __VA_ARGS__)\n \n #define trace_printf_key(key, ...) \\\n \ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__)\n-- \n2.14.1\n\n"},{"id":"333547","messageId":"20171126201119.24313-2-gennady.kupava@gmail.com","threadId":"47172","inReplyTo":"20171126201119.24313-1-gennady.kupava@gmail.com","subject":"[PATCH 2/2] trace: improve performance while category is disabled","fromName":"","fromEmail":"gennady.kupava@gmail.com","sentAt":"2017-11-26T20:11:19Z","receivedAt":"2017-11-26T20:11:44Z","isPatch":true,"sender":{"key":"gennady.kupava@gmail.com","avatar":null},"body":"From: Gennady Kupava <gkupava@bloomberg.net>\n\n- Do the check if the trace key is enabled sooner in call chain.\n- Move just enough code from trace.c into trace.h header so all code\n  necessary to determine that trace is disabled could be inlined to\n  calling functions.\n\nSigned-off-by: Gennady Kupava <gkupava@bloomberg.net>\n---\n trace.c |  3 +--\n trace.h | 58 ++++++++++++++++++++++++++++++++++++++++------------------\n 2 files changed, 41 insertions(+), 20 deletions(-)\n\ndiff --git a/trace.c b/trace.c\nindex d47ea28e8..b7530b51a 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -25,6 +25,7 @@\n #include \"quote.h\"\n \n struct trace_key trace_default_key = { \"GIT_TRACE\", 0, 0, 0 };\n+struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);\n \n /* Get a trace file descriptor from \"key\" env variable. */\n static int get_trace_fd(struct trace_key *key)\n@@ -172,8 +173,6 @@ void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n \tprint_trace_line(key, &buf);\n }\n \n-static struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);\n-\n static void trace_performance_vprintf_fl(const char *file, int line,\n \t\t\t\t\t uint64_t nanos, const char *format,\n \t\t\t\t\t va_list ap)\ndiff --git a/trace.h b/trace.h\nindex 24b32f8f4..db10f2afe 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -14,6 +14,7 @@ struct trace_key {\n extern struct trace_key trace_default_key;\n \n #define TRACE_KEY_INIT(name) { \"GIT_TRACE_\" #name, 0, 0, 0 }\n+extern struct trace_key trace_perf_key;\n \n extern void trace_repo_setup(const char *prefix);\n extern int trace_want(struct trace_key *key);\n@@ -79,24 +80,42 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);\n  * comma, but this is non-standard.\n  */\n \n-#define trace_printf(...) \\\n-\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, &trace_default_key, __VA_ARGS__)\n-\n-#define trace_printf_key(key, ...) \\\n-\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__)\n-\n-#define trace_argv_printf(argv, ...) \\\n-\ttrace_argv_printf_fl(TRACE_CONTEXT, __LINE__, argv, __VA_ARGS__)\n-\n-#define trace_strbuf(key, data) \\\n-\ttrace_strbuf_fl(TRACE_CONTEXT, __LINE__, key, data)\n-\n-#define trace_performance(nanos, ...) \\\n-\ttrace_performance_fl(TRACE_CONTEXT, __LINE__, nanos, __VA_ARGS__)\n-\n-#define trace_performance_since(start, ...) \\\n-\ttrace_performance_fl(TRACE_CONTEXT, __LINE__, getnanotime() - (start), \\\n-\t\t\t     __VA_ARGS__)\n+#define trace_printf_key(key, ...)\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass_fl(key))\t\t\t\t\t    \\\n+\t\t\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, key,   \\\n+\t\t\t\t\t    __VA_ARGS__);\t\t    \\\n+\t} while(0)\n+\n+#define trace_printf(...) trace_printf_key(&trace_default_key, __VA_ARGS__)\n+\n+#define trace_argv_printf(argv, ...)\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass_fl(&trace_default_key))\t\t\t    \\\n+\t\t       trace_argv_printf_fl(TRACE_CONTEXT, __LINE__,\t    \\\n+\t\t\t\t\t    argv, __VA_ARGS__);\t\t    \\\n+\t} while(0)\n+\n+#define trace_strbuf(key, data)\t\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass_fl(key))\t\t\t\t\t    \\\n+\t\t\ttrace_strbuf_fl(TRACE_CONTEXT, __LINE__, key, data);\\\n+\t} while(0)\n+\n+#define trace_performance(nanos, ...)\t\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass_fl(&trace_perf_key))\t\t\t    \\\n+\t\t\ttrace_performance_fl(TRACE_CONTEXT, __LINE__, nanos,\\\n+\t\t\t\t\t     __VA_ARGS__);  \t\t    \\\n+\t} while(0)\n+\n+#define trace_performance_since(start, ...)\t\t\t\t    \\\n+\tdo {\t\t\t\t\t\t\t\t    \\\n+\t\tif (trace_pass_fl(&trace_perf_key))\t\t\t    \\\n+\t\t\ttrace_performance_fl(TRACE_CONTEXT, __LINE__,       \\\n+\t\t\t\t\t     getnanotime() - (start),\t    \\\n+\t\t\t\t\t     __VA_ARGS__);\t\t    \\\n+\t} while(0)\n \n /* backend functions, use non-*fl macros instead */\n __attribute__((format (printf, 4, 5)))\n@@ -110,6 +129,9 @@ extern void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n __attribute__((format (printf, 4, 5)))\n extern void trace_performance_fl(const char *file, int line,\n \t\t\t\t uint64_t nanos, const char *fmt, ...);\n+inline int trace_pass_fl(struct trace_key *key) {\n+\treturn key->fd || !key->initialized;\n+}\n \n #endif /* HAVE_VARIADIC_MACROS */\n \n-- \n2.14.1\n\n"},{"id":"333563","messageId":"xmqqpo84fre1.fsf@gitster.mtv.corp.google.com","threadId":"47172","inReplyTo":"20171126201119.24313-2-gennady.kupava@gmail.com","subject":"Re: [PATCH 2/2] trace: improve performance while category is disabled","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2017-11-27T01:21:26Z","receivedAt":"2017-11-27T01:21:35Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"gennady.kupava@gmail.com writes:\n\n> From: Gennady Kupava <gkupava@bloomberg.net>\n>\n> - Do the check if the trace key is enabled sooner in call chain.\n> - Move just enough code from trace.c into trace.h header so all code\n>   necessary to determine that trace is disabled could be inlined to\n>   calling functions.\n\nMakes sense.  Will queue.\n\nThanks.\n\n> +inline int trace_pass_fl(struct trace_key *key) {\n> +\treturn key->fd || !key->initialized;\n> +}\n\n;-)\n"},{"id":"333564","messageId":"xmqqlgisfquy.fsf@gitster.mtv.corp.google.com","threadId":"47172","inReplyTo":"xmqqpo84fre1.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH 2/2] trace: improve performance while category is disabled","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2017-11-27T01:32:53Z","receivedAt":"2017-11-27T01:33:06Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Junio C Hamano <gitster@pobox.com> writes:\n\n> gennady.kupava@gmail.com writes:\n>\n>> From: Gennady Kupava <gkupava@bloomberg.net>\n>>\n>> - Do the check if the trace key is enabled sooner in call chain.\n>> - Move just enough code from trace.c into trace.h header so all code\n>>   necessary to determine that trace is disabled could be inlined to\n>>   calling functions.\n>\n> Makes sense.  Will queue.\n>\n> Thanks.\n\nJust in case others notice style and whitespace issues, I've applied\nthe following to fix them, so there is no need to reroll only to fix\nthese.\n\ndiff --git a/trace.h b/trace.h\nindex db10f2afeb..05395242aa 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -85,29 +85,29 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);\n \t\tif (trace_pass_fl(key))\t\t\t\t\t    \\\n \t\t\ttrace_printf_key_fl(TRACE_CONTEXT, __LINE__, key,   \\\n \t\t\t\t\t    __VA_ARGS__);\t\t    \\\n-\t} while(0)\n+\t} while (0)\n \n #define trace_printf(...) trace_printf_key(&trace_default_key, __VA_ARGS__)\n \n #define trace_argv_printf(argv, ...)\t\t\t\t\t    \\\n \tdo {\t\t\t\t\t\t\t\t    \\\n \t\tif (trace_pass_fl(&trace_default_key))\t\t\t    \\\n-\t\t       trace_argv_printf_fl(TRACE_CONTEXT, __LINE__,\t    \\\n+\t\t\ttrace_argv_printf_fl(TRACE_CONTEXT, __LINE__,\t    \\\n \t\t\t\t\t    argv, __VA_ARGS__);\t\t    \\\n-\t} while(0)\n+\t} while (0)\n \n #define trace_strbuf(key, data)\t\t\t\t\t\t    \\\n \tdo {\t\t\t\t\t\t\t\t    \\\n \t\tif (trace_pass_fl(key))\t\t\t\t\t    \\\n \t\t\ttrace_strbuf_fl(TRACE_CONTEXT, __LINE__, key, data);\\\n-\t} while(0)\n+\t} while (0)\n \n #define trace_performance(nanos, ...)\t\t\t\t\t    \\\n \tdo {\t\t\t\t\t\t\t\t    \\\n \t\tif (trace_pass_fl(&trace_perf_key))\t\t\t    \\\n \t\t\ttrace_performance_fl(TRACE_CONTEXT, __LINE__, nanos,\\\n-\t\t\t\t\t     __VA_ARGS__);  \t\t    \\\n-\t} while(0)\n+\t\t\t\t\t     __VA_ARGS__);\t\t    \\\n+\t} while (0)\n \n #define trace_performance_since(start, ...)\t\t\t\t    \\\n \tdo {\t\t\t\t\t\t\t\t    \\\n@@ -115,7 +115,7 @@ extern void trace_performance_since(uint64_t start, const char *format, ...);\n \t\t\ttrace_performance_fl(TRACE_CONTEXT, __LINE__,       \\\n \t\t\t\t\t     getnanotime() - (start),\t    \\\n \t\t\t\t\t     __VA_ARGS__);\t\t    \\\n-\t} while(0)\n+\t} while (0)\n \n /* backend functions, use non-*fl macros instead */\n __attribute__((format (printf, 4, 5)))\n@@ -129,7 +129,8 @@ extern void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n __attribute__((format (printf, 4, 5)))\n extern void trace_performance_fl(const char *file, int line,\n \t\t\t\t uint64_t nanos, const char *fmt, ...);\n-inline int trace_pass_fl(struct trace_key *key) {\n+inline int trace_pass_fl(struct trace_key *key)\n+{\n \treturn key->fd || !key->initialized;\n }\n \n"},{"id":"333569","messageId":"xmqq8tesflne.fsf@gitster.mtv.corp.google.com","threadId":"47172","inReplyTo":"xmqqlgisfquy.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH 2/2] trace: improve performance while category is disabled","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2017-11-27T03:25:25Z","receivedAt":"2017-11-27T03:25:33Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Junio C Hamano <gitster@pobox.com> writes:\n\n> Just in case others notice style and whitespace issues, I've applied\n> the following to fix them, so there is no need to reroll only to fix\n> these.\n> ...\n> -inline int trace_pass_fl(struct trace_key *key) {\n> +inline int trace_pass_fl(struct trace_key *key)\n> +{\n>  \treturn key->fd || !key->initialized;\n>  }\n\nSpotted yet another.  This function in a header file, that is\nincluded by many source files, must be made \"static inline\" (which I\nalready did as without the fix I couldn't get 'pu' to compile).\n\n\n\n"},{"id":"333603","messageId":"CAPu-DQpKRvU05pgfFpdguAfMKJnHpshsajivTCtNa56GtToUtg@mail.gmail.com","threadId":"47172","inReplyTo":"xmqq8tesflne.fsf@gitster.mtv.corp.google.com","subject":"Re: [PATCH 2/2] trace: improve performance while category is disabled","fromName":"Gennady Kupava","fromEmail":"gennady.kupava@gmail.com","sentAt":"2017-11-27T10:12:16Z","receivedAt":"2017-11-27T10:12:22Z","isPatch":true,"sender":{"key":"gennady.kupava@gmail.com","avatar":null},"body":"> Spotted yet another.  This function in a header file, that is\nincluded by many source files, must be made \"static inline\" (which I\nalready did as without the fix I couldn't get 'pu' to compile).\n\nThanks, missed that, seems my compiler inlined all calls and I didn't\nnotice the problem.\n\n\nOn 27 November 2017 at 03:25, Junio C Hamano <gitster@pobox.com> wrote:\n> Junio C Hamano <gitster@pobox.com> writes:\n>\n>> Just in case others notice style and whitespace issues, I've applied\n>> the following to fix them, so there is no need to reroll only to fix\n>> these.\n>> ...\n>> -inline int trace_pass_fl(struct trace_key *key) {\n>> +inline int trace_pass_fl(struct trace_key *key)\n>> +{\n>>       return key->fd || !key->initialized;\n>>  }\n>\n> Spotted yet another.  This function in a header file, that is\n> included by many source files, must be made \"static inline\" (which I\n> already did as without the fix I couldn't get 'pu' to compile).\n>\n>\n>\n"}]}