From c44d40219c0eea32c442350dcdb4b4b2570e0bb8 Mon Sep 17 00:00:00 2001 From: Igor Golikov Date: Sun, 3 Aug 2025 15:11:32 +0000 Subject: [PATCH] client: switch to mono time for measuring latencies Signed-off-by: Igor Golikov Fixes: https://tracker.ceph.com/issues/68929 --- src/client/Client.cc | 46 ++++++++++++++++++++++---------------------- src/client/Client.h | 22 ++++++++++----------- src/common/Clock.h | 14 ++++++++++++++ 3 files changed, 48 insertions(+), 34 deletions(-) diff --git a/src/client/Client.cc b/src/client/Client.cc index 98fd1a525ff..208051092df 100644 --- a/src/client/Client.cc +++ b/src/client/Client.cc @@ -2269,7 +2269,7 @@ int Client::make_request(MetaRequest *request, *pdirbl = reply->get_extra_bl(); // -- log times -- - utime_t lat = ceph_clock_now(); + utime_t lat = mono_clock_now(); lat -= request->sent_stamp; ldout(cct, 20) << "lat " << lat << dendl; @@ -10968,7 +10968,7 @@ void Client::C_Read_Finisher::finish_io(int r) f->pos = offset + r; } - lat = ceph_clock_now(); + lat = mono_clock_now(); lat -= start; clnt->subvolume_tracker->add_metric(in->ino, SimpleIOMetric{false, lat, static_cast(r)}); ++clnt->nr_read_request; @@ -11057,7 +11057,7 @@ void Client::C_Read_Sync_NonBlocking::finish(int r) success: r = read; - clnt->subvolume_tracker->add_metric(in->ino, SimpleIOMetric(false, ceph_clock_now() - start_time, r)); + clnt->subvolume_tracker->add_metric(in->ino, SimpleIOMetric(false, mono_clock_now() - start_time, r)); error: onfinish->complete(r); @@ -11079,7 +11079,7 @@ int64_t Client::_read(Fh *f, int64_t offset, uint64_t size, bufferlist *bl, const auto& conf = cct->_conf; Inode *in = f->inode.get(); utime_t lat; - utime_t start = ceph_clock_now(); + utime_t start = mono_clock_now(); CRF_iofinish *crf_iofinish = nullptr; if ((f->mode & CEPH_FILE_MODE_RD) == 0) @@ -11150,7 +11150,7 @@ retry: conf->client_oc && (have & (CEPH_CAP_FILE_CACHE | CEPH_CAP_FILE_LAZYIO)), - have, movepos, start, f, in, f->pos, offset, size)); + have, movepos, f, in, f->pos, offset, size)); crf_iofinish->CRF = crf.get(); } @@ -11216,7 +11216,7 @@ retry: C_Read_Sync_NonBlocking *crsa = new C_Read_Sync_NonBlocking(this, iofinish.release(), f, in, f->pos, - offset, size, bl, filer.get(), have, ceph_clock_now()); + offset, size, bl, filer.get(), have); crf.release(); // Now make first attempt at performing _read_sync @@ -11264,7 +11264,7 @@ success: f->pos = start_pos + rc; } - lat = ceph_clock_now(); + lat = mono_clock_now(); lat -= start; subvolume_tracker->add_metric(in->ino, SimpleIOMetric{false, lat, bl->length()}); ++nr_read_request; @@ -11281,8 +11281,8 @@ done: return rc; } -Client::C_Readahead::C_Readahead(Client *c, Fh *f, utime_t start) : - client(c), f(f), start_time(start){ +Client::C_Readahead::C_Readahead(Client *c, Fh *f) : + client(c), f(f), start_time(mono_clock_now()) { f->get(); f->readahead.inc_pending(); } @@ -11297,18 +11297,18 @@ void Client::C_Readahead::finish(int r) { client->put_cap_ref(f->inode.get(), CEPH_CAP_FILE_RD | CEPH_CAP_FILE_CACHE); if (r > 0) { client->update_read_io_size(r); - client->subvolume_tracker->add_metric(f->inode->ino, SimpleIOMetric(false, ceph_clock_now()-start_time, r)); + client->subvolume_tracker->add_metric(f->inode->ino, SimpleIOMetric(false, mono_clock_now()-start_time, r)); } } -void Client::do_readahead(Fh *f, Inode *in, uint64_t off, uint64_t len, utime_t start_time) +void Client::do_readahead(Fh *f, Inode *in, uint64_t off, uint64_t len) { if(f->readahead.get_min_readahead_size() > 0) { pair readahead_extent = f->readahead.update(off, len, in->size); if (readahead_extent.second > 0) { ldout(cct, 20) << "readahead " << readahead_extent.first << "~" << readahead_extent.second << " (caller wants " << off << "~" << len << ")" << dendl; - Context *onfinish2 = new C_Readahead(this, f, start_time); + Context *onfinish2 = new C_Readahead(this, f); int r2 = objectcacher->file_read(&in->oset, &in->layout, in->snapid, readahead_extent.first, readahead_extent.second, NULL, 0, onfinish2); @@ -11327,7 +11327,7 @@ void Client::C_Read_Async_Finisher::finish(int r) { // Do read ahead as long as we aren't completing with 0 bytes if (r != 0) - clnt->do_readahead(f, in, off, len, start_time); + clnt->do_readahead(f, in, off, len); onfinish->complete(r); } @@ -11349,7 +11349,7 @@ int Client::_read_async(Fh *f, uint64_t off, uint64_t len, bufferlist *bl, if (onfinish != nullptr) { io_finish.reset(new C_Read_Async_Finisher(this, onfinish, f, in, - f->pos, off, len, ceph_clock_now())); + f->pos, off, len)); } // trim read based on file size? @@ -11390,7 +11390,7 @@ int Client::_read_async(Fh *f, uint64_t off, uint64_t len, bufferlist *bl, io_finish.reset(io_finish_cond); } - auto start_time = ceph_clock_now(); + auto start_time = mono_clock_now(); r = objectcacher->file_read(&in->oset, &in->layout, in->snapid, off, len, bl, 0, io_finish.get()); @@ -11416,12 +11416,12 @@ int Client::_read_async(Fh *f, uint64_t off, uint64_t len, bufferlist *bl, client_lock.lock(); put_cap_ref(in, CEPH_CAP_FILE_CACHE); update_read_io_size(bl->length()); - subvolume_tracker->add_metric(in->ino, SimpleIOMetric{false, ceph_clock_now() - start_time, bl->length()}); + subvolume_tracker->add_metric(in->ino, SimpleIOMetric{false, mono_clock_now() - start_time, bl->length()}); } else { put_cap_ref(in, CEPH_CAP_FILE_CACHE); } - do_readahead(f, in, off, len, ceph_clock_now()); + do_readahead(f, in, off, len); return r; } @@ -11626,7 +11626,7 @@ int64_t Client::_write_success(Fh *f, utime_t start, uint64_t fpos, update_write_io_size(size); // time - lat = ceph_clock_now(); + lat = mono_clock_now(); lat -= start; subvolume_tracker->add_metric(in->ino, SimpleIOMetric{true, lat, static_cast(size)}); @@ -11826,7 +11826,7 @@ int64_t Client::_write(Fh *f, int64_t offset, uint64_t size, bufferlist bl, ldout(cct, 10) << "cur file size is " << in->size << dendl; // time it. - utime_t start = ceph_clock_now(); + utime_t start = mono_clock_now(); if (in->inline_version == 0) { int r = _getattr(in, CEPH_STAT_CAP_INLINE_DATA, f->actor_perms, true); @@ -11899,7 +11899,7 @@ int64_t Client::_write(Fh *f, int64_t offset, uint64_t size, bufferlist bl, cct->_conf->client_oc && (have & (CEPH_CAP_FILE_BUFFER | CEPH_CAP_FILE_LAZYIO)), - start, f, in, fpos, offset, size, + f, in, fpos, offset, size, do_fsync, syncdataonly)); cwf_iofinish->CWF = cwf.get(); @@ -12288,7 +12288,7 @@ void Client::C_nonblocking_fsync_state::advance() utime_t lat; - lat = ceph_clock_now(); + lat = mono_clock_now(); lat -= start; clnt->logger->tinc(l_c_fsync, lat); @@ -12342,7 +12342,7 @@ int Client::_fsync(Inode *in, bool syncdataonly) ceph_tid_t flush_tid = 0; InodeRef tmp_ref; utime_t lat; - utime_t start = ceph_clock_now(); + utime_t start = mono_clock_now(); ldout(cct, 8) << "_fsync on " << *in << " " << (syncdataonly ? "(dataonly)":"(data+metadata)") << dendl; @@ -12395,7 +12395,7 @@ int Client::_fsync(Inode *in, bool syncdataonly) << cpp_strerror(-r) << dendl; } - lat = ceph_clock_now(); + lat = mono_clock_now(); lat -= start; logger->tinc(l_c_fsync, lat); diff --git a/src/client/Client.h b/src/client/Client.h index 6d26726b054..ada0acb8c28 100644 --- a/src/client/Client.h +++ b/src/client/Client.h @@ -1391,11 +1391,11 @@ private: C_Read_Finisher(Client *clnt, Context *onfinish, Context *iofinish, bool is_read_async, int have_caps, bool movepos, - utime_t start, Fh *f, Inode *in, uint64_t fpos, + Fh *f, Inode *in, uint64_t fpos, int64_t offset, uint64_t size) : clnt(clnt), onfinish(onfinish), iofinish(iofinish), is_read_async(is_read_async), have_caps(have_caps), f(f), in(in), - start(start), fpos(fpos), offset(offset), size(size), movepos(movepos) { + start(mono_clock_now()), fpos(fpos), offset(offset), size(size), movepos(movepos) { iofinished = false; } @@ -1442,9 +1442,9 @@ private: public: C_Read_Sync_NonBlocking(Client *clnt, Context *onfinish, Fh *f, Inode *in, uint64_t fpos, uint64_t off, uint64_t len, - bufferlist *bl, Filer *filer, int have_caps, utime_t start) + bufferlist *bl, Filer *filer, int have_caps) : clnt(clnt), onfinish(onfinish), f(f), in(in), off(off), len(len), bl(bl), - filer(filer), have_caps(have_caps), start_time(start) + filer(filer), have_caps(have_caps), start_time(mono_clock_now()) { left = len; wanted = len; @@ -1486,8 +1486,8 @@ private: class C_Read_Async_Finisher : public Context { public: C_Read_Async_Finisher(Client *clnt, Context *onfinish, Fh *f, Inode *in, - uint64_t fpos, uint64_t off, uint64_t len, utime_t start) - : clnt(clnt), onfinish(onfinish), f(f), in(in), off(off), len(len), start_time(start) {} + uint64_t fpos, uint64_t off, uint64_t len) + : clnt(clnt), onfinish(onfinish), f(f), in(in), off(off), len(len), start_time(mono_clock_now()) {} private: Client *clnt; @@ -1523,11 +1523,11 @@ private: void finish_fsync(int r); C_Write_Finisher(Client *clnt, Context *onfinish, bool dont_need_uninline, - bool is_file_write, utime_t start, Fh *f, Inode *in, + bool is_file_write, Fh *f, Inode *in, uint64_t fpos, int64_t offset, uint64_t size, bool do_fsync, bool syncdataonly) : clnt(clnt), onfinish(onfinish), - is_file_write(is_file_write), start(start), f(f), in(in), fpos(fpos), + is_file_write(is_file_write), start(mono_clock_now()), f(f), in(in), fpos(fpos), offset(offset), size(size), syncdataonly(syncdataonly) { iofinished_r = 0; onuninlinefinished_r = 0; @@ -1607,7 +1607,7 @@ private: C_nonblocking_fsync_state(Client *clnt, Inode *in, bool syncdataonly, Context *onfinish) : clnt(clnt), in(in), syncdataonly(syncdataonly), onfinish(onfinish) { flush_tid = 0; - start = ceph_clock_now(); + start = mono_clock_now(); progress = 0; flush_wait = false; flush_completed = false; @@ -1646,7 +1646,7 @@ private: }; struct C_Readahead : public Context { - C_Readahead(Client *c, Fh *f, utime_t start); + C_Readahead(Client *c, Fh *f); ~C_Readahead() override; void finish(int r) override; @@ -1796,7 +1796,7 @@ private: loff_t _lseek(Fh *fh, loff_t offset, int whence); int64_t _read(Fh *fh, int64_t offset, uint64_t size, bufferlist *bl, Context *onfinish = nullptr); - void do_readahead(Fh *f, Inode *in, uint64_t off, uint64_t len, utime_t start_time); + void do_readahead(Fh *f, Inode *in, uint64_t off, uint64_t len); int64_t _write_success(Fh *fh, utime_t start, uint64_t fpos, int64_t offset, uint64_t size, Inode *in); int64_t _write(Fh *fh, int64_t offset, uint64_t size, bufferlist bl, diff --git a/src/common/Clock.h b/src/common/Clock.h index b47954ad1ce..44d54525938 100644 --- a/src/common/Clock.h +++ b/src/common/Clock.h @@ -33,4 +33,18 @@ static inline utime_t ceph_clock_now() return n; } +static inline utime_t mono_clock_now() +{ +#if defined(__linux__) + struct timespec tp; + clock_gettime(CLOCK_MONOTONIC, &tp); + utime_t n(tp); +#else + struct timeval tv; + gettimeofday(&tv, nullptr); + utime_t n(&tv); +#endif + return n; +} + #endif -- 2.39.5