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 <amaredia@redhat.com>
(cherry picked from commit 91e720d37c73719ab66be0947e6b828bb2853d7b)

diff --git a/src/rgw/rgw_asio_frontend.cc b/src/rgw/rgw_asio_frontend.cc
index e5334844f6361024cb2e91e7dd6f2c1beb1ffd03..b900e7dbc7793ceddf5a99041eda436c56541d6b 100644 (file)
--- 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 98dd4010df9c66d9ed4d084ee6cd70095d71bca9..6c672db49b6b5b5840816456b28befe3d40c5dfe 100644 (file)
--- 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 fe0b198874705b6ea3c9dd4bec04075d2e35a6d0..f2d3d217131e317e5ecd3a6ba7eefc7a24179017 100644 (file)
--- 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 39d207b86aa5fad459bfe51770f78e0e45b85b66..fb8c06824c71ecdabc3722da2a7bcf0554516cb8 100644 (file)
--- 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 b0365ece9d088a7d6e91e56dd74cb26bcae47e9d..0afea681c2c1050271d65f2b096e951970153fa3 100644 (file)
--- 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,