Add recovery and lock-recover diagnostic trace events.

Add trace events to aid debugging recovery stalls:

  - scoutfs_recov_prepare(sb, rid, which):
    Server registered that a client needs to recover something.

  - scoutfs_recov_finish(sb, rid, which, remaining):
    Client finished one recovery item, and lists remaining count.

  - scoutfs_recov_timeout_fire(sb, nr_pending):
    The 30s recovery window expired, with count of clients that
    failed to recover within the timeout.

  - scoutfs_recov_fence_rid(sb, rid):
    One event per client about to be fenced.

  - scoutfs_lock_server_greeting(sb, rid, recov_pending):
    Shows which rid we expect to recover locks.

Signed-off-by: Auke Kok <auke.kok@versity.com>

kmod/src/lock_server.c

@@ -626,9 +626,14 @@ out:
 int scoutfs_lock_server_greeting(struct super_block *sb, u64 rid)
 {
 	struct scoutfs_key key;
+	bool pending;
 	int ret;
 
-	if (scoutfs_recov_is_pending(sb, rid, SCOUTFS_RECOV_LOCKS)) {
+	pending = scoutfs_recov_is_pending(sb, rid, SCOUTFS_RECOV_LOCKS);
+
+	trace_scoutfs_lock_server_greeting(sb, rid, pending);
+
+	if (pending) {
 		scoutfs_key_set_zeros(&key);
 		ret = scoutfs_server_lock_recover_request(sb, rid, &key);
 	} else {

kmod/src/recov.c

@@ -21,6 +21,7 @@
 #include "super.h"
 #include "recov.h"
 #include "cmp.h"
+#include "scoutfs_trace.h"
 
 /*
  * There are a few server messages which can't be processed until they
@@ -119,6 +120,9 @@ int scoutfs_recov_prepare(struct super_block *sb, u64 rid, int which)
 	spin_unlock_bh(&recinf->lock);
 
 	kfree(alloc);
+
+	trace_scoutfs_recov_prepare(sb, rid, which);
+
 	return 0;
 }
 
@@ -135,6 +139,15 @@ static int recov_finished(struct recov_info *recinf)
 static void timer_callback(struct timer_list *timer)
 {
 	struct recov_info *recinf = timer_container_of(recinf, timer, timer);
+	struct recov_pending *pend;
+	int nr = 0;
+
+	spin_lock(&recinf->lock);
+	list_for_each_entry(pend, &recinf->pending, head)
+		nr++;
+	spin_unlock(&recinf->lock);
+
+	trace_scoutfs_recov_timeout_fire(recinf->sb, nr);
 
 	recinf->timeout_fn(recinf->sb);
 }
@@ -181,6 +194,8 @@ int scoutfs_recov_finish(struct super_block *sb, u64 rid, int which)
 {
 	DECLARE_RECOV_INFO(sb, recinf);
 	struct recov_pending *pend;
+	struct recov_pending *iter;
+	int remaining = 0;
 	int ret = 0;
 
 	spin_lock_bh(&recinf->lock);
@@ -196,8 +211,13 @@ int scoutfs_recov_finish(struct super_block *sb, u64 rid, int which)
 		}
 	}
 
+	list_for_each_entry(iter, &recinf->pending, head)
+		remaining++;
+
 	spin_unlock_bh(&recinf->lock);
 
+	trace_scoutfs_recov_finish(sb, rid, which, remaining);
+
 	if (ret > 0)
 		del_timer_sync(&recinf->timer);
 

kmod/src/scoutfs_trace.h

@@ -2121,6 +2121,110 @@ DEFINE_EVENT(scoutfs_server_client_count_class, scoutfs_server_client_down,
 	TP_ARGS(sb, rid, nr_clients)
 );
 
+TRACE_EVENT(scoutfs_recov_prepare,
+	TP_PROTO(struct super_block *sb, u64 rid, int which),
+
+	TP_ARGS(sb, rid, which),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, c_rid)
+		__field(int, which)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->c_rid = rid;
+		__entry->which = which;
+	),
+
+	TP_printk(SCSBF" rid %016llx which 0x%x",
+		  SCSB_TRACE_ARGS, __entry->c_rid, __entry->which)
+);
+
+TRACE_EVENT(scoutfs_recov_finish,
+	TP_PROTO(struct super_block *sb, u64 rid, int which, int remaining),
+
+	TP_ARGS(sb, rid, which, remaining),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, c_rid)
+		__field(int, which)
+		__field(int, remaining)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->c_rid = rid;
+		__entry->which = which;
+		__entry->remaining = remaining;
+	),
+
+	TP_printk(SCSBF" rid %016llx which 0x%x remaining %d",
+		  SCSB_TRACE_ARGS, __entry->c_rid, __entry->which,
+		  __entry->remaining)
+);
+
+TRACE_EVENT(scoutfs_recov_timeout_fire,
+	TP_PROTO(struct super_block *sb, int nr_pending),
+
+	TP_ARGS(sb, nr_pending),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(int, nr_pending)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->nr_pending = nr_pending;
+	),
+
+	TP_printk(SCSBF" nr_pending %d",
+		  SCSB_TRACE_ARGS, __entry->nr_pending)
+);
+
+TRACE_EVENT(scoutfs_recov_fence_rid,
+	TP_PROTO(struct super_block *sb, u64 rid),
+
+	TP_ARGS(sb, rid),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, c_rid)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->c_rid = rid;
+	),
+
+	TP_printk(SCSBF" rid %016llx",
+		  SCSB_TRACE_ARGS, __entry->c_rid)
+);
+
+TRACE_EVENT(scoutfs_lock_server_greeting,
+	TP_PROTO(struct super_block *sb, u64 rid, bool recov_pending),
+
+	TP_ARGS(sb, rid, recov_pending),
+
+	TP_STRUCT__entry(
+		SCSB_TRACE_FIELDS
+		__field(__u64, c_rid)
+		__field(bool, recov_pending)
+	),
+
+	TP_fast_assign(
+		SCSB_TRACE_ASSIGN(sb);
+		__entry->c_rid = rid;
+		__entry->recov_pending = recov_pending;
+	),
+
+	TP_printk(SCSBF" rid %016llx recov_pending %d",
+		  SCSB_TRACE_ARGS, __entry->c_rid, __entry->recov_pending)
+);
+
 DECLARE_EVENT_CLASS(scoutfs_server_commit_users_class,
         TP_PROTO(struct super_block *sb, int holding, int applying,
 		 int nr_holders, u32 budget,

kmod/src/server.c

@@ -4386,6 +4386,8 @@ static void fence_pending_recov_worker(struct work_struct *work)
 		scoutfs_err(sb, "%lu ms recovery timeout expired for client rid %016llx, fencing",
 			    SERVER_RECOV_TIMEOUT_MS, rid);
 
+		trace_scoutfs_recov_fence_rid(sb, rid);
+
 		ret = lookup_mounted_client_addr(sb, rid, &addr);
 		if (ret < 0) {
 			scoutfs_err(sb, "client rid addr lookup err %d, shutting down server", ret);