xpay: add traces for payments

plugins/xpay/xpay.c

@@ -1,4 +1,5 @@
 #include "config.h"
+#include <bitcoin/tx.h>
 #include <ccan/array_size/array_size.h>
 #include <ccan/crypto/siphash24/siphash24.h>
 #include <ccan/htable/htable_type.h>
@@ -21,6 +22,7 @@
 #include <common/pseudorand.h>
 #include <common/randbytes.h>
 #include <common/route.h>
+#include <common/trace.h>
 #include <common/wireaddr.h>
 #include <errno.h>
 #include <inttypes.h>
@@ -1223,6 +1225,8 @@ static struct command_result *injectpaymentonion_failed(struct command *aux_cmd,
 {
 	struct payment *payment = attempt->payment;
 	struct amount_msat amount = attempt->amount;
+	trace_span_resume(attempt);
+	trace_span_end(attempt);
 
 	payment->num_failures++;
 
@@ -1306,6 +1310,8 @@ static struct command_result *injectpaymentonion_succeeded(struct command *aux_c
 {
 	struct preimage preimage;
 	struct payment *payment = attempt->payment;
+	trace_span_resume(attempt);
+	trace_span_end(attempt);
 
 	if (!json_to_preimage(buf,
 			      json_get_member(buf, result, "payment_preimage"),
@@ -1471,6 +1477,12 @@ static struct command_result *do_inject(struct command *aux_cmd,
 
 	outgoing_notify_start(attempt);
 	attempt->start_time = time_mono();
+	trace_span_resume(attempt->payment); // payment is the parent span
+	trace_span_start("xpay/injectpaymentonion", attempt);
+	trace_span_tag(attempt, "partid",
+		       tal_fmt(attempt, "%d", (int)(attempt->partid)));
+	trace_span_suspend(attempt);
+	trace_span_suspend(attempt->payment);
 
 	req = jsonrpc_request_start(aux_cmd,
 				    "injectpaymentonion",
@@ -1604,16 +1616,24 @@ static void add_cltv_shadow(struct payment *payment,
 	}
 }
 
+/* Just a wrapper around payment so that we can trace the execution time of a
+ * getroutes request. */
+struct getroutes_request {
+	struct payment *payment;
+};
+
 static struct command_result *getroutes_done(struct command *aux_cmd,
 					     const char *method,
 					     const char *buf,
 					     const jsmntok_t *result,
-					     struct payment *payment)
+					     struct getroutes_request *getroutes_request)
 {
 	const jsmntok_t *t, *routes;
 	size_t i;
 	struct amount_msat needs_routing, was_routing;
+	struct payment *payment = getroutes_request->payment;
 	struct gossmap *gossmap = get_gossmap(xpay_of(payment->plugin));
+	tal_free(getroutes_request);
 
 	payment_log(payment, LOG_DBG, "getroutes_done: %s",
 		    payment->cmd ? "continuing" : "ignoring");
@@ -1724,8 +1744,10 @@ static struct command_result *getroutes_done_err(struct command *aux_cmd,
 						 const char *method,
 						 const char *buf,
 						 const jsmntok_t *error,
-						 struct payment *payment)
+						 struct getroutes_request *getroutes_request)
 {
+	struct payment *payment = getroutes_request->payment;
+	tal_free(getroutes_request);
 	int code;
 	const char *msg, *complaint;
 
@@ -1854,10 +1876,17 @@ static struct command_result *getroutes_for(struct command *aux_cmd,
 		maxfee = AMOUNT_MSAT(0);
 	}
 
+	struct getroutes_request *getroutes_request =
+	    tal(payment, struct getroutes_request);
+	getroutes_request->payment = payment;
+	trace_span_resume(payment); // payment is the parent span
+	trace_span_start("xpay/getroutes", getroutes_request);
+	trace_span_suspend_may_free(getroutes_request);
+	trace_span_suspend(payment);
 	req = jsonrpc_request_start(aux_cmd, "getroutes",
 				    getroutes_done,
 				    getroutes_done_err,
-				    payment);
+				    getroutes_request);
 
 	json_add_pubkey(req->js, "source", &xpay->local_id);
 	json_add_pubkey(req->js, "destination", dst);
@@ -2427,6 +2456,11 @@ static struct payment *new_payment(const tal_t *ctx,
 {
 	struct xpay *xpay = xpay_of(cmd->plugin);
 	struct payment *payment = tal(ctx, struct payment);
+	/* Start tracing the payment until it is destroyed. */
+	trace_span_start("xpay/payment", payment);
+	trace_span_tag(payment, "payment_hash",
+		       fmt_sha256(payment, payment_hash));
+	trace_span_suspend_may_free(payment);
 
 	payment->plugin = cmd->plugin;
 	payment->deadline = timemono_add(time_mono(), time_from_sec(retryfor));