RepoMirrors/haproxy
1
0
Fork 0
mirror of http://git.haproxy.org/git/haproxy.git/ synced 2025-01-03 18:52:04 +00:00
Code Issues Packages Projects Releases Wiki Activity

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

Browse Source 
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.
This commit is contained in:
Willy Tarreau 2019-08-29 08:40:59 +02:00
parent 2ea549bc43
commit 09fb0df6fd
4 changed files with 58 additions and 31 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

3
doc/management.txt
View File

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

38
include/proto/trace.h
View File

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

3
include/types/trace.h
View File

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

45
src/trace.c
View File

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