{"thread":{"id":"37120","subject":"[PATCH v8 00/17] add performance tracing facility","startedAt":"2014-07-11T23:56:53Z","lastAt":"2014-07-12T00:08:48Z","messageCount":18,"participants":["Karsten Blees"],"isPatch":true,"patchVersion":8,"patchTotal":17},"messages":[{"id":"245858","messageId":"53C079C5.8090503@gmail.com","threadId":"37120","inReplyTo":null,"subject":"[PATCH v8 00/17] add performance tracing facility","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-11T23:56:53Z","receivedAt":"2014-07-11T23:56:53Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Changes since v7:\n[04]: Fixed -Wextra compiler warnings, thanks to Ramsay Jones.\n[11]: Added #ifndef TRACE_CONTEXT, explained why __FILE__ \":\"\n __FUNCTION__ doesn't work.\n[17]: New Documentation/technical/api-trace.txt\n\n\nKarsten Blees (17):\n trace: move trace declarations from cache.h to new trace.h\n trace: consistently name the format parameter\n trace: remove redundant printf format attribute\n trace: improve trace performance\n Documentation/git.txt: improve documentation of 'GIT_TRACE*' variables\n sha1_file: change GIT_TRACE_PACK_ACCESS logging to use trace API\n trace: add infrastructure to augment trace output with additional info\n trace: disable additional trace output for unit tests\n trace: add current timestamp to all trace output\n trace: move code around, in preparation to file:line output\n trace: add 'file:line' to all trace output\n trace: add high resolution timer function to debug performance issues\n trace: add trace_performance facility to debug performance issues\n git: add performance tracing for git's main() function to debug\n scripts\n wt-status: simplify performance measurement by using getnanotime()\n progress: simplify performance measurement by using getnanotime()\n api-trace.txt: add trace API documentation\n\n Documentation/git.txt | 59 ++++--\n Documentation/technical/api-trace.txt | 97 +++++++++\n Makefile | 7 +\n builtin/receive-pack.c | 2 +-\n cache.h | 13 +-\n commit.h | 1 +\n config.mak.uname | 1 +\n git-compat-util.h | 4 +\n git.c | 2 +\n pkt-line.c | 8 +-\n progress.c | 71 +++----\n sha1_file.c | 30 +--\n shallow.c | 10 +-\n t/test-lib.sh | 4 +\n trace.c | 369 ++++++++++++++++++++++++++++------\n trace.h | 113 +++++++++++\n wt-status.c | 14 +-\n 17 files changed, 629 insertions(+), 176 deletions(-)\n create mode 100644 Documentation/technical/api-trace.txt\n create mode 100644 trace.h\n\n-- \n2.0.0.406.g2e9ef9b\n"},{"id":"245859","messageId":"53C07A00.6010708@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 01/17] trace: move trace declarations from cache.h to new trace.h","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-11T23:57:52Z","receivedAt":"2014-07-11T23:57:52Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Also include direct dependencies (strbuf.h and git-compat-util.h for\n__attribute__) so that trace.h can be used independently of cache.h, e.g.\nin test programs.\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n cache.h | 13 ++-----------\n trace.h | 17 +++++++++++++++++\n 2 files changed, 19 insertions(+), 11 deletions(-)\n create mode 100644 trace.h\n\ndiff --git a/cache.h b/cache.h\nindex cbe1935..466f6b3 100644\n--- a/cache.h\n+++ b/cache.h\n@@ -7,6 +7,7 @@\n #include \"advice.h\"\n #include \"gettext.h\"\n #include \"convert.h\"\n+#include \"trace.h\"\n \n #include SHA1_HEADER\n #ifndef git_SHA_CTX\n@@ -1377,17 +1378,7 @@ extern void *alloc_tag_node(void);\n extern void *alloc_object_node(void);\n extern void alloc_report(void);\n \n-/* trace.c */\n-__attribute__((format (printf, 1, 2)))\n-extern void trace_printf(const char *format, ...);\n-__attribute__((format (printf, 2, 3)))\n-extern void trace_argv_printf(const char **argv, const char *format, ...);\n-extern void trace_repo_setup(const char *prefix);\n-extern int trace_want(const char *key);\n-__attribute__((format (printf, 2, 3)))\n-extern void trace_printf_key(const char *key, const char *fmt, ...);\n-extern void trace_strbuf(const char *key, const struct strbuf *buf);\n-\n+/* pkt-line.c */\n void packet_trace_identity(const char *prog);\n \n /* add */\ndiff --git a/trace.h b/trace.h\nnew file mode 100644\nindex 0000000..6cc4541\n--- /dev/null\n+++ b/trace.h\n@@ -0,0 +1,17 @@\n+#ifndef TRACE_H\n+#define TRACE_H\n+\n+#include \"git-compat-util.h\"\n+#include \"strbuf.h\"\n+\n+__attribute__((format (printf, 1, 2)))\n+extern void trace_printf(const char *format, ...);\n+__attribute__((format (printf, 2, 3)))\n+extern void trace_argv_printf(const char **argv, const char *format, ...);\n+extern void trace_repo_setup(const char *prefix);\n+extern int trace_want(const char *key);\n+__attribute__((format (printf, 2, 3)))\n+extern void trace_printf_key(const char *key, const char *fmt, ...);\n+extern void trace_strbuf(const char *key, const struct strbuf *buf);\n+\n+#endif /* TRACE_H */\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245860","messageId":"53C07A29.8000506@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 02/17] trace: consistently name the format parameter","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-11T23:58:33Z","receivedAt":"2014-07-11T23:58:33Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"The format parameter to trace_printf functions is sometimes abbreviated\n'fmt'. Rename to 'format' everywhere (consistent with POSIX' printf\nspecification).\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n trace.c | 22 +++++++++++-----------\n trace.h | 2 +-\n 2 files changed, 12 insertions(+), 12 deletions(-)\n\ndiff --git a/trace.c b/trace.c\nindex 08180a9..37a7fa9 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -62,7 +62,7 @@ static int get_trace_fd(const char *key, int *need_close)\n static const char err_msg[] = \"Could not trace into fd given by \"\n \t\"GIT_TRACE environment variable\";\n \n-static void trace_vprintf(const char *key, const char *fmt, va_list ap)\n+static void trace_vprintf(const char *key, const char *format, va_list ap)\n {\n \tstruct strbuf buf = STRBUF_INIT;\n \n@@ -70,25 +70,25 @@ static void trace_vprintf(const char *key, const char *fmt, va_list ap)\n \t\treturn;\n \n \tset_try_to_free_routine(NULL);\t/* is never reset */\n-\tstrbuf_vaddf(&buf, fmt, ap);\n+\tstrbuf_vaddf(&buf, format, ap);\n \ttrace_strbuf(key, &buf);\n \tstrbuf_release(&buf);\n }\n \n __attribute__((format (printf, 2, 3)))\n-void trace_printf_key(const char *key, const char *fmt, ...)\n+void trace_printf_key(const char *key, const char *format, ...)\n {\n \tva_list ap;\n-\tva_start(ap, fmt);\n-\ttrace_vprintf(key, fmt, ap);\n+\tva_start(ap, format);\n+\ttrace_vprintf(key, format, ap);\n \tva_end(ap);\n }\n \n-void trace_printf(const char *fmt, ...)\n+void trace_printf(const char *format, ...)\n {\n \tva_list ap;\n-\tva_start(ap, fmt);\n-\ttrace_vprintf(\"GIT_TRACE\", fmt, ap);\n+\tva_start(ap, format);\n+\ttrace_vprintf(\"GIT_TRACE\", format, ap);\n \tva_end(ap);\n }\n \n@@ -106,7 +106,7 @@ void trace_strbuf(const char *key, const struct strbuf *buf)\n \t\tclose(fd);\n }\n \n-void trace_argv_printf(const char **argv, const char *fmt, ...)\n+void trace_argv_printf(const char **argv, const char *format, ...)\n {\n \tstruct strbuf buf = STRBUF_INIT;\n \tva_list ap;\n@@ -117,8 +117,8 @@ void trace_argv_printf(const char **argv, const char *fmt, ...)\n \t\treturn;\n \n \tset_try_to_free_routine(NULL);\t/* is never reset */\n-\tva_start(ap, fmt);\n-\tstrbuf_vaddf(&buf, fmt, ap);\n+\tva_start(ap, format);\n+\tstrbuf_vaddf(&buf, format, ap);\n \tva_end(ap);\n \n \tsq_quote_argv(&buf, argv, 0);\ndiff --git a/trace.h b/trace.h\nindex 6cc4541..8fea50b 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -11,7 +11,7 @@ extern void trace_argv_printf(const char **argv, const char *format, ...);\n extern void trace_repo_setup(const char *prefix);\n extern int trace_want(const char *key);\n __attribute__((format (printf, 2, 3)))\n-extern void trace_printf_key(const char *key, const char *fmt, ...);\n+extern void trace_printf_key(const char *key, const char *format, ...);\n extern void trace_strbuf(const char *key, const struct strbuf *buf);\n \n #endif /* TRACE_H */\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245861","messageId":"53C07A59.3020702@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 03/17] trace: remove redundant printf format attribute","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-11T23:59:21Z","receivedAt":"2014-07-11T23:59:21Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"trace_printf_key() is the only non-static function that duplicates the\nprintf format attribute in the .c file, remove it for consistency.\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n trace.c | 1 -\n 1 file changed, 1 deletion(-)\n\ndiff --git a/trace.c b/trace.c\nindex 37a7fa9..3e31558 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -75,7 +75,6 @@ static void trace_vprintf(const char *key, const char *format, va_list ap)\n \tstrbuf_release(&buf);\n }\n \n-__attribute__((format (printf, 2, 3)))\n void trace_printf_key(const char *key, const char *format, ...)\n {\n \tva_list ap;\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245862","messageId":"53C07A86.3000204@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 04/17] trace: improve trace performance","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:00:06Z","receivedAt":"2014-07-12T00:00:06Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"The trace API currently rechecks the environment variable and reopens the\ntrace file on every API call. This has the ugly side effect that errors\n(e.g. file cannot be opened, or the user specified a relative path) are\nalso reported on every call. Performance can be improved by about factor\nthree by remembering the environment state and keeping the file open.\n\nReplace the 'const char *key' parameter in the API with a pointer to a\n'struct trace_key' that bundles the environment variable name with\nadditional, trace-internal state. Change the call sites of these APIs to\nuse a static 'struct trace_key' instead of a string constant.\n\nIn trace.c::get_trace_fd(), save and reuse the file descriptor in 'struct\ntrace_key'.\n\nAdd a 'trace_disable()' API, so that packet_trace() can cleanly disable\ntracing when it encounters packed data (instead of using unsetenv()).\n\nSigned-off-by: Karsten Blees \n---\n builtin/receive-pack.c | 2 +-\n commit.h | 1 +\n pkt-line.c | 8 ++--\n shallow.c | 10 ++---\n trace.c | 100 ++++++++++++++++++++++++++-----------------------\n trace.h | 16 ++++++--\n 6 files changed, 78 insertions(+), 59 deletions(-)\n\ndiff --git a/builtin/receive-pack.c b/builtin/receive-pack.c\nindex c323081..1451050 100644\n--- a/builtin/receive-pack.c\n+++ b/builtin/receive-pack.c\n@@ -438,7 +438,7 @@ static int update_shallow_ref(struct command *cmd, struct shallow_info *si)\n \tuint32_t mask = 1 << (cmd->index % 32);\n \tint i;\n \n-\ttrace_printf_key(\"GIT_TRACE_SHALLOW\",\n+\ttrace_printf_key(&trace_shallow,\n \t\t\t \"shallow: update_shallow_ref %s\\n\", cmd->ref_name);\n \tfor (i = 0; i < si->shallow->nr; i++)\n \t\tif (si->used_shallow[i] &&\ndiff --git a/commit.h b/commit.h\nindex a9f177b..08ef643 100644\n--- a/commit.h\n+++ b/commit.h\n@@ -235,6 +235,7 @@ extern void assign_shallow_commits_to_refs(struct shallow_info *info,\n \t\t\t\t\t int *ref_status);\n extern int delayed_reachability_test(struct shallow_info *si, int c);\n extern void prune_shallow(int show_only);\n+extern struct trace_key trace_shallow;\n \n int is_descendant_of(struct commit *, struct commit_list *);\n int in_merge_bases(struct commit *, struct commit *);\ndiff --git a/pkt-line.c b/pkt-line.c\nindex bc63b3b..8bc89b1 100644\n--- a/pkt-line.c\n+++ b/pkt-line.c\n@@ -3,7 +3,7 @@\n \n char packet_buffer[LARGE_PACKET_MAX];\n static const char *packet_trace_prefix = \"git\";\n-static const char trace_key[] = \"GIT_TRACE_PACKET\";\n+static struct trace_key trace_packet = TRACE_KEY_INIT(PACKET);\n \n void packet_trace_identity(const char *prog)\n {\n@@ -15,7 +15,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)\n \tint i;\n \tstruct strbuf out;\n \n-\tif (!trace_want(trace_key))\n+\tif (!trace_want(&trace_packet))\n \t\treturn;\n \n \t/* +32 is just a guess for header + quoting */\n@@ -27,7 +27,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)\n \tif ((len >= 4 && starts_with(buf, \"PACK\")) ||\n \t (len >= 5 && starts_with(buf+1, \"PACK\"))) {\n \t\tstrbuf_addstr(&out, \"PACK ...\");\n-\t\tunsetenv(trace_key);\n+\t\ttrace_disable(&trace_packet);\n \t}\n \telse {\n \t\t/* XXX we should really handle printable utf8 */\n@@ -43,7 +43,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)\n \t}\n \n \tstrbuf_addch(&out, '\\n');\n-\ttrace_strbuf(trace_key, &out);\n+\ttrace_strbuf(&trace_packet, &out);\n \tstrbuf_release(&out);\n }\n \ndiff --git a/shallow.c b/shallow.c\nindex 0b267b6..de07709 100644\n--- a/shallow.c\n+++ b/shallow.c\n@@ -325,7 +325,7 @@ void prune_shallow(int show_only)\n \tstrbuf_release(&sb);\n }\n \n-#define TRACE_KEY \"GIT_TRACE_SHALLOW\"\n+struct trace_key trace_shallow = TRACE_KEY_INIT(SHALLOW);\n \n /*\n * Step 1, split sender shallow commits into \"ours\" and \"theirs\"\n@@ -334,7 +334,7 @@ void prune_shallow(int show_only)\n void prepare_shallow_info(struct shallow_info *info, struct sha1_array *sa)\n {\n \tint i;\n-\ttrace_printf_key(TRACE_KEY, \"shallow: prepare_shallow_info\\n\");\n+\ttrace_printf_key(&trace_shallow, \"shallow: prepare_shallow_info\\n\");\n \tmemset(info, 0, sizeof(*info));\n \tinfo->shallow = sa;\n \tif (!sa)\n@@ -365,7 +365,7 @@ void remove_nonexistent_theirs_shallow(struct shallow_info *info)\n {\n \tunsigned char (*sha1)[20] = info->shallow->sha1;\n \tint i, dst;\n-\ttrace_printf_key(TRACE_KEY, \"shallow: remove_nonexistent_theirs_shallow\\n\");\n+\ttrace_printf_key(&trace_shallow, \"shallow: remove_nonexistent_theirs_shallow\\n\");\n \tfor (i = dst = 0; i < info->nr_theirs; i++) {\n \t\tif (i != dst)\n \t\t\tinfo->theirs[dst] = info->theirs[i];\n@@ -516,7 +516,7 @@ void assign_shallow_commits_to_refs(struct shallow_info *info,\n \tint *shallow, nr_shallow = 0;\n \tstruct paint_info pi;\n \n-\ttrace_printf_key(TRACE_KEY, \"shallow: assign_shallow_commits_to_refs\\n\");\n+\ttrace_printf_key(&trace_shallow, \"shallow: assign_shallow_commits_to_refs\\n\");\n \tshallow = xmalloc(sizeof(*shallow) * (info->nr_ours + info->nr_theirs));\n \tfor (i = 0; i < info->nr_ours; i++)\n \t\tshallow[nr_shallow++] = info->ours[i];\n@@ -622,7 +622,7 @@ static void post_assign_shallow(struct shallow_info *info,\n \tint bitmap_nr = (info->ref->nr + 31) / 32;\n \tstruct commit_array ca;\n \n-\ttrace_printf_key(TRACE_KEY, \"shallow: post_assign_shallow\\n\");\n+\ttrace_printf_key(&trace_shallow, \"shallow: post_assign_shallow\\n\");\n \tif (ref_status)\n \t\tmemset(ref_status, 0, sizeof(*ref_status) * info->ref->nr);\n \ndiff --git a/trace.c b/trace.c\nindex 3e31558..8662b79 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -26,43 +26,66 @@\n #include \"quote.h\"\n \n /* Get a trace file descriptor from \"key\" env variable. */\n-static int get_trace_fd(const char *key, int *need_close)\n+static int get_trace_fd(struct trace_key *key)\n {\n-\tchar *trace = getenv(key);\n+\tstatic struct trace_key trace_default = { \"GIT_TRACE\" };\n+\tconst char *trace;\n+\n+\t/* use default \"GIT_TRACE\" if NULL */\n+\tif (!key)\n+\t\tkey = &trace_default;\n+\n+\t/* don't open twice */\n+\tif (key->initialized)\n+\t\treturn key->fd;\n+\n+\ttrace = getenv(key->key);\n \n \tif (!trace || !strcmp(trace, \"\") ||\n \t !strcmp(trace, \"0\") || !strcasecmp(trace, \"false\"))\n-\t\treturn 0;\n-\tif (!strcmp(trace, \"1\") || !strcasecmp(trace, \"true\"))\n-\t\treturn STDERR_FILENO;\n-\tif (strlen(trace) == 1 && isdigit(*trace))\n-\t\treturn atoi(trace);\n-\tif (is_absolute_path(trace)) {\n+\t\tkey->fd = 0;\n+\telse if (!strcmp(trace, \"1\") || !strcasecmp(trace, \"true\"))\n+\t\tkey->fd = STDERR_FILENO;\n+\telse if (strlen(trace) == 1 && isdigit(*trace))\n+\t\tkey->fd = atoi(trace);\n+\telse if (is_absolute_path(trace)) {\n \t\tint fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666);\n \t\tif (fd == -1) {\n \t\t\tfprintf(stderr,\n \t\t\t\t\"Could not open '%s' for tracing: %s\\n\"\n \t\t\t\t\"Defaulting to tracing on stderr...\\n\",\n \t\t\t\ttrace, strerror(errno));\n-\t\t\treturn STDERR_FILENO;\n+\t\t\tkey->fd = STDERR_FILENO;\n+\t\t} else {\n+\t\t\tkey->fd = fd;\n+\t\t\tkey->need_close = 1;\n \t\t}\n-\t\t*need_close = 1;\n-\t\treturn fd;\n+\t} else {\n+\t\tfprintf(stderr, \"What does '%s' for %s mean?\\n\"\n+\t\t\t\"If you want to trace into a file, then please set \"\n+\t\t\t\"%s to an absolute pathname (starting with /).\\n\"\n+\t\t\t\"Defaulting to tracing on stderr...\\n\",\n+\t\t\ttrace, key->key, key->key);\n+\t\tkey->fd = STDERR_FILENO;\n \t}\n \n-\tfprintf(stderr, \"What does '%s' for %s mean?\\n\", trace, key);\n-\tfprintf(stderr, \"If you want to trace into a file, \"\n-\t\t\"then please set %s to an absolute pathname \"\n-\t\t\"(starting with /).\\n\", key);\n-\tfprintf(stderr, \"Defaulting to tracing on stderr...\\n\");\n+\tkey->initialized = 1;\n+\treturn key->fd;\n+}\n \n-\treturn STDERR_FILENO;\n+void trace_disable(struct trace_key *key)\n+{\n+\tif (key->need_close)\n+\t\tclose(key->fd);\n+\tkey->fd = 0;\n+\tkey->initialized = 1;\n+\tkey->need_close = 0;\n }\n \n static const char err_msg[] = \"Could not trace into fd given by \"\n \t\"GIT_TRACE environment variable\";\n \n-static void trace_vprintf(const char *key, const char *format, va_list ap)\n+static void trace_vprintf(struct trace_key *key, const char *format, va_list ap)\n {\n \tstruct strbuf buf = STRBUF_INIT;\n \n@@ -75,7 +98,7 @@ static void trace_vprintf(const char *key, const char *format, va_list ap)\n \tstrbuf_release(&buf);\n }\n \n-void trace_printf_key(const char *key, const char *format, ...)\n+void trace_printf_key(struct trace_key *key, const char *format, ...)\n {\n \tva_list ap;\n \tva_start(ap, format);\n@@ -87,31 +110,24 @@ void trace_printf(const char *format, ...)\n {\n \tva_list ap;\n \tva_start(ap, format);\n-\ttrace_vprintf(\"GIT_TRACE\", format, ap);\n+\ttrace_vprintf(NULL, format, ap);\n \tva_end(ap);\n }\n \n-void trace_strbuf(const char *key, const struct strbuf *buf)\n+void trace_strbuf(struct trace_key *key, const struct strbuf *buf)\n {\n-\tint fd, need_close = 0;\n-\n-\tfd = get_trace_fd(key, &need_close);\n+\tint fd = get_trace_fd(key);\n \tif (!fd)\n \t\treturn;\n \n \twrite_or_whine_pipe(fd, buf->buf, buf->len, err_msg);\n-\n-\tif (need_close)\n-\t\tclose(fd);\n }\n \n void trace_argv_printf(const char **argv, const char *format, ...)\n {\n \tstruct strbuf buf = STRBUF_INIT;\n \tva_list ap;\n-\tint fd, need_close = 0;\n-\n-\tfd = get_trace_fd(\"GIT_TRACE\", &need_close);\n+\tint fd = get_trace_fd(NULL);\n \tif (!fd)\n \t\treturn;\n \n@@ -124,9 +140,6 @@ void trace_argv_printf(const char **argv, const char *format, ...)\n \tstrbuf_addch(&buf, '\\n');\n \twrite_or_whine_pipe(fd, buf.buf, buf.len, err_msg);\n \tstrbuf_release(&buf);\n-\n-\tif (need_close)\n-\t\tclose(fd);\n }\n \n static const char *quote_crnl(const char *path)\n@@ -155,11 +168,11 @@ static const char *quote_crnl(const char *path)\n /* FIXME: move prefix to startup_info struct and get rid of this arg */\n void trace_repo_setup(const char *prefix)\n {\n-\tstatic const char *key = \"GIT_TRACE_SETUP\";\n+\tstatic struct trace_key key = TRACE_KEY_INIT(SETUP);\n \tconst char *git_work_tree;\n \tchar cwd[PATH_MAX];\n \n-\tif (!trace_want(key))\n+\tif (!trace_want(&key))\n \t\treturn;\n \n \tif (!getcwd(cwd, PATH_MAX))\n@@ -171,18 +184,13 @@ void trace_repo_setup(const char *prefix)\n \tif (!prefix)\n \t\tprefix = \"(null)\";\n \n-\ttrace_printf_key(key, \"setup: git_dir: %s\\n\", quote_crnl(get_git_dir()));\n-\ttrace_printf_key(key, \"setup: worktree: %s\\n\", quote_crnl(git_work_tree));\n-\ttrace_printf_key(key, \"setup: cwd: %s\\n\", quote_crnl(cwd));\n-\ttrace_printf_key(key, \"setup: prefix: %s\\n\", quote_crnl(prefix));\n+\ttrace_printf_key(&key, \"setup: git_dir: %s\\n\", quote_crnl(get_git_dir()));\n+\ttrace_printf_key(&key, \"setup: worktree: %s\\n\", quote_crnl(git_work_tree));\n+\ttrace_printf_key(&key, \"setup: cwd: %s\\n\", quote_crnl(cwd));\n+\ttrace_printf_key(&key, \"setup: prefix: %s\\n\", quote_crnl(prefix));\n }\n \n-int trace_want(const char *key)\n+int trace_want(struct trace_key *key)\n {\n-\tconst char *trace = getenv(key);\n-\n-\tif (!trace || !strcmp(trace, \"\") ||\n-\t !strcmp(trace, \"0\") || !strcasecmp(trace, \"false\"))\n-\t\treturn 0;\n-\treturn 1;\n+\treturn !!get_trace_fd(key);\n }\ndiff --git a/trace.h b/trace.h\nindex 8fea50b..d85ac4c 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -4,14 +4,24 @@\n #include \"git-compat-util.h\"\n #include \"strbuf.h\"\n \n+struct trace_key {\n+\tconst char * const key;\n+\tint fd;\n+\tunsigned int initialized : 1;\n+\tunsigned int need_close : 1;\n+};\n+\n+#define TRACE_KEY_INIT(name) { \"GIT_TRACE_\" #name, 0, 0, 0 }\n+\n __attribute__((format (printf, 1, 2)))\n extern void trace_printf(const char *format, ...);\n __attribute__((format (printf, 2, 3)))\n extern void trace_argv_printf(const char **argv, const char *format, ...);\n extern void trace_repo_setup(const char *prefix);\n-extern int trace_want(const char *key);\n+extern int trace_want(struct trace_key *key);\n+extern void trace_disable(struct trace_key *key);\n __attribute__((format (printf, 2, 3)))\n-extern void trace_printf_key(const char *key, const char *format, ...);\n-extern void trace_strbuf(const char *key, const struct strbuf *buf);\n+extern void trace_printf_key(struct trace_key *key, const char *format, ...);\n+extern void trace_strbuf(struct trace_key *key, const struct strbuf *buf);\n \n #endif /* TRACE_H */\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245863","messageId":"53C07AB5.8000507@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 05/17] Documentation/git.txt: improve documentation of 'GIT_TRACE*' variables","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:00:53Z","receivedAt":"2014-07-12T00:00:53Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Separate GIT_TRACE description into what it prints and how to configure\nwhere trace output is printed to. Change other GIT_TRACE_* descriptions to\nrefer to GIT_TRACE.\n\nAdd descriptions for GIT_TRACE_SETUP and GIT_TRACE_SHALLOW.\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n Documentation/git.txt | 50 ++++++++++++++++++++++++++++++++++----------------\n 1 file changed, 34 insertions(+), 16 deletions(-)\n\ndiff --git a/Documentation/git.txt b/Documentation/git.txt\nindex 3bd68b0..75633e6 100644\n--- a/Documentation/git.txt\n+++ b/Documentation/git.txt\n@@ -904,18 +904,25 @@ for further details.\n \tbased on whether stdout appears to be redirected to a file or not.\n \n 'GIT_TRACE'::\n-\tIf this variable is set to \"1\", \"2\" or \"true\" (comparison\n-\tis case insensitive), Git will print `trace:` messages on\n-\tstderr telling about alias expansion, built-in command\n-\texecution and external command execution.\n-\tIf this variable is set to an integer value greater than 1\n-\tand lower than 10 (strictly) then Git will interpret this\n-\tvalue as an open file descriptor and will try to write the\n-\ttrace messages into this file descriptor.\n-\tAlternatively, if this variable is set to an absolute path\n-\t(starting with a '/' character), Git will interpret this\n-\tas a file path and will try to write the trace messages\n-\tinto it.\n+\tEnables general trace messages, e.g. alias expansion, built-in\n+\tcommand execution and external command execution.\n++\n+If this variable is set to \"1\", \"2\" or \"true\" (comparison\n+is case insensitive), trace messages will be printed to\n+stderr.\n++\n+If the variable is set to an integer value greater than 2\n+and lower than 10 (strictly) then Git will interpret this\n+value as an open file descriptor and will try to write the\n+trace messages into this file descriptor.\n++\n+Alternatively, if the variable is set to an absolute path\n+(starting with a '/' character), Git will interpret this\n+as a file path and will try to write the trace messages\n+into it.\n++\n+Unsetting the variable, or setting it to empty, \"0\" or\n+\"false\" (case insensitive) disables trace messages.\n \n 'GIT_TRACE_PACK_ACCESS'::\n \tIf this variable is set to a path, a file will be created at\n@@ -925,10 +932,21 @@ for further details.\n \tpack-related performance problems.\n \n 'GIT_TRACE_PACKET'::\n-\tIf this variable is set, it shows a trace of all packets\n-\tcoming in or out of a given program. This can help with\n-\tdebugging object negotiation or other protocol issues. Tracing\n-\tis turned off at a packet starting with \"PACK\".\n+\tEnables trace messages for all packets coming in or out of a\n+\tgiven program. This can help with debugging object negotiation\n+\tor other protocol issues. Tracing is turned off at a packet\n+\tstarting with \"PACK\".\n+\tSee 'GIT_TRACE' for available trace output options.\n+\n+'GIT_TRACE_SETUP'::\n+\tEnables trace messages printing the .git, working tree and current\n+\tworking directory after Git has completed its setup phase.\n+\tSee 'GIT_TRACE' for available trace output options.\n+\n+'GIT_TRACE_SHALLOW'::\n+\tEnables trace messages that can help debugging fetching /\n+\tcloning of shallow repositories.\n+\tSee 'GIT_TRACE' for available trace output options.\n \n GIT_LITERAL_PATHSPECS::\n \tSetting this variable to `1` will cause Git to treat all\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245864","messageId":"53C07AE2.4070107@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 06/17] sha1_file: change GIT_TRACE_PACK_ACCESS logging to use trace API","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:01:38Z","receivedAt":"2014-07-12T00:01:38Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"This changes GIT_TRACE_PACK_ACCESS functionality as follows:\n * supports the same options as GIT_TRACE (e.g. printing to stderr)\n * no longer supports relative paths\n * appends to the trace file rather than overwriting\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n Documentation/git.txt | 4 ++--\n sha1_file.c | 30 ++++--------------------------\n 2 files changed, 6 insertions(+), 28 deletions(-)\n\ndiff --git a/Documentation/git.txt b/Documentation/git.txt\nindex 75633e6..9d073f6 100644\n--- a/Documentation/git.txt\n+++ b/Documentation/git.txt\n@@ -925,11 +925,11 @@ Unsetting the variable, or setting it to empty, \"0\" or\n \"false\" (case insensitive) disables trace messages.\n \n 'GIT_TRACE_PACK_ACCESS'::\n-\tIf this variable is set to a path, a file will be created at\n-\tthe given path logging all accesses to any packs. For each\n+\tEnables trace messages for all accesses to any packs. For each\n \taccess, the pack file name and an offset in the pack is\n \trecorded. This may be helpful for troubleshooting some\n \tpack-related performance problems.\n+\tSee 'GIT_TRACE' for available trace output options.\n \n 'GIT_TRACE_PACKET'::\n \tEnables trace messages for all packets coming in or out of a\ndiff --git a/sha1_file.c b/sha1_file.c\nindex 34d527f..7a110b5 100644\n--- a/sha1_file.c\n+++ b/sha1_file.c\n@@ -36,9 +36,6 @@ static inline uintmax_t sz_fmt(size_t s) { return s; }\n \n const unsigned char null_sha1[20];\n \n-static const char *no_log_pack_access = \"no_log_pack_access\";\n-static const char *log_pack_access;\n-\n /*\n * This is meant to hold a *small* number of objects that you would\n * want read_sha1_file() to be able to return, but yet you do not want\n@@ -2085,27 +2082,9 @@ static void *read_object(const unsigned char *sha1, enum object_type *type,\n \n static void write_pack_access_log(struct packed_git *p, off_t obj_offset)\n {\n-\tstatic FILE *log_file;\n-\n-\tif (!log_pack_access)\n-\t\tlog_pack_access = getenv(\"GIT_TRACE_PACK_ACCESS\");\n-\tif (!log_pack_access)\n-\t\tlog_pack_access = no_log_pack_access;\n-\tif (log_pack_access == no_log_pack_access)\n-\t\treturn;\n-\n-\tif (!log_file) {\n-\t\tlog_file = fopen(log_pack_access, \"w\");\n-\t\tif (!log_file) {\n-\t\t\terror(\"cannot open pack access log '%s' for writing: %s\",\n-\t\t\t log_pack_access, strerror(errno));\n-\t\t\tlog_pack_access = no_log_pack_access;\n-\t\t\treturn;\n-\t\t}\n-\t}\n-\tfprintf(log_file, \"%s %\"PRIuMAX\"\\n\",\n-\t\tp->pack_name, (uintmax_t)obj_offset);\n-\tfflush(log_file);\n+\tstatic struct trace_key pack_access = TRACE_KEY_INIT(PACK_ACCESS);\n+\ttrace_printf_key(&pack_access, \"%s %\"PRIuMAX\"\\n\",\n+\t\t\t p->pack_name, (uintmax_t)obj_offset);\n }\n \n int do_check_packed_object_crc;\n@@ -2130,8 +2109,7 @@ void *unpack_entry(struct packed_git *p, off_t obj_offset,\n \tint delta_stack_nr = 0, delta_stack_alloc = UNPACK_ENTRY_STACK_PREALLOC;\n \tint base_from_cache = 0;\n \n-\tif (log_pack_access != no_log_pack_access)\n-\t\twrite_pack_access_log(p, obj_offset);\n+\twrite_pack_access_log(p, obj_offset);\n \n \t/* PHASE 1: drill down to the innermost base object */\n \tfor (;;) {\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245865","messageId":"53C07B0A.6010709@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 07/17] trace: add infrastructure to augment trace output with additional info","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:02:18Z","receivedAt":"2014-07-12T00:02:18Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"To be able to add a common prefix or suffix to all trace output (e.g.\na timestamp or file:line of the caller), factor out common setup and\ncleanup tasks of the trace* functions.\n\nWhen adding a common prefix, it makes sense that the output of each trace\ncall starts on a new line. Add '\\n' in case the caller forgot.\n\nNote that this explicitly limits trace output to line-by-line, it is no\nlonger possible to trace-print just part of a line. Until now, this was\njust an implicit assumption (trace-printing part of a line worked, but\nmessed up the trace file if multiple threads or processes were involved).\n\nThread-safety / inter-process-safety is also the reason why we need to do\nthe prefixing and suffixing in memory rather than issuing multiple write()\ncalls. Write_or_whine_pipe() / xwrite() is atomic unless the size exceeds\nMAX_IO_SIZE (8MB, see wrapper.c). In case of trace_strbuf, this costs an\nadditional string copy (which should be irrelevant for performance in light\nof actual file IO).\n\nWhile we're at it, rename trace_strbuf's 'buf' argument, which suggests\nthat the function is modifying the buffer. Trace_strbuf() currently is the\nonly trace API that can print arbitrary binary data (without barfing on\n'%' or stopping at '\\0'), so 'data' seems more appropriate.\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n trace.c | 47 +++++++++++++++++++++++++++++++++--------------\n trace.h | 2 +-\n 2 files changed, 34 insertions(+), 15 deletions(-)\n\ndiff --git a/trace.c b/trace.c\nindex 8662b79..3d02bcc 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -85,17 +85,37 @@ void trace_disable(struct trace_key *key)\n static const char err_msg[] = \"Could not trace into fd given by \"\n \t\"GIT_TRACE environment variable\";\n \n+static int prepare_trace_line(struct trace_key *key, struct strbuf *buf)\n+{\n+\tif (!trace_want(key))\n+\t\treturn 0;\n+\n+\tset_try_to_free_routine(NULL);\t/* is never reset */\n+\n+\t/* add line prefix here */\n+\n+\treturn 1;\n+}\n+\n+static void print_trace_line(struct trace_key *key, struct strbuf *buf)\n+{\n+\t/* append newline if missing */\n+\tif (buf->len && buf->buf[buf->len - 1] != '\\n')\n+\t\tstrbuf_addch(buf, '\\n');\n+\n+\twrite_or_whine_pipe(get_trace_fd(key), buf->buf, buf->len, err_msg);\n+\tstrbuf_release(buf);\n+}\n+\n static void trace_vprintf(struct trace_key *key, const char *format, va_list ap)\n {\n \tstruct strbuf buf = STRBUF_INIT;\n \n-\tif (!trace_want(key))\n+\tif (!prepare_trace_line(key, &buf))\n \t\treturn;\n \n-\tset_try_to_free_routine(NULL);\t/* is never reset */\n \tstrbuf_vaddf(&buf, format, ap);\n-\ttrace_strbuf(key, &buf);\n-\tstrbuf_release(&buf);\n+\tprint_trace_line(key, &buf);\n }\n \n void trace_printf_key(struct trace_key *key, const char *format, ...)\n@@ -114,32 +134,31 @@ void trace_printf(const char *format, ...)\n \tva_end(ap);\n }\n \n-void trace_strbuf(struct trace_key *key, const struct strbuf *buf)\n+void trace_strbuf(struct trace_key *key, const struct strbuf *data)\n {\n-\tint fd = get_trace_fd(key);\n-\tif (!fd)\n+\tstruct strbuf buf = STRBUF_INIT;\n+\n+\tif (!prepare_trace_line(key, &buf))\n \t\treturn;\n \n-\twrite_or_whine_pipe(fd, buf->buf, buf->len, err_msg);\n+\tstrbuf_addbuf(&buf, data);\n+\tprint_trace_line(key, &buf);\n }\n \n void trace_argv_printf(const char **argv, const char *format, ...)\n {\n \tstruct strbuf buf = STRBUF_INIT;\n \tva_list ap;\n-\tint fd = get_trace_fd(NULL);\n-\tif (!fd)\n+\n+\tif (!prepare_trace_line(NULL, &buf))\n \t\treturn;\n \n-\tset_try_to_free_routine(NULL);\t/* is never reset */\n \tva_start(ap, format);\n \tstrbuf_vaddf(&buf, format, ap);\n \tva_end(ap);\n \n \tsq_quote_argv(&buf, argv, 0);\n-\tstrbuf_addch(&buf, '\\n');\n-\twrite_or_whine_pipe(fd, buf.buf, buf.len, err_msg);\n-\tstrbuf_release(&buf);\n+\tprint_trace_line(NULL, &buf);\n }\n \n static const char *quote_crnl(const char *path)\ndiff --git a/trace.h b/trace.h\nindex d85ac4c..28c1089 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -22,6 +22,6 @@ extern int trace_want(struct trace_key *key);\n extern void trace_disable(struct trace_key *key);\n __attribute__((format (printf, 2, 3)))\n extern void trace_printf_key(struct trace_key *key, const char *format, ...);\n-extern void trace_strbuf(struct trace_key *key, const struct strbuf *buf);\n+extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);\n \n #endif /* TRACE_H */\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245866","messageId":"53C07B35.3090600@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 08/17] trace: disable additional trace output for unit tests","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:03:01Z","receivedAt":"2014-07-12T00:03:01Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Some unit-tests use trace output to verify internal state, and unstable\noutput such as timestamps and line numbers are not useful there.\n\nDisable additional trace output if GIT_TRACE_BARE is set.\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n t/test-lib.sh | 4 ++++\n trace.c | 6 ++++++\n 2 files changed, 10 insertions(+)\n\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex 81394c8..e37da5a 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -109,6 +109,10 @@ export GIT_AUTHOR_EMAIL GIT_AUTHOR_NAME\n export GIT_COMMITTER_EMAIL GIT_COMMITTER_NAME\n export EDITOR\n \n+# Tests using GIT_TRACE typically don't want : output\n+GIT_TRACE_BARE=1\n+export GIT_TRACE_BARE\n+\n if test -n \"${TEST_GIT_INDEX_VERSION:+isset}\"\n then\n \tGIT_INDEX_VERSION=\"$TEST_GIT_INDEX_VERSION\"\ndiff --git a/trace.c b/trace.c\nindex 3d02bcc..a194b16 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -87,11 +87,17 @@ static const char err_msg[] = \"Could not trace into fd given by \"\n \n static int prepare_trace_line(struct trace_key *key, struct strbuf *buf)\n {\n+\tstatic struct trace_key trace_bare = TRACE_KEY_INIT(BARE);\n+\n \tif (!trace_want(key))\n \t\treturn 0;\n \n \tset_try_to_free_routine(NULL);\t/* is never reset */\n \n+\t/* unit tests may want to disable additional trace output */\n+\tif (trace_want(&trace_bare))\n+\t\treturn 1;\n+\n \t/* add line prefix here */\n \n \treturn 1;\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245867","messageId":"53C07B66.5080200@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 09/17] trace: add current timestamp to all trace output","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:03:50Z","receivedAt":"2014-07-12T00:03:50Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"This is useful to tell apart trace output of separate test runs.\n\nIt can also be used for basic, coarse-grained performance analysis. Note\nthat the accuracy is tainted by writing to the trace file, and you have to\ncalculate the deltas yourself (which is next to impossible if multiple\nthreads or processes are involved).\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n trace.c | 10 +++++++++-\n 1 file changed, 9 insertions(+), 1 deletion(-)\n\ndiff --git a/trace.c b/trace.c\nindex a194b16..18e5d93 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -88,6 +88,9 @@ static const char err_msg[] = \"Could not trace into fd given by \"\n static int prepare_trace_line(struct trace_key *key, struct strbuf *buf)\n {\n \tstatic struct trace_key trace_bare = TRACE_KEY_INIT(BARE);\n+\tstruct timeval tv;\n+\tstruct tm tm;\n+\ttime_t secs;\n \n \tif (!trace_want(key))\n \t\treturn 0;\n@@ -98,7 +101,12 @@ static int prepare_trace_line(struct trace_key *key, struct strbuf *buf)\n \tif (trace_want(&trace_bare))\n \t\treturn 1;\n \n-\t/* add line prefix here */\n+\t/* print current timestamp */\n+\tgettimeofday(&tv, NULL);\n+\tsecs = tv.tv_sec;\n+\tlocaltime_r(&secs, &tm);\n+\tstrbuf_addf(buf, \"%02d:%02d:%02d.%06ld \", tm.tm_hour, tm.tm_min,\n+\t\t tm.tm_sec, (long) tv.tv_usec);\n \n \treturn 1;\n }\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245868","messageId":"53C07B8D.9050308@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 10/17] trace: move code around, in preparation to file:line output","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:04:29Z","receivedAt":"2014-07-12T00:04:29Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"No functional changes, just move stuff around so that the next patch isn't\nthat ugly...\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n trace.c | 36 ++++++++++++++++++------------------\n trace.h | 12 ++++++++----\n 2 files changed, 26 insertions(+), 22 deletions(-)\n\ndiff --git a/trace.c b/trace.c\nindex 18e5d93..e8ce619 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -132,20 +132,20 @@ static void trace_vprintf(struct trace_key *key, const char *format, va_list ap)\n \tprint_trace_line(key, &buf);\n }\n \n-void trace_printf_key(struct trace_key *key, const char *format, ...)\n+void trace_argv_printf(const char **argv, const char *format, ...)\n {\n+\tstruct strbuf buf = STRBUF_INIT;\n \tva_list ap;\n-\tva_start(ap, format);\n-\ttrace_vprintf(key, format, ap);\n-\tva_end(ap);\n-}\n \n-void trace_printf(const char *format, ...)\n-{\n-\tva_list ap;\n+\tif (!prepare_trace_line(NULL, &buf))\n+\t\treturn;\n+\n \tva_start(ap, format);\n-\ttrace_vprintf(NULL, format, ap);\n+\tstrbuf_vaddf(&buf, format, ap);\n \tva_end(ap);\n+\n+\tsq_quote_argv(&buf, argv, 0);\n+\tprint_trace_line(NULL, &buf);\n }\n \n void trace_strbuf(struct trace_key *key, const struct strbuf *data)\n@@ -159,20 +159,20 @@ void trace_strbuf(struct trace_key *key, const struct strbuf *data)\n \tprint_trace_line(key, &buf);\n }\n \n-void trace_argv_printf(const char **argv, const char *format, ...)\n+void trace_printf(const char *format, ...)\n {\n-\tstruct strbuf buf = STRBUF_INIT;\n \tva_list ap;\n-\n-\tif (!prepare_trace_line(NULL, &buf))\n-\t\treturn;\n-\n \tva_start(ap, format);\n-\tstrbuf_vaddf(&buf, format, ap);\n+\ttrace_vprintf(NULL, format, ap);\n \tva_end(ap);\n+}\n \n-\tsq_quote_argv(&buf, argv, 0);\n-\tprint_trace_line(NULL, &buf);\n+void trace_printf_key(struct trace_key *key, const char *format, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, format);\n+\ttrace_vprintf(key, format, ap);\n+\tva_end(ap);\n }\n \n static const char *quote_crnl(const char *path)\ndiff --git a/trace.h b/trace.h\nindex 28c1089..b4800e7 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -13,15 +13,19 @@ struct trace_key {\n \n #define TRACE_KEY_INIT(name) { \"GIT_TRACE_\" #name, 0, 0, 0 }\n \n-__attribute__((format (printf, 1, 2)))\n-extern void trace_printf(const char *format, ...);\n-__attribute__((format (printf, 2, 3)))\n-extern void trace_argv_printf(const char **argv, const char *format, ...);\n extern void trace_repo_setup(const char *prefix);\n extern int trace_want(struct trace_key *key);\n extern void trace_disable(struct trace_key *key);\n+\n+__attribute__((format (printf, 1, 2)))\n+extern void trace_printf(const char *format, ...);\n+\n __attribute__((format (printf, 2, 3)))\n extern void trace_printf_key(struct trace_key *key, const char *format, ...);\n+\n+__attribute__((format (printf, 2, 3)))\n+extern void trace_argv_printf(const char **argv, const char *format, ...);\n+\n extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);\n \n #endif /* TRACE_H */\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245869","messageId":"53C07BAF.6040807@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 11/17] trace: add 'file:line' to all trace output","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:05:03Z","receivedAt":"2014-07-12T00:05:03Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"This is useful to see where trace output came from.\n\nAdd 'const char *file, int line' parameters to the printing functions and\nrename them to *_fl.\n\nAdd trace_printf* and trace_strbuf macros resolving to the *_fl functions\nand let the preprocessor fill in __FILE__ and __LINE__.\n\nAs the trace_printf* functions take a variable number of arguments, this\nrequires variadic macros (i.e. '#define foo(...) foo_impl(__VA_ARGS__)'.\nThough part of C99, it is unclear whether older compilers support this.\nThus keep the old functions and only enable variadic macros for GNUC and\nMSVC 2005+ (_MSC_VER 1400). This has the nice side effect that the old\nC-style declarations serve as documentation how the macros are to be used.\n\nPrint 'file:line ' as prefix to each trace line. Align the remaining trace\noutput at column 40 to accommodate 18 char file names + 4 digit line\nnumber (currently there are 30 *.c files of length 18 and just 11 of 19).\nTrace output from longer source files (e.g. builtin/receive-pack.c) will\nnot be aligned.\n\nSigned-off-by: Karsten Blees \n---\n git-compat-util.h | 4 ++++\n trace.c | 72 +++++++++++++++++++++++++++++++++++++++++++++----------\n trace.h | 62 +++++++++++++++++++++++++++++++++++++++++++++++\n 3 files changed, 126 insertions(+), 12 deletions(-)\n\ndiff --git a/git-compat-util.h b/git-compat-util.h\nindex b6f03b3..4dd065d 100644\n--- a/git-compat-util.h\n+++ b/git-compat-util.h\n@@ -704,6 +704,10 @@ void git_qsort(void *base, size_t nmemb, size_t size,\n #endif\n #endif\n \n+#if defined(__GNUC__) || (_MSC_VER >= 1400)\n+#define HAVE_VARIADIC_MACROS 1\n+#endif\n+\n /*\n * Preserves errno, prints a message, but gives no warning for ENOENT.\n * Always returns the return value of unlink(2).\ndiff --git a/trace.c b/trace.c\nindex e8ce619..f013958 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -85,7 +85,8 @@ void trace_disable(struct trace_key *key)\n static const char err_msg[] = \"Could not trace into fd given by \"\n \t\"GIT_TRACE environment variable\";\n \n-static int prepare_trace_line(struct trace_key *key, struct strbuf *buf)\n+static int prepare_trace_line(const char *file, int line,\n+\t\t\t struct trace_key *key, struct strbuf *buf)\n {\n \tstatic struct trace_key trace_bare = TRACE_KEY_INIT(BARE);\n \tstruct timeval tv;\n@@ -108,6 +109,14 @@ static int prepare_trace_line(struct trace_key *key, struct strbuf *buf)\n \tstrbuf_addf(buf, \"%02d:%02d:%02d.%06ld \", tm.tm_hour, tm.tm_min,\n \t\t tm.tm_sec, (long) tv.tv_usec);\n \n+#ifdef HAVE_VARIADIC_MACROS\n+\t/* print file:line */\n+\tstrbuf_addf(buf, \"%s:%d \", file, line);\n+\t/* align trace output (column 40 catches most files names in git) */\n+\twhile (buf->len < 40)\n+\t\tstrbuf_addch(buf, ' ');\n+#endif\n+\n \treturn 1;\n }\n \n@@ -121,49 +130,52 @@ static void print_trace_line(struct trace_key *key, struct strbuf *buf)\n \tstrbuf_release(buf);\n }\n \n-static void trace_vprintf(struct trace_key *key, const char *format, va_list ap)\n+static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,\n+\t\t\t const char *format, va_list ap)\n {\n \tstruct strbuf buf = STRBUF_INIT;\n \n-\tif (!prepare_trace_line(key, &buf))\n+\tif (!prepare_trace_line(file, line, key, &buf))\n \t\treturn;\n \n \tstrbuf_vaddf(&buf, format, ap);\n \tprint_trace_line(key, &buf);\n }\n \n-void trace_argv_printf(const char **argv, const char *format, ...)\n+static void trace_argv_vprintf_fl(const char *file, int line,\n+\t\t\t\t const char **argv, const char *format,\n+\t\t\t\t va_list ap)\n {\n \tstruct strbuf buf = STRBUF_INIT;\n-\tva_list ap;\n \n-\tif (!prepare_trace_line(NULL, &buf))\n+\tif (!prepare_trace_line(file, line, NULL, &buf))\n \t\treturn;\n \n-\tva_start(ap, format);\n \tstrbuf_vaddf(&buf, format, ap);\n-\tva_end(ap);\n \n \tsq_quote_argv(&buf, argv, 0);\n \tprint_trace_line(NULL, &buf);\n }\n \n-void trace_strbuf(struct trace_key *key, const struct strbuf *data)\n+void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n+\t\t const struct strbuf *data)\n {\n \tstruct strbuf buf = STRBUF_INIT;\n \n-\tif (!prepare_trace_line(key, &buf))\n+\tif (!prepare_trace_line(file, line, key, &buf))\n \t\treturn;\n \n \tstrbuf_addbuf(&buf, data);\n \tprint_trace_line(key, &buf);\n }\n \n+#ifndef HAVE_VARIADIC_MACROS\n+\n void trace_printf(const char *format, ...)\n {\n \tva_list ap;\n \tva_start(ap, format);\n-\ttrace_vprintf(NULL, format, ap);\n+\ttrace_vprintf_fl(NULL, 0, NULL, format, ap);\n \tva_end(ap);\n }\n \n@@ -171,10 +183,46 @@ void trace_printf_key(struct trace_key *key, const char *format, ...)\n {\n \tva_list ap;\n \tva_start(ap, format);\n-\ttrace_vprintf(key, format, ap);\n+\ttrace_vprintf_fl(NULL, 0, key, format, ap);\n+\tva_end(ap);\n+}\n+\n+void trace_argv_printf(const char **argv, const char *format, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, format);\n+\ttrace_argv_vprintf_fl(NULL, 0, argv, format, ap);\n \tva_end(ap);\n }\n \n+void trace_strbuf(const char *key, const struct strbuf *data)\n+{\n+\ttrace_strbuf_fl(NULL, 0, key, data);\n+}\n+\n+#else\n+\n+void trace_printf_key_fl(const char *file, int line, struct trace_key *key,\n+\t\t\t const char *format, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, format);\n+\ttrace_vprintf_fl(file, line, key, format, ap);\n+\tva_end(ap);\n+}\n+\n+void trace_argv_printf_fl(const char *file, int line, const char **argv,\n+\t\t\t const char *format, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, format);\n+\ttrace_argv_vprintf_fl(file, line, argv, format, ap);\n+\tva_end(ap);\n+}\n+\n+#endif /* HAVE_VARIADIC_MACROS */\n+\n+\n static const char *quote_crnl(const char *path)\n {\n \tstatic char new_path[PATH_MAX];\ndiff --git a/trace.h b/trace.h\nindex b4800e7..7a5ba2e 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -17,6 +17,8 @@ extern void trace_repo_setup(const char *prefix);\n extern int trace_want(struct trace_key *key);\n extern void trace_disable(struct trace_key *key);\n \n+#ifndef HAVE_VARIADIC_MACROS\n+\n __attribute__((format (printf, 1, 2)))\n extern void trace_printf(const char *format, ...);\n \n@@ -28,4 +30,64 @@ extern void trace_argv_printf(const char **argv, const char *format, ...);\n \n extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);\n \n+#else\n+\n+/*\n+ * Macros to add file:line - see above for C-style declarations of how these\n+ * should be used.\n+ */\n+\n+/*\n+ * TRACE_CONTEXT may be set to __FUNCTION__ if the compiler supports it. The\n+ * default is __FILE__, as it is consistent with assert(), and static function\n+ * names are not necessarily unique.\n+ *\n+ * __FILE__ \":\" __FUNCTION__ doesn't work with GNUC, as __FILE__ is supplied\n+ * by the preprocessor as a string literal, and __FUNCTION__ is filled in by\n+ * the compiler as a string constant.\n+ */\n+#ifndef TRACE_CONTEXT\n+# define TRACE_CONTEXT __FILE__\n+#endif\n+\n+/*\n+ * Note: with C99 variadic macros, __VA_ARGS__ must include the last fixed\n+ * parameter ('format' in this case). Otherwise, a call without variable\n+ * arguments will have a surplus ','. E.g.:\n+ *\n+ * #define foo(format, ...) bar(format, __VA_ARGS__)\n+ * foo(\"test\");\n+ *\n+ * will expand to\n+ *\n+ * bar(\"test\",);\n+ *\n+ * which is invalid (note the ',)'). With GNUC, '##__VA_ARGS__' drops the\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+/* backend functions, use non-*fl macros instead */\n+__attribute__((format (printf, 4, 5)))\n+extern void trace_printf_key_fl(const char *file, int line, struct trace_key *key,\n+\t\t\t\tconst char *format, ...);\n+__attribute__((format (printf, 4, 5)))\n+extern void trace_argv_printf_fl(const char *file, int line, const char **argv,\n+\t\t\t\t const char *format, ...);\n+extern void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n+\t\t\t const struct strbuf *data);\n+\n+#endif /* HAVE_VARIADIC_MACROS */\n+\n #endif /* TRACE_H */\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245870","messageId":"53C07BD6.5010008@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 12/17] trace: add high resolution timer function to debug performance issues","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:05:42Z","receivedAt":"2014-07-12T00:05:42Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Add a getnanotime() function that returns nanoseconds since 01/01/1970 as\nunsigned 64-bit integer (i.e. overflows in july 2554). This is easier to\nwork with than e.g. struct timeval or struct timespec. Basing the timer on\nthe epoch allows using the results with other time-related APIs.\n\nTo simplify adaption to different platforms, split the implementation into\na common getnanotime() and a platform-specific highres_nanos() function.\n\nThe common getnanotime() function handles errors, falling back to\ngettimeofday() if highres_nanos() isn't implemented or doesn't work.\n\ngetnanotime() is also responsible for normalizing to the epoch. The offset\nto the system clock is calculated only once on initialization, i.e.\nmanually setting the system clock has no impact on the timer (except if\nthe fallback gettimeofday() is in use). Git processes are typically short\nlived, so we don't need to handle clock drift.\n\nThe highres_nanos() function returns monotonically increasing nanoseconds\nrelative to some arbitrary point in time (e.g. system boot), or 0 on\nfailure. Providing platform-specific implementations should be relatively\neasy, e.g. adapting to clock_gettime() as defined by the POSIX realtime\nextensions is seven lines of code.\n\nThis version includes highres_nanos() implementations for:\n * Linux: using clock_gettime(CLOCK_MONOTONIC)\n * Windows: using QueryPerformanceCounter()\n\nTodo:\n * enable clock_gettime() on more platforms\n * add Mac OSX version, e.g. using mach_absolute_time + mach_timebase_info\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n Makefile | 7 +++++\n config.mak.uname | 1 +\n trace.c | 82 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++\n trace.h | 1 +\n 4 files changed, 91 insertions(+)\n\ndiff --git a/Makefile b/Makefile\nindex 07ea105..80f4390 100644\n--- a/Makefile\n+++ b/Makefile\n@@ -340,6 +340,8 @@ all::\n #\n # Define GMTIME_UNRELIABLE_ERRORS if your gmtime() function does not\n # return NULL when it receives a bogus time_t.\n+#\n+# Define HAVE_CLOCK_GETTIME if your platform has clock_gettime in librt.\n \n GIT-VERSION-FILE: FORCE\n \t@$(SHELL_PATH) ./GIT-VERSION-GEN\n@@ -1497,6 +1499,11 @@ ifdef GMTIME_UNRELIABLE_ERRORS\n \tBASIC_CFLAGS += -DGMTIME_UNRELIABLE_ERRORS\n endif\n \n+ifdef HAVE_CLOCK_GETTIME\n+\tBASIC_CFLAGS += -DHAVE_CLOCK_GETTIME\n+\tEXTLIBS += -lrt\n+endif\n+\n ifeq ($(TCLTK_PATH),)\n NO_TCLTK = NoThanks\n endif\ndiff --git a/config.mak.uname b/config.mak.uname\nindex 1ae675b..dad2618 100644\n--- a/config.mak.uname\n+++ b/config.mak.uname\n@@ -34,6 +34,7 @@ ifeq ($(uname_S),Linux)\n \tHAVE_PATHS_H = YesPlease\n \tLIBC_CONTAINS_LIBINTL = YesPlease\n \tHAVE_DEV_TTY = YesPlease\n+\tHAVE_CLOCK_GETTIME = YesPlease\n endif\n ifeq ($(uname_S),GNU/kFreeBSD)\n \tHAVE_ALLOCA_H = YesPlease\ndiff --git a/trace.c b/trace.c\nindex f013958..b9d7272 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -275,3 +275,85 @@ int trace_want(struct trace_key *key)\n {\n \treturn !!get_trace_fd(key);\n }\n+\n+#ifdef HAVE_CLOCK_GETTIME\n+\n+static inline uint64_t highres_nanos(void)\n+{\n+\tstruct timespec ts;\n+\tif (clock_gettime(CLOCK_MONOTONIC, &ts))\n+\t\treturn 0;\n+\treturn (uint64_t) ts.tv_sec * 1000000000 + ts.tv_nsec;\n+}\n+\n+#elif defined (GIT_WINDOWS_NATIVE)\n+\n+static inline uint64_t highres_nanos(void)\n+{\n+\tstatic uint64_t high_ns, scaled_low_ns;\n+\tstatic int scale;\n+\tLARGE_INTEGER cnt;\n+\n+\tif (!scale) {\n+\t\tif (!QueryPerformanceFrequency(&cnt))\n+\t\t\treturn 0;\n+\n+\t\t/* high_ns = number of ns per cnt.HighPart */\n+\t\thigh_ns = (1000000000LL << 32) / (uint64_t) cnt.QuadPart;\n+\n+\t\t/*\n+\t\t * Number of ns per cnt.LowPart is 10^9 / frequency (or\n+\t\t * high_ns >> 32). For maximum precision, we scale this factor\n+\t\t * so that it just fits within 32 bit (i.e. won't overflow if\n+\t\t * multiplied with cnt.LowPart).\n+\t\t */\n+\t\tscaled_low_ns = high_ns;\n+\t\tscale = 32;\n+\t\twhile (scaled_low_ns >= 0x100000000LL) {\n+\t\t\tscaled_low_ns >>= 1;\n+\t\t\tscale--;\n+\t\t}\n+\t}\n+\n+\t/* if QPF worked on initialization, we expect QPC to work as well */\n+\tQueryPerformanceCounter(&cnt);\n+\n+\treturn (high_ns * cnt.HighPart) +\n+\t ((scaled_low_ns * cnt.LowPart) >> scale);\n+}\n+\n+#else\n+# define highres_nanos() 0\n+#endif\n+\n+static inline uint64_t gettimeofday_nanos(void)\n+{\n+\tstruct timeval tv;\n+\tgettimeofday(&tv, NULL);\n+\treturn (uint64_t) tv.tv_sec * 1000000000 + tv.tv_usec * 1000;\n+}\n+\n+/*\n+ * Returns nanoseconds since the epoch (01/01/1970), for performance tracing\n+ * (i.e. favoring high precision over wall clock time accuracy).\n+ */\n+inline uint64_t getnanotime(void)\n+{\n+\tstatic uint64_t offset;\n+\tif (offset > 1) {\n+\t\t/* initialization succeeded, return offset + high res time */\n+\t\treturn offset + highres_nanos();\n+\t} else if (offset == 1) {\n+\t\t/* initialization failed, fall back to gettimeofday */\n+\t\treturn gettimeofday_nanos();\n+\t} else {\n+\t\t/* initialize offset if high resolution timer works */\n+\t\tuint64_t now = gettimeofday_nanos();\n+\t\tuint64_t highres = highres_nanos();\n+\t\tif (highres)\n+\t\t\toffset = now - highres;\n+\t\telse\n+\t\t\toffset = 1;\n+\t\treturn now;\n+\t}\n+}\ndiff --git a/trace.h b/trace.h\nindex 7a5ba2e..4b893a5 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -16,6 +16,7 @@ struct trace_key {\n extern void trace_repo_setup(const char *prefix);\n extern int trace_want(struct trace_key *key);\n extern void trace_disable(struct trace_key *key);\n+extern uint64_t getnanotime(void);\n \n #ifndef HAVE_VARIADIC_MACROS\n \n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245871","messageId":"53C07C04.5020708@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 13/17] trace: add trace_performance facility to debug performance issues","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:06:28Z","receivedAt":"2014-07-12T00:06:28Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Add trace_performance and trace_performance_since macros that print a\nduration and an optional printf-formatted text to the file specified in\nenvironment variable GIT_TRACE_PERFORMANCE.\n\nThese macros, in conjunction with getnanotime(), are intended to simplify\nperformance measurements from within the application (i.e. profiling via\nmanual instrumentation, rather than using an external profiling tool).\n\nUnless enabled via GIT_TRACE_PERFORMANCE, these macros have no noticeable\nimpact on performance, so that test code for well known time killers may\nbe shipped in release builds. Alternatively, a developer could provide an\nadditional performance patch (not meant for master) that allows reviewers\nto reproduce performance tests more easily, e.g. on other platforms or\nusing their own repositories.\n\nUsage examples:\n\nSimple use case (measure one code section):\n\n uint64_t start = getnanotime();\n /* code section to measure */\n trace_performance_since(start, \"foobar\");\n\nComplex use case (measure repetitive code sections):\n\n uint64_t t = 0;\n for (;;) {\n /* ignore */\n t -= getnanotime();\n /* code section to measure */\n t += getnanotime();\n /* ignore */\n }\n trace_performance(t, \"frotz\");\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n trace.c | 47 +++++++++++++++++++++++++++++++++++++++++++++++\n trace.h | 18 ++++++++++++++++++\n 2 files changed, 65 insertions(+)\n\ndiff --git a/trace.c b/trace.c\nindex b9d7272..af64dbb 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -169,6 +169,27 @@ 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+{\n+\tstruct strbuf buf = STRBUF_INIT;\n+\n+\tif (!prepare_trace_line(file, line, &trace_perf_key, &buf))\n+\t\treturn;\n+\n+\tstrbuf_addf(&buf, \"performance: %.9f s\", (double) nanos / 1000000000);\n+\n+\tif (format && *format) {\n+\t\tstrbuf_addstr(&buf, \": \");\n+\t\tstrbuf_vaddf(&buf, format, ap);\n+\t}\n+\n+\tprint_trace_line(&trace_perf_key, &buf);\n+}\n+\n #ifndef HAVE_VARIADIC_MACROS\n \n void trace_printf(const char *format, ...)\n@@ -200,6 +221,23 @@ void trace_strbuf(const char *key, const struct strbuf *data)\n \ttrace_strbuf_fl(NULL, 0, key, data);\n }\n \n+void trace_performance(uint64_t nanos, const char *format, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, format);\n+\ttrace_performance_vprintf_fl(NULL, 0, nanos, format, ap);\n+\tva_end(ap);\n+}\n+\n+void trace_performance_since(uint64_t start, const char *format, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, format);\n+\ttrace_performance_vprintf_fl(NULL, 0, getnanotime() - start,\n+\t\t\t\t format, ap);\n+\tva_end(ap);\n+}\n+\n #else\n \n void trace_printf_key_fl(const char *file, int line, struct trace_key *key,\n@@ -220,6 +258,15 @@ void trace_argv_printf_fl(const char *file, int line, const char **argv,\n \tva_end(ap);\n }\n \n+void trace_performance_fl(const char *file, int line, uint64_t nanos,\n+\t\t\t const char *format, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, format);\n+\ttrace_performance_vprintf_fl(file, line, nanos, format, ap);\n+\tva_end(ap);\n+}\n+\n #endif /* HAVE_VARIADIC_MACROS */\n \n \ndiff --git a/trace.h b/trace.h\nindex 4b893a5..c843e68 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -31,6 +31,14 @@ extern void trace_argv_printf(const char **argv, const char *format, ...);\n \n extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);\n \n+/* Prints elapsed time (in nanoseconds) if GIT_TRACE_PERFORMANCE is enabled. */\n+__attribute__((format (printf, 2, 3)))\n+extern void trace_performance(uint64_t nanos, const char *format, ...);\n+\n+/* Prints elapsed time since 'start' if GIT_TRACE_PERFORMANCE is enabled. */\n+__attribute__((format (printf, 2, 3)))\n+extern void trace_performance_since(uint64_t start, const char *format, ...);\n+\n #else\n \n /*\n@@ -79,6 +87,13 @@ extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);\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+\n /* backend functions, use non-*fl macros instead */\n __attribute__((format (printf, 4, 5)))\n extern void trace_printf_key_fl(const char *file, int line, struct trace_key *key,\n@@ -88,6 +103,9 @@ extern void trace_argv_printf_fl(const char *file, int line, const char **argv,\n \t\t\t\t const char *format, ...);\n extern void trace_strbuf_fl(const char *file, int line, struct trace_key *key,\n \t\t\t const struct strbuf *data);\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 \n #endif /* HAVE_VARIADIC_MACROS */\n \n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245872","messageId":"53C07C25.6070002@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 14/17] git: add performance tracing for git's main() function to debug scripts","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:07:01Z","receivedAt":"2014-07-12T00:07:01Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Use trace_performance to measure and print execution time and command line\narguments of the entire main() function. In constrast to the shell's 'time'\nutility, which measures total time of the parent process, this logs all\ninvolved git commands recursively. This is particularly useful to debug\nperformance issues of scripted commands (i.e. which git commands were\ncalled with which parameters, and how long did they execute).\n\nDue to git's deliberate use of exit(), the implementation uses an atexit\nroutine rather than just adding trace_performance_since() at the end of\nmain().\n\nUsage example: > GIT_TRACE_PERFORMANCE=~/git-trace.log git stash list\n\nCreates a log file like this:\n23:57:38.638765 trace.c:405 performance: 0.000310107 s: git command: 'git' 'rev-parse' '--git-dir'\n23:57:38.644387 trace.c:405 performance: 0.000261759 s: git command: 'git' 'rev-parse' '--show-toplevel'\n23:57:38.646207 trace.c:405 performance: 0.000304468 s: git command: 'git' 'config' '--get-colorbool' 'color.interactive'\n23:57:38.648491 trace.c:405 performance: 0.000241667 s: git command: 'git' 'config' '--get-color' 'color.interactive.help' 'red bold'\n23:57:38.650465 trace.c:405 performance: 0.000243063 s: git command: 'git' 'config' '--get-color' '' 'reset'\n23:57:38.654850 trace.c:405 performance: 0.025126313 s: git command: 'git' 'stash' 'list'\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n Documentation/git.txt | 5 +++++\n git.c | 2 ++\n trace.c | 22 ++++++++++++++++++++++\n trace.h | 1 +\n 4 files changed, 30 insertions(+)\n\ndiff --git a/Documentation/git.txt b/Documentation/git.txt\nindex 9d073f6..fcb8afa 100644\n--- a/Documentation/git.txt\n+++ b/Documentation/git.txt\n@@ -938,6 +938,11 @@ Unsetting the variable, or setting it to empty, \"0\" or\n \tstarting with \"PACK\".\n \tSee 'GIT_TRACE' for available trace output options.\n \n+'GIT_TRACE_PERFORMANCE'::\n+\tEnables performance related trace messages, e.g. total execution\n+\ttime of each Git command.\n+\tSee 'GIT_TRACE' for available trace output options.\n+\n 'GIT_TRACE_SETUP'::\n \tEnables trace messages printing the .git, working tree and current\n \tworking directory after Git has completed its setup phase.\ndiff --git a/git.c b/git.c\nindex 7780572..d4daeb8 100644\n--- a/git.c\n+++ b/git.c\n@@ -568,6 +568,8 @@ int main(int argc, char **av)\n \n \tgit_setup_gettext();\n \n+\ttrace_command_performance(argv);\n+\n \t/*\n \t * \"git-xxxx\" is the same as \"git xxxx\", but we obviously:\n \t *\ndiff --git a/trace.c b/trace.c\nindex af64dbb..e583dc6 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -404,3 +404,25 @@ inline uint64_t getnanotime(void)\n \t\treturn now;\n \t}\n }\n+\n+static uint64_t command_start_time;\n+static struct strbuf command_line = STRBUF_INIT;\n+\n+static void print_command_performance_atexit(void)\n+{\n+\ttrace_performance_since(command_start_time, \"git command:%s\",\n+\t\t\t\tcommand_line.buf);\n+}\n+\n+void trace_command_performance(const char **argv)\n+{\n+\tif (!trace_want(&trace_perf_key))\n+\t\treturn;\n+\n+\tif (!command_start_time)\n+\t\tatexit(print_command_performance_atexit);\n+\n+\tstrbuf_reset(&command_line);\n+\tsq_quote_argv(&command_line, argv, 0);\n+\tcommand_start_time = getnanotime();\n+}\ndiff --git a/trace.h b/trace.h\nindex c843e68..ae6a332 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -17,6 +17,7 @@ extern void trace_repo_setup(const char *prefix);\n extern int trace_want(struct trace_key *key);\n extern void trace_disable(struct trace_key *key);\n extern uint64_t getnanotime(void);\n+extern void trace_command_performance(const char **argv);\n \n #ifndef HAVE_VARIADIC_MACROS\n \n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245873","messageId":"53C07C48.2000004@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 15/17] wt-status: simplify performance measurement by using getnanotime()","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:07:36Z","receivedAt":"2014-07-12T00:07:36Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Calculating duration from a single uint64_t is simpler than from a struct\ntimeval. Change performance measurement for 'advice.statusuoption' from\ngettimeofday() to getnanotime().\n\nAlso initialize t_begin to prevent uninitialized variable warning.\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n wt-status.c | 14 +++-----------\n 1 file changed, 3 insertions(+), 11 deletions(-)\n\ndiff --git a/wt-status.c b/wt-status.c\nindex 318a191..dfdc018 100644\n--- a/wt-status.c\n+++ b/wt-status.c\n@@ -574,14 +574,11 @@ static void wt_status_collect_untracked(struct wt_status *s)\n {\n \tint i;\n \tstruct dir_struct dir;\n-\tstruct timeval t_begin;\n+\tuint64_t t_begin = getnanotime();\n \n \tif (!s->show_untracked_files)\n \t\treturn;\n \n-\tif (advice_status_u_option)\n-\t\tgettimeofday(&t_begin, NULL);\n-\n \tmemset(&dir, 0, sizeof(dir));\n \tif (s->show_untracked_files != SHOW_ALL_UNTRACKED_FILES)\n \t\tdir.flags |=\n@@ -612,13 +609,8 @@ static void wt_status_collect_untracked(struct wt_status *s)\n \tfree(dir.ignored);\n \tclear_directory(&dir);\n \n-\tif (advice_status_u_option) {\n-\t\tstruct timeval t_end;\n-\t\tgettimeofday(&t_end, NULL);\n-\t\ts->untracked_in_ms =\n-\t\t\t(uint64_t)t_end.tv_sec * 1000 + t_end.tv_usec / 1000 -\n-\t\t\t((uint64_t)t_begin.tv_sec * 1000 + t_begin.tv_usec / 1000);\n-\t}\n+\tif (advice_status_u_option)\n+\t\ts->untracked_in_ms = (getnanotime() - t_begin) / 1000000;\n }\n \n void wt_status_collect(struct wt_status *s)\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245874","messageId":"53C07C6B.7030309@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 16/17] progress: simplify performance measurement by using getnanotime()","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:08:11Z","receivedAt":"2014-07-12T00:08:11Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Calculating duration from a single uint64_t is simpler than from a struct\ntimeval. Change throughput measurement from gettimeofday() to\ngetnanotime().\n\nAlso calculate misec only if needed, and change integer division to integer\nmultiplication + shift, which should be slightly faster.\n\nSigned-off-by: Karsten Blees \nSigned-off-by: Junio C Hamano \n---\n progress.c | 71 +++++++++++++++++++++++++++++++-------------------------------\n 1 file changed, 36 insertions(+), 35 deletions(-)\n\ndiff --git a/progress.c b/progress.c\nindex 261314e..412e6b1 100644\n--- a/progress.c\n+++ b/progress.c\n@@ -12,13 +12,14 @@\n #include \"gettext.h\"\n #include \"progress.h\"\n #include \"strbuf.h\"\n+#include \"trace.h\"\n \n #define TP_IDX_MAX 8\n \n struct throughput {\n \toff_t curr_total;\n \toff_t prev_total;\n-\tstruct timeval prev_tv;\n+\tuint64_t prev_ns;\n \tunsigned int avg_bytes;\n \tunsigned int avg_misecs;\n \tunsigned int last_bytes[TP_IDX_MAX];\n@@ -127,65 +128,65 @@ static void throughput_string(struct strbuf *buf, off_t total,\n void display_throughput(struct progress *progress, off_t total)\n {\n \tstruct throughput *tp;\n-\tstruct timeval tv;\n-\tunsigned int misecs;\n+\tuint64_t now_ns;\n+\tunsigned int misecs, count, rate;\n+\tstruct strbuf buf = STRBUF_INIT;\n \n \tif (!progress)\n \t\treturn;\n \ttp = progress->throughput;\n \n-\tgettimeofday(&tv, NULL);\n+\tnow_ns = getnanotime();\n \n \tif (!tp) {\n \t\tprogress->throughput = tp = calloc(1, sizeof(*tp));\n \t\tif (tp) {\n \t\t\ttp->prev_total = tp->curr_total = total;\n-\t\t\ttp->prev_tv = tv;\n+\t\t\ttp->prev_ns = now_ns;\n \t\t}\n \t\treturn;\n \t}\n \ttp->curr_total = total;\n \n+\t/* only update throughput every 0.5 s */\n+\tif (now_ns - tp->prev_ns <= 500000000)\n+\t\treturn;\n+\n \t/*\n-\t * We have x = bytes and y = microsecs. We want z = KiB/s:\n+\t * We have x = bytes and y = nanosecs. We want z = KiB/s:\n \t *\n-\t *\tz = (x / 1024) / (y / 1000000)\n-\t *\tz = x / y * 1000000 / 1024\n-\t *\tz = x / (y * 1024 / 1000000)\n+\t *\tz = (x / 1024) / (y / 1000000000)\n+\t *\tz = x / y * 1000000000 / 1024\n+\t *\tz = x / (y * 1024 / 1000000000)\n \t *\tz = x / y'\n \t *\n \t * To simplify things we'll keep track of misecs, or 1024th of a sec\n \t * obtained with:\n \t *\n-\t *\ty' = y * 1024 / 1000000\n-\t *\ty' = y / (1000000 / 1024)\n-\t *\ty' = y / 977\n+\t *\ty' = y * 1024 / 1000000000\n+\t *\ty' = y * (2^10 / 2^42) * (2^42 / 1000000000)\n+\t *\ty' = y / 2^32 * 4398\n+\t *\ty' = (y * 4398) >> 32\n \t */\n-\tmisecs = (tv.tv_sec - tp->prev_tv.tv_sec) * 1024;\n-\tmisecs += (int)(tv.tv_usec - tp->prev_tv.tv_usec) / 977;\n+\tmisecs = ((now_ns - tp->prev_ns) * 4398) >> 32;\n \n-\tif (misecs > 512) {\n-\t\tstruct strbuf buf = STRBUF_INIT;\n-\t\tunsigned int count, rate;\n+\tcount = total - tp->prev_total;\n+\ttp->prev_total = total;\n+\ttp->prev_ns = now_ns;\n+\ttp->avg_bytes += count;\n+\ttp->avg_misecs += misecs;\n+\trate = tp->avg_bytes / tp->avg_misecs;\n+\ttp->avg_bytes -= tp->last_bytes[tp->idx];\n+\ttp->avg_misecs -= tp->last_misecs[tp->idx];\n+\ttp->last_bytes[tp->idx] = count;\n+\ttp->last_misecs[tp->idx] = misecs;\n+\ttp->idx = (tp->idx + 1) % TP_IDX_MAX;\n \n-\t\tcount = total - tp->prev_total;\n-\t\ttp->prev_total = total;\n-\t\ttp->prev_tv = tv;\n-\t\ttp->avg_bytes += count;\n-\t\ttp->avg_misecs += misecs;\n-\t\trate = tp->avg_bytes / tp->avg_misecs;\n-\t\ttp->avg_bytes -= tp->last_bytes[tp->idx];\n-\t\ttp->avg_misecs -= tp->last_misecs[tp->idx];\n-\t\ttp->last_bytes[tp->idx] = count;\n-\t\ttp->last_misecs[tp->idx] = misecs;\n-\t\ttp->idx = (tp->idx + 1) % TP_IDX_MAX;\n-\n-\t\tthroughput_string(&buf, total, rate);\n-\t\tstrncpy(tp->display, buf.buf, sizeof(tp->display));\n-\t\tstrbuf_release(&buf);\n-\t\tif (progress->last_value != -1 && progress_update)\n-\t\t\tdisplay(progress, progress->last_value, NULL);\n-\t}\n+\tthroughput_string(&buf, total, rate);\n+\tstrncpy(tp->display, buf.buf, sizeof(tp->display));\n+\tstrbuf_release(&buf);\n+\tif (progress->last_value != -1 && progress_update)\n+\t\tdisplay(progress, progress->last_value, NULL);\n }\n \n int display_progress(struct progress *progress, unsigned n)\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"},{"id":"245875","messageId":"53C07C90.8080309@gmail.com","threadId":"37120","inReplyTo":"53C079C5.8090503@gmail.com","subject":"[PATCH v8 17/17] api-trace.txt: add trace API documentation","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-07-12T00:08:48Z","receivedAt":"2014-07-12T00:08:48Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Signed-off-by: Karsten Blees \n---\n Documentation/technical/api-trace.txt | 97 +++++++++++++++++++++++++++++++++++\n 1 file changed, 97 insertions(+)\n create mode 100644 Documentation/technical/api-trace.txt\n\ndiff --git a/Documentation/technical/api-trace.txt b/Documentation/technical/api-trace.txt\nnew file mode 100644\nindex 0000000..097a651\n--- /dev/null\n+++ b/Documentation/technical/api-trace.txt\n@@ -0,0 +1,97 @@\n+trace API\n+=========\n+\n+The trace API can be used to print debug messages to stderr or a file. Trace\n+code is inactive unless explicitly enabled by setting `GIT_TRACE*` environment\n+variables.\n+\n+The trace implementation automatically adds `timestamp file:line ... \\n` to\n+all trace messages. E.g.:\n+\n+------------\n+23:59:59.123456 git.c:312 trace: built-in: git 'foo'\n+00:00:00.000001 builtin/foo.c:99 foo: some message\n+------------\n+\n+Data Structures\n+---------------\n+\n+`struct trace_key`::\n+\n+\tDefines a trace key (or category). The default (for API functions that\n+\tdon't take a key) is `GIT_TRACE`.\n++\n+E.g. to define a trace key controlled by environment variable `GIT_TRACE_FOO`:\n++\n+------------\n+static struct trace_key trace_foo = TRACE_KEY_INIT(FOO);\n+\n+static void trace_print_foo(const char *message)\n+{\n+\ttrace_print_key(&trace_foo, message);\n+}\n+------------\n++\n+Note: don't use `const` as the trace implementation stores internal state in\n+the `trace_key` structure.\n+\n+Functions\n+---------\n+\n+`int trace_want(struct trace_key *key)`::\n+\n+\tChecks whether the trace key is enabled. Used to prevent expensive\n+\tstring formatting before calling one of the printing APIs.\n+\n+`void trace_disable(struct trace_key *key)`::\n+\n+\tDisables tracing for the specified key, even if the environment\n+\tvariable was set.\n+\n+`void trace_printf(const char *format, ...)`::\n+`void trace_printf_key(struct trace_key *key, const char *format, ...)`::\n+\n+\tPrints a formatted message, similar to printf.\n+\n+`void trace_argv_printf(const char **argv, const char *format, ...)``::\n+\n+\tPrints a formatted message, followed by a quoted list of arguments.\n+\n+`void trace_strbuf(struct trace_key *key, const struct strbuf *data)`::\n+\n+\tPrints the strbuf, without additional formatting (i.e. doesn't\n+\tchoke on `%` or even `\\0`).\n+\n+`uint64_t getnanotime(void)`::\n+\n+\tReturns nanoseconds since the epoch (01/01/1970), typically used\n+\tfor performance measurements.\n++\n+Currently there are high precision timer implementations for Linux (using\n+`clock_gettime(CLOCK_MONOTONIC)`) and Windows (`QueryPerformanceCounter`).\n+Other platforms use `gettimeofday` as time source.\n+\n+`void trace_performance(uint64_t nanos, const char *format, ...)`::\n+`void trace_performance_since(uint64_t start, const char *format, ...)`::\n+\n+\tPrints the elapsed time (in nanoseconds), or elapsed time since\n+\t`start`, followed by a formatted message. Enabled via environment\n+\tvariable `GIT_TRACE_PERFORMANCE`. Used for manual profiling, e.g.:\n++\n+------------\n+uint64_t start = getnanotime();\n+/* code section to measure */\n+trace_performance_since(start, \"foobar\");\n+------------\n++\n+------------\n+uint64_t t = 0;\n+for (;;) {\n+\t/* ignore */\n+\tt -= getnanotime();\n+\t/* code section to measure */\n+\tt += getnanotime();\n+\t/* ignore */\n+}\n+trace_performance(t, \"frotz\");\n+------------\n-- \n2.0.0.406.g2e9ef9b\n\n-- \n-- \n*** Please reply-to-all at all times ***\n*** (do not pretend to know who is subscribed and who is not) ***\n*** Please avoid top-posting. ***\nThe msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.\n\nYou received this message because you are subscribed to the Google\nGroups \"msysGit\" group.\nTo post to this group, send email to msysgit@googlegroups.com\nTo unsubscribe from this group, send email to\nmsysgit+unsubscribe@googlegroups.com\nFor more options, and view previous threads, visit this group at\nhttp://groups.google.com/group/msysgit?hl=en_US?hl=en\n\n--- \nYou received this message because you are subscribed to the Google Groups \"msysGit\" group.\nTo unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.\nFor more options, visit https://groups.google.com/d/optout.\n"}]}