xpay: add traces for payments

[Lagrang3]

Produce traces (see common/trace.h) for every payment in order to gather statistics about the duration of a full payment execution.

xpay doesn't spend much time on computation itself. The runtime bottlenecks are always rpc calls to either askrene or lightningd's pay primitives.

The trace hierarchy here takes the following form:

• xpay/fetchinvoice: stand alone trace for the operation of fetching the invoice if xpay receives a BIP353 address or an offer.
• xpay/payment: a whole payment
  -> xpay/getroutes: waiting for askrene-getroutes,
  -> xpay/injectpaymentonion: waiting for the payment onion to return.

[Lagrang3]

@cdecker, are these trace annotations useful? Do you think I should add more tags?

[cdecker]

Very nice change. I'm not sure the back-to-back suspends in line 1485 is correct, but it doesn't matter as all it does is to unset the thread's context.

[Lagrang3]

Very nice change. I'm not sure the back-to-back suspends in line 1485 is correct, but it doesn't matter as all it does is to unset the thread's context.

Yes, please check.
At line 1882: resume payment, brings it into current trace
next: create new trace getroutes with payment as parent, now getroutes is current trace
next: suspend getroutes (we must before rendering execution to the io loop), now payment (the parent) is current,
next: suspend payment

[Lagrang3]

rebased

[Lagrang3]

This test: tests/test_askrene.py:test_reservations_leak_under_load was hitting an access after free of a trace's parent.
I couldn't find the bug but refactored the traces. I think the new version is cleaner.
We keep a root trace for each payment instance, then child traces are added for each call to getroutes and injectpaymentonion. I did not add new code to start and end the traces because libplugin already does that for every jsonrpc
call. I needed only to attach the jsonrpc call trace to parent payment.

[Lagrang3]

I think I fixed this finally.
trace has a simple interface, it also fits perfectly when your application is single threaded.
Here to correctly trace concurrent payment executions you would need to do awkward things.

For example I wanted to measure the time a payment spends waiting for injectpaymentonion.
Before sending the RPC request out we do the following:

// global current trace is assumed to be NULL
// we get control back from the io loop, we resume the current payment
+       trace_span_resume(attempt->payment); // payment is the parent span
// start a new sub-trace for the rpc
+       trace_span_start("xpay/injectpaymentonion", attempt);
+       trace_span_tag(attempt, "partid",
+                      tal_fmt(attempt, "%d", (int)(attempt->partid)));
// before we hand control back to the io loop, we unwind the trace stack
+       trace_span_suspend(attempt);
+       trace_span_suspend(attempt->payment);
// global current trace is back to NULL

in the RPC callback, both error and happy path we do:

// global current trace is assumed to be NULL
// we get control back from the io loop, we resume the current payment
+       trace_span_resume(attempt->payment);
// also resume the trace of the RPC call
+       trace_span_resume(attempt);
// end the RPC trace
+       trace_span_end(attempt);
// again unwind the rest of the trace stack with only one element
+       trace_span_suspend(attempt->payment);
// global current trace is back to NULL