trace: First draft of API

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				\

common/trace.c

@@ -0,0 +1,200 @@
+#include "config.h"
+#include <assert.h>
+#include <ccan/htable/htable.h>
+#include <ccan/short_types/short_types.h>
+#include <ccan/str/hex/hex.h>
+#include <ccan/tal/str/str.h>
+#include <ccan/tal/tal.h>
+#include <ccan/time/time.h>
+#include <common/json_stream.h>
+#include <common/memleak.h>
+#include <common/trace.h>
+#include <sodium/randombytes.h>
+#include <stdio.h>
+
+#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 */

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

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				\

lightningd/jsonrpc.c

@@ -26,6 +26,7 @@
 #include <common/json_param.h>
 #include <common/memleak.h>
 #include <common/timeout.h>
+#include <common/trace.h>
 #include <db/exec.h>
 #include <fcntl.h>
 #include <lightningd/jsonrpc.h>
@@ -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)

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(); }