From 1ad0a4842521721e1d27f7d8b7edee8917055a24 Mon Sep 17 00:00:00 2001 From: Ali Maredia Date: Tue, 2 Mar 2021 00:24:14 -0500 Subject: [PATCH] rgw: add latency to the request summary of an op Latency of a request added at the end of request summary rgw log line. This summary line also contains information about the request like the op, bucket, object, http status. Signed-off-by: Ali Maredia (cherry picked from commit 91e720d37c73719ab66be0947e6b828bb2853d7b) --- src/rgw/rgw_asio_frontend.cc | 6 ++++-- src/rgw/rgw_civetweb_frontend.cc | 3 ++- src/rgw/rgw_loadgen_process.cc | 2 +- src/rgw/rgw_process.cc | 8 +++++++- src/rgw/rgw_process.h | 1 + 5 files changed, 15 insertions(+), 5 deletions(-) diff --git a/src/rgw/rgw_asio_frontend.cc b/src/rgw/rgw_asio_frontend.cc index e5334844f6361..b900e7dbc7793 100644 --- a/src/rgw/rgw_asio_frontend.cc +++ b/src/rgw/rgw_asio_frontend.cc @@ -254,10 +254,11 @@ void handle_connection(boost::asio::io_context& context, int http_ret = 0; string user = "-"; const auto started = ceph::coarse_real_clock::now(); + ceph::coarse_real_clock::duration latency{}; process_request(env.store, env.rest, &req, env.uri_prefix, *env.auth_registry, &client, env.olog, y, - scheduler, &user, &http_ret); + scheduler, &user, &latency, &http_ret); if (cct->_conf->subsys.should_gather(dout_subsys, 1)) { // access log line elements begin per Apache Combined Log Format with additions following @@ -268,7 +269,8 @@ void handle_connection(boost::asio::io_context& context, << client.get_bytes_sent() + client.get_bytes_received() << ' ' << log_header{message, http::field::referer, "\""} << ' ' << log_header{message, http::field::user_agent, "\""} << ' ' - << log_header{message, http::field::range} << dendl; + << log_header{message, http::field::range} << " latency=" + << latency << dendl; } } diff --git a/src/rgw/rgw_civetweb_frontend.cc b/src/rgw/rgw_civetweb_frontend.cc index 98dd4010df9c6..6c672db49b6b5 100644 --- a/src/rgw/rgw_civetweb_frontend.cc +++ b/src/rgw/rgw_civetweb_frontend.cc @@ -66,10 +66,11 @@ int RGWCivetWebFrontend::process(struct mg_connection* const conn) RGWRequest req(env.store->getRados()->get_new_req_id()); int http_ret = 0; + ceph::coarse_real_clock::duration latency{}; //assert (scheduler != nullptr); int ret = process_request(env.store, env.rest, &req, env.uri_prefix, *env.auth_registry, &client_io, env.olog, - null_yield, scheduler.get(), nullptr, &http_ret); + null_yield, scheduler.get(), nullptr, &latency, &http_ret); if (ret < 0) { /* We don't really care about return code. */ dout(20) << "process_request() returned " << ret << dendl; diff --git a/src/rgw/rgw_loadgen_process.cc b/src/rgw/rgw_loadgen_process.cc index fe0b198874705..f2d3d217131e3 100644 --- a/src/rgw/rgw_loadgen_process.cc +++ b/src/rgw/rgw_loadgen_process.cc @@ -134,7 +134,7 @@ void RGWLoadGenProcess::handle_request(RGWRequest* r) int ret = process_request(store, rest, req, uri_prefix, *auth_registry, &client_io, olog, - null_yield, nullptr, nullptr); + null_yield, nullptr, nullptr, nullptr); if (ret < 0) { /* we don't really care about return code */ dout(20) << "process_request() returned " << ret << dendl; diff --git a/src/rgw/rgw_process.cc b/src/rgw/rgw_process.cc index 39d207b86aa5f..fb8c06824c71e 100644 --- a/src/rgw/rgw_process.cc +++ b/src/rgw/rgw_process.cc @@ -182,6 +182,7 @@ int process_request(rgw::sal::RGWRadosStore* const store, optional_yield yield, rgw::dmclock::Scheduler *scheduler, string* user, + ceph::coarse_real_clock::duration* latency, int* http_ret) { int ret = client_io->init(g_ceph_context); @@ -355,10 +356,15 @@ done: handler->put_op(op); rest->put_handler(handler); + const auto lat = s->time_elapsed(); + if (latency) { + *latency = lat; + } + dout(1) << "====== req done req=" << hex << req << dec << " op status=" << op_ret << " http_status=" << s->err.http_ret - << " latency=" << s->time_elapsed() + << " latency=" << lat << " ======" << dendl; diff --git a/src/rgw/rgw_process.h b/src/rgw/rgw_process.h index b0365ece9d088..0afea681c2c10 100644 --- a/src/rgw/rgw_process.h +++ b/src/rgw/rgw_process.h @@ -186,6 +186,7 @@ extern int process_request(rgw::sal::RGWRadosStore* store, optional_yield y, rgw::dmclock::Scheduler *scheduler, std::string* user, + ceph::coarse_real_clock::duration* latency, int* http_ret = nullptr); extern int rgw_process_authenticated(RGWHandler_REST* handler, -- 2.39.5