Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
143 changes: 89 additions & 54 deletions common/trace.c
Original file line number Diff line number Diff line change
Expand Up @@ -11,12 +11,23 @@
#include <common/memleak.h>
#include <common/pseudorand.h>
#include <common/trace.h>
#include <fcntl.h>
#include <inttypes.h>
#include <stdio.h>
#include <sys/socket.h>
#include <sys/un.h>
#include <unistd.h>

#if HAVE_USDT
#include <sys/sdt.h>
#else
#define DTRACE_PROBE1(provider, probe, arg1) \
do { \
} while (0)
#define DTRACE_PROBE2(provider, probe, arg1, arg2) \
do { \
} while (0)
#endif

/* The traceperent format is defined in W3C Trace Context RFC[1].
* Its format is defined as
Expand All @@ -42,6 +53,11 @@ const char *trace_service_name = "lightningd";
static bool disable_trace = false;
static FILE *trace_to_file = NULL;

/* UDS datagram socket for sending completed spans. */
static int trace_socket_fd = -1;
static struct sockaddr_un trace_socket_addr;
static socklen_t trace_socket_addrlen;

#define SPAN_MAX_TAGS 2

struct span_tag {
Expand Down Expand Up @@ -70,10 +86,7 @@ struct span {
bool suspended;
};

static size_t span_keyof(const struct span *span)
{
return span->key;
}
static size_t span_keyof(const struct span *span) { return span->key; }

static size_t span_key_hash(size_t key)
{
Expand All @@ -91,12 +104,11 @@ static struct span fixed_spans[8];
static struct span_htable *spans = NULL;
static struct span *current;

static void init_span(struct span *s,
size_t key,
const char *name,
static void init_span(struct span *s, size_t key, const char *name,
struct span *parent)
{
struct timeabs now = time_now(); /* discouraged: but tracing wants non-dev time */
struct timeabs now =
time_now(); /* discouraged: but tracing wants non-dev time */

s->key = key;
s->id = pseudorand_u64();
Expand Down Expand Up @@ -145,9 +157,11 @@ static void trace_inject_traceparent(void)
init_span(current, trace_key(&spans), "", NULL);
assert(current && !current->parent);

if (!hex_decode(traceparent + 3, 16, &trace_hi, sizeof(trace_hi))
|| !hex_decode(traceparent + 3 + 16, 16, &trace_lo, sizeof(trace_lo))
|| !hex_decode(traceparent + 3 + 16 + 16 + 1, 16, &span, sizeof(span))) {
if (!hex_decode(traceparent + 3, 16, &trace_hi, sizeof(trace_hi)) ||
!hex_decode(traceparent + 3 + 16, 16, &trace_lo,
sizeof(trace_lo)) ||
!hex_decode(traceparent + 3 + 16 + 16 + 1, 16, &span,
sizeof(span))) {
/* We failed to parse the traceparent, abandon. */
fprintf(stderr, "Failed!");
trace_span_clear(current);
Expand All @@ -159,13 +173,13 @@ static void trace_inject_traceparent(void)
}
}

static void memleak_scan_spans(struct htable *memtable, struct span_htable *spantable)
static void memleak_scan_spans(struct htable *memtable,
struct span_htable *spantable)
{
struct span_htable_iter i;
const struct span *span;

for (span = span_htable_first(spantable, &i);
span;
for (span = span_htable_first(spantable, &i); span;
span = span_htable_next(spantable, &i)) {
memleak_ptr(memtable, span);
memleak_scan_region(memtable, span, sizeof(*span));
Expand All @@ -175,6 +189,7 @@ static void memleak_scan_spans(struct htable *memtable, struct span_htable *span
static void trace_init(void)
{
const char *dev_trace_file;
const char *trace_socket_path;

if (spans)
return;
Expand All @@ -188,22 +203,43 @@ static void trace_init(void)
current = NULL;
dev_trace_file = getenv("CLN_DEV_TRACE_FILE");
if (dev_trace_file) {
const char *fname = tal_fmt(tmpctx, "%s.%u",
dev_trace_file, (unsigned)getpid());
const char *fname = tal_fmt(tmpctx, "%s.%u", dev_trace_file,
(unsigned)getpid());
trace_to_file = fopen(fname, "a+");
if (!trace_to_file)
err(1, "Opening CLN_DEV_TRACE_FILE %s", fname);
}
trace_inject_traceparent();

/* Open a non-blocking UDS datagram socket for trace emission. */
trace_socket_path = getenv("CLN_TRACE_SOCKET");
if (trace_socket_path) {
trace_socket_fd = socket(AF_UNIX, SOCK_DGRAM, 0);
if (trace_socket_fd >= 0) {
fcntl(trace_socket_fd, F_SETFL, O_NONBLOCK);
memset(&trace_socket_addr, 0,
sizeof(trace_socket_addr));
trace_socket_addr.sun_family = AF_UNIX;
strncpy(trace_socket_addr.sun_path, trace_socket_path,
sizeof(trace_socket_addr.sun_path) - 1);
trace_socket_addrlen =
sizeof(trace_socket_addr.sun_family) +
strlen(trace_socket_addr.sun_path) + 1;
}
}

/* If no output backend is active, disable tracing to skip
* all the expensive span management work. */
if (!trace_to_file && trace_socket_fd < 0 && !HAVE_USDT)
disable_trace = true;

if (!disable_trace)
trace_inject_traceparent();
}

/**
* Convert the pointer to a context object to a numeric key.
*/
static size_t trace_key(const void *key)
{
return (size_t)key;
}
static size_t trace_key(const void *key) { return (size_t)key; }

static struct span *trace_span_find(size_t key)
{
Expand Down Expand Up @@ -233,39 +269,38 @@ static void trace_emit(struct span *s)
char buffer[MAX_BUF_SIZE + 1];
size_t len;

snprintf(span_id, sizeof(span_id), "%016"PRIx64, s->id);
snprintf(span_id, sizeof(span_id), "%016" PRIx64, s->id);
len = snprintf(buffer, MAX_BUF_SIZE,
"[{\"id\":\"%s\",\"name\":\"%s\","
"\"timestamp\":%"PRIu64",\"duration\":%"PRIu64","
"\"timestamp\":%" PRIu64 ",\"duration\":%" PRIu64 ","
"\"localEndpoint\":{\"serviceName\":\"%s\"},",
span_id, s->name, s->start_time, s->end_time - s->start_time, trace_service_name);
span_id, s->name, s->start_time,
s->end_time - s->start_time, trace_service_name);

if (s->parent != NULL) {
len += snprintf(buffer + len, MAX_BUF_SIZE - len,
"\"parentId\":\"%016"PRIx64"\",",
s->parent->id);
len +=
snprintf(buffer + len, MAX_BUF_SIZE - len,
"\"parentId\":\"%016" PRIx64 "\",", s->parent->id);
if (len > MAX_BUF_SIZE)
len = MAX_BUF_SIZE;
}

len += snprintf(buffer + len, MAX_BUF_SIZE - len,
"\"tags\":{");
len += snprintf(buffer + len, MAX_BUF_SIZE - len, "\"tags\":{");
if (len > MAX_BUF_SIZE)
len = MAX_BUF_SIZE;
for (size_t i = 0; i < SPAN_MAX_TAGS; i++) {
if (!s->tags[i].name)
continue;
len += snprintf(buffer + len, MAX_BUF_SIZE - len,
"%s\"%s\":\"%.*s\"", i == 0 ? "" : ", ",
s->tags[i].name,
s->tags[i].valuelen,
s->tags[i].name, s->tags[i].valuelen,
s->tags[i].valuestr);
if (len > MAX_BUF_SIZE)
len = MAX_BUF_SIZE;
}

len += snprintf(buffer + len, MAX_BUF_SIZE - len,
"},\"traceId\":\"%016"PRIx64"%016"PRIx64"\"}]",
"},\"traceId\":\"%016" PRIx64 "%016" PRIx64 "\"}]",
s->trace_id_hi, s->trace_id_lo);
if (len > MAX_BUF_SIZE)
len = MAX_BUF_SIZE;
Expand All @@ -276,6 +311,12 @@ static void trace_emit(struct span *s)
fprintf(trace_to_file, "span_emit %s %s\n", span_id, buffer);
fflush(trace_to_file);
}
if (trace_socket_fd >= 0) {
/* Fire-and-forget: silently ignore all sendto errors. */
sendto(trace_socket_fd, buffer, len, MSG_DONTWAIT,
(struct sockaddr *)&trace_socket_addr,
trace_socket_addrlen);
}
}

/**
Expand All @@ -300,9 +341,9 @@ void trace_span_start_(const char *name, const void *key)
{
size_t numkey = trace_key(key);

trace_init();
if (disable_trace)
return;
trace_init();

assert(trace_span_find(numkey) == NULL);
struct span *s = trace_span_slot();
Expand Down Expand Up @@ -332,11 +373,12 @@ void trace_span_end(const void *key)
assert(s && "Span to end not found");
assert(s == current && "Ending a span that isn't the current one");

struct timeabs now = time_now(); /* discouraged: but tracing wants non-dev time */
struct timeabs now =
time_now(); /* discouraged: but tracing wants non-dev time */
s->end_time = (now.ts.tv_sec * 1000000) + now.ts.tv_nsec / 1000;
DTRACE_PROBE1(lightningd, span_end, s->id);
if (trace_to_file) {
fprintf(trace_to_file, "span_end %016"PRIx64"\n", s->id);
fprintf(trace_to_file, "span_end %016" PRIx64 "\n", s->id);
fflush(trace_to_file);
}
trace_emit(s);
Expand Down Expand Up @@ -364,9 +406,8 @@ void trace_span_tag(const void *key, const char *name, const char *value)
t->name = name;
t->valuestr = value;
t->valuelen = strlen(value);
if (t->valuestr[0] == '"'
&& t->valuelen > 1
&& t->valuestr[t->valuelen-1] == '"') {
if (t->valuestr[0] == '"' && t->valuelen > 1 &&
t->valuestr[t->valuelen - 1] == '"') {
t->valuestr++;
t->valuelen -= 2;
}
Expand All @@ -385,12 +426,13 @@ void trace_span_suspend_(const void *key, const char *lbl)
struct span *span = trace_span_find(numkey);
TRACE_DBG("Suspending span %s (%zu)\n", current->name, current->key);
assert(current == span);
assert(!span->suspended);
assert(!span->suspended);
span->suspended = true;
current = current->parent;
DTRACE_PROBE1(lightningd, span_suspend, span->id);
if (trace_to_file) {
fprintf(trace_to_file, "span_suspend %016"PRIx64"\n", span->id);
fprintf(trace_to_file, "span_suspend %016" PRIx64 "\n",
span->id);
fflush(trace_to_file);
}
}
Expand Down Expand Up @@ -426,29 +468,22 @@ void trace_span_resume_(const void *key, const char *lbl)

size_t numkey = trace_key(key);
current = trace_span_find(numkey);
assert(current->suspended);
assert(current->suspended);
current->suspended = false;
TRACE_DBG("Resuming span %s (%zu)\n", current->name, current->key);
DTRACE_PROBE1(lightningd, span_resume, current->id);
if (trace_to_file) {
fprintf(trace_to_file, "span_resume %016"PRIx64"\n", current->id);
fprintf(trace_to_file, "span_resume %016" PRIx64 "\n",
current->id);
fflush(trace_to_file);
}
}

void trace_cleanup(void)
{
spans = tal_free(spans);
if (trace_socket_fd >= 0) {
close(trace_socket_fd);
trace_socket_fd = -1;
}
}

#else /* HAVE_USDT */

void trace_span_start_(const char *name, const void *key) {}
void trace_span_end(const void *key) {}
void trace_span_suspend_(const void *key, const char *lbl) {}
void trace_span_suspend_may_free_(const void *key, const char *lbl) {}
void trace_span_resume_(const void *key, const char *lbl) {}
void trace_span_tag(const void *key, const char *name, const char *value) {}
void trace_cleanup(void) {}

#endif /* HAVE_USDT */
Loading
Loading