[10/15] fs/fuse kio: implement fstat_lat statistics info

Submitted by Pavel Butsykin on May 17, 2019, 1:20 p.m.

Details

Message ID 20190517132048.13162-11-pbutsykin@virtuozzo.com
State New
Series "Statistics for vstorage kernel fast-path"
Headers show

Commit Message

Pavel Butsykin May 17, 2019, 1:20 p.m.
This statistic shows latency of requests for each open kio file. Latency is
displayed for 99 and 95 percentile in the following time ranges: 20ms, 50ms,
100ms, 200ms, 500ms. In turn, the request latency is detailed in three parts:
pending_lat - time spent in the queue
net_lat     - time spent in the network
io_lat      - disk operation time

example:
# rw open/age inactive  net_lat                      net_lat_global               io_lat                       io_lat_global                plat                         plat_global                  path
rw       2/6360    0    (5% > 500ms, 1% > 500ms)     (5% > 500ms, 1% > 500ms)     (95% <= 20ms, 99% <= 50ms)   (95% <= 20ms, 99% <= 50ms)   (95% <= 20ms, 99% <= 20ms)   (95% <= 20ms, 99% <= 20ms)   /fio_test/randasyncread_jobs24_4k.0.0
rw       2/6360    0    (5% > 500ms, 1% > 500ms)     (5% > 500ms, 1% > 500ms)     (95% <= 20ms, 99% <= 50ms)   (95% <= 20ms, 99% <= 20ms)   (95% <= 20ms, 99% <= 20ms)   (95% <= 20ms, 99% <= 20ms)   /fio_test/randasyncread_jobs24_4k.1.0

Signed-off-by: Pavel Butsykin <pbutsykin@virtuozzo.com>
---
 fs/fuse/kio/pcs/fuse_stat.c | 183 +++++++++++++++++++++++++++++++++++++++++++-
 fs/fuse/kio/pcs/fuse_stat.h |  30 +++++++-
 fs/fuse/kio/pcs/pcs_map.c   |   2 +-
 3 files changed, 212 insertions(+), 3 deletions(-)

Patch hide | download patch | download mbox

diff --git a/fs/fuse/kio/pcs/fuse_stat.c b/fs/fuse/kio/pcs/fuse_stat.c
index 85c8f7e04413..452bb4e9664c 100644
--- a/fs/fuse/kio/pcs/fuse_stat.c
+++ b/fs/fuse/kio/pcs/fuse_stat.c
@@ -7,6 +7,44 @@ 
 
 extern struct super_block *fuse_control_sb;
 
+static u64 lat_oreder_list[] = {
+	[LAT_ORDER1] = 20 * USEC_PER_MSEC,
+	[LAT_ORDER2] = 50 * USEC_PER_MSEC,
+	[LAT_ORDER3] = 100 * USEC_PER_MSEC,
+	[LAT_ORDER4] = 200 * USEC_PER_MSEC,
+	[LAT_ORDER5] = 500 * USEC_PER_MSEC,
+};
+
+
+static void fuse_latency_update(struct fuse_lat_stat *s, u64 lat)
+{
+	int i;
+
+	s->count++;
+
+	for (i = LAT_ORDER1; i <= LAT_ORDER5; i++) {
+		if (likely(lat <= lat_oreder_list[i])) {
+			s->lat[i]++;
+			return;
+		}
+	}
+	s->lat[LAT_ORDER_OTHER]++;
+	return;
+}
+
+static inline void fuse_latency_count(struct fuse_lat_cnt *c, u64 val)
+{
+	fuse_latency_update(&c->curr, val);
+	fuse_latency_update(&c->glob, val);
+}
+
+static inline void fuse_latency_cnt_up(struct fuse_lat_cnt *c)
+{
+	BUILD_BUG_ON(sizeof(c->last) != sizeof(c->curr));
+
+	memcpy(&c->last, &c->curr, sizeof(c->last));
+	memset(&c->curr, 0, sizeof(c->curr));
+}
 
 static const char *fuse_kio_op_name(unsigned opcode)
 {
@@ -96,12 +134,142 @@  static inline unsigned long long fuse_val_cnt_max(struct fuse_val_cnt const* c)
 #define CNT_MAX(c)    fuse_val_cnt_max(&(c))
 
 
+#define MAX_PERCENT 100
+static int latency_npercl_format(struct fuse_lat_stat *s, u8 percl, char *buf,
+				 size_t sz)
+{
+	u64 cnt = s->count, nper;
+	int i;
+
+	BUG_ON(percl > MAX_PERCENT);
+
+	if (!cnt)
+		return 0;
+
+	nper = cnt * (MAX_PERCENT - percl);
+	if (s->lat[LAT_ORDER_OTHER] * MAX_PERCENT >= nper)
+		return scnprintf(buf, sz, "%u%% > %llums", MAX_PERCENT - percl,
+				 lat_oreder_list[LAT_ORDER_OTHER - 1] / 1000);
+
+	for(i = LAT_ORDER_OTHER - 1; i >= 0; i--) {
+		if (s->lat[i] * MAX_PERCENT >= nper)
+			return scnprintf(buf, sz, "%u%% <= %llums", percl,
+					 lat_oreder_list[i] / 1000);
+	}
+	BUG();
+	return 0;
+}
+
+#define LAT_LINE_MAX 27
+static void latency_percl_print(struct fuse_lat_stat *s, struct seq_file *m)
+{
+	int n, icnt = LAT_LINE_MAX;
+	char buf[LAT_LINE_MAX];
+
+	seq_printf(m, "(");
+	n = latency_npercl_format(s, 95, buf, sizeof(buf) - 1);
+	if (n) {
+		seq_printf(m,"%.*s, ", n, buf);
+		icnt -= n;
+		icnt -= 2;
+	}
+	n = latency_npercl_format(s, 99, buf, sizeof(buf) - 1);
+	if (n) {
+		seq_printf(m, "%.*s", n, buf);
+		icnt -= n;
+	}
+
+	WARN_ON(icnt < 0);
+	seq_printf(m, ")%*s", max(icnt, 0), "");
+}
+
+static void fuse_kio_fstat_lat_itr(struct fuse_file *ff,
+				   struct pcs_dentry_info *di, void *ctx)
+{
+	struct seq_file *m = ctx;
+	struct fuse_io_cnt *fstat = &di->stat;
+	umode_t mode = di->inode->inode.i_mode;
+	abs_time_t now = jiffies;
+	struct fuse_lat_cnt io_lat;
+	struct fuse_lat_cnt net_lat;
+	struct fuse_lat_cnt pending_lat;
+
+	seq_printf(m, "%s%s %7u/%-7llu %-5u",
+		   mode & S_IRUGO ? "r": "", mode & S_IWUGO ? "w": "",
+		   atomic_read(&ff->count), (now - di->stat.created_ts) / 1000, 0);
+
+	spin_lock(&fstat->lock);
+	io_lat = fstat->io_lat;
+	net_lat = fstat->net_lat;
+	pending_lat = fstat->pending_lat;
+	spin_unlock(&fstat->lock);
+
+	latency_percl_print(&net_lat.last, m);
+	latency_percl_print(&net_lat.glob, m);
+
+	latency_percl_print(&io_lat.last, m);
+	latency_percl_print(&io_lat.glob, m);
+
+	latency_percl_print(&pending_lat.last, m);
+	latency_percl_print(&pending_lat.glob, m);
+
+	seq_dentry(m, ff->ff_dentry, "");
+	seq_putc(m, '\n');
+}
+
+static int pcs_fuse_fstat_lat_show(struct seq_file *m, void *v)
+{
+	struct inode *inode = m->private;
+	struct pcs_fuse_stat *stat;
+	struct fuse_conn *fc;
+
+	if (!inode)
+		return 0;
+
+	mutex_lock(&fuse_mutex);
+	stat = inode->i_private;
+	if (!stat) {
+		mutex_unlock(&fuse_mutex);
+		return 0;
+	}
+
+	seq_printf(m, "# rw open/age inactive  net_lat\t\t\t     net_lat_global\t\t  io_lat\t\t       io_lat_global\t\t    plat\t\t\t plat_global\t\t      path\n");
+
+	fc = container_of(stat, struct pcs_fuse_cluster, cc.stat)->fc;
+	if (fc) {
+		spin_lock(&fc->lock);
+		pcs_kio_file_list(fc, fuse_kio_fstat_lat_itr, m);
+		spin_unlock(&fc->lock);
+	}
+	mutex_unlock(&fuse_mutex);
+
+
+	return 0;
+}
+
+static int pcs_fuse_fstat_lat_open(struct inode *inode, struct file *file)
+{
+	return single_open(file, pcs_fuse_fstat_lat_show, inode);
+}
+
+static const struct file_operations pcs_fuse_fstat_lat_ops = {
+	.owner   = THIS_MODULE,
+	.open    = pcs_fuse_fstat_lat_open,
+	.read    = seq_read,
+	.llseek	 = seq_lseek,
+	.release = single_release,
+};
+
 static void fuse_fstat_up_itr(struct fuse_file *ff, struct pcs_dentry_info *di,
 			      void *ctx)
 {
 	struct fuse_io_cnt *fstat = &di->stat;
 
 	spin_lock(&fstat->lock);
+	fuse_latency_cnt_up(&fstat->io_lat);
+	fuse_latency_cnt_up(&fstat->net_lat);
+	fuse_latency_cnt_up(&fstat->pending_lat);
+
 	fuse_val_cnt_up(&fstat->io.read_bytes);
 	fuse_val_cnt_up(&fstat->io.write_bytes);
 	fuse_val_cnt_up(&fstat->io.flush_cnt);
@@ -316,7 +484,8 @@  struct fuse_val_cnt *req_stat_entry(struct pcs_fuse_io_stat *io, u32 type)
 	return NULL;
 }
 
-void pcs_fuse_stat_io_count(struct pcs_int_request *ireq, struct pcs_msg *resp)
+void pcs_fuse_stat_io_count(struct pcs_int_request *ireq, struct pcs_msg *resp,
+			    u32 io_lat, u32 net_lat)
 {
 	struct pcs_cluster_core *cc = ireq->cc;
 	struct pcs_fuse_stat *stat = &cc->stat;
@@ -333,7 +502,13 @@  void pcs_fuse_stat_io_count(struct pcs_int_request *ireq, struct pcs_msg *resp)
 
 	se = req_stat_entry(&fstat->io, h->hdr.type);
 	if (likely(se)) {
+		u32 pending_lat = ktime_to_us(ktime_sub(ireq->ts_sent, ireq->ts));
+
 		spin_lock(&fstat->lock);
+		fuse_latency_count(&fstat->pending_lat, pending_lat);
+		fuse_latency_count(&fstat->io_lat, io_lat);
+		fuse_latency_count(&fstat->net_lat, net_lat);
+
 		fuse_val_stat_update(&se->curr, size);
 		spin_unlock(&fstat->lock);
 	}
@@ -436,6 +611,10 @@  void pcs_fuse_stat_init(struct pcs_fuse_stat *stat)
 	stat->fstat = fuse_kio_add_dentry(stat->kio_stat, fc, "fstat",
 					  S_IFREG | S_IRUSR, 1, NULL,
 					  &pcs_fuse_fstat_ops, stat);
+
+	stat->fstat_lat = fuse_kio_add_dentry(stat->kio_stat, fc, "fstat_lat",
+					      S_IFREG | S_IRUSR, 1, NULL,
+					      &pcs_fuse_fstat_lat_ops, stat);
 out:
 	mutex_unlock(&fuse_mutex);
 }
@@ -453,6 +632,8 @@  void pcs_fuse_stat_fini(struct pcs_fuse_stat *stat)
 			fuse_kio_rm_dentry(stat->requests);
 		if (stat->fstat)
 			fuse_kio_rm_dentry(stat->fstat);
+		if (stat->fstat_lat)
+			fuse_kio_rm_dentry(stat->fstat_lat);
 		fuse_kio_rm_dentry(stat->kio_stat);
 	}
 	mutex_unlock(&fuse_mutex);
diff --git a/fs/fuse/kio/pcs/fuse_stat.h b/fs/fuse/kio/pcs/fuse_stat.h
index b65620b51738..32971cf77dc4 100644
--- a/fs/fuse/kio/pcs/fuse_stat.h
+++ b/fs/fuse/kio/pcs/fuse_stat.h
@@ -34,11 +34,38 @@  struct pcs_fuse_stat {
 	struct dentry *iostat;
 	struct dentry *requests;
 	struct dentry *fstat;
+	struct dentry *fstat_lat;
+};
+
+enum {
+	LAT_ORDER1 = 0,
+	LAT_ORDER2 = 1,
+	LAT_ORDER3 = 2,
+	LAT_ORDER4 = 3,
+	LAT_ORDER5 = 4,
+	LAT_ORDER_OTHER = 5,
+};
+
+#define LATENCY_ORDER_MAX (LAT_ORDER_OTHER + 1)
+
+struct fuse_lat_stat {
+	u64 lat[LATENCY_ORDER_MAX];
+	u64 count;
+};
+
+struct fuse_lat_cnt {
+	struct fuse_lat_stat  curr;
+	struct fuse_lat_stat  last;
+	struct fuse_lat_stat  glob;
 };
 
 struct fuse_io_cnt {
 	struct pcs_fuse_io_stat io;
 
+	struct fuse_lat_cnt io_lat;
+	struct fuse_lat_cnt net_lat;
+	struct fuse_lat_cnt pending_lat;
+
 	abs_time_t created_ts;
 	spinlock_t lock;
 };
@@ -46,6 +73,7 @@  struct fuse_io_cnt {
 void pcs_fuse_stat_init(struct pcs_fuse_stat *stat);
 void pcs_fuse_stat_fini(struct pcs_fuse_stat *stat);
 
-void pcs_fuse_stat_io_count(struct pcs_int_request *ireq, struct pcs_msg *resp);
+void pcs_fuse_stat_io_count(struct pcs_int_request *ireq, struct pcs_msg *resp,
+			    u32 io_lat, u32 net_lat);
 
 #endif /* _FUSE_STAT_H_ */
diff --git a/fs/fuse/kio/pcs/pcs_map.c b/fs/fuse/kio/pcs/pcs_map.c
index 5ef2efe44090..3a8fe95a99f7 100644
--- a/fs/fuse/kio/pcs/pcs_map.c
+++ b/fs/fuse/kio/pcs/pcs_map.c
@@ -2701,7 +2701,7 @@  static int commit_sync_info(struct pcs_int_request *req,
 				max_iolat = srec->sync.ts_io;
 		}
 	}
-	pcs_fuse_stat_io_count(req, resp);
+	pcs_fuse_stat_io_count(req, resp, max_iolat, lat - max_iolat);
 	cs_log_io_times(req, resp, max_iolat);
 
 	evaluate_dirty_status(m);