From d97eede1e7c8d8969fde4fbc0574bf71ecf043bf Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 23 Apr 2025 09:54:15 +0930 Subject: [PATCH 01/10] common/test/run-trace: increase iterations for trivial benchmarking. With an average runtime of 18.7674, this implies 1876ns per trace, which is far in excess of the 370ns claimed in doc/developers-guide/tracing-cln-performance.md. We also add a tag in there, so we measure that! Results on my laptop: real 0m18.524000-19.100000(18.7674+/-0.21)s user 0m16.171000-16.833000(16.424+/-0.26)s sys 0m2.259000-2.400000(2.337+/-0.059)s Signed-off-by: Rusty Russell --- common/test/run-trace.c | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/common/test/run-trace.c b/common/test/run-trace.c index 99fd94b69484..7811f68c91dd 100644 --- a/common/test/run-trace.c +++ b/common/test/run-trace.c @@ -13,16 +13,20 @@ int main(int argx, char *argv[]) common_setup(argv[0]); /* Create a bunch of nested spans to emit. */ - for(int i=0; i<25000; i++) { + for(int i=0; i<2500000; i++) { trace_span_start("a", &a); + trace_span_tag(&a, "method", "getrawblockbyheight"); trace_span_start("b", &b); + trace_span_tag(&b, "method", "getrawblockbyheight"); trace_span_start("c", &c); + trace_span_tag(&c, "method", "getrawblockbyheight"); trace_span_end(&c); trace_span_end(&b); trace_span_start("d", &d); + trace_span_tag(&d, "method", "getrawblockbyheight"); trace_span_end(&d); trace_span_end(&a); From 249a9c516861395b608224fc0cdc80e56e7e7200 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 23 Apr 2025 09:55:15 +0930 Subject: [PATCH 02/10] trace: track suspensions, check they match. I added this debugging because the next test revealed a mismatch, so I wanted to see where it was happening. The comment in lightningd suggests it's possible, but I can't see any code which suspends in the lightningd io_loop, so I cannot see how this is triggered. Signed-off-by: Rusty Russell --- common/trace.c | 6 ++++++ lightningd/lightningd.c | 8 -------- 2 files changed, 6 insertions(+), 8 deletions(-) diff --git a/common/trace.c b/common/trace.c index 5bd5fa5647fa..d85c61afb9e0 100644 --- a/common/trace.c +++ b/common/trace.c @@ -67,6 +67,7 @@ struct span { struct span_tag *tags; char *name; + bool suspended; /* Indicate whether this is a remote span, i.e., it was inherited by some other process, which is in charge of emitting the span. This just means that we don't emit this @@ -286,6 +287,7 @@ void trace_span_start(const char *name, const void *key) s->parent = current; s->tags = notleak(tal_arr(NULL, struct span_tag, 0)); s->name = notleak(tal_strdup(NULL, name)); + s->suspended = false; /* If this is a new root span we also need to associate a new * trace_id with it. */ @@ -369,6 +371,8 @@ 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); + span->suspended = true; current = NULL; DTRACE_PROBE1(lightningd, span_suspend, span->id); } @@ -402,6 +406,8 @@ void trace_span_resume_(const void *key, const char *lbl) size_t numkey = trace_key(key); current = trace_span_find(numkey); + assert(current->suspended); + current->suspended = false; TRACE_DBG("Resuming span %s (%zu)\n", current->name, current->key); DTRACE_PROBE1(lightningd, span_resume, current->id); } diff --git a/lightningd/lightningd.c b/lightningd/lightningd.c index a5d46e7f35ca..756cae072c23 100644 --- a/lightningd/lightningd.c +++ b/lightningd/lightningd.c @@ -1409,14 +1409,6 @@ int main(int argc, char *argv[]) /*~ Now handle sigchld, so we can clean up appropriately. */ sigchld_conn = notleak(io_new_conn(ld, sigchld_rfd, sigchld_rfd_in, ld)); - /* This span was started before handing control to `io_loop` - * which suspends active spans in-between processing - * events. Depending on how the `io_loop` was interrupted, the - * current context span may have been suspended. We need to - * manually resume it for this case. Notice that resuming is - * idempotent, and doing so repeatedly is safe. - */ - trace_span_resume(argv); trace_span_end(argv); /*~ Mark ourselves live. From 8c48314591d755ab3c91621af1a2a557e69486b6 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 23 Apr 2025 10:24:18 +0930 Subject: [PATCH 03/10] pytest: add test hooks so we can test tracing. Suggested-by: Christian Decker Signed-off-by: Rusty Russell --- common/trace.c | 42 ++++++++++++++++++++++++++++++++++++ tests/test_misc.py | 54 ++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 96 insertions(+) diff --git a/common/trace.c b/common/trace.c index d85c61afb9e0..c92a82dd4140 100644 --- a/common/trace.c +++ b/common/trace.c @@ -1,5 +1,6 @@ #include "config.h" #include +#include #include #include #include @@ -8,6 +9,7 @@ #include #include #include +#include #include #include #include @@ -42,6 +44,7 @@ const char *trace_service_name = "lightningd"; static bool disable_trace = false; +static FILE *trace_to_file = NULL; struct span_tag { char *name, *value; @@ -151,11 +154,20 @@ static inline void trace_check_tree(void) {} static void trace_init(void) { + const char *dev_trace_file; if (active_spans) return; active_spans = calloc(MAX_ACTIVE_SPANS, sizeof(struct span)); 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()); + trace_to_file = fopen(fname, "a+"); + if (!trace_to_file) + err(1, "Opening CLN_DEV_TRACE_FILE %s", fname); + } trace_inject_traceparent(); } @@ -250,6 +262,10 @@ static void trace_emit(struct span *s) tal_append_fmt(&res, "}, \"traceId\": \"%s\"}]", trace_id); DTRACE_PROBE2(lightningd, span_emit, span_id, res); + if (trace_to_file) { + fprintf(trace_to_file, "span_emit %s %s\n", span_id, res); + fflush(trace_to_file); + } tal_free(res); } @@ -301,6 +317,12 @@ void trace_span_start(const char *name, const void *key) current = s; trace_check_tree(); DTRACE_PROBE1(lightningd, span_start, s->id); + if (trace_to_file) { + char span_id[HEX_SPAN_ID_SIZE]; + hex_encode(s->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); + fprintf(trace_to_file, "span_start %s\n", span_id); + fflush(trace_to_file); + } } void trace_span_remote(u8 trace_id[TRACE_ID_SIZE], u8 span_id[SPAN_ID_SIZE]) @@ -323,6 +345,12 @@ void trace_span_end(const void *key) 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); + if (trace_to_file) { + char span_id[HEX_SPAN_ID_SIZE]; + hex_encode(s->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); + fprintf(trace_to_file, "span_end %s\n", span_id); + fflush(trace_to_file); + } trace_emit(s); /* Reset the context span we are in. */ @@ -375,6 +403,12 @@ void trace_span_suspend_(const void *key, const char *lbl) span->suspended = true; current = NULL; DTRACE_PROBE1(lightningd, span_suspend, span->id); + if (trace_to_file) { + char span_id[HEX_SPAN_ID_SIZE]; + hex_encode(span->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); + fprintf(trace_to_file, "span_suspend %s\n", span_id); + fflush(trace_to_file); + } } static void destroy_trace_span(const void *key) @@ -387,6 +421,8 @@ static void destroy_trace_span(const void *key) return; /* Otherwise resume so we can terminate it */ + if (trace_to_file) + fprintf(trace_to_file, "destroying span\n"); trace_span_resume(key); trace_span_end(key); } @@ -410,6 +446,12 @@ void trace_span_resume_(const void *key, const char *lbl) 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) { + char span_id[HEX_SPAN_ID_SIZE]; + hex_encode(current->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); + fprintf(trace_to_file, "span_resume %s\n", span_id); + fflush(trace_to_file); + } } void trace_cleanup(void) diff --git a/tests/test_misc.py b/tests/test_misc.py index a8547e0c7ff6..3a5232f45df8 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -13,6 +13,7 @@ ) import copy +import glob import json import os import pytest @@ -4697,3 +4698,56 @@ def test_bolt12_invoice_decode(node_factory): assert l1.rpc.decode(inv)['valid'] is True subprocess.run(["devtools/bolt12-cli", "decode", inv], check=True) + + +@unittest.skipIf(env('HAVE_USDT') != '1', "Test requires tracing compiled in") +def test_tracing(node_factory): + l1 = node_factory.get_node(start=False) + trace_fnamebase = os.path.join(l1.daemon.lightning_dir, TEST_NETWORK, "l1.trace") + l1.daemon.env["CLN_DEV_TRACE_FILE"] = trace_fnamebase + l1.start() + l1.stop() + + traces = set() + suspended = set() + for fname in glob.glob(f"{trace_fnamebase}.*"): + for linenum, l in enumerate(open(fname, "rt").readlines(), 1): + # In case an assertion fails + print(f"Parsing {fname}:{linenum}") + parts = l.split(maxsplit=2) + cmd = parts[0] + spanid = parts[1] + if cmd == 'span_emit': + assert spanid in traces + assert spanid not in suspended + # Should be valid JSON + res = json.loads(parts[2]) + + # This is an array for some reason + assert len(res) == 1 + res = res[0] + assert res['id'] == spanid + assert res['localEndpoint'] == {"serviceName": "lightningd"} + expected_keys = ['id', 'name', 'timestamp', 'duration', 'tags', 'traceId', 'localEndpoint'] + if 'parentId' in res: + assert res['parentId'] in traces + expected_keys.append('parentId') + assert set(res.keys()) == set(expected_keys) + traces.remove(spanid) + elif cmd == 'span_end': + assert spanid in traces + elif cmd == 'span_start': + assert spanid not in traces + traces.add(spanid) + elif cmd == 'span_suspend': + assert spanid in traces + assert spanid not in suspended + suspended.add(spanid) + elif cmd == 'span_resume': + assert spanid in traces + suspended.remove(spanid) + else: + assert False, "Unknown trace line" + + assert suspended == set() + assert traces == set() From 77b52479a41e7a7cb9e0ca947cf7115ec4c134d9 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 23 Apr 2025 10:24:32 +0930 Subject: [PATCH 04/10] trace: fix parent handling (and test it!). Testing parenting handling revealed several issues: 1. By calling "trace_span_start" when CLN_TRACEPARENT is set produces a bogus entry, for which the span_id is overwritten so we never end it. 2. We don't need to close the remote parent when we close the first child: in fact, this causes the remaining traces to be detached from the parent! 3. Suspension should return current to the parent, not to NULL. Now the traces balance as we expect. Signed-off-by: Rusty Russell --- common/trace.c | 70 +++++++++++++++++++++++++--------------------- tests/test_misc.py | 24 ++++++++++++++++ 2 files changed, 62 insertions(+), 32 deletions(-) diff --git a/common/trace.c b/common/trace.c index c92a82dd4140..d0a705c7be2e 100644 --- a/common/trace.c +++ b/common/trace.c @@ -82,6 +82,36 @@ struct span { static struct span *active_spans = NULL; static struct span *current; +static void init_span(struct span *s, + size_t key, + const char *name, + struct span *parent) +{ + struct timeabs now = time_now(); + + s->key = key; + randombytes_buf(s->id, SPAN_ID_SIZE); + s->start_time = (now.ts.tv_sec * 1000000) + now.ts.tv_nsec / 1000; + s->parent = parent; + s->tags = notleak(tal_arr(NULL, struct span_tag, 0)); + s->name = notleak(tal_strdup(NULL, name)); + s->suspended = false; + + /* If this is a new root span we also need to associate a new + * trace_id with it. */ + if (!s->parent) { + randombytes_buf(s->trace_id, TRACE_ID_SIZE); + } else { + memcpy(s->parent_id, parent->id, SPAN_ID_SIZE); + memcpy(s->trace_id, parent->trace_id, TRACE_ID_SIZE); + } +} + +/* FIXME: forward decls for minimal patch size */ +static struct span *trace_span_slot(void); +static size_t trace_key(const void *key); +static void trace_span_clear(struct span *s); + /* If the `CLN_TRACEPARENT` envvar is set, we inject that as the * parent for the startup. This allows us to integrate the startup * tracing with whatever tooling we build around it. This only has an @@ -95,7 +125,10 @@ static void trace_inject_traceparent(void) return; assert(strlen(traceparent) == TRACEPARENT_LEN); - trace_span_start("", active_spans); + current = trace_span_slot(); + assert(current); + + init_span(current, trace_key(active_spans), "", NULL); current->remote = true; assert(current && !current->parent); if (!hex_decode(traceparent + 3, 2*TRACE_ID_SIZE, current->trace_id, @@ -104,7 +137,8 @@ static void trace_inject_traceparent(void) SPAN_ID_SIZE)) { /* We failed to parse the traceparent, abandon. */ fprintf(stderr, "Failed!"); - trace_span_end(active_spans); + trace_span_clear(current); + current = NULL; } } @@ -191,9 +225,6 @@ static struct span *trace_span_find(size_t key) return NULL; } -/* FIXME: Forward declaration for minimal patch size */ -static void trace_span_clear(struct span *s); - /** * Find an empty slot for a new span. */ @@ -286,7 +317,6 @@ static void trace_span_clear(struct span *s) void trace_span_start(const char *name, const void *key) { size_t numkey = trace_key(key); - struct timeabs now = time_now(); if (disable_trace) return; @@ -297,23 +327,7 @@ void trace_span_start(const char *name, const void *key) struct span *s = trace_span_slot(); if (!s) return; - s->key = numkey; - randombytes_buf(s->id, SPAN_ID_SIZE); - 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)); - s->suspended = false; - - /* If this is a new root span we also need to associate a new - * trace_id with it. */ - if (!current) { - randombytes_buf(s->trace_id, TRACE_ID_SIZE); - } else { - memcpy(s->parent_id, current->id, SPAN_ID_SIZE); - memcpy(s->trace_id, current->trace_id, TRACE_ID_SIZE); - } - + init_span(s, numkey, name, current); current = s; trace_check_tree(); DTRACE_PROBE1(lightningd, span_start, s->id); @@ -358,14 +372,6 @@ void trace_span_end(const void *key) /* Now reset the span */ trace_span_clear(s); - - /* One last special case: if the parent is remote, it must be - * the root. And we should terminate that trace along with - * this one. */ - if (current && current->remote) { - assert(current->parent == NULL); - current = NULL; - } trace_check_tree(); } @@ -401,7 +407,7 @@ void trace_span_suspend_(const void *key, const char *lbl) assert(current == span); assert(!span->suspended); span->suspended = true; - current = NULL; + current = current->parent; DTRACE_PROBE1(lightningd, span_suspend, span->id); if (trace_to_file) { char span_id[HEX_SPAN_ID_SIZE]; diff --git a/tests/test_misc.py b/tests/test_misc.py index 3a5232f45df8..bacaaab93252 100644 --- a/tests/test_misc.py +++ b/tests/test_misc.py @@ -4751,3 +4751,27 @@ def test_tracing(node_factory): assert suspended == set() assert traces == set() + + # Test parent trace + trace_fnamebase = os.path.join(l1.daemon.lightning_dir, TEST_NETWORK, "l1.parent.trace") + l1.daemon.env["CLN_DEV_TRACE_FILE"] = trace_fnamebase + l1.daemon.env["CLN_TRACEPARENT"] = "00-00112233445566778899aabbccddeeff-0123456789abcdef-00" + l1.start() + l1.stop() + + # The parent should set all the trace ids and span ids + for fname in glob.glob(f"{trace_fnamebase}.*"): + for linenum, l in enumerate(open(fname, "rt").readlines(), 1): + # In case an assertion fails + print(f"Parsing {fname}:{linenum}") + parts = l.split(maxsplit=2) + cmd = parts[0] + spanid = parts[1] + # This span doesn't actually appear anywhere + assert spanid != '0123456789abcdef' + if cmd == 'span_emit': + # Should be valid JSON + res = json.loads(parts[2]) + assert res[0]['traceId'] == '00112233445566778899aabbccddeeff' + # Everyone has a parent! + assert 'parentId' in res[0] From 7f59b9c4a77506548f1e4b4775cd2b46fa81a08a Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 23 Apr 2025 10:24:40 +0930 Subject: [PATCH 05/10] trace: don't copy strings where we don't need to. 1. trace_span_start() is always called with a string literal, so no copy needed (and we can use a macro to enforce this). 2. trace_span_tag() name and value are always longer-lived than the span, so no need to copy these either. Before: real 0m18.524000-19.100000(18.7674+/-0.21)s user 0m16.171000-16.833000(16.424+/-0.26)s sys 0m2.259000-2.400000(2.337+/-0.059)s After: real 0m16.421000-18.407000(17.8128+/-0.72)s user 0m14.242000-16.041000(15.5382+/-0.67)s sys 0m2.179000-2.363000(2.273+/-0.061)s Signed-off-by: Rusty Russell --- common/trace.c | 13 +++++++------ common/trace.h | 4 +++- lightningd/test/run-find_my_abspath.c | 6 +++--- lightningd/test/run-jsonrpc.c | 6 +++--- plugins/test/run-route-calc.c | 6 +++--- plugins/test/run-route-overlong.c | 6 +++--- 6 files changed, 22 insertions(+), 19 deletions(-) diff --git a/common/trace.c b/common/trace.c index d0a705c7be2e..dec354916137 100644 --- a/common/trace.c +++ b/common/trace.c @@ -68,7 +68,7 @@ struct span { size_t key; struct span *parent; struct span_tag *tags; - char *name; + const char *name; bool suspended; /* Indicate whether this is a remote span, i.e., it was @@ -94,7 +94,7 @@ static void init_span(struct span *s, s->start_time = (now.ts.tv_sec * 1000000) + now.ts.tv_nsec / 1000; s->parent = parent; s->tags = notleak(tal_arr(NULL, struct span_tag, 0)); - s->name = notleak(tal_strdup(NULL, name)); + s->name = name; s->suspended = false; /* If this is a new root span we also need to associate a new @@ -308,13 +308,13 @@ static void trace_span_clear(struct span *s) s->key = 0; memset(s->id, 0, SPAN_ID_SIZE); memset(s->trace_id, 0, TRACE_ID_SIZE); - ; + s->parent = NULL; - s->name = tal_free(s->name); + s->name = NULL; s->tags = tal_free(s->tags); } -void trace_span_start(const char *name, const void *key) +void trace_span_start_(const char *name, const void *key) { size_t numkey = trace_key(key); @@ -380,6 +380,7 @@ void trace_span_tag(const void *key, const char *name, const char *value) if (disable_trace) return; + assert(name); size_t numkey = trace_key(key); struct span *span = trace_span_find(numkey); assert(span); @@ -468,7 +469,7 @@ void trace_cleanup(void) #else /* HAVE_USDT */ -void trace_span_start(const char *name, const void *key) {} +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) {} diff --git a/common/trace.h b/common/trace.h index d8996684b9d7..3c299e84b9a2 100644 --- a/common/trace.h +++ b/common/trace.h @@ -7,7 +7,9 @@ #define TRACE_ID_SIZE 16 #undef TRACE_DEBUG -void trace_span_start(const char *name, const void *key); +/* name must be a string constant */ +#define trace_span_start(name, key) trace_span_start_(name "", (key)) +void trace_span_start_(const char *name, const void *key); void trace_span_end(const void *key); void trace_span_tag(const void *key, const char *name, const char *value); void trace_cleanup(void); diff --git a/lightningd/test/run-find_my_abspath.c b/lightningd/test/run-find_my_abspath.c index 59b0b80f57a8..47e5553b0727 100644 --- a/lightningd/test/run-find_my_abspath.c +++ b/lightningd/test/run-find_my_abspath.c @@ -269,9 +269,9 @@ void trace_span_end(const void *key UNNEEDED) /* Generated stub for trace_span_resume_ */ void trace_span_resume_(const void *key UNNEEDED, const char *lbl UNNEEDED) { fprintf(stderr, "trace_span_resume_ 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_start_ */ +void trace_span_start_(const char *name UNNEEDED, const void *key UNNEEDED) +{ fprintf(stderr, "trace_span_start_ called!\n"); abort(); } /* Generated stub for txfilter_add_derkey */ void txfilter_add_derkey(struct txfilter *filter UNNEEDED, const u8 derkey[PUBKEY_CMPR_LEN]) diff --git a/lightningd/test/run-jsonrpc.c b/lightningd/test/run-jsonrpc.c index f337c24e35b4..cf064ca891a4 100644 --- a/lightningd/test/run-jsonrpc.c +++ b/lightningd/test/run-jsonrpc.c @@ -176,9 +176,9 @@ void towire_node_id(u8 **pptr UNNEEDED, const struct node_id *id UNNEEDED) /* 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_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(); } diff --git a/plugins/test/run-route-calc.c b/plugins/test/run-route-calc.c index b9b575991c52..a0bdda823448 100644 --- a/plugins/test/run-route-calc.c +++ b/plugins/test/run-route-calc.c @@ -326,9 +326,9 @@ void towire_channel_id(u8 **pptr UNNEEDED, const struct channel_id *channel_id U /* 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_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(); } diff --git a/plugins/test/run-route-overlong.c b/plugins/test/run-route-overlong.c index d07c328c6f54..da6f0a607a03 100644 --- a/plugins/test/run-route-overlong.c +++ b/plugins/test/run-route-overlong.c @@ -323,9 +323,9 @@ void towire_channel_id(u8 **pptr UNNEEDED, const struct channel_id *channel_id U /* 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_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(); } From 038a11beadc845ec9266b272209feb8a8d667dff Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 23 Apr 2025 10:24:40 +0930 Subject: [PATCH 06/10] trace: we only ever add two tags, so use a static array. Avoids allocations. Also assume that name and value parameters outlive the trace span, so don't copy. Before: real 0m16.421000-18.407000(17.8128+/-0.72)s user 0m14.242000-16.041000(15.5382+/-0.67)s sys 0m2.179000-2.363000(2.273+/-0.061)s After: real 0m13.441000-14.592000(14.2686+/-0.43)s user 0m11.265000-12.289000(11.9626+/-0.37)s sys 0m2.175000-2.381000(2.3048+/-0.072)s Signed-off-by: Rusty Russell --- common/trace.c | 46 ++++++++++++++++++++++++++++++---------------- 1 file changed, 30 insertions(+), 16 deletions(-) diff --git a/common/trace.c b/common/trace.c index dec354916137..feffc38bf3b5 100644 --- a/common/trace.c +++ b/common/trace.c @@ -46,8 +46,12 @@ const char *trace_service_name = "lightningd"; static bool disable_trace = false; static FILE *trace_to_file = NULL; +#define SPAN_MAX_TAGS 2 + struct span_tag { - char *name, *value; + const char *name; + const char *valuestr; + int valuelen; }; struct span { @@ -67,7 +71,7 @@ struct span { * spans. */ size_t key; struct span *parent; - struct span_tag *tags; + struct span_tag tags[SPAN_MAX_TAGS]; const char *name; bool suspended; @@ -93,7 +97,6 @@ static void init_span(struct span *s, randombytes_buf(s->id, SPAN_ID_SIZE); s->start_time = (now.ts.tv_sec * 1000000) + now.ts.tv_nsec / 1000; s->parent = parent; - s->tags = notleak(tal_arr(NULL, struct span_tag, 0)); s->name = name; s->suspended = false; @@ -286,9 +289,13 @@ static void trace_emit(struct span *s) } 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); + for (size_t i = 0; i < SPAN_MAX_TAGS; i++) { + if (!s->tags[i].name) + continue; + tal_append_fmt(&res, "%s\"%s\": \"%.*s\"", i == 0 ? "" : ", ", + s->tags[i].name, + s->tags[i].valuelen, + s->tags[i].valuestr); } tal_append_fmt(&res, "}, \"traceId\": \"%s\"}]", trace_id); @@ -311,7 +318,8 @@ static void trace_span_clear(struct span *s) s->parent = NULL; s->name = NULL; - s->tags = tal_free(s->tags); + for (size_t i = 0; i < SPAN_MAX_TAGS; i++) + s->tags[i].name = NULL; } void trace_span_start_(const char *name, const void *key) @@ -385,16 +393,22 @@ void trace_span_tag(const void *key, const char *name, const char *value) 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); - if (strstarts(value, "\"") - && strlen(value) > 1 - && strends(value, "\"")) { - value = tal_strndup(tmpctx, value + 1, - strlen(value) - 2); + for (size_t i = 0; i < SPAN_MAX_TAGS; i++) { + struct span_tag *t = &span->tags[i]; + if (!t->name) { + t->name = name; + t->valuestr = value; + t->valuelen = strlen(value); + if (t->valuestr[0] == '"' + && t->valuelen > 1 + && t->valuestr[t->valuelen-1] == '"') { + t->valuestr++; + t->valuelen -= 2; + } + return; + } } - span->tags[s].value = tal_strdup(span->tags, value); + abort(); } void trace_span_suspend_(const void *key, const char *lbl) From 530220823a8a70ce4322a41d5ad43b96a75d99ba Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 23 Apr 2025 10:24:40 +0930 Subject: [PATCH 07/10] trace: use a static buffer instead of tal_fmt(). There's an EBPF limit anyway, so stick with a 512-byte buffer. This brings us back to 621ns per trace: Before: real 0m13.441000-14.592000(14.2686+/-0.43)s user 0m11.265000-12.289000(11.9626+/-0.37)s sys 0m2.175000-2.381000(2.3048+/-0.072)s After: real 0m5.819000-6.472000(6.2064+/-0.26)s user 0m3.779000-4.101000(3.956+/-0.12)s sys 0m2.040000-2.431000(2.2496+/-0.15)s Signed-off-by: Rusty Russell --- common/trace.c | 50 ++++++++++++++++++++++++++++++++------------------ 1 file changed, 32 insertions(+), 18 deletions(-) diff --git a/common/trace.c b/common/trace.c index feffc38bf3b5..643f014507f4 100644 --- a/common/trace.c +++ b/common/trace.c @@ -257,11 +257,15 @@ static struct span *trace_span_slot(void) return s; } +#define MAX_BUF_SIZE 2048 + static void trace_emit(struct span *s) { char span_id[HEX_SPAN_ID_SIZE]; char trace_id[HEX_TRACE_ID_SIZE]; char parent_span_id[HEX_SPAN_ID_SIZE]; + char buffer[MAX_BUF_SIZE + 1]; + size_t len; /* If this is a remote span it's not up to us to emit it. Make * this a no-op. `trace_span_end` will take care of cleaning @@ -275,36 +279,46 @@ static void trace_emit(struct span *s) if (s->parent) hex_encode(s->parent_id, SPAN_ID_SIZE, parent_span_id, HEX_SPAN_ID_SIZE); - char *res = tal_fmt( - NULL, - "[{\"id\": \"%s\", \"name\": \"%s\", " - "\"timestamp\": %" PRIu64 ", \"duration\": %" PRIu64 ",", - span_id, s->name, s->start_time, s->end_time - s->start_time); - - tal_append_fmt(&res, "\"localEndpoint\": { \"serviceName\": \"%s\"}, ", - trace_service_name); + len = snprintf(buffer, MAX_BUF_SIZE, + "[{\"id\":\"%s\",\"name\":\"%s\"," + "\"timestamp\":%"PRIu64",\"duration\":%"PRIu64"," + "\"localEndpoint\":{\"serviceName\":\"%s\"},", + span_id, s->name, s->start_time, s->end_time - s->start_time, trace_service_name); if (s->parent != NULL) { - tal_append_fmt(&res, "\"parentId\": \"%s\",", parent_span_id); + len += snprintf(buffer + len, MAX_BUF_SIZE - len, + "\"parentId\":\"%s\",", + parent_span_id); + if (len > MAX_BUF_SIZE) + len = MAX_BUF_SIZE; } - tal_append_fmt(&res, "\"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; - tal_append_fmt(&res, "%s\"%s\": \"%.*s\"", i == 0 ? "" : ", ", - s->tags[i].name, - s->tags[i].valuelen, - s->tags[i].valuestr); + len += snprintf(buffer + len, MAX_BUF_SIZE - len, + "%s\"%s\":\"%.*s\"", i == 0 ? "" : ", ", + s->tags[i].name, + s->tags[i].valuelen, + s->tags[i].valuestr); + if (len > MAX_BUF_SIZE) + len = MAX_BUF_SIZE; } - tal_append_fmt(&res, "}, \"traceId\": \"%s\"}]", trace_id); - DTRACE_PROBE2(lightningd, span_emit, span_id, res); + len += snprintf(buffer + len, MAX_BUF_SIZE - len, + "},\"traceId\":\"%s\"}]", trace_id); + if (len > MAX_BUF_SIZE) + len = MAX_BUF_SIZE; + buffer[len] = '\0'; + DTRACE_PROBE2(lightningd, span_emit, span_id, buffer); if (trace_to_file) { - fprintf(trace_to_file, "span_emit %s %s\n", span_id, res); + fprintf(trace_to_file, "span_emit %s %s\n", span_id, buffer); fflush(trace_to_file); } - tal_free(res); } /** From 7cda94271dae529fda07981bb41ba987f28b8b00 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 23 Apr 2025 10:24:40 +0930 Subject: [PATCH 08/10] trace: don't use randombytes_buf(), use pseudorand. This is much faster to give 64 bits of data, and we don't need cryptographic randomness. This brings us back to 413ns per trace. Before: real 0m5.819000-6.472000(6.2064+/-0.26)s user 0m3.779000-4.101000(3.956+/-0.12)s sys 0m2.040000-2.431000(2.2496+/-0.15)s After: real 0m3.981000-4.247000(4.1276+/-0.11)s user 0m3.979000-4.245000(4.126+/-0.11)s sys 0m0.000000-0.002000(0.001+/-0.00063)s Signed-off-by: Rusty Russell Changelog-Fixed: lightingd: trimmed overhead of tracing infrastructure. --- common/test/Makefile | 1 + common/trace.c | 84 +++++++++++++------------------- common/trace.h | 4 +- plugins/bkpr/test/run-bkpr_db.c | 3 ++ plugins/bkpr/test/run-recorder.c | 3 ++ 5 files changed, 43 insertions(+), 52 deletions(-) diff --git a/common/test/Makefile b/common/test/Makefile index 444803342f99..75331d62e6dc 100644 --- a/common/test/Makefile +++ b/common/test/Makefile @@ -118,6 +118,7 @@ common/test/run-splice_script: \ common/test/run-trace: \ common/amount.o \ common/memleak.o \ + common/pseudorand.o \ common/trace.o \ wire/fromwire.o \ wire/towire.o diff --git a/common/trace.c b/common/trace.c index 643f014507f4..0bf90d5287da 100644 --- a/common/trace.c +++ b/common/trace.c @@ -1,5 +1,6 @@ #include "config.h" #include +#include #include #include #include @@ -8,9 +9,9 @@ #include #include #include +#include #include #include -#include #include #include @@ -19,9 +20,6 @@ #define MAX_ACTIVE_SPANS 128 -#define HEX_SPAN_ID_SIZE (2*SPAN_ID_SIZE+1) -#define HEX_TRACE_ID_SIZE (2 * TRACE_ID_SIZE + 1) - /* The traceperent format is defined in W3C Trace Context RFC[1]. * Its format is defined as * @@ -56,13 +54,13 @@ struct span_tag { struct span { /* Our own id */ - u8 id[SPAN_ID_SIZE]; + u64 id; /* 0 if we have no parent. */ - u8 parent_id[SPAN_ID_SIZE]; + u64 parent_id; /* The trace_id for this span and all its children. */ - u8 trace_id[TRACE_ID_SIZE]; + u64 trace_id_hi, trace_id_lo; u64 start_time; u64 end_time; @@ -94,7 +92,7 @@ static void init_span(struct span *s, struct timeabs now = time_now(); s->key = key; - randombytes_buf(s->id, SPAN_ID_SIZE); + s->id = pseudorand_u64(); s->start_time = (now.ts.tv_sec * 1000000) + now.ts.tv_nsec / 1000; s->parent = parent; s->name = name; @@ -103,10 +101,12 @@ static void init_span(struct span *s, /* If this is a new root span we also need to associate a new * trace_id with it. */ if (!s->parent) { - randombytes_buf(s->trace_id, TRACE_ID_SIZE); + s->trace_id_hi = pseudorand_u64(); + s->trace_id_lo = pseudorand_u64(); } else { - memcpy(s->parent_id, parent->id, SPAN_ID_SIZE); - memcpy(s->trace_id, parent->trace_id, TRACE_ID_SIZE); + s->parent_id = current->id; + s->trace_id_hi = current->trace_id_hi; + s->trace_id_lo = current->trace_id_lo; } } @@ -122,7 +122,9 @@ static void trace_span_clear(struct span *s); * own parent. */ static void trace_inject_traceparent(void) { - char *traceparent; + const char *traceparent; + be64 trace_hi, trace_lo, span; + traceparent = getenv("CLN_TRACEPARENT"); if (!traceparent) return; @@ -134,14 +136,18 @@ static void trace_inject_traceparent(void) init_span(current, trace_key(active_spans), "", NULL); current->remote = true; assert(current && !current->parent); - if (!hex_decode(traceparent + 3, 2*TRACE_ID_SIZE, current->trace_id, - TRACE_ID_SIZE) || - !hex_decode(traceparent + 36, 2*SPAN_ID_SIZE, current->id, - SPAN_ID_SIZE)) { + + 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); current = NULL; + } else { + current->trace_id_hi = be64_to_cpu(trace_hi); + current->trace_id_lo = be64_to_cpu(trace_lo); + current->id = be64_to_cpu(span); } } @@ -261,9 +267,7 @@ static struct span *trace_span_slot(void) static void trace_emit(struct span *s) { - char span_id[HEX_SPAN_ID_SIZE]; - char trace_id[HEX_TRACE_ID_SIZE]; - char parent_span_id[HEX_SPAN_ID_SIZE]; + char span_id[hex_str_size(sizeof(s->id))]; char buffer[MAX_BUF_SIZE + 1]; size_t len; @@ -273,12 +277,7 @@ static void trace_emit(struct span *s) if (s->remote) return; - hex_encode(s->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); - hex_encode(s->trace_id, TRACE_ID_SIZE, trace_id, HEX_TRACE_ID_SIZE); - - if (s->parent) - hex_encode(s->parent_id, SPAN_ID_SIZE, parent_span_id, HEX_SPAN_ID_SIZE); - + snprintf(span_id, sizeof(span_id), "%016"PRIx64, s->id); len = snprintf(buffer, MAX_BUF_SIZE, "[{\"id\":\"%s\",\"name\":\"%s\"," "\"timestamp\":%"PRIu64",\"duration\":%"PRIu64"," @@ -287,8 +286,8 @@ static void trace_emit(struct span *s) if (s->parent != NULL) { len += snprintf(buffer + len, MAX_BUF_SIZE - len, - "\"parentId\":\"%s\",", - parent_span_id); + "\"parentId\":\"%016"PRIx64"\",", + s->parent_id); if (len > MAX_BUF_SIZE) len = MAX_BUF_SIZE; } @@ -310,10 +309,12 @@ static void trace_emit(struct span *s) } len += snprintf(buffer + len, MAX_BUF_SIZE - len, - "},\"traceId\":\"%s\"}]", trace_id); + "},\"traceId\":\"%016"PRIx64"%016"PRIx64"\"}]", + s->trace_id_hi, s->trace_id_lo); if (len > MAX_BUF_SIZE) len = MAX_BUF_SIZE; buffer[len] = '\0'; + /* FIXME: span_id here is in hex, could be u64? */ DTRACE_PROBE2(lightningd, span_emit, span_id, buffer); if (trace_to_file) { fprintf(trace_to_file, "span_emit %s %s\n", span_id, buffer); @@ -326,14 +327,7 @@ static void trace_emit(struct span *s) */ static void trace_span_clear(struct span *s) { - s->key = 0; - memset(s->id, 0, SPAN_ID_SIZE); - memset(s->trace_id, 0, TRACE_ID_SIZE); - - s->parent = NULL; - s->name = NULL; - for (size_t i = 0; i < SPAN_MAX_TAGS; i++) - s->tags[i].name = NULL; + memset(s, 0, sizeof(*s)); } void trace_span_start_(const char *name, const void *key) @@ -354,14 +348,12 @@ void trace_span_start_(const char *name, const void *key) trace_check_tree(); DTRACE_PROBE1(lightningd, span_start, s->id); if (trace_to_file) { - char span_id[HEX_SPAN_ID_SIZE]; - hex_encode(s->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); - fprintf(trace_to_file, "span_start %s\n", span_id); + fprintf(trace_to_file, "span_start %016"PRIx64"\n", s->id); fflush(trace_to_file); } } -void trace_span_remote(u8 trace_id[TRACE_ID_SIZE], u8 span_id[SPAN_ID_SIZE]) +void trace_span_remote(u64 trace_id_hi, u64 trade_id_lo, u64 span_id) { abort(); } @@ -382,9 +374,7 @@ void trace_span_end(const void *key) s->end_time = (now.ts.tv_sec * 1000000) + now.ts.tv_nsec / 1000; DTRACE_PROBE1(lightningd, span_end, s->id); if (trace_to_file) { - char span_id[HEX_SPAN_ID_SIZE]; - hex_encode(s->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); - fprintf(trace_to_file, "span_end %s\n", span_id); + fprintf(trace_to_file, "span_end %016"PRIx64"\n", s->id); fflush(trace_to_file); } trace_emit(s); @@ -439,9 +429,7 @@ void trace_span_suspend_(const void *key, const char *lbl) current = current->parent; DTRACE_PROBE1(lightningd, span_suspend, span->id); if (trace_to_file) { - char span_id[HEX_SPAN_ID_SIZE]; - hex_encode(span->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); - fprintf(trace_to_file, "span_suspend %s\n", span_id); + fprintf(trace_to_file, "span_suspend %016"PRIx64"\n", span->id); fflush(trace_to_file); } } @@ -482,9 +470,7 @@ void trace_span_resume_(const void *key, const char *lbl) TRACE_DBG("Resuming span %s (%zu)\n", current->name, current->key); DTRACE_PROBE1(lightningd, span_resume, current->id); if (trace_to_file) { - char span_id[HEX_SPAN_ID_SIZE]; - hex_encode(current->id, SPAN_ID_SIZE, span_id, HEX_SPAN_ID_SIZE); - fprintf(trace_to_file, "span_resume %s\n", span_id); + fprintf(trace_to_file, "span_resume %016"PRIx64"\n", current->id); fflush(trace_to_file); } } diff --git a/common/trace.h b/common/trace.h index 3c299e84b9a2..fe3649af58b5 100644 --- a/common/trace.h +++ b/common/trace.h @@ -3,8 +3,6 @@ #include "config.h" #include -#define SPAN_ID_SIZE 8 -#define TRACE_ID_SIZE 16 #undef TRACE_DEBUG /* name must be a string constant */ @@ -13,7 +11,7 @@ void trace_span_start_(const char *name, const void *key); void trace_span_end(const void *key); void trace_span_tag(const void *key, const char *name, const char *value); void trace_cleanup(void); -void trace_span_remote(u8 trace_id[TRACE_ID_SIZE], u8 span_id[SPAN_ID_SIZE]); +void trace_span_remote(u64 trace_id_hi, u64 trade_id_lo, u64 span_id); #define TRACE_LBL __FILE__ ":" stringify(__LINE__) void trace_span_suspend_(const void *key, const char *lbl); diff --git a/plugins/bkpr/test/run-bkpr_db.c b/plugins/bkpr/test/run-bkpr_db.c index 10ba59aea78f..ecf21f1772c7 100644 --- a/plugins/bkpr/test/run-bkpr_db.c +++ b/plugins/bkpr/test/run-bkpr_db.c @@ -219,6 +219,9 @@ bool param_check(struct command *cmd UNNEEDED, const char *buffer UNNEEDED, const jsmntok_t tokens[] UNNEEDED, ...) { fprintf(stderr, "param_check called!\n"); abort(); } +/* Generated stub for pseudorand_u64 */ +uint64_t pseudorand_u64(void) +{ fprintf(stderr, "pseudorand_u64 called!\n"); abort(); } /* Generated stub for toks_alloc */ jsmntok_t *toks_alloc(const tal_t *ctx UNNEEDED) { fprintf(stderr, "toks_alloc called!\n"); abort(); } diff --git a/plugins/bkpr/test/run-recorder.c b/plugins/bkpr/test/run-recorder.c index 16cd8e9b7877..8f46a7eee66f 100644 --- a/plugins/bkpr/test/run-recorder.c +++ b/plugins/bkpr/test/run-recorder.c @@ -225,6 +225,9 @@ bool param_check(struct command *cmd UNNEEDED, const char *buffer UNNEEDED, const jsmntok_t tokens[] UNNEEDED, ...) { fprintf(stderr, "param_check called!\n"); abort(); } +/* Generated stub for pseudorand_u64 */ +uint64_t pseudorand_u64(void) +{ fprintf(stderr, "pseudorand_u64 called!\n"); abort(); } /* Generated stub for toks_alloc */ jsmntok_t *toks_alloc(const tal_t *ctx UNNEEDED) { fprintf(stderr, "toks_alloc called!\n"); abort(); } From e8d79026bb813e4f14826f7e7d9aaa32423041f8 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 23 Apr 2025 10:24:40 +0930 Subject: [PATCH 09/10] common: remove unnecessary parent_id and remote fields. We don't ever actually close the remote span (we don't have its key, after all), and we keep a pointer to the parent. Signed-off-by: Rusty Russell --- common/trace.c | 19 +------------------ 1 file changed, 1 insertion(+), 18 deletions(-) diff --git a/common/trace.c b/common/trace.c index 0bf90d5287da..8fef023a12c9 100644 --- a/common/trace.c +++ b/common/trace.c @@ -56,9 +56,6 @@ struct span { /* Our own id */ u64 id; - /* 0 if we have no parent. */ - u64 parent_id; - /* The trace_id for this span and all its children. */ u64 trace_id_hi, trace_id_lo; @@ -73,12 +70,6 @@ struct span { const char *name; bool suspended; - /* Indicate whether this is a remote span, i.e., it was - inherited by some other process, which is in charge of - emitting the span. This just means that we don't emit this - span ourselves, but we want to add child spans to the remote - span. */ - bool remote; }; static struct span *active_spans = NULL; @@ -104,7 +95,6 @@ static void init_span(struct span *s, s->trace_id_hi = pseudorand_u64(); s->trace_id_lo = pseudorand_u64(); } else { - s->parent_id = current->id; s->trace_id_hi = current->trace_id_hi; s->trace_id_lo = current->trace_id_lo; } @@ -134,7 +124,6 @@ static void trace_inject_traceparent(void) assert(current); init_span(current, trace_key(active_spans), "", NULL); - current->remote = true; assert(current && !current->parent); if (!hex_decode(traceparent + 3, 16, &trace_hi, sizeof(trace_hi)) @@ -271,12 +260,6 @@ static void trace_emit(struct span *s) char buffer[MAX_BUF_SIZE + 1]; size_t len; - /* If this is a remote span it's not up to us to emit it. Make - * this a no-op. `trace_span_end` will take care of cleaning - * the in-memory span up. */ - if (s->remote) - return; - snprintf(span_id, sizeof(span_id), "%016"PRIx64, s->id); len = snprintf(buffer, MAX_BUF_SIZE, "[{\"id\":\"%s\",\"name\":\"%s\"," @@ -287,7 +270,7 @@ static void trace_emit(struct span *s) if (s->parent != NULL) { len += snprintf(buffer + len, MAX_BUF_SIZE - len, "\"parentId\":\"%016"PRIx64"\",", - s->parent_id); + s->parent->id); if (len > MAX_BUF_SIZE) len = MAX_BUF_SIZE; } From 68da93d85aa686419db8def358732cb9d2d6eae8 Mon Sep 17 00:00:00 2001 From: Rusty Russell Date: Wed, 23 Apr 2025 10:24:40 +0930 Subject: [PATCH 10/10] trace: double allocation if we run out. This doesn't happen very often, but can with autoclean. However, we rarely traverse to the end, since we always expect to find what we're looking for, and we fill from the front. So even a large array (unless it's used) is fine. Subtle: when we injected a parent, we used "active_spans" as the (arbitrary) key. That can now change with reallocation, and so if that memory were reused we could have a key clash. So we use "&active_spans" which doesn't change. Signed-off-by: Rusty Russell --- common/trace.c | 35 +++++++++++++++-------------------- 1 file changed, 15 insertions(+), 20 deletions(-) diff --git a/common/trace.c b/common/trace.c index 8fef023a12c9..c65d7f374fec 100644 --- a/common/trace.c +++ b/common/trace.c @@ -2,7 +2,6 @@ #include #include #include -#include #include #include #include @@ -18,8 +17,6 @@ #if HAVE_USDT #include -#define MAX_ACTIVE_SPANS 128 - /* The traceperent format is defined in W3C Trace Context RFC[1]. * Its format is defined as * @@ -123,7 +120,7 @@ static void trace_inject_traceparent(void) current = trace_span_slot(); assert(current); - init_span(current, trace_key(active_spans), "", NULL); + init_span(current, trace_key(&active_spans), "", NULL); assert(current && !current->parent); if (!hex_decode(traceparent + 3, 16, &trace_hi, sizeof(trace_hi)) @@ -145,7 +142,7 @@ static void trace_inject_traceparent(void) /** Quickly print out the entries in the `active_spans`. */ static void trace_spans_print(void) { - for (size_t j = 0; j < MAX_ACTIVE_SPANS; j++) { + for (size_t j = 0; j < tal_count(active_spans); j++) { struct span *s = &active_spans[j], *parent = s->parent; TRACE_DBG(" > %zu: %s (key=%zu, parent=%s, " "parent_key=%zu)\n", @@ -156,17 +153,17 @@ static void trace_spans_print(void) /** Small helper to check for consistency in the linking. The idea is * that we should be able to reach the root (a span without a - * `parent`) in less than `MAX_ACTIVE_SPANS` steps. */ + * `parent`) in less than the number of spans. */ static void trace_check_tree(void) { /* `current` is either NULL or a valid entry. */ /* Walk the tree structure from leaves to their roots. It - * should not take more than `MAX_ACTIVE_SPANS`. */ + * should not take more than the number of spans. */ struct span *c; - for (size_t i = 0; i < MAX_ACTIVE_SPANS; i++) { + for (size_t i = 0; i < tal_count(active_spans); i++) { c = &active_spans[i]; - for (int j = 0; j < MAX_ACTIVE_SPANS; j++) + for (int j = 0; j < tal_count(active_spans); j++) if (c->parent == NULL) break; else @@ -189,7 +186,8 @@ static void trace_init(void) const char *dev_trace_file; if (active_spans) return; - active_spans = calloc(MAX_ACTIVE_SPANS, sizeof(struct span)); + + active_spans = notleak(tal_arrz(NULL, struct span, 1)); current = NULL; dev_trace_file = getenv("CLN_DEV_TRACE_FILE"); @@ -213,7 +211,7 @@ static size_t trace_key(const void *key) static struct span *trace_span_find(size_t key) { - for (size_t i = 0; i < MAX_ACTIVE_SPANS; i++) + for (size_t i = 0; i < tal_count(active_spans); i++) if (active_spans[i].key == key) return &active_spans[i]; @@ -232,14 +230,12 @@ static struct span *trace_span_slot(void) * that, and we should get an empty slot. */ struct span *s = trace_span_find(0); - /* Might end up here if we have more than MAX_ACTIVE_SPANS - * concurrent spans. */ + /* In the unlikely case this fails, double it */ if (!s) { - fprintf(stderr, "%u: out of spans, disabling tracing\n", getpid()); - for (size_t i = 0; i < MAX_ACTIVE_SPANS; i++) - trace_span_clear(&active_spans[i]); - disable_trace = true; - return NULL; + TRACE_DBG("%u: out of %zu spans, doubling!\n", + getpid(), tal_count(active_spans)); + tal_resizez(&active_spans, tal_count(active_spans) * 2); + s = trace_span_find(0); } assert(s->parent == NULL); @@ -460,8 +456,7 @@ void trace_span_resume_(const void *key, const char *lbl) void trace_cleanup(void) { - free(active_spans); - active_spans = NULL; + active_spans = tal_free(active_spans); } #else /* HAVE_USDT */