From 24b44c83f246c874681876d06ab0d1c3cc33fcbf Mon Sep 17 00:00:00 2001
From: Lars Ellenberg <lars.ellenberg@linbit.com>
Date: Tue, 2 Oct 2018 15:03:19 +0200
Subject: [PATCH] drbd: fix regression in request timeout handling

Symptoms:
Frequent messages like
| We did not send a P_BARRIER for 80360848ms > ko-count (7) * timeout (60 * 0.1s); drbd kernel thread blocked?
| Remote failed to finish a request within 80360852ms > ko-count (7) * timeout (60 * 0.1s)
with ridiculous times (which effectively are the uptime)

By introducing CONFIG_DRBD_TIMING_STATS, and disabling it by default,
we deactivated the detailed request timing in 9.0.15.
But still relied on those now initialized-to-zero timestamps
in the request_timer_fn().

Go back to using jiffies there,
for this purpose its granularity is more than good enough.
---
 drbd/drbd_debugfs.c | 51 ++++++++++++++++++++++++++-------------------
 drbd/drbd_int.h     | 49 +++++++++++++++++++++++--------------------
 drbd/drbd_main.c    |  6 ++++--
 drbd/drbd_req.c     | 48 +++++++++++++++++++++++-------------------
 drbd/drbd_sender.c  |  2 ++
 5 files changed, 88 insertions(+), 68 deletions(-)

diff --git a/drbd/drbd_debugfs.c b/drbd/drbd_debugfs.c
index 73160dbf..ac231f6f 100644
--- a/drbd/drbd_debugfs.c
+++ b/drbd/drbd_debugfs.c
@@ -123,7 +123,7 @@ static void print_one_age_or_dash(struct seq_file *m, struct drbd_request *req,
 }
 #endif
 
-static void seq_print_one_request(struct seq_file *m, struct drbd_request *req, ktime_t now)
+static void seq_print_one_request(struct seq_file *m, struct drbd_request *req, ktime_t now, unsigned long jif)
 {
 	/* change anything here, fixup header below! */
 	unsigned int s = req->local_rq_state;
@@ -134,26 +134,30 @@ static void seq_print_one_request(struct seq_file *m, struct drbd_request *req,
 		(unsigned long long)req->i.sector, req->i.size >> 9,
 		(s & RQ_WRITE) ? "W" : "R");
 
+#ifdef CONFIG_DRBD_TIMING_STATS
 #define RQ_HDR_2 "\tstart\tin AL\tsubmit"
-#define RQ_HDR_3 "\tsent\tacked\tdone"
 	seq_printf(m, "\t%d", (int)ktime_to_ms(ktime_sub(now, req->start_kt)));
-#ifdef CONFIG_DRBD_TIMING_STATS
 	seq_print_age_or_dash(m, s & RQ_IN_ACT_LOG, ktime_sub(now, req->in_actlog_kt));
 	seq_print_age_or_dash(m, s & RQ_LOCAL_PENDING, ktime_sub(now, req->pre_submit_kt));
 
+#define RQ_HDR_3 "\tsent\tacked\tdone"
 	print_one_age_or_dash(m, req, RQ_NET_SENT, 0, now, offsetof(typeof(*req), pre_send_kt));
 	print_one_age_or_dash(m, req, RQ_NET_SENT, RQ_NET_PENDING, now, offsetof(typeof(*req), acked_kt));
 	print_one_age_or_dash(m, req, RQ_NET_DONE, 0, now, offsetof(typeof(*req), net_done_kt));
+#else
+#define RQ_HDR_2 "\tstart"
+#define RQ_HDR_3 ""
+	seq_printf(m, "\t%d", (int)jiffies_to_msecs(jif - req->start_jif));
 #endif
 #define RQ_HDR_4 "\tstate\n"
 	seq_print_request_state(m, req);
 }
 #define RQ_HDR RQ_HDR_1 RQ_HDR_2 RQ_HDR_3 RQ_HDR_4
 
-static void seq_print_minor_vnr_req(struct seq_file *m, struct drbd_request *req, ktime_t now)
+static void seq_print_minor_vnr_req(struct seq_file *m, struct drbd_request *req, ktime_t now, unsigned long jif)
 {
 	seq_printf(m, "%u\t%u\t", req->device->minor, req->device->vnr);
-	seq_print_one_request(m, req, now);
+	seq_print_one_request(m, req, now, jif);
 }
 
 static void seq_print_resource_pending_meta_io(struct seq_file *m, struct drbd_resource *resource, unsigned long jif)
@@ -184,7 +188,7 @@ static void seq_print_resource_pending_meta_io(struct seq_file *m, struct drbd_r
 	rcu_read_unlock();
 }
 
-static void seq_print_waiting_for_AL(struct seq_file *m, struct drbd_resource *resource, ktime_t now)
+static void seq_print_waiting_for_AL(struct seq_file *m, struct drbd_resource *resource, ktime_t now, unsigned long jif)
 {
 	struct drbd_device *device;
 	int i;
@@ -192,7 +196,6 @@ static void seq_print_waiting_for_AL(struct seq_file *m, struct drbd_resource *r
 	seq_puts(m, "minor\tvnr\tage\t#waiting\n");
 	rcu_read_lock();
 	idr_for_each_entry(&resource->devices, device, i) {
-		ktime_t ktime;
 		struct drbd_request *req;
 		int n = atomic_read(&device->ap_actlog_cnt);
 		if (n) {
@@ -201,17 +204,19 @@ static void seq_print_waiting_for_AL(struct seq_file *m, struct drbd_resource *r
 				struct drbd_request, req_pending_master_completion);
 			/* if the oldest request does not wait for the activity log
 			 * it is not interesting for us here */
-			if (req && !(req->local_rq_state & RQ_IN_ACT_LOG))
-				ktime = req->start_kt;
-			else
+			if (req && (req->local_rq_state & RQ_IN_ACT_LOG))
 				req = NULL;
 			spin_unlock_irq(&device->resource->req_lock);
 		}
 		if (n) {
 			seq_printf(m, "%u\t%u\t", device->minor, device->vnr);
-			if (req)
-				seq_printf(m, "%d\t", (int)ktime_to_ms(ktime_sub(now, ktime)));
-			else
+			if (req) {
+#ifdef CONFIG_DRBD_TIMING_STATS
+				seq_printf(m, "%d\t", (int)ktime_to_ms(ktime_sub(now, req->start_kt)));
+#else
+				seq_printf(m, "%d\t", (int)jiffies_to_msecs(jif - req->start_jif));
+#endif
+			} else
 				seq_puts(m, "-\t");
 			seq_printf(m, "%u\n", n);
 		}
@@ -345,7 +350,7 @@ static void seq_print_resource_pending_peer_requests(struct seq_file *m,
 static void seq_print_resource_transfer_log_summary(struct seq_file *m,
 	struct drbd_resource *resource,
 	struct drbd_connection *connection,
-	ktime_t now)
+	ktime_t now, unsigned long jif)
 {
 	struct drbd_request *req;
 	unsigned int count = 0;
@@ -400,7 +405,7 @@ static void seq_print_resource_transfer_log_summary(struct seq_file *m,
 			continue;
 		show_state |= tmp;
 		seq_printf(m, "%u\t", count);
-		seq_print_minor_vnr_req(m, req, now);
+		seq_print_minor_vnr_req(m, req, now, jif);
 		if (show_state == 0x1f)
 			break;
 	}
@@ -453,11 +458,11 @@ static int resource_in_flight_summary_show(struct seq_file *m, void *pos)
 	seq_putc(m, '\n');
 
 	seq_puts(m, "application requests waiting for activity log\n");
-	seq_print_waiting_for_AL(m, resource, now);
+	seq_print_waiting_for_AL(m, resource, now, jif);
 	seq_putc(m, '\n');
 
 	seq_puts(m, "oldest application requests\n");
-	seq_print_resource_transfer_log_summary(m, resource, connection, now);
+	seq_print_resource_transfer_log_summary(m, resource, connection, now, jif);
 	seq_putc(m, '\n');
 
 	jif = jiffies - jif;
@@ -760,6 +765,7 @@ static int connection_oldest_requests_show(struct seq_file *m, void *ignored)
 {
 	struct drbd_connection *connection = m->private;
 	ktime_t now = ktime_get();
+	unsigned long jif = jiffies;
 	struct drbd_request *r1, *r2;
 
 	/* BUMP me if you change the file format/content/presentation */
@@ -768,15 +774,15 @@ static int connection_oldest_requests_show(struct seq_file *m, void *ignored)
 	spin_lock_irq(&connection->resource->req_lock);
 	r1 = connection->todo.req_next;
 	if (r1)
-		seq_print_minor_vnr_req(m, r1, now);
+		seq_print_minor_vnr_req(m, r1, now, jif);
 	r2 = connection->req_ack_pending;
 	if (r2 && r2 != r1) {
 		r1 = r2;
-		seq_print_minor_vnr_req(m, r1, now);
+		seq_print_minor_vnr_req(m, r1, now, jif);
 	}
 	r2 = connection->req_not_net_done;
 	if (r2 && r2 != r1)
-		seq_print_minor_vnr_req(m, r2, now);
+		seq_print_minor_vnr_req(m, r2, now, jif);
 	spin_unlock_irq(&connection->resource->req_lock);
 	return 0;
 }
@@ -1005,6 +1011,7 @@ static int device_oldest_requests_show(struct seq_file *m, void *ignored)
 	struct drbd_device *device = m->private;
 	struct drbd_resource *resource = device->resource;
 	ktime_t now = ktime_get();
+	unsigned long jif = jiffies;
 	struct drbd_request *r1, *r2;
 	int i;
 
@@ -1020,9 +1027,9 @@ static int device_oldest_requests_show(struct seq_file *m, void *ignored)
 		r2 = list_first_entry_or_null(&device->pending_completion[i],
 			struct drbd_request, req_pending_local);
 		if (r1)
-			seq_print_one_request(m, r1, now);
+			seq_print_one_request(m, r1, now, jif);
 		if (r2 && r2 != r1)
-			seq_print_one_request(m, r2, now);
+			seq_print_one_request(m, r2, now, jif);
 	}
 	spin_unlock_irq(&resource->req_lock);
 	return 0;
diff --git a/drbd/drbd_int.h b/drbd/drbd_int.h
index de8df2a1..231b0497 100644
--- a/drbd/drbd_int.h
+++ b/drbd/drbd_int.h
@@ -313,57 +313,55 @@ struct drbd_request {
 	struct list_head req_pending_local;
 
 	/* for generic IO accounting */
-	ktime_t start_kt;
-
-	/* for DRBD internal statistics */
-	ktime_t pre_submit_kt;
+	unsigned long start_jif;
 
-	/* per connection */
-	ktime_t pre_send_kt[DRBD_PEERS_MAX];
-
-	/* Minimal set of time stamps to determine if we wait for activity log
-	 * transactions, local disk or peer.  32 bit "jiffies" are good enough,
-	 * we don't expect a DRBD request to be stalled for several month.
-	 */
+	/* for request_timer_fn() */
+	unsigned long pre_submit_jif;
+	unsigned long pre_send_jif[DRBD_PEERS_MAX];
 
 #ifdef CONFIG_DRBD_TIMING_STATS
+	/* for DRBD internal statistics */
+	ktime_t start_kt;
+
 	/* before actual request processing */
 	ktime_t in_actlog_kt;
 
 	/* local disk */
+	ktime_t pre_submit_kt;
 
 	/* per connection */
+	ktime_t pre_send_kt[DRBD_PEERS_MAX];
 	ktime_t acked_kt[DRBD_PEERS_MAX];
 	ktime_t net_done_kt[DRBD_PEERS_MAX];
 #endif
 	/* Possibly even more detail to track each phase:
-	 *  master_completion_jif
+	 *  master_completion_kt
 	 *      how long did it take to complete the master bio
 	 *      (application visible latency)
-	 *  allocated_jif
+	 *  allocated_kt
 	 *      how long the master bio was blocked until we finally allocated
 	 *      a tracking struct
-	 *  in_actlog_jif
+	 *  in_actlog_kt
 	 *      how long did we wait for activity log transactions
 	 *
-	 *  net_queued_jif
+	 *  net_queued_kt
 	 *      when did we finally queue it for sending
-	 *  pre_send_jif
+	 *  pre_send_kt
 	 *      when did we start sending it
-	 *  post_send_jif
+	 *  post_send_kt
 	 *      how long did we block in the network stack trying to send it
-	 *  acked_jif
+	 *  acked_kt
 	 *      when did we receive (or fake, in protocol A) a remote ACK
-	 *  net_done_jif
+	 *  net_done_kt
 	 *      when did we receive final acknowledgement (P_BARRIER_ACK),
 	 *      or decide, e.g. on connection loss, that we do no longer expect
 	 *      anything from this peer for this request.
 	 *
-	 *  pre_submit_jif
-	 *  post_sub_jif
+	 *  pre_submit_kt
+	 *  post_sub_kt
 	 *      when did we start submiting to the lower level device,
 	 *      and how long did we block in that submit function
-	 *  local_completion_jif
+	 *  local_completion_kt
 	 *      how long did it take the lower level device to complete this request
 	 */
 
@@ -1849,7 +1847,10 @@ extern void conn_free_crypto(struct drbd_connection *connection);
 
 /* drbd_req */
 extern void do_submit(struct work_struct *ws);
-extern void __drbd_make_request(struct drbd_device *, struct bio *, ktime_t);
+#ifndef CONFIG_DRBD_TIMING_STATS
+#define __drbd_make_request(d,b,k,j) __drbd_make_request(d,b,j)
+#endif
+extern void __drbd_make_request(struct drbd_device *, struct bio *, ktime_t, unsigned long);
 extern MAKE_REQUEST_TYPE drbd_make_request(struct request_queue *q, struct bio *bio);
 #ifdef COMPAT_HAVE_BLK_QUEUE_MERGE_BVEC
 extern int drbd_merge_bvec(struct request_queue *, struct bvec_merge_data *, struct bio_vec *);
@@ -2816,12 +2817,14 @@ static inline struct drbd_connection *first_connection(struct drbd_resource *res
 #define ktime_aggregate(D, R, M) D->M = ktime_add(D->M, ktime_sub(R->M, R->start_kt))
 #define ktime_aggregate_pd(P, N, R, M) P->M = ktime_add(P->M, ktime_sub(R->M[N], R->start_kt))
 #define ktime_get_accounting(V) V = ktime_get()
+#define ktime_get_accounting_assign(V, T) V = T
 #define ktime_var_for_accounting(V) ktime_t V = ktime_get()
 #else
 #define ktime_aggregate_delta(D, ST, M)
 #define ktime_aggregate(D, R, M)
 #define ktime_aggregate_pd(P, N, R, M)
 #define ktime_get_accounting(V)
+#define ktime_get_accounting_assign(V, T)
 #define ktime_var_for_accounting(V)
 #endif
 
diff --git a/drbd/drbd_main.c b/drbd/drbd_main.c
index 56da6be4..85f38664 100644
--- a/drbd/drbd_main.c
+++ b/drbd/drbd_main.c
@@ -3056,8 +3056,10 @@ static void do_retry(struct work_struct *ws)
 	list_for_each_entry_safe(req, tmp, &writes, tl_requests) {
 		struct drbd_device *device = req->device;
 		struct bio *bio = req->master_bio;
-		ktime_t start_kt = req->start_kt;
+		unsigned long start_jif = req->start_jif;
 		bool expected;
+		ktime_get_accounting_assign(ktime_t start_kt, req->start_kt);
+
 
 		expected =
 			expect(device, atomic_read(&req->completion_ref) == 0) &&
@@ -3091,7 +3093,7 @@ static void do_retry(struct work_struct *ws)
 		/* We are not just doing generic_make_request(),
 		 * as we want to keep the start_time information. */
 		inc_ap_bio(device, bio_data_dir(bio));
-		__drbd_make_request(device, bio, start_kt);
+		__drbd_make_request(device, bio, start_kt, start_jif);
 	}
 }
 
diff --git a/drbd/drbd_req.c b/drbd/drbd_req.c
index 6190970a..a2a6b143 100644
--- a/drbd/drbd_req.c
+++ b/drbd/drbd_req.c
@@ -34,14 +34,6 @@
 
 static bool drbd_may_do_local_read(struct drbd_device *device, sector_t sector, int size);
 
-static inline unsigned long ktime_to_jiffies(ktime_t kt)
-{
-	/* ktime_t starts 1st of jan 1970, 00:00 Uhr UTC,
-	   while jiffies start a system boot. */
-	ktime_t o = ktime_sub(ktime_get(), kt);
-	return jiffies - nsecs_to_jiffies(ktime_to_ns(o));
-}
-
 #ifndef __disk_stat_inc
 /* Update disk stats at start of I/O request */
 static void _drbd_start_io_acct(struct drbd_device *device, struct drbd_request *req)
@@ -55,7 +47,7 @@ static void _drbd_end_io_acct(struct drbd_device *device, struct drbd_request *r
 {
 	generic_end_io_acct(device->rq_queue, bio_data_dir(req->master_bio),
 			    &device->vdisk->part0,
-			    ktime_to_jiffies(req->start_kt));
+			    req->start_jif);
 }
 #else
 static void _drbd_start_io_acct(struct drbd_device *device, struct drbd_request *req)
@@ -1580,8 +1572,13 @@ static void drbd_req_in_actlog(struct drbd_request *req)
  * request on the submitter thread.
  * Returns ERR_PTR(-ENOMEM) if we cannot allocate a drbd_request.
  */
+#ifndef CONFIG_DRBD_TIMING_STATS
+#define drbd_request_prepare(d,b,k,j) drbd_request_prepare(d,b,j)
+#endif
 static struct drbd_request *
-drbd_request_prepare(struct drbd_device *device, struct bio *bio, ktime_t start_kt)
+drbd_request_prepare(struct drbd_device *device, struct bio *bio,
+		ktime_t start_kt,
+		unsigned long start_jif)
 {
 	const int rw = bio_data_dir(bio);
 	struct drbd_request *req;
@@ -1599,7 +1596,8 @@ drbd_request_prepare(struct drbd_device *device, struct bio *bio, ktime_t start_
 	if (get_ldev(device))
 		req_make_private_bio(req, bio);
 
-	req->start_kt = start_kt;
+	req->start_jif = start_jif;
+	ktime_get_accounting_assign(req->start_kt, start_kt);
 
 	/* Update disk stats */
 	_drbd_start_io_acct(device, req);
@@ -1833,12 +1831,14 @@ static void drbd_send_and_submit(struct drbd_device *device, struct drbd_request
 		list_add_tail(&req->req_pending_master_completion,
 			&device->pending_master_completion[rw == WRITE]);
 	if (req->private_bio) {
-		/* needs to be marked within the same spinlock */
+		/* pre_submit_jif is used in request_timer_fn() */
+		req->pre_submit_jif = jiffies;
 		ktime_get_accounting(req->pre_submit_kt);
 		list_add_tail(&req->req_pending_local,
 			&device->pending_completion[rw == WRITE]);
 		_req_mod(req, TO_BE_SUBMITTED, NULL);
-		/* but we need to give up the spinlock to submit */
+		/* needs to be marked within the same spinlock
+		 * but we need to give up the spinlock to submit */
 		submit_private_bio = true;
 	} else if (no_remote) {
 nodata:
@@ -1870,9 +1870,11 @@ out:
 		complete_master_bio(device, &m);
 }
 
-void __drbd_make_request(struct drbd_device *device, struct bio *bio, ktime_t start_kt)
+void __drbd_make_request(struct drbd_device *device, struct bio *bio,
+		ktime_t start_kt,
+		unsigned long start_jif)
 {
-	struct drbd_request *req = drbd_request_prepare(device, bio, start_kt);
+	struct drbd_request *req = drbd_request_prepare(device, bio, start_kt, start_jif);
 	if (IS_ERR_OR_NULL(req))
 		return;
 	drbd_send_and_submit(device, req);
@@ -2243,7 +2245,10 @@ MAKE_REQUEST_TYPE drbd_make_request(struct request_queue *q, struct bio *bio)
 {
 	struct drbd_device *device = (struct drbd_device *) q->queuedata;
 	struct drbd_resource *resource = device->resource;
+#ifdef CONFIG_DRBD_TIMING_STATS
 	ktime_t start_kt;
+#endif
+	unsigned long start_jif;
 #ifdef COMPAT_NEED_MAKE_REQUEST_RECURSION
 	struct bio_list *current_bio_list;
 #endif
@@ -2268,10 +2273,11 @@ MAKE_REQUEST_TYPE drbd_make_request(struct request_queue *q, struct bio *bio)
 		MAKE_REQUEST_RETURN;
 	}
 
-	start_kt = ktime_get();
+	ktime_get_accounting(start_kt);
+	start_jif = jiffies;
 
 	inc_ap_bio(device, bio_data_dir(bio));
-	__drbd_make_request(device, bio, start_kt);
+	__drbd_make_request(device, bio, start_kt, start_jif);
 
 #ifdef COMPAT_NEED_MAKE_REQUEST_RECURSION
 	current->bio_list = current_bio_list;
@@ -2333,7 +2339,7 @@ static bool net_timeout_reached(struct drbd_request *net_req,
 	struct drbd_device *device = net_req->device;
 	struct drbd_peer_device *peer_device = conn_peer_device(connection, device->vnr);
 	int peer_node_id = peer_device->node_id;
-	unsigned long pre_send_jif = ktime_to_jiffies(net_req->pre_send_kt[peer_node_id]);
+	unsigned long pre_send_jif = net_req->pre_send_jif[peer_node_id];
 
 	if (!time_after(now, pre_send_jif + ent))
 		return false;
@@ -2426,8 +2432,8 @@ void request_timer_fn(DRBD_TIMER_FN_ARG)
 		req_read = list_first_entry_or_null(&device->pending_completion[0], struct drbd_request, req_pending_local);
 		req_write = list_first_entry_or_null(&device->pending_completion[1], struct drbd_request, req_pending_local);
 
-		write_pre_submit_jif = ktime_to_jiffies(req_write->pre_submit_kt);
-		read_pre_submit_jif = ktime_to_jiffies(req_read->pre_submit_kt);
+		write_pre_submit_jif = req_write->pre_submit_jif;
+		read_pre_submit_jif = req_read->pre_submit_jif;
 		oldest_submit_jif =
 			(req_write && req_read)
 			? ( time_before(write_pre_submit_jif, read_pre_submit_jif)
@@ -2491,7 +2497,7 @@ void request_timer_fn(DRBD_TIMER_FN_ARG)
 		if (!timeout)
 			continue;
 
-		pre_send_jif = ktime_to_jiffies(req->pre_send_kt[connection->peer_node_id]);
+		pre_send_jif = req->pre_send_jif[connection->peer_node_id];
 
 		ent = timeout * HZ/10 * ko_count;
 		et = min_not_zero(et, ent);
diff --git a/drbd/drbd_sender.c b/drbd/drbd_sender.c
index 053cff9a..c925a535 100644
--- a/drbd/drbd_sender.c
+++ b/drbd/drbd_sender.c
@@ -2611,6 +2611,8 @@ static int process_one_request(struct drbd_connection *connection)
 	int err;
 	enum drbd_req_event what;
 
+	/* pre_send_jif[] is used in net_timeout_reached() */
+	req->pre_send_jif[peer_device->node_id] = jiffies;
 	ktime_get_accounting(req->pre_send_kt[peer_device->node_id]);
 	if (drbd_req_is_write(req)) {
 		/* If a WRITE does not expect a barrier ack,
-- 
2.34.1

