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.

diff --git a/contrib/trace/trace.awk b/contrib/trace/trace.awk
index 8c8854a906880f5f9ed9916eb51fa78e37f08a95..6bd5b10a5a3fe3b75bdcc4582103b60fb5bc88ec 100755 (executable)
--- 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 535efa736303e6a619645320380a1b4b90a25f7d..18d90566d14ba2ccec2442f95902c98751972c3c 100644 (file)
--- 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 174edd2cc5612d715ac1d8187965c8afd859a91f..db312dd1892f48838da1215371b1233a44d2f920 100644 (file)
--- 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 4bbbc302abe2a48cc3b648fd216b86623d37f2af..9425be9f713de0a3c42bc596a6d39201b098ff8b 100644 (file)
--- 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);
+}