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 8c8854a..6bd5b10 100755
--- a/contrib/trace/trace.awk
+++ b/contrib/trace/trace.awk
@@ -44,6 +44,8 @@
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 @@
}
{
- # 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 535efa7..18d9056 100644
--- a/include/common/standard.h
+++ b/include/common/standard.h
@@ -1105,6 +1105,10 @@
*/
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 174edd2..db312dd 100644
--- a/src/standard.c
+++ b/src/standard.c
@@ -3880,6 +3880,12 @@
}
}
+/* 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 4bbbc30..9425be9 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 @@
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);
+}