connectd: report ping latencies (from ping probes) to lightningd.

Signed-off-by: Rusty Russell <rusty@rustcorp.com.au>

Author: rustyrussell

connectd/connectd.c

@@ -2419,6 +2419,7 @@ static struct io_plan *recv_req(struct io_conn *conn,
 	case WIRE_CONNECTD_START_SHUTDOWN_REPLY:
 	case WIRE_CONNECTD_INJECT_ONIONMSG_REPLY:
 	case WIRE_CONNECTD_ONIONMSG_FORWARD_FAIL:
+	case WIRE_CONNECTD_PING_LATENCY:
 		break;
 	}
 

connectd/connectd.h

@@ -96,6 +96,9 @@ struct peer {
 	enum pong_expect_type expecting_pong;
 	u64 ping_reqid;
 
+	/* Timestamp when we initially sent probe ping */
+	struct timemono ping_start;
+
 	/* Random ping timer, to detect dead connections. */
 	struct oneshot *ping_timer;
 

connectd/connectd_wire.csv

@@ -156,6 +156,11 @@ msgdata,connectd_ping_done,sent,bool,
 # 0 == no pong expected, otherwise length of pong.
 msgdata,connectd_ping_done,totlen,u16,
 
+# We give lightningd stats about ping latencies
+msgtype,connectd_ping_latency,2038
+msgdata,connectd_ping_latency,id,node_id,
+msgdata,connectd_ping_latency,ping_nsec,u64,
+
 # We tell lightningd we got an onionmsg
 msgtype,connectd_got_onionmsg_to_us,2145
 msgdata,connectd_got_onionmsg_to_us,path_secret,?secret,

connectd/multiplex.c

@@ -645,6 +645,7 @@ static void send_ping(struct peer *peer)
 		}
 
 		inject_peer_msg(peer, take(make_ping(NULL, 1, 0)));
+		peer->ping_start = time_mono();
 		peer->expecting_pong = PONG_EXPECTED_PROBING;
 	}
 
@@ -719,6 +720,10 @@ static void handle_pong_in(struct peer *peer, const u8 *msg)
 		/* fall thru */
 	case PONG_EXPECTED_PROBING:
 		peer->expecting_pong = PONG_UNEXPECTED;
+		daemon_conn_send(peer->daemon->master,
+				 take(towire_connectd_ping_latency(NULL,
+								   &peer->id,
+								   time_to_nsec(timemono_since(peer->ping_start)))));
 		return;
 	case PONG_UNEXPECTED:
 		status_debug("Unexpected pong?");

lightningd/connect_control.c

@@ -472,6 +472,21 @@ void tell_connectd_peer_importance(struct peer *peer,
 	}
 }
 
+static void handle_ping_latency(struct lightningd *ld, const u8 *msg)
+{
+	struct node_id id;
+	u64 nsec;
+
+	if (!fromwire_connectd_ping_latency(msg, &id, &nsec)) {
+		log_broken(ld->log, "Malformed ping_latency: %s",
+			   tal_hex(tmpctx, msg));
+		return;
+	}
+
+	log_peer_trace(ld->log, &id, "Ping latency: %"PRIu64"nsec",
+		       nsec);
+}
+
 static unsigned connectd_msg(struct subd *connectd, const u8 *msg, const int *fds)
 {
 	enum connectd_wire t = fromwire_peektype(msg);
@@ -537,6 +552,10 @@ static unsigned connectd_msg(struct subd *connectd, const u8 *msg, const int *fd
 	case WIRE_CONNECTD_PING_DONE:
 		handle_ping_done(connectd, msg);
 		break;
+
+	case WIRE_CONNECTD_PING_LATENCY:
+		handle_ping_latency(connectd->ld, msg);
+		break;
 	}
 	return 0;
 }