git/list[1] front-page[2] threads[3] people[4] search[5] about
 

[PATCH v8 14/17] git: add performance tracing for git's main() function to debug scripts

From
Karsten Blees <karsten.blees@gmail.com>
Date
Jul 12, 2014, 00:07 UTC
Message-ID
<53C07C25.6070002@gmail.com>
In-Reply-To
<53C079C5.8090503@gmail.com>

Use trace_performance to measure and print execution time and command line arguments of the entire main() function. In constrast to the shell's 'time' utility, which measures total time of the parent process, this logs all involved git commands recursively. This is particularly useful to debug performance issues of scripted commands (i.e. which git commands were called with which parameters, and how long did they execute).

Due to git's deliberate use of exit(), the implementation uses an atexit routine rather than just adding trace_performance_since() at the end of main().

Usage example: > GIT_TRACE_PERFORMANCE=~/git-trace.log git stash list

Creates a log file like this: 23:57:38.638765 trace.c:405 performance: 0.000310107 s: git command: 'git' 'rev-parse' '--git-dir' 23:57:38.644387 trace.c:405 performance: 0.000261759 s: git command: 'git' 'rev-parse' '--show-toplevel' 23:57:38.646207 trace.c:405 performance: 0.000304468 s: git command: 'git' 'config' '--get-colorbool' 'color.interactive' 23:57:38.648491 trace.c:405 performance: 0.000241667 s: git command: 'git' 'config' '--get-color' 'color.interactive.help' 'red bold' 23:57:38.650465 trace.c:405 performance: 0.000243063 s: git command: 'git' 'config' '--get-color' '' 'reset' 23:57:38.654850 trace.c:405 performance: 0.025126313 s: git command: 'git' 'stash' 'list'

Signed-off-by: Karsten Blees <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 Documentation/git.txt |  5 +++++
 git.c                 |  2 ++
 trace.c               | 22 ++++++++++++++++++++++
 trace.h               |  1 +
 4 files changed, 30 insertions(+)
diff --git a/Documentation/git.txt b/Documentation/git.txt
index 9d073f6..fcb8afa 100644
--- a/Documentation/git.txt
+++ b/Documentation/git.txt
@@ -938,6 +938,11 @@ Unsetting the variable, or setting it to empty, "0" or
 	starting with "PACK".
 	See 'GIT_TRACE' for available trace output options.
 
+'GIT_TRACE_PERFORMANCE'::
+	Enables performance related trace messages, e.g. total execution
+	time of each Git command.
+	See 'GIT_TRACE' for available trace output options.
+
 'GIT_TRACE_SETUP'::
 	Enables trace messages printing the .git, working tree and current
 	working directory after Git has completed its setup phase.
diff --git a/git.c b/git.c
index 7780572..d4daeb8 100644
--- a/git.c
+++ b/git.c
@@ -568,6 +568,8 @@ int main(int argc, char **av)
 
 	git_setup_gettext();
 
+	trace_command_performance(argv);
+
 	/*
 	 * "git-xxxx" is the same as "git xxxx", but we obviously:
 	 *
diff --git a/trace.c b/trace.c
index af64dbb..e583dc6 100644
--- a/trace.c
+++ b/trace.c
@@ -404,3 +404,25 @@ inline uint64_t getnanotime(void)
 		return now;
 	}
 }
+
+static uint64_t command_start_time;
+static struct strbuf command_line = STRBUF_INIT;
+
+static void print_command_performance_atexit(void)
+{
+	trace_performance_since(command_start_time, "git command:%s",
+				command_line.buf);
+}
+
+void trace_command_performance(const char **argv)
+{
+	if (!trace_want(&trace_perf_key))
+		return;
+
+	if (!command_start_time)
+		atexit(print_command_performance_atexit);
+
+	strbuf_reset(&command_line);
+	sq_quote_argv(&command_line, argv, 0);
+	command_start_time = getnanotime();
+}
diff --git a/trace.h b/trace.h
index c843e68..ae6a332 100644
--- a/trace.h
+++ b/trace.h
@@ -17,6 +17,7 @@ extern void trace_repo_setup(const char *prefix);
 extern int trace_want(struct trace_key *key);
 extern void trace_disable(struct trace_key *key);
 extern uint64_t getnanotime(void);
+extern void trace_command_performance(const char **argv);
 
 #ifndef HAVE_VARIADIC_MACROS
 

-- 
2.0.0.406.g2e9ef9b

-- 
-- 
*** Please reply-to-all at all times ***
*** (do not pretend to know who is subscribed and who is not) ***
*** Please avoid top-posting. ***
The msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.

You received this message because you are subscribed to the Google
Groups "msysGit" group.
To post to this group, send email to msysgit@googlegroups.com
To unsubscribe from this group, send email to
msysgit+unsubscribe@googlegroups.com
For more options, and view previous threads, visit this group at
http://groups.google.com/group/msysgit?hl=en_US?hl=en

--- 
You received this message because you are subscribed to the Google Groups "msysGit" group.
To unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Previous: Karsten BleesNext: Karsten Blees
Message 15 of 18 in “add performance tracing facility”
  1. 00/17 add performance tracing facilityKarsten Blees, Jul 11, 2014
  2. 01/17 trace: move trace declarations from cache.h to new trace.hKarsten Blees, Jul 11, 2014
  3. 02/17 trace: consistently name the format parameterKarsten Blees, Jul 11, 2014
  4. 03/17 trace: remove redundant printf format attributeKarsten Blees, Jul 11, 2014
  5. 04/17 trace: improve trace performanceKarsten Blees, Jul 12, 2014
  6. 05/17 Documentation/git.txt: improve documentation of 'GIT_TRACE*' variablesKarsten Blees, Jul 12, 2014
  7. 06/17 sha1_file: change GIT_TRACE_PACK_ACCESS logging to use trace APIKarsten Blees, Jul 12, 2014
  8. 07/17 trace: add infrastructure to augment trace output with additional infoKarsten Blees, Jul 12, 2014
  9. 08/17 trace: disable additional trace output for unit testsKarsten Blees, Jul 12, 2014
  10. 09/17 trace: add current timestamp to all trace outputKarsten Blees, Jul 12, 2014
  11. 10/17 trace: move code around, in preparation to file:line outputKarsten Blees, Jul 12, 2014
  12. 11/17 trace: add 'file:line' to all trace outputKarsten Blees, Jul 12, 2014
  13. 12/17 trace: add high resolution timer function to debug performance issuesKarsten Blees, Jul 12, 2014
  14. 13/17 trace: add trace_performance facility to debug performance issuesKarsten Blees, Jul 12, 2014
  15. 14/17 git: add performance tracing for git's main() function to debug scriptsKarsten Blees, Jul 12, 2014
  16. 15/17 wt-status: simplify performance measurement by using getnanotime()Karsten Blees, Jul 12, 2014
  17. 16/17 progress: simplify performance measurement by using getnanotime()Karsten Blees, Jul 12, 2014
  18. 17/17 api-trace.txt: add trace API documentationKarsten Blees, Jul 12, 2014

Read the whole thread, see it on lore, or plain text.

$ cat FOOTERMessages come from the public archive at lore.kernel.org/git, fetched every hour. The front page is chosen and written each morning by an AI editor and can be wrong; the threads themselves are the record. About and API. For agents: an MCP server at https://gitlist.dev/mcp, and any thread, story or person page as Markdown by adding .md to its URL (or sending Accept: text/markdown). Details in /llms.txt.