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

[PATCH v8 07/17] trace: add infrastructure to augment trace output with additional info

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

To be able to add a common prefix or suffix to all trace output (e.g. a timestamp or file:line of the caller), factor out common setup and cleanup tasks of the trace* functions.

When adding a common prefix, it makes sense that the output of each trace call starts on a new line. Add '\n' in case the caller forgot.

Note that this explicitly limits trace output to line-by-line, it is no longer possible to trace-print just part of a line. Until now, this was just an implicit assumption (trace-printing part of a line worked, but messed up the trace file if multiple threads or processes were involved).

Thread-safety / inter-process-safety is also the reason why we need to do the prefixing and suffixing in memory rather than issuing multiple write() calls. Write_or_whine_pipe() / xwrite() is atomic unless the size exceeds MAX_IO_SIZE (8MB, see wrapper.c). In case of trace_strbuf, this costs an additional string copy (which should be irrelevant for performance in light of actual file IO).

While we're at it, rename trace_strbuf's 'buf' argument, which suggests that the function is modifying the buffer. Trace_strbuf() currently is the only trace API that can print arbitrary binary data (without barfing on '%' or stopping at '\0'), so 'data' seems more appropriate.

Signed-off-by: Karsten Blees <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 trace.c | 47 +++++++++++++++++++++++++++++++++--------------
 trace.h |  2 +-
 2 files changed, 34 insertions(+), 15 deletions(-)
diff --git a/trace.c b/trace.c
index 8662b79..3d02bcc 100644
--- a/trace.c
+++ b/trace.c
@@ -85,17 +85,37 @@ void trace_disable(struct trace_key *key)
 static const char err_msg[] = "Could not trace into fd given by "
 	"GIT_TRACE environment variable";
 
+static int prepare_trace_line(struct trace_key *key, struct strbuf *buf)
+{
+	if (!trace_want(key))
+		return 0;
+
+	set_try_to_free_routine(NULL);	/* is never reset */
+
+	/* add line prefix here */
+
+	return 1;
+}
+
+static void print_trace_line(struct trace_key *key, struct strbuf *buf)
+{
+	/* append newline if missing */
+	if (buf->len && buf->buf[buf->len - 1] != '\n')
+		strbuf_addch(buf, '\n');
+
+	write_or_whine_pipe(get_trace_fd(key), buf->buf, buf->len, err_msg);
+	strbuf_release(buf);
+}
+
 static void trace_vprintf(struct trace_key *key, const char *format, va_list ap)
 {
 	struct strbuf buf = STRBUF_INIT;
 
-	if (!trace_want(key))
+	if (!prepare_trace_line(key, &buf))
 		return;
 
-	set_try_to_free_routine(NULL);	/* is never reset */
 	strbuf_vaddf(&buf, format, ap);
-	trace_strbuf(key, &buf);
-	strbuf_release(&buf);
+	print_trace_line(key, &buf);
 }
 
 void trace_printf_key(struct trace_key *key, const char *format, ...)
@@ -114,32 +134,31 @@ void trace_printf(const char *format, ...)
 	va_end(ap);
 }
 
-void trace_strbuf(struct trace_key *key, const struct strbuf *buf)
+void trace_strbuf(struct trace_key *key, const struct strbuf *data)
 {
-	int fd = get_trace_fd(key);
-	if (!fd)
+	struct strbuf buf = STRBUF_INIT;
+
+	if (!prepare_trace_line(key, &buf))
 		return;
 
-	write_or_whine_pipe(fd, buf->buf, buf->len, err_msg);
+	strbuf_addbuf(&buf, data);
+	print_trace_line(key, &buf);
 }
 
 void trace_argv_printf(const char **argv, const char *format, ...)
 {
 	struct strbuf buf = STRBUF_INIT;
 	va_list ap;
-	int fd = get_trace_fd(NULL);
-	if (!fd)
+
+	if (!prepare_trace_line(NULL, &buf))
 		return;
 
-	set_try_to_free_routine(NULL);	/* is never reset */
 	va_start(ap, format);
 	strbuf_vaddf(&buf, format, ap);
 	va_end(ap);
 
 	sq_quote_argv(&buf, argv, 0);
-	strbuf_addch(&buf, '\n');
-	write_or_whine_pipe(fd, buf.buf, buf.len, err_msg);
-	strbuf_release(&buf);
+	print_trace_line(NULL, &buf);
 }
 
 static const char *quote_crnl(const char *path)
diff --git a/trace.h b/trace.h
index d85ac4c..28c1089 100644
--- a/trace.h
+++ b/trace.h
@@ -22,6 +22,6 @@ extern int trace_want(struct trace_key *key);
 extern void trace_disable(struct trace_key *key);
 __attribute__((format (printf, 2, 3)))
 extern void trace_printf_key(struct trace_key *key, const char *format, ...);
-extern void trace_strbuf(struct trace_key *key, const struct strbuf *buf);
+extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);
 
 #endif /* TRACE_H */

-- 
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 8 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.