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

@@ -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",

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.
  */

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

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);
+}