diff --git a/common/Makefile b/common/Makefile index 1944a5f15..fbefb5eb0 100644 --- a/common/Makefile +++ b/common/Makefile @@ -88,6 +88,7 @@ COMMON_SRC_NOGEN := \ common/status_wire.c \ common/subdaemon.c \ common/timeout.c \ + common/trace.c \ common/tx_roles.c \ common/type_to_string.c \ common/utils.c \ diff --git a/common/trace.c b/common/trace.c new file mode 100644 index 000000000..ad3fa0c99 --- /dev/null +++ b/common/trace.c @@ -0,0 +1,200 @@ +#include "config.h" +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#if HAVE_USDT +#define MAX_ACTIVE_SPANS 128 +#define SPAN_ID_LEN 33 + +const char *trace_service_name = "lightningd"; + +struct span_tag { + char *name, *value; +}; + +struct span { + size_t key; + u64 id; + struct span *parent; + u64 start_time; + u64 end_time; + struct span_tag *tags; + char *name; +}; + +/* All traces we emit are prefixed with this constant. */ +static u64 trace_prefix = 0; +static struct span *active_spans; +static struct span *current; +static size_t last_span_id; + +static void trace_span_id_serialize(struct span *s, char *dest) +{ + hex_encode(&trace_prefix, 8, dest, 17); + hex_encode(&s->id, 8, 16 + dest, 17); +} + +static void trace_init(void) { + randombytes_buf(&trace_prefix, sizeof(u64)); + active_spans = malloc(sizeof(struct span) * MAX_ACTIVE_SPANS); + last_span_id = 1; + current = NULL; +} + +/** + * Convert the pointer to a context object to a numeric key. + */ +static size_t trace_key(const void *key) +{ + return (size_t)key; +} + +static struct span *trace_span_find(size_t key) +{ + for (size_t i = 0; i < MAX_ACTIVE_SPANS; i++) + if (active_spans[i].key == key) + return &active_spans[i]; + + return NULL; +} + +/** + * Find an empty slot for a new span. + */ +static struct span *trace_span_slot(void) +{ + struct span *s = trace_span_find(0); + + /* Might end up here if we have more than MAX_ACTIVE_SPANS + * concurrent spans. */ + assert(s); + assert(s->parent == NULL); + assert(s != current); + return s; +} + +static void trace_emit(struct span *s) +{ + char id[SPAN_ID_LEN]; + trace_span_id_serialize(s, id); + + char *res = tal_fmt( + NULL, + "[{\"id\": \"%s\", \"name\": \"%s\", " + "\"timestamp\": %" PRIu64 ", \"duration\": %" PRIu64 ",", + id + 16, s->name, s->start_time, s->end_time - s->start_time); + + tal_append_fmt(&res, "\"localEndpoint\": { \"serviceName\": \"%s\"}, ", + trace_service_name); + + if (s->parent != NULL) { + trace_span_id_serialize(s->parent, id); + tal_append_fmt(&res, "\"parentId\": \"%s\",", id + 16); + } + + tal_append_fmt(&res, "\"tags\": {"); + for (size_t i = 0; i < tal_count(s->tags); i++) { + tal_append_fmt(&res, "%s\"%s\": \"%s\"", i == 0 ? "" : ", ", + s->tags[i].name, s->tags[i].value); + } + + trace_span_id_serialize(s, id); + tal_append_fmt(&res, "}, \"traceId\": \"%.*s\"}]", 16, id); + fprintf(stderr, "%s\n", res); + tal_free(res); +} + +/** + * Release the span back into the pool of available spans. + */ +static void trace_span_clear(struct span *s) +{ + s->key = 0; + s->id = 0; + s->parent = NULL; + s->name = tal_free(s->name); + s->tags = tal_free(s->tags); +} + +void trace_span_start(const char *name, const void *key) +{ + if (!trace_prefix) + trace_init(); + + size_t numkey = trace_key(key); + struct timeabs now = time_now(); + + assert(trace_span_find(numkey) == NULL); + struct span *s = trace_span_slot(); + assert(current == NULL || current->id != 0); + // assert(current != s); + s->key = numkey; + s->id = last_span_id++; + s->start_time = (now.ts.tv_sec * 1000000) + now.ts.tv_nsec / 1000; + s->parent = current; + s->tags = notleak(tal_arr(NULL, struct span_tag, 0)); + s->name = notleak(tal_strdup(NULL, name)); + current = s; +} + +void trace_span_end(const void *key) +{ + size_t numkey = trace_key(key); + struct span *s = trace_span_find(numkey); + assert(s && "Span to end not found"); + assert(s == current && "Ending a span that isn't the current one"); + + struct timeabs now = time_now(); + s->end_time = (now.ts.tv_sec * 1000000) + now.ts.tv_nsec / 1000; + trace_emit(s); + + /* Reset the context span we are in. */ + current = s->parent; + + /* Now reset the span */ + trace_span_clear(s); +} + +void trace_span_tag(const void *key, const char *name, const char *value) +{ + size_t numkey = trace_key(key); + struct span *span = trace_span_find(numkey); + assert(span); + + size_t s = tal_count(span->tags); + tal_resize(&span->tags, s + 1); + span->tags[s].name = tal_strdup(span->tags, name); + span->tags[s].value = tal_strdup(span->tags, value); +} + +void trace_span_suspend(const void *key) +{ + current = NULL; + fprintf(stderr, "spanSuspend-%s (%p)\n", "???", key); +} + +void trace_span_resume(const void *key) +{ + size_t numkey = trace_key(key); + current = trace_span_find(numkey); + fprintf(stderr, "spanResume-%s (%p)\n", "???", key); +} +#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) {} +void trace_span_resume(const void *key) {} +void trace_span_tag(const void *key, const char *name, const char *value) {} + +#endif /* HAVE_USDT */ diff --git a/common/trace.h b/common/trace.h new file mode 100644 index 000000000..7143659c9 --- /dev/null +++ b/common/trace.h @@ -0,0 +1,11 @@ +#ifndef LIGHTNING_COMMON_TRACE_H +#define LIGHTNING_COMMON_TRACE_H +#include "config.h" + +void trace_span_start(const char *name, const void *key); +void trace_span_end(const void *key); +void trace_span_suspend(const void *key); +void trace_span_resume(const void *key); +void trace_span_tag(const void *key, const char *name, const char *value); + +#endif /* LIGHTNING_COMMON_TRACE_H */ diff --git a/lightningd/Makefile b/lightningd/Makefile index a12345ce9..b867e56ce 100644 --- a/lightningd/Makefile +++ b/lightningd/Makefile @@ -133,6 +133,7 @@ LIGHTNINGD_COMMON_OBJS := \ common/sphinx.o \ common/status_wire.o \ common/timeout.o \ + common/trace.o \ common/tx_roles.o \ common/type_to_string.o \ common/utils.o \ diff --git a/lightningd/jsonrpc.c b/lightningd/jsonrpc.c index a0bddd7c6..d3aa23b12 100644 --- a/lightningd/jsonrpc.c +++ b/lightningd/jsonrpc.c @@ -26,6 +26,7 @@ #include #include #include +#include #include #include #include @@ -978,7 +979,10 @@ parse_request(struct json_connection *jcon, const jsmntok_t tok[]) rpc_hook->custom_replace = NULL; rpc_hook->custom_buffer = NULL; + trace_span_start("lightningd/jsonrpc", &c); + trace_span_tag(&c, "method", c->json_cmd->name); completed = plugin_hook_call_rpc_command(jcon->ld, c->id, rpc_hook); + trace_span_end(&c); /* If it's deferred, mark it (otherwise, it's completed) */ if (!completed) diff --git a/lightningd/test/run-jsonrpc.c b/lightningd/test/run-jsonrpc.c index 182be1d0e..3d86fe1a1 100644 --- a/lightningd/test/run-jsonrpc.c +++ b/lightningd/test/run-jsonrpc.c @@ -137,6 +137,15 @@ void towire_channel_id(u8 **pptr UNNEEDED, const struct channel_id *channel_id U /* Generated stub for towire_node_id */ void towire_node_id(u8 **pptr UNNEEDED, const struct node_id *id UNNEEDED) { fprintf(stderr, "towire_node_id called!\n"); abort(); } +/* Generated stub for trace_span_end */ +void trace_span_end(const void *key UNNEEDED) +{ fprintf(stderr, "trace_span_end called!\n"); abort(); } +/* Generated stub for trace_span_start */ +void trace_span_start(const char *name UNNEEDED, const void *key UNNEEDED) +{ fprintf(stderr, "trace_span_start called!\n"); abort(); } +/* Generated stub for trace_span_tag */ +void trace_span_tag(const void *key UNNEEDED, const char *name UNNEEDED, const char *value UNNEEDED) +{ fprintf(stderr, "trace_span_tag called!\n"); abort(); } /* Generated stub for unilateral_feerate */ u32 unilateral_feerate(struct chain_topology *topo UNNEEDED, bool option_anchors UNNEEDED) { fprintf(stderr, "unilateral_feerate called!\n"); abort(); }