Merge 5b27344 into 7b8ea7f

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,206 @@
+#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
+#include <sys/sdt.h>
+
+#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);
+	DTRACE_PROBE2(lightningd, span_emit, id, 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;
+	DTRACE_PROBE1(lightningd, span_start, s->id);
+}
+
+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;
+	DTRACE_PROBE1(lightningd, span_end, s->id);
+	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)
+{
+	size_t numkey = trace_key(key);
+	struct span *span = trace_span_find(numkey);
+	current = NULL;
+	DTRACE_PROBE1(lightningd, span_suspend, span->id);
+}
+
+void trace_span_resume(const void *key)
+{
+	size_t numkey = trace_key(key);
+	current = trace_span_find(numkey);
+	DTRACE_PROBE1(lightningd, span_resume, current->id);
+}
+#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 */

configure

@@ -413,6 +413,18 @@ int main(void)
 	return 0;
 }
 /*END*/
+var=HAVE_USDT
+desc=User Statically-Defined Tracing (USDT)
+style=DEFINES_EVERYTHING|EXECUTE|MAY_NOT_COMPILE
+code=
+#include <sys/sdt.h>
+
+int main(void)
+{
+	DTRACE_PROBE(lightningd, test_sdt);
+	return 0;
+}
+/*END*/
 var=HAVE_GCC
 desc=compiler is GCC
 style=OUTSIDE_MAIN

doc/developers-guide/tracing.md

@@ -0,0 +1,109 @@
+# Tracing CLN Performance
+
+CLN includes a simple opentracing exporter that allows tracing the
+execution of the node in real-time, without incurring a performance
+penalty when not listening for traces. Quoting the [Wikipedia][wp]
+entry on Tracing:
+
+> In software engineering, tracing involves a specialized use of
+> logging to record information about a program's execution. This
+> information is typically used by programmers for debugging purposes,
+> and additionally, depending on the type and detail of information
+> contained in a trace log, by experienced system administrators or
+> technical-support personnel and by software monitoring tools to
+> diagnose common problems with software.
+
+The tracing system in CLN is implemented using [USDTs][usdt] (no, not
+that kind of [USDT][tether]). As such it emits events into the kernel,
+from where an exporter can receive them. If no exporter is configured
+then the kernel will replace the call-sites of the probe with a `NOP`,
+thus causing only minimal overhead when not tracing.
+
+## Compiling with tracing support
+
+CLN will build with tracing support if the necessary headers
+(`sys/sdt.h`) are present during the compilation. For debian and
+ubuntu based systems that is easily achieved by installing
+`systemtap-sdt-dev`:
+
+```bash
+# apt-get install -y systemtap-sdt-dev
+```
+-
+Don't forget to run `./configure` and `make` to recompile after
+installing the dependencies. `config.vars` should contain the
+following line after running `./configure`:
+
+```
+HAVE_USDT=1
+```
+
+If you have a compiled binary you can verify whether it was compiled
+with USDT support with the following command:
+
+```bash
+$ readelf -S lightningd/lightningd | grep -i sdt
+```
+
+Alternatively you can list the tracepoints in the binary with the
+following:
+
+```bash
+$ sudo bpftrace -l 'U:lightningd/lightningd:*'
+usdt:lightningd/lightningd:lightningd:span_emit
+usdt:lightningd/lightningd:lightningd:span_end
+usdt:lightningd/lightningd:lightningd:span_resume
+usdt:lightningd/lightningd:lightningd:span_start
+usdt:lightningd/lightningd:lightningd:span_suspend
+```
+
+## Exporters
+
+The simplest way to get started with eBPF in general (which the
+tracing is built upon) is the `bpftrace` command that we've already
+seen above when checking if the binary was built with tracing support.
+
+```bash
+$ sudo bpftrace -l 'U:lightningd/lightningd:*'
+usdt:lightningd/lightningd:lightningd:span_emit
+usdt:lightningd/lightningd:lightningd:span_end
+usdt:lightningd/lightningd:lightningd:span_resume
+usdt:lightningd/lightningd:lightningd:span_start
+usdt:lightningd/lightningd:lightningd:span_suspend
+```
+
+We want to attach to the `span_emit` probe, as that's the one getting
+the opentracing-compatible JSON string passed as an argument, and we'd
+like to extract that.
+
+```bash
+$ export BPFTRACE_STRLEN=200
+$ sudo -E bpftrace -e 'U:../lightning/lightningd/lightningd:span_emit {printf("%s\n", str(arg1, 10240));}'
+
+Attaching 1 probe...
+[{"id": "5006000000000000", "name": "lightningd/jsonrpc", "timestamp": 1690202283751653, "duration": 154,"localEndpoint": { "serviceName": "lightningd"}, "tags": {"method": "sql"}, "traceId": "b7f9b1
+[{"id": "5106000000000000", "name": "lightningd/jsonrpc", "timestamp": 1690202283752515, "duration": 146,"localEndpoint": { "serviceName": "lightningd"}, "tags": {"method": "listnodes"}, "traceId": "
+[{"id": "8206000000000000", "name": "lightningd/jsonrpc", "timestamp": 1690202283759889, "duration": 657,"localEndpoint": { "serviceName": "lightningd"}, "tags": {"method": "dev-memleak"}, "traceId":
+[{"id": "8306000000000000", "name": "lightningd/jsonrpc", "timestamp": 1690202283784095, "duration": 135,"localEndpoint": { "serviceName": "lightningd"}, "tags": {"method": "dev-report-fds"}, "traceI
+[{"id": "8406000000000000", "name": "lightningd/jsonrpc", "timestamp": 1690202283785116, "duration": 204,"localEndpoint": { "serviceName": "lightningd"}, "tags": {"method": "stop"}, "traceId": "f6d42
+[{"id": "3100000000000000", "name": "lightningd/jsonrpc", "timestamp": 1690202283860017, "duration": 770,"localEndpoint": { "serviceName": "lightningd"}, "tags": {"method": "dev-memleak"}, "traceId":
+[{"id": "3200000000000000", "name": "lightningd/jsonrpc", "timestamp": 1690202283992271, "duration": 155,"localEndpoint": { "serviceName": "lightningd"}, "tags": {"method": "dev-report-fds"}, "traceI
+[{"id": "3300000000000000", "name": "lightningd/jsonrpc", "timestamp": 1690202283993745, "duration": 370,"localEndpoint": { "serviceName": "lightningd"}, "tags": {"method": "stop"}, "traceId": "92576
+[{"id": "5206000000000000", "name": "lightningd/jsonrpc", "timestamp": 1690202284070125, "duration": 911,"localEndpoint": { "serviceName": "lightningd"}, "tags": {"method": "dev-memleak"}, "traceId":
+[{"id": "5506000000000000", "name": "lightningd/jsonrpc", "timestamp": 1690202284313462, "duration": 62,"localEndpoint": { "serviceName": "lightningd"}, "tags": {"method": "dev-report-fds"}, "traceId
+[{"id": "5606000000000000", "name": "lightningd/jsonrpc", "timestamp": 1690202284314014, "duration": 117,"localEndpoint": { "serviceName": "lightningd"}, "tags": {"method": "stop"}, "traceId": "b7f9b
+[{"id": "5406000000000000", "name": "plugin/bitcoind", "timestamp": 1690202284312469, "duration": 4774,"localEndpoint": { "serviceName": "lightningd"}, "parentId": "5306000000000000","tags": {"method
+[{"id": "5306000000000000", "name": "extend_tip", "timestamp": 1690202284312428, "duration": 4902,"localEndpoint": { "serviceName": "lightningd"}, "tags": {}, "traceId": "b7f9b1e8af12d252"}]
+
+```
+
+Notice that due to a [limitation][200char] in `bpftrace` you'll at
+most get the first 200 bytes of the payload. If you write your own
+exporter you'll be able to specify the size of the buffer that is
+being used, and can extract the entire span.
+
+[wp]: https://en.wikipedia.org/wiki/Tracing_(software)
+[usdt]: https://illumos.org/books/dtrace/chp-usdt.html
+[tether]: https://en.wikipedia.org/wiki/Tether_(cryptocurrency)
+[bcc]: https://github.com/iovisor/bcc
+[200char]: https://github.com/iovisor/bpftrace/issues/305

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/bitcoind.c

@@ -15,6 +15,7 @@
 #include <common/configdir.h>
 #include <common/json_parse.h>
 #include <common/memleak.h>
+#include <common/trace.h>
 #include <db/exec.h>
 #include <lightningd/bitcoind.h>
 #include <lightningd/chaintopology.h>
@@ -464,6 +465,8 @@ getrawblockbyheight_callback(const char *buf, const jsmntok_t *toks,
 	const char *block_str, *err;
 	struct bitcoin_blkid blkid;
 	struct bitcoin_block *blk;
+	trace_span_resume(call);
+	trace_span_end(call);
 
 	/* If block hash is `null`, this means not found! Call the callback
 	 * with NULL values. */
@@ -514,6 +517,9 @@ void bitcoind_getrawblockbyheight_(struct bitcoind *bitcoind,
 	call->cb = cb;
 	call->cb_arg = cb_arg;
 
+	trace_span_start("plugin/bitcoind", call);
+	trace_span_tag(call, "method", "getrawblockbyheight");
+	trace_span_suspend(call);
 	req = jsonrpc_request_start(bitcoind, "getrawblockbyheight", NULL, true,
 				    bitcoind->log,
 				    NULL,  getrawblockbyheight_callback,