From d9284902e1b2e292595696caf11cdead18acec96 Mon Sep 17 00:00:00 2001 From: Casey Bodley Date: Tue, 8 May 2018 15:23:41 -0400 Subject: [PATCH] rgw: use coarse_real_clock for req_state::time Signed-off-by: Casey Bodley --- src/rgw/rgw_admin.cc | 3 ++- src/rgw/rgw_common.cc | 2 +- src/rgw/rgw_common.h | 6 +++++- src/rgw/rgw_file.cc | 3 +-- src/rgw/rgw_log.cc | 19 ++++++++++++------- src/rgw/rgw_log.h | 6 +++--- src/rgw/rgw_op.cc | 7 ++----- src/rgw/rgw_request.cc | 3 +-- src/rgw/rgw_request.h | 1 - 9 files changed, 27 insertions(+), 23 deletions(-) diff --git a/src/rgw/rgw_admin.cc b/src/rgw/rgw_admin.cc index be71476fd4a6..e924aa716e6a 100644 --- a/src/rgw/rgw_admin.cc +++ b/src/rgw/rgw_admin.cc @@ -5343,7 +5343,8 @@ int main(int argc, const char **argv) formatter->open_array_section("log_entries"); do { - uint64_t total_time = entry.total_time.to_msec(); + using namespace std::chrono; + uint64_t total_time = duration_cast(entry.total_time).count(); agg_time += total_time; agg_bytes_sent += entry.bytes_sent; diff --git a/src/rgw/rgw_common.cc b/src/rgw/rgw_common.cc index 285724e9d67b..42c7e979da3b 100644 --- a/src/rgw/rgw_common.cc +++ b/src/rgw/rgw_common.cc @@ -284,7 +284,7 @@ req_state::req_state(CephContext* _cct, RGWEnv* e, RGWUserInfo* u) enable_usage_log = e->get_enable_usage_log(); defer_to_bucket_acls = e->get_defer_to_bucket_acls(); - time = ceph_clock_now(); + time = Clock::now(); } req_state::~req_state() { diff --git a/src/rgw/rgw_common.h b/src/rgw/rgw_common.h index 692c51e21382..9bec2967ecf7 100644 --- a/src/rgw/rgw_common.h +++ b/src/rgw/rgw_common.h @@ -1886,7 +1886,11 @@ struct req_state { req_info info; req_init_state init_state; - utime_t time; + using Clock = ceph::coarse_real_clock; + Clock::time_point time; + + Clock::duration time_elapsed() const { return Clock::now() - time; } + void *obj_ctx{nullptr}; string dialect; string req_id; diff --git a/src/rgw/rgw_file.cc b/src/rgw/rgw_file.cc index da46af7a2a7c..e363d7d96341 100644 --- a/src/rgw/rgw_file.cc +++ b/src/rgw/rgw_file.cc @@ -1511,8 +1511,7 @@ namespace rgw { done: dispose_processor(processor); - perfcounter->tinc(l_rgw_put_lat, - (ceph_clock_now() - s->time)); + perfcounter->tinc(l_rgw_put_lat, s->time_elapsed()); return op_ret; } /* exec_finish */ diff --git a/src/rgw/rgw_log.cc b/src/rgw/rgw_log.cc index 16f0a2931b23..11f856c9d54a 100644 --- a/src/rgw/rgw_log.cc +++ b/src/rgw/rgw_log.cc @@ -237,8 +237,11 @@ void rgw_format_ops_log_entry(struct rgw_log_entry& entry, Formatter *formatter) { formatter->open_object_section("log_entry"); formatter->dump_string("bucket", entry.bucket); - entry.time.gmtime(formatter->dump_stream("time")); // UTC - entry.time.localtime(formatter->dump_stream("time_local")); + { + auto t = utime_t{entry.time}; + t.gmtime(formatter->dump_stream("time")); // UTC + t.localtime(formatter->dump_stream("time_local")); + } formatter->dump_string("remote_addr", entry.remote_addr); string obj_owner = entry.object_owner.to_str(); if (obj_owner.length()) @@ -251,9 +254,11 @@ void rgw_format_ops_log_entry(struct rgw_log_entry& entry, Formatter *formatter) formatter->dump_int("bytes_sent", entry.bytes_sent); formatter->dump_int("bytes_received", entry.bytes_received); formatter->dump_int("object_size", entry.obj_size); - uint64_t total_time = entry.total_time.to_msec(); - - formatter->dump_int("total_time", total_time); + { + using namespace std::chrono; + uint64_t total_time = duration_cast(entry.total_time).count(); + formatter->dump_int("total_time", total_time); + } formatter->dump_string("user_agent", entry.user_agent); formatter->dump_string("referrer", entry.referrer); if (entry.x_headers.size() > 0) { @@ -406,7 +411,7 @@ int rgw_log_op(RGWRados *store, RGWREST* const rest, struct req_state *s, uint64_t bytes_received = ACCOUNTING_IO(s)->get_bytes_received(); entry.time = s->time; - entry.total_time = ceph_clock_now() - s->time; + entry.total_time = s->time_elapsed(); entry.bytes_sent = bytes_sent; entry.bytes_received = bytes_received; if (s->err.http_ret) { @@ -423,7 +428,7 @@ int rgw_log_op(RGWRados *store, RGWREST* const rest, struct req_state *s, encode(entry, bl); struct tm bdt; - time_t t = entry.time.sec(); + time_t t = req_state::Clock::to_time_t(entry.time); if (s->cct->_conf->rgw_log_object_name_utc) gmtime_r(&t, &bdt); else diff --git a/src/rgw/rgw_log.h b/src/rgw/rgw_log.h index c2df19a887d0..23a00c10ecfb 100644 --- a/src/rgw/rgw_log.h +++ b/src/rgw/rgw_log.h @@ -5,7 +5,6 @@ #define CEPH_RGW_LOG_H #include #include "rgw_common.h" -#include "include/utime.h" #include "common/Formatter.h" #include "common/OutputDataSocket.h" @@ -14,11 +13,12 @@ class RGWRados; struct rgw_log_entry { using headers_map = boost::container::flat_map; + using Clock = req_state::Clock; rgw_user object_owner; rgw_user bucket_owner; string bucket; - utime_t time; + Clock::time_point time; string remote_addr; string user; rgw_obj_key obj; @@ -29,7 +29,7 @@ struct rgw_log_entry { uint64_t bytes_sent; uint64_t bytes_received; uint64_t obj_size; - utime_t total_time; + Clock::duration total_time; string user_agent; string referrer; string bucket_id; diff --git a/src/rgw/rgw_op.cc b/src/rgw/rgw_op.cc index 8c9e568e8a5f..67ae986e60fa 100644 --- a/src/rgw/rgw_op.cc +++ b/src/rgw/rgw_op.cc @@ -1710,7 +1710,6 @@ static bool object_is_expired(map& attrs) { void RGWGetObj::execute() { - utime_t start_time = s->time; bufferlist bl; gc_invalidate_time = ceph_clock_now(); gc_invalidate_time += (s->cct->_conf->rgw_gc_obj_min_wait / 2); @@ -1867,8 +1866,7 @@ void RGWGetObj::execute() if (op_ret >= 0) op_ret = filter->flush(); - perfcounter->tinc(l_rgw_get_lat, - (ceph_clock_now() - start_time)); + perfcounter->tinc(l_rgw_get_lat, s->time_elapsed()); if (op_ret < 0) { goto done_err; } @@ -3803,8 +3801,7 @@ void RGWPutObj::execute() done: dispose_processor(processor); - perfcounter->tinc(l_rgw_put_lat, - (ceph_clock_now() - s->time)); + perfcounter->tinc(l_rgw_put_lat, s->time_elapsed()); } int RGWPostObj::verify_permission() diff --git a/src/rgw/rgw_request.cc b/src/rgw/rgw_request.cc index dcad1993e25e..11a147629f5c 100644 --- a/src/rgw/rgw_request.cc +++ b/src/rgw/rgw_request.cc @@ -22,7 +22,6 @@ void RGWRequest::log_format(struct req_state *s, const char *fmt, ...) } /* RGWRequest::log_format */ void RGWRequest::log_init() { - ts = ceph_clock_now(); } void RGWRequest::log(struct req_state *s, const char *msg) { @@ -31,7 +30,7 @@ void RGWRequest::log(struct req_state *s, const char *msg) { req_str.append(" "); req_str.append(s->info.request_uri); } - utime_t t = ceph_clock_now() - ts; + auto t = s->time_elapsed(); dout(2) << "req " << id << ":" << t << ":" << s->dialect << ":" << req_str << ":" << (op ? op->name() : "") << ":" << msg << dendl; diff --git a/src/rgw/rgw_request.h b/src/rgw/rgw_request.h index 11345bb0d230..a30437768d27 100644 --- a/src/rgw/rgw_request.h +++ b/src/rgw/rgw_request.h @@ -23,7 +23,6 @@ struct RGWRequest struct req_state *s; string req_str; RGWOp *op; - utime_t ts; explicit RGWRequest(uint64_t id) : id(id), s(NULL), op(NULL) {} -- 2.47.3