Re: [PATCH v12 3/4] ceph: add read/write latency metric support

[Xiubo Li <xiubli@xxxxxxxxxx>]

On 2020/3/19 22:36, Jeff Layton wrote:
> On Thu, 2020-03-19 at 10:06 -0400, xiubli@xxxxxxxxxx wrote:
> > From: Xiubo Li <xiubli@xxxxxxxxxx>
> >
> > Calculate the latency for OSD read requests. Add a new r_end_stamp
> > field to struct ceph_osd_request that will hold the time of that
> > the reply was received. Use that to calculate the RTT for each call,
> > and divide the sum of those by number of calls to get averate RTT.
> >
> > Keep a tally of RTT for OSD writes and number of calls to track average
> > latency of OSD writes.
> >
> > URL: https://tracker.ceph.com/issues/43215
> > Signed-off-by: Xiubo Li <xiubli@xxxxxxxxxx>
> > ---
> >   fs/ceph/addr.c                  |  18 +++++++
> >   fs/ceph/debugfs.c               |  60 +++++++++++++++++++++-
> >   fs/ceph/file.c                  |  26 ++++++++++
> >   fs/ceph/metric.c                | 110 ++++++++++++++++++++++++++++++++++++++++
> >   fs/ceph/metric.h                |  23 +++++++++
> >   include/linux/ceph/osd_client.h |   1 +
> >   net/ceph/osd_client.c           |   2 +
> >   7 files changed, 239 insertions(+), 1 deletion(-)
> >
> > diff --git a/fs/ceph/addr.c b/fs/ceph/addr.c
> > index 6f4678d..f359619 100644
> > --- a/fs/ceph/addr.c
> > +++ b/fs/ceph/addr.c
> > @@ -216,6 +216,9 @@ static int ceph_sync_readpages(struct ceph_fs_client *fsc,
> >   	if (!rc)
> >   		rc = ceph_osdc_wait_request(osdc, req);
> >   
> > +	ceph_update_read_latency(&fsc->mdsc->metric, req->r_start_stamp,
> > +				 req->r_end_stamp, rc);
> > +
> >   	ceph_osdc_put_request(req);
> >   	dout("readpages result %d\n", rc);
> >   	return rc;
> > @@ -299,6 +302,7 @@ static int ceph_readpage(struct file *filp, struct page *page)
> >   static void finish_read(struct ceph_osd_request *req)
> >   {
> >   	struct inode *inode = req->r_inode;
> > +	struct ceph_fs_client *fsc = ceph_inode_to_client(inode);
> >   	struct ceph_osd_data *osd_data;
> >   	int rc = req->r_result <= 0 ? req->r_result : 0;
> >   	int bytes = req->r_result >= 0 ? req->r_result : 0;
> > @@ -336,6 +340,10 @@ static void finish_read(struct ceph_osd_request *req)
> >   		put_page(page);
> >   		bytes -= PAGE_SIZE;
> >   	}
> > +
> > +	ceph_update_read_latency(&fsc->mdsc->metric, req->r_start_stamp,
> > +				 req->r_end_stamp, rc);
> > +
> >   	kfree(osd_data->pages);
> >   }
> >   
> > @@ -643,6 +651,9 @@ static int ceph_sync_writepages(struct ceph_fs_client *fsc,
> >   	if (!rc)
> >   		rc = ceph_osdc_wait_request(osdc, req);
> >   
> > +	ceph_update_write_latency(&fsc->mdsc->metric, req->r_start_stamp,
> > +				  req->r_end_stamp, rc);
> > +
> >   	ceph_osdc_put_request(req);
> >   	if (rc == 0)
> >   		rc = len;
> > @@ -794,6 +805,9 @@ static void writepages_finish(struct ceph_osd_request *req)
> >   		ceph_clear_error_write(ci);
> >   	}
> >   
> > +	ceph_update_write_latency(&fsc->mdsc->metric, req->r_start_stamp,
> > +				  req->r_end_stamp, rc);
> > +
> >   	/*
> >   	 * We lost the cache cap, need to truncate the page before
> >   	 * it is unlocked, otherwise we'd truncate it later in the
> > @@ -1852,6 +1866,10 @@ int ceph_uninline_data(struct file *filp, struct page *locked_page)
> >   	err = ceph_osdc_start_request(&fsc->client->osdc, req, false);
> >   	if (!err)
> >   		err = ceph_osdc_wait_request(&fsc->client->osdc, req);
> > +
> > +	ceph_update_write_latency(&fsc->mdsc->metric, req->r_start_stamp,
> > +				  req->r_end_stamp, err);
> > +
> >   out_put:
> >   	ceph_osdc_put_request(req);
> >   	if (err == -ECANCELED)
> > diff --git a/fs/ceph/debugfs.c b/fs/ceph/debugfs.c
> > index 66b9622..de07fdb 100644
> > --- a/fs/ceph/debugfs.c
> > +++ b/fs/ceph/debugfs.c
> > @@ -7,6 +7,7 @@
> >   #include <linux/ctype.h>
> >   #include <linux/debugfs.h>
> >   #include <linux/seq_file.h>
> > +#include <linux/math64.h>
> >   
> >   #include <linux/ceph/libceph.h>
> >   #include <linux/ceph/mon_client.h>
> > @@ -124,13 +125,70 @@ static int mdsc_show(struct seq_file *s, void *p)
> >   	return 0;
> >   }
> >   
> > +static u64 get_avg(u64 *totalp, u64 *sump, spinlock_t *lockp, u64 *total)
> > +{
> > +	u64 t, sum, avg = 0;
> > +
> > +	spin_lock(lockp);
> > +	t = *totalp;
> > +	sum = *sump;
> > +	spin_unlock(lockp);
> > +
> > +	if (likely(t))
> > +		avg = DIV64_U64_ROUND_CLOSEST(sum, t);
> > +
> > +	*total = t;
> > +	return avg;
> > +}
> > +
> > +#define CEPH_METRIC_SHOW(name, total, avg, min, max, sq) {		\
> > +	u64 _total, _avg, _min, _max, _sq, _st, _re = 0;		\
> > +	_avg = jiffies_to_usecs(avg);					\
> > +	_min = jiffies_to_usecs(min == S64_MAX ? 0 : min);		\
> > +	_max = jiffies_to_usecs(max);					\
> > +	_total = total - 1;						\
> > +	_sq = _total > 0 ? DIV64_U64_ROUND_CLOSEST(sq, _total) : 0;	\
> > +	_sq = jiffies_to_usecs(_sq);					\
> > +	_st = int_sqrt64(_sq);						\
> > +	if (_st > 0) {							\
> > +		_re = 5 * (_sq - (_st * _st));				\
> > +		_re = _re > 0 ? _re - 1 : 0;				\
> > +		_re = _st > 0 ? div64_s64(_re, _st) : 0;		\
> > +	}								\
> > +	seq_printf(s, "%-14s%-12llu%-16llu%-16llu%-16llu%llu.%llu\n",	\
> > +		   name, total, _avg, _min, _max, _st, _re);		\
> > +}
> > +
> >   static int metric_show(struct seq_file *s, void *p)
> >   {
> >   	struct ceph_fs_client *fsc = s->private;
> >   	struct ceph_mds_client *mdsc = fsc->mdsc;
> >   	struct ceph_client_metric *m = &mdsc->metric;
> >   	int i, nr_caps = 0;
> > -
> > +	u64 total, avg, min, max, sq;
> > +
> > +	seq_printf(s, "item          total       avg_lat(us)     min_lat(us)     max_lat(us)     stdev(us)\n");
> > +	seq_printf(s, "-----------------------------------------------------------------------------------\n");
> > +
> > +	avg = get_avg(&m->total_reads,
> > +		      &m->read_latency_sum,
> > +		      &m->read_latency_lock,
> > +		      &total);
> > +	min = atomic64_read(&m->read_latency_min);
> > +	max = atomic64_read(&m->read_latency_max);
> > +	sq = percpu_counter_sum(&m->read_latency_sq_sum);
> > +	CEPH_METRIC_SHOW("read", total, avg, min, max, sq);
> > +
> > +	avg = get_avg(&m->total_writes,
> > +		      &m->write_latency_sum,
> > +		      &m->write_latency_lock,
> > +		      &total);
> > +	min = atomic64_read(&m->write_latency_min);
> > +	max = atomic64_read(&m->write_latency_max);
> > +	sq = percpu_counter_sum(&m->write_latency_sq_sum);
> > +	CEPH_METRIC_SHOW("write", total, avg, min, max, sq);
> > +
> > +	seq_printf(s, "\n");
> >   	seq_printf(s, "item          total           miss            hit\n");
> >   	seq_printf(s, "-------------------------------------------------\n");
> >   
> > diff --git a/fs/ceph/file.c b/fs/ceph/file.c
> > index 4a5ccbb..8e40022 100644
> > --- a/fs/ceph/file.c
> > +++ b/fs/ceph/file.c
> > @@ -906,6 +906,10 @@ static ssize_t ceph_sync_read(struct kiocb *iocb, struct iov_iter *to,
> >   		ret = ceph_osdc_start_request(osdc, req, false);
> >   		if (!ret)
> >   			ret = ceph_osdc_wait_request(osdc, req);
> > +
> > +		ceph_update_read_latency(&fsc->mdsc->metric, req->r_start_stamp,
> > +					 req->r_end_stamp, ret);
> > +
> >   		ceph_osdc_put_request(req);
> >   
> >   		i_size = i_size_read(inode);
> > @@ -1044,6 +1048,8 @@ static void ceph_aio_complete_req(struct ceph_osd_request *req)
> >   	struct inode *inode = req->r_inode;
> >   	struct ceph_aio_request *aio_req = req->r_priv;
> >   	struct ceph_osd_data *osd_data = osd_req_op_extent_osd_data(req, 0);
> > +	struct ceph_fs_client *fsc = ceph_inode_to_client(inode);
> > +	struct ceph_client_metric *metric = &fsc->mdsc->metric;
> >   
> >   	BUG_ON(osd_data->type != CEPH_OSD_DATA_TYPE_BVECS);
> >   	BUG_ON(!osd_data->num_bvecs);
> > @@ -1051,6 +1057,16 @@ static void ceph_aio_complete_req(struct ceph_osd_request *req)
> >   	dout("ceph_aio_complete_req %p rc %d bytes %u\n",
> >   	     inode, rc, osd_data->bvec_pos.iter.bi_size);
> >   
> > +	/* r_start_stamp == 0 means the request was not submitted */
> > +	if (req->r_start_stamp) {
> > +		if (aio_req->write)
> > +			ceph_update_write_latency(metric, req->r_start_stamp,
> > +						  req->r_end_stamp, rc);
> > +		else
> > +			ceph_update_read_latency(metric, req->r_start_stamp,
> > +						 req->r_end_stamp, rc);
> > +	}
> > +
> >   	if (rc == -EOLDSNAPC) {
> >   		struct ceph_aio_work *aio_work;
> >   		BUG_ON(!aio_req->write);
> > @@ -1179,6 +1195,7 @@ static void ceph_aio_retry_work(struct work_struct *work)
> >   	struct inode *inode = file_inode(file);
> >   	struct ceph_inode_info *ci = ceph_inode(inode);
> >   	struct ceph_fs_client *fsc = ceph_inode_to_client(inode);
> > +	struct ceph_client_metric *metric = &fsc->mdsc->metric;
> >   	struct ceph_vino vino;
> >   	struct ceph_osd_request *req;
> >   	struct bio_vec *bvecs;
> > @@ -1295,6 +1312,13 @@ static void ceph_aio_retry_work(struct work_struct *work)
> >   		if (!ret)
> >   			ret = ceph_osdc_wait_request(&fsc->client->osdc, req);
> >   
> > +		if (write)
> > +			ceph_update_write_latency(metric, req->r_start_stamp,
> > +						  req->r_end_stamp, ret);
> > +		else
> > +			ceph_update_read_latency(metric, req->r_start_stamp,
> > +						 req->r_end_stamp, ret);
> > +
> >   		size = i_size_read(inode);
> >   		if (!write) {
> >   			if (ret == -ENOENT)
> > @@ -1466,6 +1490,8 @@ static void ceph_aio_retry_work(struct work_struct *work)
> >   		if (!ret)
> >   			ret = ceph_osdc_wait_request(&fsc->client->osdc, req);
> >   
> > +		ceph_update_write_latency(&fsc->mdsc->metric, req->r_start_stamp,
> > +					  req->r_end_stamp, ret);
> >   out:
> >   		ceph_osdc_put_request(req);
> >   		if (ret != 0) {
> > diff --git a/fs/ceph/metric.c b/fs/ceph/metric.c
> > index 2a4b739..6cb64fb 100644
> > --- a/fs/ceph/metric.c
> > +++ b/fs/ceph/metric.c
> > @@ -2,6 +2,7 @@
> >   
> >   #include <linux/types.h>
> >   #include <linux/percpu_counter.h>
> > +#include <linux/math64.h>
> >   
> >   #include "metric.h"
> >   
> > @@ -29,8 +30,32 @@ int ceph_metric_init(struct ceph_client_metric *m)
> >   	if (ret)
> >   		goto err_i_caps_mis;
> >   
> > +	ret = percpu_counter_init(&m->read_latency_sq_sum, 0, GFP_KERNEL);
> > +	if (ret)
> > +		goto err_read_latency_sq_sum;
> > +
> > +	atomic64_set(&m->read_latency_min, S64_MAX);
> > +	atomic64_set(&m->read_latency_max, 0);
> > +	spin_lock_init(&m->read_latency_lock);
> > +	m->total_reads = 0;
> > +	m->read_latency_sum = 0;
> > +
> > +	ret = percpu_counter_init(&m->write_latency_sq_sum, 0, GFP_KERNEL);
> > +	if (ret)
> > +		goto err_write_latency_sq_sum;
> > +
> > +	atomic64_set(&m->write_latency_min, S64_MAX);
> > +	atomic64_set(&m->write_latency_max, 0);
> > +	spin_lock_init(&m->write_latency_lock);
> > +	m->total_writes = 0;
> > +	m->write_latency_sum = 0;
> > +
> >   	return 0;
> >   
> > +err_write_latency_sq_sum:
> > +	percpu_counter_destroy(&m->read_latency_sq_sum);
> > +err_read_latency_sq_sum:
> > +	percpu_counter_destroy(&m->i_caps_mis);
> >   err_i_caps_mis:
> >   	percpu_counter_destroy(&m->i_caps_hit);
> >   err_i_caps_hit:
> > @@ -46,8 +71,93 @@ void ceph_metric_destroy(struct ceph_client_metric *m)
> >   	if (!m)
> >   		return;
> >   
> > +	percpu_counter_destroy(&m->write_latency_sq_sum);
> > +	percpu_counter_destroy(&m->read_latency_sq_sum);
> >   	percpu_counter_destroy(&m->i_caps_mis);
> >   	percpu_counter_destroy(&m->i_caps_hit);
> >   	percpu_counter_destroy(&m->d_lease_mis);
> >   	percpu_counter_destroy(&m->d_lease_hit);
> >   }
> > +
> > +static inline void __update_min_latency(atomic64_t *min, unsigned long lat)
> > +{
> > +	u64 cur, old;
> > +
> > +	cur = atomic64_read(min);
> > +	do {
> > +		old = cur;
> > +		if (likely(lat >= old))
> > +			break;
> > +	} while (unlikely((cur = atomic64_cmpxchg(min, old, lat)) != old));
> > +}
> > +
> > +static inline void __update_max_latency(atomic64_t *max, unsigned long lat)
> > +{
> > +	u64 cur, old;
> > +
> > +	cur = atomic64_read(max);
> > +	do {
> > +		old = cur;
> > +		if (likely(lat <= old))
> > +			break;
> > +	} while (unlikely((cur = atomic64_cmpxchg(max, old, lat)) != old));
> > +}
> > +
> > +static inline void __update_avg_and_sq(u64 *totalp, u64 *lsump,
> > +				       struct percpu_counter *sq_sump,
> > +				       spinlock_t *lockp, unsigned long lat)
> > +{
> > +	u64 total, avg, sq, lsum;
> > +
> > +	spin_lock(lockp);
> > +	total = ++(*totalp);
> > +	*lsump += lat;
> > +	lsum = *lsump;
> > +	spin_unlock(lockp);

For each read/write/metadata latency updating,  I am trying to just make 
the critical code as small as possible here.


> > +
> > +	if (unlikely(total == 1))
> > +		return;
> > +
> > +	/* the sq is (lat - old_avg) * (lat - new_avg) */
> > +	avg = DIV64_U64_ROUND_CLOSEST((lsum - lat), (total - 1));
> > +	sq = lat - avg;
> > +	avg = DIV64_U64_ROUND_CLOSEST(lsum, total);
> > +	sq = sq * (lat - avg);
> > +	percpu_counter_add(sq_sump, sq);

IMO, the percpu_counter could bring us benefit without locks, which will 
do many div/muti many times and will take some longer time on computing 
the sq.


> > +}
> > +
> > +void ceph_update_read_latency(struct ceph_client_metric *m,
> > +			      unsigned long r_start,
> > +			      unsigned long r_end,
> > +			      int rc)
> > +{
> > +	unsigned long lat = r_end - r_start;
> > +
> > +	if (unlikely(rc < 0 && rc != -ENOENT && rc != -ETIMEDOUT))
> > +		return;
> > +
> > +	__update_min_latency(&m->read_latency_min, lat);
> > +	__update_max_latency(&m->read_latency_max, lat);

And also here to update the min/max without locks, but this should be 
okay to switch to u64 and under the locks.

Thought ?

If this makes sense, I will make the min/max to u64 type, and keep the 
sq_sum as the percpu. Or I will make them all to u64.

Thanks.



> > +	__update_avg_and_sq(&m->total_reads, &m->read_latency_sum,
> > +			    &m->read_latency_sq_sum,
> > +			    &m->read_latency_lock,
> > +			    lat);
> > +}
> > +
> > +void ceph_update_write_latency(struct ceph_client_metric *m,
> > +			       unsigned long r_start,
> > +			       unsigned long r_end,
> > +			       int rc)
> > +{
> > +	unsigned long lat = r_end - r_start;
> > +
> > +	if (unlikely(rc && rc != -ETIMEDOUT))
> > +		return;
> > +
> > +	__update_min_latency(&m->write_latency_min, lat);
> > +	__update_max_latency(&m->write_latency_max, lat);
> > +	__update_avg_and_sq(&m->total_writes, &m->write_latency_sum,
> > +			    &m->write_latency_sq_sum,
> > +			    &m->write_latency_lock,
> > +			    lat);
> > +}
> > diff --git a/fs/ceph/metric.h b/fs/ceph/metric.h
> > index 098ee8a..c7eae56 100644
> > --- a/fs/ceph/metric.h
> > +++ b/fs/ceph/metric.h
> > @@ -13,6 +13,20 @@ struct ceph_client_metric {
> >   
> >   	struct percpu_counter i_caps_hit;
> >   	struct percpu_counter i_caps_mis;
> > +
> > +	struct percpu_counter read_latency_sq_sum;
> > +	atomic64_t read_latency_min;
> > +	atomic64_t read_latency_max;
> I'd make the above 3 values be regular values and make them all use the
> read_latency_lock. Given that you're taking a lock anyway, it's more
> efficient to just do all of the manipulation under a single spinlock
> rather than fooling with atomic or percpu values. These are all almost
> certainly going to be in the same cacheline anyway.
>
> > +	spinlock_t read_latency_lock;
> > +	u64 total_reads;
> > +	u64 read_latency_sum;
> > +
> > +	struct percpu_counter write_latency_sq_sum;
> > +	atomic64_t write_latency_min;
> > +	atomic64_t write_latency_max;
> > +	spinlock_t write_latency_lock;
> > +	u64 total_writes;
> > +	u64 write_latency_sum;
> >   };
> >   
> >   extern int ceph_metric_init(struct ceph_client_metric *m);
> > @@ -27,4 +41,13 @@ static inline void ceph_update_cap_mis(struct ceph_client_metric *m)
> >   {
> >   	percpu_counter_inc(&m->i_caps_mis);
> >   }
> > +
> > +extern void ceph_update_read_latency(struct ceph_client_metric *m,
> > +				     unsigned long r_start,
> > +				     unsigned long r_end,
> > +				     int rc);
> > +extern void ceph_update_write_latency(struct ceph_client_metric *m,
> > +				      unsigned long r_start,
> > +				      unsigned long r_end,
> > +				      int rc);
> >   #endif /* _FS_CEPH_MDS_METRIC_H */
> > diff --git a/include/linux/ceph/osd_client.h b/include/linux/ceph/osd_client.h
> > index 9d9f745..02ff3a3 100644
> > --- a/include/linux/ceph/osd_client.h
> > +++ b/include/linux/ceph/osd_client.h
> > @@ -213,6 +213,7 @@ struct ceph_osd_request {
> >   	/* internal */
> >   	unsigned long r_stamp;                /* jiffies, send or check time */
> >   	unsigned long r_start_stamp;          /* jiffies */
> > +	unsigned long r_end_stamp;            /* jiffies */
> >   	int r_attempts;
> >   	u32 r_map_dne_bound;
> >   
> > diff --git a/net/ceph/osd_client.c b/net/ceph/osd_client.c
> > index 998e26b..28e33e0 100644
> > --- a/net/ceph/osd_client.c
> > +++ b/net/ceph/osd_client.c
> > @@ -2389,6 +2389,8 @@ static void finish_request(struct ceph_osd_request *req)
> >   	WARN_ON(lookup_request_mc(&osdc->map_checks, req->r_tid));
> >   	dout("%s req %p tid %llu\n", __func__, req, req->r_tid);
> >   
> > +	req->r_end_stamp = jiffies;
> > +
> >   	if (req->r_osd)
> >   		unlink_request(req->r_osd, req);
> >   	atomic_dec(&osdc->num_requests);