From 1296382d0bf7e600bbb60e927e546053d381e473 Mon Sep 17 00:00:00 2001
From: Willy Tarreau <w@1wt.eu>
Date: Tue, 24 Oct 2017 10:54:08 +0200
Subject: [PATCH] CONTRIB: trace: add the possibility to place trace calls in
 the code

Now any call to trace() in the code will automatically appear interleaved
with the call sequence and timestamped in the trace file. They appear with
a '#' on the 3rd argument (caller's pointer) in order to make them easy to
spot. If the trace functionality is not used, a dmumy weak function is used
instead so that it doesn't require to recompile every time traces are
enabled/disabled.

The trace decoder knows how to deal with these messages, detects them and
indents them similarly to the currently traced function. This can be used
to print function arguments for example.

Note that we systematically flush the log when calling trace() to ensure we
never miss important events, so this may impact performance.

The trace() function uses the same format as printf() so it should be easy
to setup during debugging sessions.
---
 contrib/trace/trace.awk   | 10 +++++++++-
 include/common/standard.h |  4 ++++
 src/standard.c            |  6 ++++++
 src/trace.c               | 39 +++++++++++++++++++++++++++++++++++++++
 4 files changed, 58 insertions(+), 1 deletion(-)

diff --git a/contrib/trace/trace.awk b/contrib/trace/trace.awk
index 8c8854a906..6bd5b10a5a 100755
--- a/contrib/trace/trace.awk
+++ b/contrib/trace/trace.awk
@@ -44,6 +44,8 @@ BEGIN {
     indents[">",i-1] = indents[">",i-1] " "
     indents["<",i] = indents["<",i-1] "  "
     indents["<",i-1] = indents["<",i-1] " "
+    indents[" ",i] = indents[" ",i-1] "##"
+    indents[" ",i-1] = indents[" ",i-1] " "
   }
 }
 
@@ -61,7 +63,13 @@ function getptr(ptr)
 }
 
 {
-  # input format: <timestamp> <level> <caller> <dir> <callee>
+  # input format: <timestamp> <level> <caller> <dir> <callee> [<ret>|<args>...]
+  if ($3 == "#") { # this is a trace comment
+    printf "%s %s  ", $1, indents[" ",$2]
+    $1=""; $2=""; $3=""
+    print substr($0,4)
+    next
+  }
   getptr($3); caller_loc=loc; caller_name=name
   getptr($5); callee_loc=loc; callee_name=name
   printf "%s %s  %s %s %s [%s:%s] %s [%s:%s]\n",
diff --git a/include/common/standard.h b/include/common/standard.h
index 535efa7363..18d90566d1 100644
--- a/include/common/standard.h
+++ b/include/common/standard.h
@@ -1105,6 +1105,10 @@ char *env_expand(char *in);
  */
 void debug_hexdump(FILE *out, const char *pfx, const char *buf, unsigned int baseaddr, int len);
 
+/* this is used to emit traces when building with TRACE=1 */
+__attribute__((format(printf, 1, 2)))
+void trace(char *fmt, ...);
+
 /* used from everywhere just to drain results we don't want to read and which
  * recent versions of gcc increasingly and annoyingly complain about.
  */
diff --git a/src/standard.c b/src/standard.c
index 174edd2cc5..db312dd189 100644
--- a/src/standard.c
+++ b/src/standard.c
@@ -3880,6 +3880,12 @@ void debug_hexdump(FILE *out, const char *pfx, const char *buf,
 	}
 }
 
+/* do nothing, just a placeholder for debugging calls, the real one is in trace.c */
+__attribute__((weak,format(printf, 1, 2)))
+void trace(char *msg, ...)
+{
+}
+
 /*
  * Local variables:
  *  c-indent-level: 8
diff --git a/src/trace.c b/src/trace.c
index 4bbbc302ab..9425be9f71 100644
--- a/src/trace.c
+++ b/src/trace.c
@@ -29,11 +29,20 @@
  *
  * where <dir> is '>' when entering a function and '<' when leaving.
  *
+ * It is also possible to emit comments using the trace() function which uses
+ * the printf() format. Such comments are then inserted by replacing the caller
+ * pointer with a sharp ('#') like this :
+ *
+ *   <sec.usec> <level> # <comment>
+ *  or :
+ *   <tsc> <level> # <comment>
+ *
  * The article below is a nice explanation of how this works :
  *   http://balau82.wordpress.com/2010/10/06/trace-and-profile-function-calls-with-gcc/
  */
 
 #include <sys/time.h>
+#include <stdarg.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
@@ -229,3 +238,33 @@ void __cyg_profile_func_exit(void *to,  void *from)
 	if (!disabled)
 		return make_line(from, to, level--, '<');
 }
+
+/* the one adds comments in the trace above. The output format is :
+ * <timestamp> <level> # <string>
+ */
+__attribute__((format(printf, 1, 2)))
+void trace(char *fmt, ...)
+{
+	va_list ap;
+
+	if (unlikely(!log) && !open_trace())
+		return;
+
+	if (unlikely(!fast_time))
+		gettimeofday(now_ptr, NULL);
+
+	if (!use_tsc)
+		fprintf(log, "%u.%06u %d # ",
+			(unsigned int)now_ptr->tv_sec,
+			(unsigned int)now_ptr->tv_usec,
+			level + 1);
+	else
+		fprintf(log, "%llx %d # ",
+			rdtsc(), level + 1);
+
+	va_start(ap, fmt);
+	vfprintf(log, fmt, ap);
+	va_end(ap);
+	fputc('\n', log);
+	fflush(log);
+}