From 0bc0ff9300397a04f44bc913d73d95de9f028db0 Mon Sep 17 00:00:00 2001
From: Zach Brown <zab@versity.com>
Date: Tue, 19 Feb 2019 14:38:12 -0800
Subject: [PATCH] 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        |  1 +
 kmod/src/net.c           |  5 +++++
 kmod/src/scoutfs_trace.h | 26 ++++++++++++++++++++++++++
 kmod/src/super.c         | 32 ++++++++++++++++++++++++++++++++
 kmod/src/super.h         |  2 ++
 5 files changed, 66 insertions(+)

diff --git a/kmod/src/format.h b/kmod/src/format.h
index be2931dc..cf73e6be 100644
--- a/kmod/src/format.h
+++ b/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;
diff --git a/kmod/src/net.c b/kmod/src/net.c
index 6ea3ccd3..98aae7b4 100644
--- a/kmod/src/net.c
+++ b/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);
diff --git a/kmod/src/scoutfs_trace.h b/kmod/src/scoutfs_trace.h
index 0693f1ce..8834d196 100644
--- a/kmod/src/scoutfs_trace.h
+++ b/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 */
diff --git a/kmod/src/super.c b/kmod/src/super.c
index 8149abd1..6e18e219 100644
--- a/kmod/src/super.c
+++ b/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
diff --git a/kmod/src/super.h b/kmod/src/super.h
index 99671dab..e24f4d9a 100644
--- a/kmod/src/super.h
+++ b/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