scoutfs: add clock sync trace events

Generate unique trace events on the send and recv side of each message
sent between nodes.  This can be used to reasonbly efficiently
synchronize the monotonic clock in trace events between nodes given only
their captured trace events.

Signed-off-by: Zach Brown <zab@versity.com>

kmod/src/format.h

@@ -625,6 +625,7 @@ struct scoutfs_net_greeting {
  * response messages.
  */
 struct scoutfs_net_header {
+	__le64 clock_sync_id;
 	__le64 seq;
 	__le64 recv_seq;
 	__le64 id;

kmod/src/net.c

@@ -656,6 +656,8 @@ static void scoutfs_net_recv_worker(struct work_struct *work)
 			break;
 		}
 
+		trace_scoutfs_recv_clock_sync(nh.clock_sync_id);
+
 		data_len = le16_to_cpu(nh.data_len);
 
 		scoutfs_inc_counter(sb, net_recv_messages);
@@ -798,6 +800,9 @@ static void scoutfs_net_send_worker(struct work_struct *work)
 		trace_scoutfs_net_send_message(sb, &conn->sockname,
 					       &conn->peername, &msend->nh);
 
+		msend->nh.clock_sync_id = scoutfs_clock_sync_id();
+		trace_scoutfs_send_clock_sync(msend->nh.clock_sync_id);
+
 		ret = sendmsg_full(conn->sock, &msend->nh, len);
 
 		spin_lock(&conn->lock);

kmod/src/scoutfs_trace.h

@@ -2513,6 +2513,32 @@ DEFINE_EVENT(scoutfs_quorum_block_class, scoutfs_quorum_write_block,
 	TP_ARGS(sb, io_blkno, blk)
 );
 
+/*
+ * We can emit trace events to make it easier to synchronize the
+ * monotonic clocks in trace logs between nodes.  By looking at the send
+ * and recv times of many messages flowing between nodes we can get
+ * surprisingly good estimates of the clock offset between them.
+ */
+DECLARE_EVENT_CLASS(scoutfs_clock_sync_class,
+	TP_PROTO(__le64 clock_sync_id),
+	TP_ARGS(clock_sync_id),
+	TP_STRUCT__entry(
+		__field(__u64, clock_sync_id)
+	),
+	TP_fast_assign(
+		__entry->clock_sync_id = le64_to_cpu(clock_sync_id);
+	),
+	TP_printk("clock_sync_id %016llx", __entry->clock_sync_id)
+);
+DEFINE_EVENT(scoutfs_clock_sync_class, scoutfs_send_clock_sync,
+	TP_PROTO(__le64 clock_sync_id),
+	TP_ARGS(clock_sync_id)
+);
+DEFINE_EVENT(scoutfs_clock_sync_class, scoutfs_recv_clock_sync,
+	TP_PROTO(__le64 clock_sync_id),
+	TP_ARGS(clock_sync_id)
+);
+
 #endif /* _TRACE_SCOUTFS_H */
 
 /* This part must be outside protection */

kmod/src/super.c

@@ -20,6 +20,7 @@
 #include <linux/statfs.h>
 #include <linux/sched.h>
 #include <linux/debugfs.h>
+#include <linux/percpu.h>
 
 #include "super.h"
 #include "block.h"
@@ -47,6 +48,37 @@
 
 static struct dentry *scoutfs_debugfs_root;
 
+static DEFINE_PER_CPU(u64, clock_sync_ids) = 0;
+
+/*
+ * Give the caller a unique clock sync id for a message they're about to
+ * send.  We make the ids reasonably globally unique by using randomly
+ * initialized per-cpu 64bit counters.
+ */
+__le64 scoutfs_clock_sync_id(void)
+{
+	u64 rnd = 0;
+	u64 ret;
+	u64 *id;
+
+retry:
+	preempt_disable();
+	id = this_cpu_ptr(&clock_sync_ids);
+	if (*id == 0) {
+		if (rnd == 0) {
+			preempt_enable();
+			get_random_bytes(&rnd, sizeof(rnd));
+			goto retry;
+		}
+		*id = rnd;
+	}
+
+	ret = ++(*id);
+	preempt_enable();
+
+	return cpu_to_le64(ret);
+}
+
 /*
  * Ask the server for the current statfs fields.  The message is very
  * cheap so we're not worrying about spinning in statfs flooding the

kmod/src/super.h

@@ -91,4 +91,6 @@ int scoutfs_write_dirty_super(struct super_block *sb);
 /* to keep this out of the ioctl.h public interface definition */
 long scoutfs_ioctl(struct file *file, unsigned int cmd, unsigned long arg);
 
+__le64 scoutfs_clock_sync_id(void);
+
 #endif