From 3fa51d9e23d8c25aede4035a7a301106c64a7a6e Mon Sep 17 00:00:00 2001
From: Philipp Reisner <philipp.reisner@linbit.com>
Date: Wed, 11 Jul 2018 09:32:26 +0200
Subject: [PATCH] drbd: make the additional timing measurement a compile time
 option

Whit that removed,
on my mid-range Skylake system Xeon Silver 4112 CPU @ 2.60GHz
this brings me from 455k read IOPs to 466k read IOPs.
---
 drbd/Kconfig             | 11 +++++++++++
 drbd/drbd_actlog.c       |  2 +-
 drbd/drbd_debugfs.c      | 17 +++++++++++++++--
 drbd/drbd_int.h          | 23 ++++++++++++++++++++---
 drbd/drbd_main.c         |  2 ++
 drbd/drbd_req.c          | 14 ++++++++------
 drbd/drbd_sender.c       |  2 +-
 drbd/linux/drbd_config.h |  2 ++
 8 files changed, 60 insertions(+), 13 deletions(-)

diff --git a/drbd/Kconfig b/drbd/Kconfig
index 7845bd6e..07467c75 100644
--- a/drbd/Kconfig
+++ b/drbd/Kconfig
@@ -71,3 +71,14 @@ config DRBD_FAULT_INJECTION
 		echo 5 > /sys/module/drbd/parameters/fault_rate
 
 	  If unsure, say N.
+
+config DRBD_TIMING_STATS
+	bool "Enable additional timing collection"
+	depends on BLK_DEV_DRBD
+	help
+
+	  this option enables a virtual file in debug-fs
+	  /sys/kernel/debug/drbd/resources/<res>/volumes/<vol_nr>/req_timing
+
+	  that unveiles the culmative time consumed by requests in various
+	  stages of the request processing
diff --git a/drbd/drbd_actlog.c b/drbd/drbd_actlog.c
index 3ce8cc1f..145d8503 100644
--- a/drbd/drbd_actlog.c
+++ b/drbd/drbd_actlog.c
@@ -351,7 +351,7 @@ static int __al_write_transaction(struct drbd_device *device, struct al_transact
 	unsigned extent_nr;
 	unsigned crc = 0;
 	int err = 0;
-	ktime_t start_kt = ktime_get();
+	ktime_var_for_accounting(start_kt);
 
 	memset(buffer, 0, sizeof(*buffer));
 	buffer->magic = cpu_to_be32(DRBD_AL_MAGIC);
diff --git a/drbd/drbd_debugfs.c b/drbd/drbd_debugfs.c
index 2ae638bc..54441a2e 100644
--- a/drbd/drbd_debugfs.c
+++ b/drbd/drbd_debugfs.c
@@ -23,6 +23,7 @@ static struct dentry *drbd_debugfs_refcounts;
 static struct dentry *drbd_debugfs_resources;
 static struct dentry *drbd_debugfs_minors;
 
+#ifdef CONFIG_DRBD_TIMING_STATS
 static void seq_print_age_or_dash(struct seq_file *m, bool valid, ktime_t dt)
 {
 	if (valid)
@@ -30,6 +31,7 @@ static void seq_print_age_or_dash(struct seq_file *m, bool valid, ktime_t dt)
 	else
 		seq_puts(m, "\t-");
 }
+#endif
 
 static void __seq_print_rq_state_bit(struct seq_file *m,
 	bool is_set, char *sep, const char *set_name, const char *unset_name)
@@ -100,6 +102,7 @@ static void seq_print_request_state(struct seq_file *m, struct drbd_request *req
 
 #define memberat(PTR, TYPE, OFFSET) (*(TYPE *)((char *)PTR + OFFSET))
 
+#ifdef CONFIG_DRBD_TIMING_STATS
 static void print_one_age_or_dash(struct seq_file *m, struct drbd_request *req,
 				  unsigned int set_mask, unsigned int clear_mask,
 				  ktime_t now, size_t offset)
@@ -118,6 +121,7 @@ static void print_one_age_or_dash(struct seq_file *m, struct drbd_request *req,
 	}
 	seq_puts(m, "\t-");
 }
+#endif
 
 static void seq_print_one_request(struct seq_file *m, struct drbd_request *req, ktime_t now)
 {
@@ -131,15 +135,16 @@ static void seq_print_one_request(struct seq_file *m, struct drbd_request *req,
 		(s & RQ_WRITE) ? "W" : "R");
 
 #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));
-
+#endif
 #define RQ_HDR_4 "\tstate\n"
 	seq_print_request_state(m, req);
 }
@@ -1099,6 +1104,7 @@ static int device_ed_gen_id_show(struct seq_file *m, void *ignored)
 
 #define PRId64 "lld"
 
+#ifdef CONFIG_DRBD_TIMING_STATS
 static int device_req_timing_show(struct seq_file *m, void *ignored)
 {
 	struct drbd_device *device = m->private;
@@ -1174,6 +1180,7 @@ static ssize_t device_req_timing_write(struct file *file, const char __user *ubu
 	*ppos += cnt;
 	return cnt;
 }
+#endif
 
 static int device_attr_release(struct inode *inode, struct file *file)
 {
@@ -1206,7 +1213,9 @@ drbd_debugfs_device_attr(data_gen_id)
 drbd_debugfs_device_attr(io_frozen)
 drbd_debugfs_device_attr(ed_gen_id)
 drbd_debugfs_device_attr(openers)
+#ifdef CONFIG_DRBD_TIMING_STATS
 __drbd_debugfs_device_attr(req_timing, device_req_timing_write)
+#endif
 
 void drbd_debugfs_device_add(struct drbd_device *device)
 {
@@ -1246,7 +1255,9 @@ void drbd_debugfs_device_add(struct drbd_device *device)
 	vol_dcf(io_frozen);
 	vol_dcf(ed_gen_id);
 	vol_dcf(openers);
+#ifdef CONFIG_DRBD_TIMING_STATS
 	drbd_dcf(device->debugfs_vol, device, req_timing, S_IRUSR | S_IWUSR);
+#endif
 
 	/* Caller holds conf_update */
 	for_each_peer_device(peer_device, device) {
@@ -1271,7 +1282,9 @@ void drbd_debugfs_device_cleanup(struct drbd_device *device)
 	drbd_debugfs_remove(&device->debugfs_vol_io_frozen);
 	drbd_debugfs_remove(&device->debugfs_vol_ed_gen_id);
 	drbd_debugfs_remove(&device->debugfs_vol_openers);
+#ifdef CONFIG_DRBD_TIMING_STATS
 	drbd_debugfs_remove(&device->debugfs_vol_req_timing);
+#endif
 	drbd_debugfs_remove(&device->debugfs_vol);
 }
 
diff --git a/drbd/drbd_int.h b/drbd/drbd_int.h
index 7b5f3a66..2b926005 100644
--- a/drbd/drbd_int.h
+++ b/drbd/drbd_int.h
@@ -315,23 +315,26 @@ struct drbd_request {
 	ktime_t start_kt;
 
 	/* for DRBD internal statistics */
+	ktime_t pre_submit_kt;
+
+	/* 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.
 	 */
 
+#ifdef CONFIG_DRBD_TIMING_STATS
 	/* 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
 	 *      how long did it take to complete the master bio
@@ -1221,7 +1224,9 @@ struct drbd_device {
 	struct dentry *debugfs_vol_io_frozen;
 	struct dentry *debugfs_vol_ed_gen_id;
 	struct dentry *debugfs_vol_openers;
+#ifdef CONFIG_DRBD_TIMING_STATS
 	struct dentry *debugfs_vol_req_timing;
+#endif
 #endif
 
 	unsigned int vnr;	/* volume number within the connection */
@@ -1304,6 +1309,7 @@ struct drbd_device {
 	bool have_quorum[2];	/* no quorum -> suspend IO or error IO */
 	bool cached_state_unstable; /* updates with each state change */
 
+#ifdef CONFIG_DRBD_TIMING_STATS
 	spinlock_t timing_lock;
 	unsigned long reqs;
 	ktime_t in_actlog_kt;
@@ -1315,6 +1321,7 @@ struct drbd_device {
 	ktime_t al_before_bm_write_hinted_kt; /* sum over all al_writ_cnt */
 	ktime_t al_mid_kt;
 	ktime_t al_after_sync_page_kt;
+#endif
 
 	struct rcu_head rcu;
 	struct work_struct finalize_work;
@@ -2777,8 +2784,18 @@ static inline struct drbd_connection *first_connection(struct drbd_resource *res
 
 #define NODE_MASK(id) ((u64)1 << (id))
 
+#ifdef CONFIG_DRBD_TIMING_STATS
 #define ktime_aggregate_delta(D, ST, M) D->M = ktime_add(D->M, ktime_sub(ktime_get(), ST))
 #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_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_var_for_accounting(V)
+#endif
 
 #endif
diff --git a/drbd/drbd_main.c b/drbd/drbd_main.c
index 7dd1cbd3..32a7c9f2 100644
--- a/drbd/drbd_main.c
+++ b/drbd/drbd_main.c
@@ -3654,7 +3654,9 @@ enum drbd_ret_code drbd_create_device(struct drbd_config_context *adm_ctx, unsig
 	atomic_set(&device->rs_sect_ev, 0);
 	atomic_set(&device->md_io.in_use, 0);
 
+#ifdef CONFIG_DRBD_TIMING_STATS
 	spin_lock_init(&device->timing_lock);
+#endif
 	spin_lock_init(&device->al_lock);
 	mutex_init(&device->bm_resync_fo_mutex);
 
diff --git a/drbd/drbd_req.c b/drbd/drbd_req.c
index a2b372b3..00fb6ef1 100644
--- a/drbd/drbd_req.c
+++ b/drbd/drbd_req.c
@@ -198,6 +198,7 @@ void drbd_req_destroy(struct kref *kref)
 	s = req->local_rq_state;
 	destroy_next = req->destroy_next;
 
+#ifdef CONFIG_DRBD_TIMING_STATS
 	if (s & RQ_WRITE) {
 		unsigned long flags;
 
@@ -216,6 +217,7 @@ void drbd_req_destroy(struct kref *kref)
 		}
 		spin_unlock_irqrestore(&device->timing_lock, flags);
 	}
+#endif
 
 	/* paranoia */
 	for_each_peer_device(peer_device, device) {
@@ -733,7 +735,7 @@ static void mod_rq_state(struct drbd_request *req, struct bio_and_error *m,
 	if ((old_net & RQ_NET_PENDING) && (clear & RQ_NET_PENDING)) {
 		dec_ap_pending(peer_device);
 		++c_put;
-		req->acked_kt[peer_device->node_id] = ktime_get();
+		ktime_get_accounting(req->acked_kt[peer_device->node_id]);
 		advance_conn_req_ack_pending(peer_device, req);
 	}
 
@@ -749,7 +751,7 @@ static void mod_rq_state(struct drbd_request *req, struct bio_and_error *m,
 			atomic_sub(req_payload_sectors(req), ap_in_flight);
 		if (old_net & RQ_EXP_BARR_ACK)
 			kref_put(&req->kref, drbd_req_destroy);
-		req->net_done_kt[peer_device->node_id] = ktime_get();
+		ktime_get_accounting(req->net_done_kt[peer_device->node_id]);
 
 		if (peer_device->repl_state[NOW] == L_AHEAD &&
 		    atomic_read(ap_in_flight) == 0 &&
@@ -1591,7 +1593,7 @@ drbd_request_prepare(struct drbd_device *device, struct bio *bio, ktime_t start_
 			if (!drbd_al_begin_io_fastpath(device, &req->i))
 				goto queue_for_submitter_thread;
 			req->local_rq_state |= RQ_IN_ACT_LOG;
-			req->in_actlog_kt = ktime_get();
+			ktime_get_accounting(req->in_actlog_kt);
 		}
 	}
 	return req;
@@ -1796,7 +1798,7 @@ static void drbd_send_and_submit(struct drbd_device *device, struct drbd_request
 			&device->pending_master_completion[rw == WRITE]);
 	if (req->private_bio) {
 		/* needs to be marked within the same spinlock */
-		req->pre_submit_kt = ktime_get();
+		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);
@@ -1929,7 +1931,7 @@ static void submit_fast_path(struct drbd_device *device, struct waiting_for_act_
 				continue;
 
 			req->local_rq_state |= RQ_IN_ACT_LOG;
-			req->in_actlog_kt = ktime_get();
+			ktime_get_accounting(req->in_actlog_kt);
 			atomic_dec(&device->ap_actlog_cnt);
 		}
 
@@ -2019,7 +2021,7 @@ static void send_and_submit_pending(struct drbd_device *device, struct waiting_f
 	}
 	list_for_each_entry_safe(req, tmp, &wfa->requests.pending, tl_requests) {
 		req->local_rq_state |= RQ_IN_ACT_LOG;
-		req->in_actlog_kt = ktime_get();
+		ktime_get_accounting(req->in_actlog_kt);
 		atomic_dec(&device->ap_actlog_cnt);
 		list_del_init(&req->tl_requests);
 		drbd_send_and_submit(device, req);
diff --git a/drbd/drbd_sender.c b/drbd/drbd_sender.c
index f2a39b9c..ff49655d 100644
--- a/drbd/drbd_sender.c
+++ b/drbd/drbd_sender.c
@@ -2609,7 +2609,7 @@ static int process_one_request(struct drbd_connection *connection)
 	int err;
 	enum drbd_req_event what;
 
-	req->pre_send_kt[peer_device->node_id] = ktime_get();
+	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,
 		 * we are supposed to only send an "out of sync" info packet */
diff --git a/drbd/linux/drbd_config.h b/drbd/linux/drbd_config.h
index 49035d55..50cdb12b 100644
--- a/drbd/linux/drbd_config.h
+++ b/drbd/linux/drbd_config.h
@@ -54,6 +54,8 @@ extern const char *drbd_buildtag(void);
 
 /* CONFIG_KREF_DEBUG has to be enabled in Kbuild */
 
+/* Do not enable CONFIG_DRBD_TIMING_STATS */
+
 #ifdef __KERNEL__
 #include "compat.h"
 #endif
-- 
2.34.1

