MINOR: trace: prepend the function name for developer level traces

Working on adding traces to mux-h2 revealed that the function names are
manually copied a lot in developer traces. The reason is that they are
not preprocessor macros and as such cannot be concatenated. Let's
slightly adjust the trace() function call to take a function name just
after the file:line argument. This argument is only added for the
TRACE_DEVEL and 3 new TRACE_ENTER, TRACE_LEAVE, and TRACE_POINT macros
and left NULL for others. This way the function name is only reported
for traces aimed at the developers. The pretty-print callback was also
extended to benefit from this. This will also significantly shrink the
data segment as the "entering" and "leaving" strings will now be merged.

One technical point worth mentioning is that the function name is *not*
passed as an ist to the inline function because it's not considered as
a builtin constant by the compiler, and would lead to strlen() being
run on it from all call places before calling the inline function. Thus
instead we pass the const char * (that the compiler knows where to find)
and it's the __trace() function that converts it to an ist for internal
consumption and for the pretty-print callback. Doing this avoids losing
5-10% peak performance.

diff --git a/doc/management.txt b/doc/management.txt
index 1dd52f5c87cf8987bb6aba0ca5294ba308790048..a65eeca4f50fa34ead30c672f7782db4c5d1b445 100644 (file)
--- a/doc/management.txt
+++ b/doc/management.txt
@@ -2674,7 +2674,8 @@ trace <source> level [<level>]
       developer    it reports everything available, which can include advanced
                    information such as "breaking out of this loop" that are
                    only relevant to a developer trying to understand a bug that
-                   only happens once in a while in field.
+                   only happens once in a while in field. Function names are
+                   only reported at this level.
 
   It is highly recommended to always use the "user" level only and switch to
   other levels only if instructed to do so by a developer. Also it is a good

diff --git a/include/proto/trace.h b/include/proto/trace.h
index 726fefdbf900cd3cfbf970ea500d8cb50b9e6e01..9c5c111282aae7ca375e4dd4bb548dede74f284d 100644 (file)
--- a/include/proto/trace.h
+++ b/include/proto/trace.h
@@ -47,32 +47,44 @@
  * These 4 arguments as well as the cb() function pointer may all be NULL, or
  * simply omitted (in which case they will be replaced by a NULL). This
  * ordering allows many TRACE() calls to be placed using copy-paste and just
- * change the message at the beginning.
+ * change the message at the beginning. Only TRACE_DEVEL(), TRACE_ENTER() and
+ * TRACE_LEAVE() will report the calling function's name.
  */
 #define TRACE(msg, mask, ...)    \
-       trace(TRACE_LEVEL,           (mask), TRACE_SOURCE, ist(TRC_LOC), TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
+       trace(TRACE_LEVEL,           (mask), TRACE_SOURCE, ist(TRC_LOC), NULL, TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
 
 #define TRACE_USER(msg, mask, ...)                     \
-       trace(TRACE_LEVEL_USER,      (mask), TRACE_SOURCE, ist(TRC_LOC), TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
+       trace(TRACE_LEVEL_USER,      (mask), TRACE_SOURCE, ist(TRC_LOC), NULL, TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
 
 #define TRACE_DATA(msg, mask, ...)  \
-       trace(TRACE_LEVEL_DATA,   (mask), TRACE_SOURCE, ist(TRC_LOC), TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
+       trace(TRACE_LEVEL_DATA,   (mask), TRACE_SOURCE, ist(TRC_LOC), NULL, TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
 
 #define TRACE_PROTO(msg, mask, ...)    \
-       trace(TRACE_LEVEL_PROTO,     (mask), TRACE_SOURCE, ist(TRC_LOC), TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
+       trace(TRACE_LEVEL_PROTO,     (mask), TRACE_SOURCE, ist(TRC_LOC), NULL, TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
 
 #define TRACE_STATE(msg, mask, ...)    \
-       trace(TRACE_LEVEL_STATE,     (mask), TRACE_SOURCE, ist(TRC_LOC), TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
+       trace(TRACE_LEVEL_STATE,     (mask), TRACE_SOURCE, ist(TRC_LOC), NULL, TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
 
 #define TRACE_DEVEL(msg, mask, ...)    \
-       trace(TRACE_LEVEL_DEVELOPER, (mask), TRACE_SOURCE, ist(TRC_LOC), TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
+       trace(TRACE_LEVEL_DEVELOPER, (mask), TRACE_SOURCE, ist(TRC_LOC), __FUNCTION__, TRC_5ARGS(__VA_ARGS__,,,,,), ist(msg))
+
+#define TRACE_ENTER(mask, ...)  \
+       trace(TRACE_LEVEL_DEVELOPER, (mask), TRACE_SOURCE, ist(TRC_LOC), __FUNCTION__, TRC_5ARGS(__VA_ARGS__,,,,,), ist("entering"))
+
+#define TRACE_LEAVE(mask, ...)  \
+       trace(TRACE_LEVEL_DEVELOPER, (mask), TRACE_SOURCE, ist(TRC_LOC), __FUNCTION__, TRC_5ARGS(__VA_ARGS__,,,,,), ist("leaving"))
+
+#define TRACE_POINT(mask, ...)  \
+       trace(TRACE_LEVEL_DEVELOPER, (mask), TRACE_SOURCE, ist(TRC_LOC), __FUNCTION__, TRC_5ARGS(__VA_ARGS__,,,,,), ist("in"))
 
 extern struct list trace_sources;
 extern THREAD_LOCAL struct buffer trace_buf;
 
-void __trace(enum trace_level level, uint64_t mask, struct trace_source *src, const struct ist where,
+void __trace(enum trace_level level, uint64_t mask, struct trace_source *src,
+             const struct ist where, const char *func,
              const void *a1, const void *a2, const void *a3, const void *a4,
-             void (*cb)(enum trace_level level, uint64_t mask, const struct trace_source *src, const struct ist where,
+             void (*cb)(enum trace_level level, uint64_t mask, const struct trace_source *src,
+                        const struct ist where, const struct ist func,
                         const void *a1, const void *a2, const void *a3, const void *a4),
              const struct ist msg);
 
@@ -106,14 +118,16 @@ static inline void trace_register_source(struct trace_source *source)
 }
 
 /* sends a trace for the given source */
-static inline void trace(enum trace_level level, uint64_t mask, struct trace_source *src, const struct ist where,
+static inline void trace(enum trace_level level, uint64_t mask, struct trace_source *src,
+                         const struct ist where, const char *func,
                          const void *a1, const void *a2, const void *a3, const void *a4,
-                         void (*cb)(enum trace_level level, uint64_t mask, const struct trace_source *src, const struct ist where,
+                         void (*cb)(enum trace_level level, uint64_t mask, const struct trace_source *src,
+                                    const struct ist where, const struct ist func,
                                     const void *a1, const void *a2, const void *a3, const void *a4),
                          const struct ist msg)
 {
        if (unlikely(src->state != TRACE_STATE_STOPPED))
-               __trace(level, mask, src, where, a1, a2, a3, a4, cb, msg);
+               __trace(level, mask, src, where, func, a1, a2, a3, a4, cb, msg);
 }
 
 #endif /* _PROTO_TRACE_H */

diff --git a/include/types/trace.h b/include/types/trace.h
index 03eb7dbc99e94e00d6fab9ac3f35befdd0922e0b..91a57f88cbe1202b52080813bbcf518e7d16fd0f 100644 (file)
--- a/include/types/trace.h
+++ b/include/types/trace.h
@@ -124,7 +124,8 @@ struct trace_source {
        const struct trace_event *known_events;
        struct list source_link; // element in list of known trace sources
        void (*default_cb)(enum trace_level level, uint64_t mask,
-                          const struct trace_source *src, const struct ist where,
+                          const struct trace_source *src,
+                          const struct ist where, const struct ist func,
                           const void *a1, const void *a2, const void *a3, const void *a4);
        uint32_t arg_def;        // argument definitions (sum of TRC_ARG{1..4}_*)
        const struct name_desc *lockon_args; // must be 4 entries if not NULL

diff --git a/src/trace.c b/src/trace.c
index 7769b5d26a361e2cd548fbed5ff3832285dac8ed..63ad1f9b4711062e639b0583384d55a2d21ed207 100644 (file)
--- a/src/trace.c
+++ b/src/trace.c
@@ -69,9 +69,11 @@ static inline const void *trace_pick_arg(uint32_t arg_def, const void *a1, const
 }
 
 /* write a message for the given trace source */
-void __trace(enum trace_level level, uint64_t mask, struct trace_source *src, const struct ist where,
+void __trace(enum trace_level level, uint64_t mask, struct trace_source *src,
+             const struct ist where, const char *func,
              const void *a1, const void *a2, const void *a3, const void *a4,
-             void (*cb)(enum trace_level level, uint64_t mask, const struct trace_source *src, const struct ist where,
+             void (*cb)(enum trace_level level, uint64_t mask, const struct trace_source *src,
+                        const struct ist where, const struct ist func,
                         const void *a1, const void *a2, const void *a3, const void *a4),
              const struct ist msg)
 {
@@ -83,8 +85,10 @@ void __trace(enum trace_level level, uint64_t mask, struct trace_source *src, co
        const struct stream *strm = NULL;
        const struct connection *conn = NULL;
        const void *lockon_ptr = NULL;
+       struct ist ist_func = ist(func);
        char tnum[4];
-       struct ist line[8];
+       struct ist line[10];
+       int words = 0;
 
        if (likely(src->state == TRACE_STATE_STOPPED))
                return;
@@ -177,20 +181,26 @@ void __trace(enum trace_level level, uint64_t mask, struct trace_source *src, co
        /* log the logging location truncated to 10 chars from the right so that
         * the line number and the end of the file name are there.
         */
-       line[0] = ist("[");
+       line[words++] = ist("[");
        tnum[0] = '0' + tid / 10;
        tnum[1] = '0' + tid % 10;
        tnum[2] = '|';
        tnum[3] = 0;
-       line[1] = ist(tnum);
-       line[2] = src->name;
-       line[3] = ist("|");
-       line[4] = where;
-       if (line[4].len > 13) {
-               line[4].ptr += (line[4].len - 13);
-               line[4].len = 13;
+       line[words++] = ist(tnum);
+       line[words++] = src->name;
+       line[words++] = ist("|");
+       line[words] = where;
+       if (line[words].len > 13) {
+               line[words].ptr += (line[words].len - 13);
+               line[words].len = 13;
+       }
+       words++;
+       line[words++] = ist("] ");
+
+       if (ist_func.ptr) {
+               line[words++] = ist_func;
+               line[words++] = ist("(): ");
        }
-       line[5] = ist("] ");
 
        if (!cb)
                cb = src->default_cb;
@@ -202,15 +212,16 @@ void __trace(enum trace_level level, uint64_t mask, struct trace_source *src, co
                 */
                b_reset(&trace_buf);
                b_istput(&trace_buf, msg);
-               cb(level, mask, src, where, a1, a2, a3, a4);
-               line[6].ptr = trace_buf.area;
-               line[6].len = trace_buf.data;
+               cb(level, mask, src, where, ist_func, a1, a2, a3, a4);
+               line[words].ptr = trace_buf.area;
+               line[words].len = trace_buf.data;
+               words++;
        }
        else
-               line[6] = msg;
+               line[words++] = msg;
 
        if (src->sink)
-               sink_write(src->sink, line, 7);
+               sink_write(src->sink, line, words);
 
  end:
        /* check if we need to stop the trace now */