{"thread":{"id":"36886","subject":"[PATCH v5 00/11] add performance tracing facility","startedAt":"2014-06-11T07:55:47Z","lastAt":"2014-06-26T01:11:44Z","messageCount":23,"participants":["Karsten Blees","Junio C Hamano","Duy Nguyen"],"isPatch":true,"patchVersion":5,"patchTotal":11},"messages":[{"id":"243869","messageId":"53980B83.9050409@gmail.com","threadId":"36886","inReplyTo":null,"subject":"[PATCH v5 00/11] add performance tracing facility","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T07:55:47Z","receivedAt":"2014-06-11T07:55:47Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Here's v5 of the performance tracing patch series, now including a bunch of cleanups and adding timestamp, file and line to all trace output.\n\nI'm particularly interested in feedback for the output format. As file names have different lengths, printing file:line as prefix results in unaligned output:\n\n > GIT_TRACE=1 git stash list\n 00:12:10.544266 git.c:512 trace: exec: 'git-stash' 'list'\n 00:12:10.544266 run-command.c:337 trace: run_command: 'git-stash' 'list'\n 00:12:10.649779 git.c:312 trace: built-in: git 'rev-parse' '--git-dir'\n\nWe could add separators to make it easier to parse, e.g.:\n\n > GIT_TRACE=1 git stash list\n [00:12:10.544266 git.c:512] trace: exec: 'git-stash' 'list'\n [00:12:10.544266 run-command.c:337] trace: run_command: 'git-stash' 'list'\n [00:12:10.649779 git.c:312] trace: built-in: git 'rev-parse' '--git-dir'\n\nOr print file:line at the end (but what about multi-line messages, such as packet-trace?):\n\n > GIT_TRACE=1 git stash list\n 00:12:10.544266 trace: exec: 'git-stash' 'list' (git.c:512)\n 00:12:10.544266 trace: run_command: 'git-stash' 'list' (run-command.c:337)\n 00:12:10.649779 trace: built-in: git 'rev-parse' '--git-dir' (git.c:312)\n\n\nKarsten Blees (11):\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: factor out printing to the trace file\n trace: add infrastructure to augment trace output with additional info\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\n Makefile | 7 ++\n cache.h | 13 +--\n config.mak.uname | 1 +\n git-compat-util.h | 4 +\n git.c | 2 +\n trace.c | 304 +++++++++++++++++++++++++++++++++++++++++++++++-------\n trace.h | 96 +++++++++++++++++\n 7 files changed, 379 insertions(+), 48 deletions(-)\n create mode 100644 trace.h\n\n-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243870","messageId":"53980BC1.3000109@gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"[PATCH v5 01/11] trace: move trace declarations from cache.h to new trace.h","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T07:56:49Z","receivedAt":"2014-06-11T07:56:49Z","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 \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 1e4b4f0..79ac940 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@@ -1378,17 +1379,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-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243871","messageId":"53980BE3.4090807@gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"[PATCH v5 02/11] trace: consistently name the format parameter","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T07:57:23Z","receivedAt":"2014-06-11T07:57:23Z","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 \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-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243872","messageId":"53980C07.60406@gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"[PATCH v5 03/11] trace: remove redundant printf format attribute","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T07:57:59Z","receivedAt":"2014-06-11T07:57:59Z","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 \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-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243873","messageId":"53980C21.5080203@gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"[PATCH v5 04/11] trace: factor out printing to the trace file","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T07:58:25Z","receivedAt":"2014-06-11T07:58:25Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Opening and writing to the trace file is currently duplicated in\ntrace_strbuf() and trace_argv_printf(). Factor out this logic to prepare\nfor adding timestamp and file:line to trace output.\n\nIn case of trace_argv_printf(), this adds an additional trace_want() check\nto prevent unnecessary string formatting.\n\nSigned-off-by: Karsten Blees \n---\n trace.c | 37 +++++++++++++++++++------------------\n 1 file changed, 19 insertions(+), 18 deletions(-)\n\ndiff --git a/trace.c b/trace.c\nindex 3e31558..b7ca51b 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -62,6 +62,21 @@ 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+/* Print 'buf' verbatim to trace file designated by env var 'key' */\n+static void do_trace_print(const char *key, const struct strbuf *buf)\n+{\n+\tint fd, need_close = 0;\n+\n+\tfd = get_trace_fd(key, &need_close);\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 static void trace_vprintf(const char *key, const char *format, va_list ap)\n {\n \tstruct strbuf buf = STRBUF_INIT;\n@@ -71,7 +86,7 @@ static void trace_vprintf(const char *key, const char *format, va_list ap)\n \n \tset_try_to_free_routine(NULL);\t/* is never reset */\n \tstrbuf_vaddf(&buf, format, ap);\n-\ttrace_strbuf(key, &buf);\n+\tdo_trace_print(key, &buf);\n \tstrbuf_release(&buf);\n }\n \n@@ -93,26 +108,15 @@ void trace_printf(const char *format, ...)\n \n void trace_strbuf(const char *key, const struct strbuf *buf)\n {\n-\tint fd, need_close = 0;\n-\n-\tfd = get_trace_fd(key, &need_close);\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+\tdo_trace_print(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, need_close = 0;\n \n-\tfd = get_trace_fd(\"GIT_TRACE\", &need_close);\n-\tif (!fd)\n+\tif (!trace_want(\"GIT_TRACE\"))\n \t\treturn;\n \n \tset_try_to_free_routine(NULL);\t/* is never reset */\n@@ -122,11 +126,8 @@ void trace_argv_printf(const char **argv, const char *format, ...)\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+\tdo_trace_print(\"GIT_TRACE\", &buf);\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-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243874","messageId":"53980C51.6020304@gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"[PATCH v5 05/11] trace: add infrastructure to augment trace output with additional info","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T07:59:13Z","receivedAt":"2014-06-11T07:59:13Z","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 \n---\n trace.c | 45 ++++++++++++++++++++++++++++++++++-----------\n trace.h | 2 +-\n 2 files changed, 35 insertions(+), 12 deletions(-)\n\ndiff --git a/trace.c b/trace.c\nindex b7ca51b..c920429 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -77,17 +77,37 @@ static void do_trace_print(const char *key, const struct strbuf *buf)\n \t\tclose(fd);\n }\n \n+static int prepare_trace_line(const char *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(const char *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+\tdo_trace_print(key, buf);\n+\tstrbuf_release(buf);\n+}\n+\n static void trace_vprintf(const char *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-\tdo_trace_print(key, &buf);\n-\tstrbuf_release(&buf);\n+\tprint_trace_line(key, &buf);\n }\n \n void trace_printf_key(const char *key, const char *format, ...)\n@@ -106,9 +126,15 @@ void trace_printf(const char *format, ...)\n \tva_end(ap);\n }\n \n-void trace_strbuf(const char *key, const struct strbuf *buf)\n+void trace_strbuf(const char *key, const struct strbuf *data)\n {\n-\tdo_trace_print(key, buf);\n+\tstruct strbuf buf = STRBUF_INIT;\n+\n+\tif (!prepare_trace_line(key, &buf))\n+\t\treturn;\n+\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@@ -116,18 +142,15 @@ void trace_argv_printf(const char **argv, const char *format, ...)\n \tstruct strbuf buf = STRBUF_INIT;\n \tva_list ap;\n \n-\tif (!trace_want(\"GIT_TRACE\"))\n+\tif (!prepare_trace_line(\"GIT_TRACE\", &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-\tdo_trace_print(\"GIT_TRACE\", &buf);\n-\tstrbuf_release(&buf);\n+\tprint_trace_line(\"GIT_TRACE\", &buf);\n }\n \n static const char *quote_crnl(const char *path)\ndiff --git a/trace.h b/trace.h\nindex 8fea50b..e03db2f 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -12,6 +12,6 @@ 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 *format, ...);\n-extern void trace_strbuf(const char *key, const struct strbuf *buf);\n+extern void trace_strbuf(const char *key, const struct strbuf *data);\n \n #endif /* TRACE_H */\n-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243875","messageId":"53980C6E.9000409@gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"[PATCH v5 06/11] trace: add current timestamp to all trace output","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T07:59:42Z","receivedAt":"2014-06-11T07:59:42Z","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 \n---\n trace.c | 11 ++++++++++-\n 1 file changed, 10 insertions(+), 1 deletion(-)\n\ndiff --git a/trace.c b/trace.c\nindex c920429..5a3393a 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -79,12 +79,21 @@ static void do_trace_print(const char *key, const struct strbuf *buf)\n \n static int prepare_trace_line(const char *key, struct strbuf *buf)\n {\n+\tstruct timeval tv;\n+\tstruct tm tm;\n+\ttime_t secs;\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+\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, tv.tv_usec);\n \n \treturn 1;\n }\n-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243876","messageId":"53980C8B.2010207@gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"[PATCH v5 07/11] trace: move code around, in preparation to file:line output","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T08:00:11Z","receivedAt":"2014-06-11T08:00:11Z","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 \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 5a3393a..c86d33c 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -119,20 +119,20 @@ static void trace_vprintf(const char *key, const char *format, va_list ap)\n \tprint_trace_line(key, &buf);\n }\n \n-void trace_printf_key(const char *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(\"GIT_TRACE\", &buf))\n+\t\treturn;\n+\n \tva_start(ap, format);\n-\ttrace_vprintf(\"GIT_TRACE\", format, ap);\n+\tstrbuf_vaddf(&buf, format, ap);\n \tva_end(ap);\n+\n+\tsq_quote_argv(&buf, argv, 0);\n+\tprint_trace_line(\"GIT_TRACE\", &buf);\n }\n \n void trace_strbuf(const char *key, const struct strbuf *data)\n@@ -146,20 +146,20 @@ void trace_strbuf(const char *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(\"GIT_TRACE\", &buf))\n-\t\treturn;\n-\n \tva_start(ap, format);\n-\tstrbuf_vaddf(&buf, format, ap);\n+\ttrace_vprintf(\"GIT_TRACE\", format, ap);\n \tva_end(ap);\n+}\n \n-\tsq_quote_argv(&buf, argv, 0);\n-\tprint_trace_line(\"GIT_TRACE\", &buf);\n+void trace_printf_key(const char *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 e03db2f..5c7f2dc 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -4,14 +4,18 @@\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+\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(const char *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(const char *key, const struct strbuf *data);\n \n #endif /* TRACE_H */\n-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243877","messageId":"53980CA4.9050101@gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"[PATCH v5 08/11] trace: add 'file:line' to all trace output","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T08:00:36Z","receivedAt":"2014-06-11T08:00:36Z","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\nSigned-off-by: Karsten Blees \n---\n git-compat-util.h | 4 ++++\n trace.c | 69 +++++++++++++++++++++++++++++++++++++++++++++----------\n trace.h | 49 +++++++++++++++++++++++++++++++++++++++\n 3 files changed, 110 insertions(+), 12 deletions(-)\n\ndiff --git a/git-compat-util.h b/git-compat-util.h\nindex 7849d31..e5a773b 100644\n--- a/git-compat-util.h\n+++ b/git-compat-util.h\n@@ -700,6 +700,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 c86d33c..231e24a 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -77,7 +77,8 @@ static void do_trace_print(const char *key, const struct strbuf *buf)\n \t\tclose(fd);\n }\n \n-static int prepare_trace_line(const char *key, struct strbuf *buf)\n+static int prepare_trace_line(const char *file, int line, const char *key,\n+\t\t\t struct strbuf *buf)\n {\n \tstruct timeval tv;\n \tstruct tm tm;\n@@ -95,6 +96,11 @@ static int prepare_trace_line(const char *key, struct strbuf *buf)\n \tstrbuf_addf(buf, \"%02d:%02d:%02d.%06ld \", tm.tm_hour, tm.tm_min,\n \t\t tm.tm_sec, tv.tv_usec);\n \n+#ifdef HAVE_VARIADIC_MACROS\n+\t/* print file:line */\n+\tstrbuf_addf(buf, \"%s:%d \", file, line);\n+#endif\n+\n \treturn 1;\n }\n \n@@ -108,49 +114,52 @@ static void print_trace_line(const char *key, struct strbuf *buf)\n \tstrbuf_release(buf);\n }\n \n-static void trace_vprintf(const char *key, const char *format, va_list ap)\n+static void trace_vprintf_fl(const char *file, int line, const char *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(\"GIT_TRACE\", &buf))\n+\tif (!prepare_trace_line(file, line, \"GIT_TRACE\", &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(\"GIT_TRACE\", &buf);\n }\n \n-void trace_strbuf(const char *key, const struct strbuf *data)\n+void trace_strbuf_fl(const char *file, int line, const char *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(\"GIT_TRACE\", format, ap);\n+\ttrace_vprintf_fl(NULL, 0, \"GIT_TRACE\", format, ap);\n \tva_end(ap);\n }\n \n@@ -158,10 +167,46 @@ void trace_printf_key(const char *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, const char *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 5c7f2dc..916dc2b 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -7,6 +7,8 @@\n extern void trace_repo_setup(const char *prefix);\n extern int trace_want(const char *key);\n \n+#ifndef HAVE_VARIADIC_MACROS\n+\n __attribute__((format (printf, 1, 2)))\n extern void trace_printf(const char *format, ...);\n \n@@ -18,4 +20,51 @@ extern void trace_argv_printf(const char **argv, const char *format, ...);\n \n extern void trace_strbuf(const char *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+ * 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(__FILE__, __LINE__, \"GIT_TRACE\", __VA_ARGS__)\n+\n+#define trace_printf_key(key, ...) \\\n+\ttrace_printf_key_fl(__FILE__, __LINE__, key, __VA_ARGS__)\n+\n+#define trace_argv_printf(argv, ...) \\\n+\ttrace_argv_printf_fl(__FILE__, __LINE__, argv, __VA_ARGS__)\n+\n+#define trace_strbuf(key, data) \\\n+\ttrace_strbuf_fl(__FILE__, __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, const char *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, const char *key,\n+\t\t\t const struct strbuf *data);\n+\n+#endif /* HAVE_VARIADIC_MACROS */\n+\n #endif /* TRACE_H */\n-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243878","messageId":"53980CBF.2060400@gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"[PATCH v5 09/11] trace: add high resolution timer function to debug performance issues","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T08:01:03Z","receivedAt":"2014-06-11T08:01:03Z","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 (div 10e9) 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 \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 231e24a..4bd52f2 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -264,3 +264,85 @@ int trace_want(const char *key)\n \t\treturn 0;\n \treturn 1;\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 916dc2b..c4964aa 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -6,6 +6,7 @@\n \n extern void trace_repo_setup(const char *prefix);\n extern int trace_want(const char *key);\n+extern uint64_t getnanotime(void);\n \n #ifndef HAVE_VARIADIC_MACROS\n \n-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243879","messageId":"53980CD8.5090801@gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"[PATCH v5 10/11] trace: add trace_performance facility to debug performance issues","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T08:01:28Z","receivedAt":"2014-06-11T08:01: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\nMedium use case (measure consecutive code sections):\n\n uint64_t start = getnanotime();\n /* first code section to measure */\n start = trace_performance_since(start, \"first foobar\");\n /* second code section to measure */\n trace_performance_since(start, \"second 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 \n---\n trace.c | 49 +++++++++++++++++++++++++++++++++++++++++++++++++\n trace.h | 24 ++++++++++++++++++++++++\n 2 files changed, 73 insertions(+)\n\ndiff --git a/trace.c b/trace.c\nindex 4bd52f2..0551509 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -153,6 +153,27 @@ void trace_strbuf_fl(const char *file, int line, const char *key,\n \tprint_trace_line(key, &buf);\n }\n \n+static const char *GIT_TRACE_PERFORMANCE = \"GIT_TRACE_PERFORMANCE\";\n+\n+static void trace_performance_vfl(const char *file, int line,\n+\t\t\t\t uint64_t nanos, const char *format,\n+\t\t\t\t va_list ap)\n+{\n+\tstruct strbuf buf = STRBUF_INIT;\n+\n+\tif (!prepare_trace_line(file, line, GIT_TRACE_PERFORMANCE, &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(GIT_TRACE_PERFORMANCE, &buf);\n+}\n+\n #ifndef HAVE_VARIADIC_MACROS\n \n void trace_printf(const char *format, ...)\n@@ -184,6 +205,24 @@ void trace_strbuf(const char *key, const struct strbuf *data)\n \ttrace_strbuf_fl(NULL, 0, key, data);\n }\n \n+uint64_t trace_performance(uint64_t nanos, const char *format, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, format);\n+\ttrace_performance_vfl(NULL, 0, nanos, format, ap);\n+\tva_end(ap);\n+\treturn getnanotime();\n+}\n+\n+uint64_t trace_performance_since(uint64_t start, const char *format, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, format);\n+\ttrace_performance_vfl(NULL, 0, getnanotime() - start, format, ap);\n+\tva_end(ap);\n+\treturn getnanotime();\n+}\n+\n #else\n \n void trace_printf_key_fl(const char *file, int line, const char *key,\n@@ -204,6 +243,16 @@ void trace_argv_printf_fl(const char *file, int line, const char **argv,\n \tva_end(ap);\n }\n \n+uint64_t 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_vfl(file, line, nanos, format, ap);\n+\tva_end(ap);\n+\treturn getnanotime();\n+}\n+\n #endif /* HAVE_VARIADIC_MACROS */\n \n \ndiff --git a/trace.h b/trace.h\nindex c4964aa..9687563 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -21,6 +21,20 @@ extern void trace_argv_printf(const char **argv, const char *format, ...);\n \n extern void trace_strbuf(const char *key, const struct strbuf *data);\n \n+/*\n+ * Prints specified time (in nanoseconds) if GIT_TRACE_PERFORMANCE is enabled.\n+ * Returns current time in nanoseconds.\n+ */\n+__attribute__((format (printf, 2, 3)))\n+extern uint64_t trace_performance(uint64_t nanos, const char *format, ...);\n+\n+/*\n+ * Prints time since 'start' if GIT_TRACE_PERFORMANCE is enabled.\n+ * Returns current time in nanoseconds.\n+ */\n+__attribute__((format (printf, 2, 3)))\n+extern uint64_t trace_performance_since(uint64_t start, const char *format, ...);\n+\n #else\n \n /*\n@@ -56,6 +70,13 @@ extern void trace_strbuf(const char *key, const struct strbuf *data);\n #define trace_strbuf(key, data) \\\n \ttrace_strbuf_fl(__FILE__, __LINE__, key, data)\n \n+#define trace_performance(nanos, ...) \\\n+\ttrace_performance_fl(__FILE__, __LINE__, nanos, __VA_ARGS__)\n+\n+#define trace_performance_since(start, ...) \\\n+\ttrace_performance_fl(__FILE__, __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, const char *key,\n@@ -65,6 +86,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, const char *key,\n \t\t\t const struct strbuf *data);\n+__attribute__((format (printf, 4, 5)))\n+extern uint64_t 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-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243880","messageId":"53980CF9.9080906@gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"[PATCH v5 11/11] git: add performance tracing for git's main() function to debug scripts","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T08:02:01Z","receivedAt":"2014-06-11T08:02: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 \n---\n git.c | 2 ++\n trace.c | 22 ++++++++++++++++++++++\n trace.h | 1 +\n 3 files changed, 25 insertions(+)\n\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 0551509..9fc3921 100644\n--- a/trace.c\n+++ b/trace.c\n@@ -395,3 +395,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(GIT_TRACE_PERFORMANCE))\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 9687563..a51e731 100644\n--- a/trace.h\n+++ b/trace.h\n@@ -7,6 +7,7 @@\n extern void trace_repo_setup(const char *prefix);\n extern int trace_want(const char *key);\n extern uint64_t getnanotime(void);\n+extern void trace_command_performance(const char **argv);\n \n #ifndef HAVE_VARIADIC_MACROS\n \n-- \n1.9.2.msysgit.0.501.gaeecf09\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":"243883","messageId":"53980F68.7050009@gmail.com","threadId":"36886","inReplyTo":"53980CBF.2060400@gmail.com","subject":"Re: [PATCH v5 09/11] trace: add high resolution timer function to debug performance issues","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-11T08:12:24Z","receivedAt":"2014-06-11T08:12:24Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Am 11.06.2014 10:01, schrieb Karsten Blees:\n> the epoch allows using the results (div 10e9) with other time-related APIs.\n\ns/10e9/1e9/\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":"244012","messageId":"xmqqvbs656bu.fsf@gitster.dls.corp.google.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"Re: [PATCH v5 00/11] add performance tracing facility","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2014-06-12T18:30:13Z","receivedAt":"2014-06-12T18:30:13Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Karsten Blees writes:\n\n> Here's v5 of the performance tracing patch series, now including a bunch of cleanups and adding timestamp, file and line to all trace output.\n>\n> I'm particularly interested in feedback for the output format. As file names have different lengths, printing file:line as prefix results in unaligned output:\n>\n> > GIT_TRACE=1 git stash list\n> 00:12:10.544266 git.c:512 trace: exec: 'git-stash' 'list'\n> 00:12:10.544266 run-command.c:337 trace: run_command: 'git-stash' 'list'\n> 00:12:10.649779 git.c:312 trace: built-in: git 'rev-parse' '--git-dir'\n>\n> We could add separators to make it easier to parse, e.g.:\n>\n> > GIT_TRACE=1 git stash list\n> [00:12:10.544266 git.c:512] trace: exec: 'git-stash' 'list'\n> [00:12:10.544266 run-command.c:337] trace: run_command: 'git-stash' 'list'\n> [00:12:10.649779 git.c:312] trace: built-in: git 'rev-parse' '--git-dir'\n\nThis is easier to parse if \" \" and \":\" are found in the names of\n_our_ source files and \"]\" isn't, but is that really the case?\n\n> Or print file:line at the end (but what about multi-line messages, such as packet-trace?):\n>\n> > GIT_TRACE=1 git stash list\n> 00:12:10.544266 trace: exec: 'git-stash' 'list' (git.c:512)\n\nSomehow I find this a lot harder to read than the other two.\n\nI am not commenting on the usefulness of the patch series (yet),\nthough.\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":"244453","messageId":"xmqq4mzjo58t.fsf@gitster.dls.corp.google.com","threadId":"36886","inReplyTo":"53980F68.7050009@gmail.com","subject":"Re: [PATCH v5 09/11] trace: add high resolution timer function to debug performance issues","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2014-06-17T16:44:34Z","receivedAt":"2014-06-17T16:44:34Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Karsten Blees writes:\n\n> Am 11.06.2014 10:01, schrieb Karsten Blees:\n>> the epoch allows using the results (div 10e9) with other time-related APIs.\n>\n> s/10e9/1e9/\n\nThat replacement is fine but the \"(div 1e9)\" still wants to be\nclarified. What did you exactly mean by that? If the result is\ndivided by 10^9 then it yields the number of seconds?\n\nThanks.\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":"244455","messageId":"xmqqsin3mpfe.fsf@gitster.dls.corp.google.com","threadId":"36886","inReplyTo":"53980CD8.5090801@gmail.com","subject":"Re: [PATCH v5 10/11] trace: add trace_performance facility to debug performance issues","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2014-06-17T17:11:33Z","receivedAt":"2014-06-17T17:11:33Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Karsten Blees writes:\n\n> Simple use case (measure one code section):\n>\n> uint64_t start = getnanotime();\n> /* code section to measure */\n> trace_performance_since(start, \"foobar\");\n>\n> Medium use case (measure consecutive code sections):\n>\n> uint64_t start = getnanotime();\n> /* first code section to measure */\n> start = trace_performance_since(start, \"first foobar\");\n> /* second code section to measure */\n> trace_performance_since(start, \"second foobar\");\n>\n> Complex 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\nHmph. Even though trace_performance() makes an extra call to\ngetnanotime() in order to return, examples do not use the returned\nvalue? The second example is a good illustration why it makes sense\nfor trace_performance_since(), though.\n\n> +static void trace_performance_vfl(const char *file, int line,\n> +\t\t\t\t uint64_t nanos, const char *format,\n> +\t\t\t\t va_list ap)\n> +{\n\nJust being curious, but what does \"v\" stand for?\n\nThe \"_fl\" suffix you gave to printf family made a lot of sense to\nme, and I would have expected that this to be called with a \"_flt\"\nsuffix, meaning \"we have file, line and then time as extra\nparameters\" or something.\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":"244516","messageId":"53A1ACD7.1040504@gmail.com","threadId":"36886","inReplyTo":"xmqq4mzjo58t.fsf@gitster.dls.corp.google.com","subject":"Re: [PATCH v5 09/11] trace: add high resolution timer function to debug performance issues","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-18T15:14:31Z","receivedAt":"2014-06-18T15:14:31Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Am 17.06.2014 18:44, schrieb Junio C Hamano:\n> Karsten Blees writes:\n> \n>> Am 11.06.2014 10:01, schrieb Karsten Blees:\n>>> the epoch allows using the results (div 10e9) with other time-related APIs.\n>>\n>> s/10e9/1e9/\n> \n> That replacement is fine but the \"(div 1e9)\" still wants to be\n> clarified. What did you exactly mean by that? If the result is\n> divided by 10^9 then it yields the number of seconds?\n> \n> Thanks.\n> \n\nDiv 10^9 yields a time_t. But as not all time-related APIs use time_t, perhaps its best to drop the \"(div 1e9)\" altogether. That the function returns nanoseconds should be clear enough. Will drop in the next round.\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":"244517","messageId":"53A1ACE2.30406@gmail.com","threadId":"36886","inReplyTo":"xmqqsin3mpfe.fsf@gitster.dls.corp.google.com","subject":"Re: [PATCH v5 10/11] trace: add trace_performance facility to debug performance issues","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-18T15:14:42Z","receivedAt":"2014-06-18T15:14:42Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Am 17.06.2014 19:11, schrieb Junio C Hamano:\n> Karsten Blees writes:\n> \n>> Simple use case (measure one code section):\n>>\n>> uint64_t start = getnanotime();\n>> /* code section to measure */\n>> trace_performance_since(start, \"foobar\");\n>>\n>> Medium use case (measure consecutive code sections):\n>>\n>> uint64_t start = getnanotime();\n>> /* first code section to measure */\n>> start = trace_performance_since(start, \"first foobar\");\n>> /* second code section to measure */\n>> trace_performance_since(start, \"second foobar\");\n>>\n>> Complex 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> \n> Hmph. Even though trace_performance() makes an extra call to\n> getnanotime() in order to return, examples do not use the returned\n> value? The second example is a good illustration why it makes sense\n> for trace_performance_since(), though.\n> \n\nRight, it makes no sense for trace_performance(), and for\ntrace_performance_since() only if followed by another 'measured' code\nsection. In that special case, I think it wouldn't hurt if you had to\nwrite:\n\n uint64_t start = getnanotime();\n /* first code section to measure */\n trace_performance_since(start, \"first foobar\");\n\n start = getnanotime();\n /* second code section to measure */\n trace_performance_since(start, \"second foobar\");\n\nSo I guess I'll drop the return value (and the second example, which\nis then redundant to the first).\n\n>> +static void trace_performance_vfl(const char *file, int line,\n>> +\t\t\t\t uint64_t nanos, const char *format,\n>> +\t\t\t\t va_list ap)\n>> +{\n> \n> Just being curious, but what does \"v\" stand for?\n> \n\ntrace_performance_vfl(, va_list)\nvs.\ntrace_performance_fl(, ...)\n\nWill change to trace_performance_vprintf_fl()\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":"244518","messageId":"53A1ACE7.2070601@gmail.com","threadId":"36886","inReplyTo":"xmqqvbs656bu.fsf@gitster.dls.corp.google.com","subject":"Re: [PATCH v5 00/11] add performance tracing facility","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-18T15:14:47Z","receivedAt":"2014-06-18T15:14:47Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Am 12.06.2014 20:30, schrieb Junio C Hamano:\n> Karsten Blees writes:\n> \n>> Here's v5 of the performance tracing patch series, now including a bunch of cleanups and adding timestamp, file and line to all trace output.\n>>\n>> I'm particularly interested in feedback for the output format. As file names have different lengths, printing file:line as prefix results in unaligned output:\n>>\n>> > GIT_TRACE=1 git stash list\n>> 00:12:10.544266 git.c:512 trace: exec: 'git-stash' 'list'\n>> 00:12:10.544266 run-command.c:337 trace: run_command: 'git-stash' 'list'\n>> 00:12:10.649779 git.c:312 trace: built-in: git 'rev-parse' '--git-dir'\n>>\n>> We could add separators to make it easier to parse, e.g.:\n>>\n>> > GIT_TRACE=1 git stash list\n>> [00:12:10.544266 git.c:512] trace: exec: 'git-stash' 'list'\n>> [00:12:10.544266 run-command.c:337] trace: run_command: 'git-stash' 'list'\n>> [00:12:10.649779 git.c:312] trace: built-in: git 'rev-parse' '--git-dir'\n> \n> This is easier to parse if \" \" and \":\" are found in the names of\n> _our_ source files and \"]\" isn't, but is that really the case?\n> \n\nBy \"parsing\" I actually meant the HumanEye (tm) parser, not lex/yacc and\nfriends (\"[]\" just make nice recognizable separators).\n\nHowever, I think it shouldn't be too complicated to properly align the output,\nat least for the majority of 'short' file names in the git code base. E.g.:\n\n00:12:10.544266 git.c:512 trace: exec: 'git-stash' 'list'\n00:12:10.544266 run-command.c:337 trace: run_command: 'git-stash' 'list'\n00:12:10.649779 git.c:312 trace: built-in: git 'rev-parse' '--git-dir'\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":"244544","messageId":"xmqqbntqjffa.fsf@gitster.dls.corp.google.com","threadId":"36886","inReplyTo":"53A1ACE2.30406@gmail.com","subject":"Re: [PATCH v5 10/11] trace: add trace_performance facility to debug performance issues","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2014-06-18T17:28:09Z","receivedAt":"2014-06-18T17:28:09Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Karsten Blees writes:\n\n> Right, it makes no sense for trace_performance(), and for\n> trace_performance_since() only if followed by another 'measured' code\n> section. In that special case, I think it wouldn't hurt if you had to\n> write:\n>\n> uint64_t start = getnanotime();\n> /* first code section to measure */\n> trace_performance_since(start, \"first foobar\");\n>\n> start = getnanotime();\n> /* second code section to measure */\n> trace_performance_since(start, \"second foobar\");\n>\n> So I guess I'll drop the return value (and the second example, which\n> is then redundant to the first).\n\nThat also sounds OK to me.\n\n>>> +static void trace_performance_vfl(const char *file, int line,\n>>> +\t\t\t\t uint64_t nanos, const char *format,\n>>> +\t\t\t\t va_list ap)\n>>> +{\n>> \n>> Just being curious, but what does \"v\" stand for?\n>> \n>\n> trace_performance_vfl(, va_list)\n> vs.\n> trace_performance_fl(, ...)\n>\n> Will change to trace_performance_vprintf_fl()\n\nAh, OK. The name with 'vprintf' in it does sound better.\n\nThanks.\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":"244968","messageId":"CACsJy8AV5GhB+7iHL11vAMvp=X2yeHgO-ejrtMQqGNG3z_ekBw@mail.gmail.com","threadId":"36886","inReplyTo":"53980B83.9050409@gmail.com","subject":"Re: [PATCH v5 00/11] add performance tracing facility","fromName":"Duy Nguyen","fromEmail":"pclouds@gmail.com","sentAt":"2014-06-25T14:28:46Z","receivedAt":"2014-06-25T14:28:46Z","isPatch":true,"sender":{"key":"pclouds@gmail.com","avatar":"https://avatars.githubusercontent.com/u/720?v=4"},"body":"On Wed, Jun 11, 2014 at 2:55 PM, Karsten Blees wrote:\n> Here's v5 of the performance tracing patch series, now including a bunch of cleanups and adding timestamp, file and line to all trace output.\n>\n> I'm particularly interested in feedback for the output format. As file names have different lengths, printing file:line as prefix results in unaligned output:\n>\n> > GIT_TRACE=1 git stash list\n> 00:12:10.544266 git.c:512 trace: exec: 'git-stash' 'list'\n> 00:12:10.544266 run-command.c:337 trace: run_command: 'git-stash' 'list'\n> 00:12:10.649779 git.c:312 trace: built-in: git 'rev-parse' '--git-dir'\n\nCan I have an (build-time) option to show : instead of\n:? I know it's not supported by all compilers, which may\nmake support a bit cumbersome..\n-- \nDuy\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":"244969","messageId":"53AAE17A.7050500@gmail.com","threadId":"36886","inReplyTo":"CACsJy8AV5GhB+7iHL11vAMvp=X2yeHgO-ejrtMQqGNG3z_ekBw@mail.gmail.com","subject":"Re: [PATCH v5 00/11] add performance tracing facility","fromName":"Karsten Blees","fromEmail":"karsten.blees@gmail.com","sentAt":"2014-06-25T14:49:30Z","receivedAt":"2014-06-25T14:49:30Z","isPatch":true,"sender":{"key":"karsten.blees@gmail.com","avatar":"https://avatars.githubusercontent.com/u/1111200?v=4"},"body":"Am 25.06.2014 16:28, schrieb Duy Nguyen:\n> On Wed, Jun 11, 2014 at 2:55 PM, Karsten Blees wrote:\n>> Here's v5 of the performance tracing patch series, now including a bunch of cleanups and adding timestamp, file and line to all trace output.\n>>\n>> I'm particularly interested in feedback for the output format. As file names have different lengths, printing file:line as prefix results in unaligned output:\n>>\n>> > GIT_TRACE=1 git stash list\n>> 00:12:10.544266 git.c:512 trace: exec: 'git-stash' 'list'\n>> 00:12:10.544266 run-command.c:337 trace: run_command: 'git-stash' 'list'\n>> 00:12:10.649779 git.c:312 trace: built-in: git 'rev-parse' '--git-dir'\n> \n> Can I have an (build-time) option to show : instead of\n> :? I know it's not supported by all compilers, which may\n> make support a bit cumbersome..\n> \n\nIs this really useful? : is unique, but : is not. E.g. in case of \"hash_name:47\" you'd have to guess if its the one in attr.c or name-hash.c...\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":"245004","messageId":"CACsJy8AoDJLMbhG82AMnt61hK_DoXQ16SY_M2J_XnUuTamv0qQ@mail.gmail.com","threadId":"36886","inReplyTo":"53AAE17A.7050500@gmail.com","subject":"Re: [PATCH v5 00/11] add performance tracing facility","fromName":"Duy Nguyen","fromEmail":"pclouds@gmail.com","sentAt":"2014-06-26T01:11:44Z","receivedAt":"2014-06-26T01:11:44Z","isPatch":true,"sender":{"key":"pclouds@gmail.com","avatar":"https://avatars.githubusercontent.com/u/720?v=4"},"body":"On Wed, Jun 25, 2014 at 9:49 PM, Karsten Blees wrote:\n> Am 25.06.2014 16:28, schrieb Duy Nguyen:\n>> On Wed, Jun 11, 2014 at 2:55 PM, Karsten Blees wrote:\n>>> Here's v5 of the performance tracing patch series, now including a bunch of cleanups and adding timestamp, file and line to all trace output.\n>>>\n>>> I'm particularly interested in feedback for the output format. As file names have different lengths, printing file:line as prefix results in unaligned output:\n>>>\n>>> > GIT_TRACE=1 git stash list\n>>> 00:12:10.544266 git.c:512 trace: exec: 'git-stash' 'list'\n>>> 00:12:10.544266 run-command.c:337 trace: run_command: 'git-stash' 'list'\n>>> 00:12:10.649779 git.c:312 trace: built-in: git 'rev-parse' '--git-dir'\n>>\n>> Can I have an (build-time) option to show : instead of\n>> :? I know it's not supported by all compilers, which may\n>> make support a bit cumbersome..\n>>\n>\n> Is this really useful? : is unique, but : is not. E.g. in case of \"hash_name:47\" you'd have to guess if its the one in attr.c or name-hash.c...\n\nIt depends on your view. If I'm tracing a certain operation, function\nnames let me know roughly what's going on without looking at the code\nbecause all (or many of) the names and their purposes are already in\nmy mind. But for publishing the traces, then I agree : is\nbetter.\n-- \nDuy\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"}]}