From 8c9805921edac7257a135873e663aea5c4316d1e Mon Sep 17 00:00:00 2001 From: Marcus Watts Date: Sun, 18 Jun 2017 18:18:39 -0400 Subject: [PATCH] Fix bytes_sent bugs. log bytes sent/received. add cct to bufferingfilter add cct to RGWRestfulIO AccountingFilter - save cct for debugging output implement AccountingFilter::complete_request() - account for bytes reported here. BufferingFilter::complete_request() - ignore counts from send_content_length() complete_header(); Code quality note: this patch makes "cct" available for a lot of newly added debug statements. The debug statements are mostly not very useful (and should go away in the future) - *But* the "cct" logic should be redone and incorporated into some base class (such RestfulClient) so that it is possible to easily add in debug statements such as these in the future. Fixes: http://tracker.ceph.com/issues/19870 Signed-off-by: Marcus Watts (cherry picked from commit 0172aab860abe324923a392baf51f956a65b64a5) --- src/rgw/rgw_asio_frontend.cc | 4 +- src/rgw/rgw_civetweb_frontend.cc | 4 +- src/rgw/rgw_client_io.h | 4 +- src/rgw/rgw_client_io_filters.h | 67 +++++++++++++++++++++++++++++--- src/rgw/rgw_fcgi_process.cc | 4 +- src/rgw/rgw_loadgen_process.cc | 2 +- src/rgw/rgw_log.cc | 5 +++ 7 files changed, 75 insertions(+), 15 deletions(-) diff --git a/src/rgw/rgw_asio_frontend.cc b/src/rgw/rgw_asio_frontend.cc index 5fc1deec42e4b..ee6be6256a5ba 100644 --- a/src/rgw/rgw_asio_frontend.cc +++ b/src/rgw/rgw_asio_frontend.cc @@ -111,11 +111,11 @@ static void handle_connection(RGWProcessEnv& env, tcp::socket socket, rgw::asio::ClientIO real_client{socket, parser, buffer}; auto real_client_io = rgw::io::add_reordering( - rgw::io::add_buffering( + rgw::io::add_buffering(cct, rgw::io::add_chunking( rgw::io::add_conlen_controlling( &real_client)))); - RGWRestfulIO client(&real_client_io); + RGWRestfulIO client(cct, &real_client_io); process_request(env.store, env.rest, &req, env.uri_prefix, *env.auth_registry, &client, env.olog); diff --git a/src/rgw/rgw_civetweb_frontend.cc b/src/rgw/rgw_civetweb_frontend.cc index 4b1fd766cbfaa..8cf7a20b0dc01 100644 --- a/src/rgw/rgw_civetweb_frontend.cc +++ b/src/rgw/rgw_civetweb_frontend.cc @@ -24,11 +24,11 @@ int RGWCivetWebFrontend::process(struct mg_connection* const conn) RGWCivetWeb cw_client(conn); auto real_client_io = rgw::io::add_reordering( - rgw::io::add_buffering( + rgw::io::add_buffering(dout_context, rgw::io::add_chunking( rgw::io::add_conlen_controlling( &cw_client)))); - RGWRestfulIO client_io(&real_client_io); + RGWRestfulIO client_io(dout_context, &real_client_io); RGWRequest req(env.store->get_new_req_id()); int ret = process_request(env.store, env.rest, &req, env.uri_prefix, diff --git a/src/rgw/rgw_client_io.h b/src/rgw/rgw_client_io.h index d06eaea3c2d16..8579b23835269 100644 --- a/src/rgw/rgw_client_io.h +++ b/src/rgw/rgw_client_io.h @@ -339,8 +339,8 @@ class RGWRestfulIO : public rgw::io::AccountingFilter { public: ~RGWRestfulIO() override = default; - RGWRestfulIO(rgw::io::RestfulClient* engine) - : AccountingFilter(std::move(engine)) { + RGWRestfulIO(CephContext *_cx, rgw::io::RestfulClient* engine) + : AccountingFilter(_cx, std::move(engine)) { } void add_filter(std::shared_ptr new_filter) { diff --git a/src/rgw/rgw_client_io_filters.h b/src/rgw/rgw_client_io_filters.h index 0862f33d3ef57..04761fc782905 100644 --- a/src/rgw/rgw_client_io_filters.h +++ b/src/rgw/rgw_client_io_filters.h @@ -20,20 +20,24 @@ class AccountingFilter : public DecoratedRestfulClient, bool enabled; uint64_t total_sent; uint64_t total_received; + CephContext *cct; public: template - AccountingFilter(U&& decoratee) + AccountingFilter(CephContext *cct, U&& decoratee) : DecoratedRestfulClient(std::forward(decoratee)), enabled(false), total_sent(0), - total_received(0) { + total_received(0), cct(cct) { } size_t send_status(const int status, const char* const status_name) override { const auto sent = DecoratedRestfulClient::send_status(status, status_name); + lsubdout(cct, rgw, 30) << "AccountingFilter::send_status: e=" + << (enabled ? "1" : "0") << ", sent=" << sent << ", total=" + << total_sent << dendl; if (enabled) { total_sent += sent; } @@ -42,6 +46,9 @@ public: size_t send_100_continue() override { const auto sent = DecoratedRestfulClient::send_100_continue(); + lsubdout(cct, rgw, 30) << "AccountingFilter::send_100_continue: e=" + << (enabled ? "1" : "0") << ", sent=" << sent << ", total=" + << total_sent << dendl; if (enabled) { total_sent += sent; } @@ -51,6 +58,9 @@ public: size_t send_header(const boost::string_ref& name, const boost::string_ref& value) override { const auto sent = DecoratedRestfulClient::send_header(name, value); + lsubdout(cct, rgw, 30) << "AccountingFilter::send_header: e=" + << (enabled ? "1" : "0") << ", sent=" << sent << ", total=" + << total_sent << dendl; if (enabled) { total_sent += sent; } @@ -59,6 +69,9 @@ public: size_t send_content_length(const uint64_t len) override { const auto sent = DecoratedRestfulClient::send_content_length(len); + lsubdout(cct, rgw, 30) << "AccountingFilter::send_content_length: e=" + << (enabled ? "1" : "0") << ", sent=" << sent << ", total=" + << total_sent << dendl; if (enabled) { total_sent += sent; } @@ -67,6 +80,9 @@ public: size_t send_chunked_transfer_encoding() override { const auto sent = DecoratedRestfulClient::send_chunked_transfer_encoding(); + lsubdout(cct, rgw, 30) << "AccountingFilter::send_chunked_transfer_encoding: e=" + << (enabled ? "1" : "0") << ", sent=" << sent << ", total=" + << total_sent << dendl; if (enabled) { total_sent += sent; } @@ -75,6 +91,9 @@ public: size_t complete_header() override { const auto sent = DecoratedRestfulClient::complete_header(); + lsubdout(cct, rgw, 30) << "AccountingFilter::complete_header: e=" + << (enabled ? "1" : "0") << ", sent=" << sent << ", total=" + << total_sent << dendl; if (enabled) { total_sent += sent; } @@ -83,6 +102,8 @@ public: size_t recv_body(char* buf, size_t max) override { const auto received = DecoratedRestfulClient::recv_body(buf, max); + lsubdout(cct, rgw, 30) << "AccountingFilter::recv_body: e=" + << (enabled ? "1" : "0") << ", received=" << received << dendl; if (enabled) { total_received += received; } @@ -92,6 +113,20 @@ public: size_t send_body(const char* const buf, const size_t len) override { const auto sent = DecoratedRestfulClient::send_body(buf, len); + lsubdout(cct, rgw, 30) << "AccountingFilter::send_body: e=" + << (enabled ? "1" : "0") << ", sent=" << sent << ", total=" + << total_sent << dendl; + if (enabled) { + total_sent += sent; + } + return sent; + } + + size_t complete_request() override { + const auto sent = DecoratedRestfulClient::complete_request(); + lsubdout(cct, rgw, 30) << "AccountingFilter::complete_request: e=" + << (enabled ? "1" : "0") << ", sent=" << sent << ", total=" + << total_sent << dendl; if (enabled) { total_sent += sent; } @@ -108,6 +143,8 @@ public: void set_account(bool enabled) override { this->enabled = enabled; + lsubdout(cct, rgw, 30) << "AccountingFilter::set_account: e=" + << (enabled ? "1" : "0") << dendl; } }; @@ -122,13 +159,14 @@ protected: bool has_content_length; bool buffer_data; + CephContext *cct; public: template - BufferingFilter(U&& decoratee) + BufferingFilter(CephContext *cct, U&& decoratee) : DecoratedRestfulClient(std::forward(decoratee)), has_content_length(false), - buffer_data(false) { + buffer_data(false), cct(cct) { } size_t send_content_length(const uint64_t len) override; @@ -144,6 +182,9 @@ size_t BufferingFilter::send_body(const char* const buf, { if (buffer_data) { data.append(buf, len); + + lsubdout(cct, rgw, 30) << "BufferingFilter::send_body: defer count = " + << len << dendl; return 0; } @@ -170,6 +211,8 @@ size_t BufferingFilter::complete_header() if (! has_content_length) { /* We will dump everything in complete_request(). */ buffer_data = true; + lsubdout(cct, rgw, 30) << "BufferingFilter::complete_header: has_content_length=" + << (has_content_length ? "1" : "0") << dendl; return 0; } @@ -182,8 +225,16 @@ size_t BufferingFilter::complete_request() size_t sent = 0; if (! has_content_length) { + /* It is not correct to count these bytes here, + * because they can only be part of the header. + * Therefore force count to 0. + */ sent += DecoratedRestfulClient::send_content_length(data.length()); sent += DecoratedRestfulClient::complete_header(); + lsubdout(cct, rgw, 30) << + "BufferingFilter::complete_request: !has_content_length: IGNORE: sent=" + << sent << dendl; + sent = 0; } if (buffer_data) { @@ -195,14 +246,18 @@ size_t BufferingFilter::complete_request() } data.clear(); buffer_data = false; + lsubdout(cct, rgw, 30) << "BufferingFilter::complete_request: buffer_data: sent=" + << sent << dendl; } return sent + DecoratedRestfulClient::complete_request(); } template static inline -BufferingFilter add_buffering(T&& t) { - return BufferingFilter(std::forward(t)); +BufferingFilter add_buffering( +CephContext *cct, +T&& t) { + return BufferingFilter(cct, std::forward(t)); } diff --git a/src/rgw/rgw_fcgi_process.cc b/src/rgw/rgw_fcgi_process.cc index 332cde29719f3..3d6eac2b5dde3 100644 --- a/src/rgw/rgw_fcgi_process.cc +++ b/src/rgw/rgw_fcgi_process.cc @@ -118,10 +118,10 @@ void RGWFCGXProcess::handle_request(RGWRequest* r) RGWFCGX fcgxfe(req->fcgx); auto real_client_io = rgw::io::add_reordering( - rgw::io::add_buffering( + rgw::io::add_buffering(cct, rgw::io::add_chunking( &fcgxfe))); - RGWRestfulIO client_io(&real_client_io); + RGWRestfulIO client_io(cct, &real_client_io); int ret = process_request(store, rest, req, uri_prefix, diff --git a/src/rgw/rgw_loadgen_process.cc b/src/rgw/rgw_loadgen_process.cc index fef37f805bac9..13a344e3b4694 100644 --- a/src/rgw/rgw_loadgen_process.cc +++ b/src/rgw/rgw_loadgen_process.cc @@ -131,7 +131,7 @@ void RGWLoadGenProcess::handle_request(RGWRequest* r) env.sign(access_key); RGWLoadGenIO real_client_io(&env); - RGWRestfulIO client_io(&real_client_io); + RGWRestfulIO client_io(cct, &real_client_io); int ret = process_request(store, rest, req, uri_prefix, *auth_registry, &client_io, olog); diff --git a/src/rgw/rgw_log.cc b/src/rgw/rgw_log.cc index 7bceab0aa6896..588aa0a26fde8 100644 --- a/src/rgw/rgw_log.cc +++ b/src/rgw/rgw_log.cc @@ -221,6 +221,11 @@ static void log_usage(struct req_state *s, const string& op_name) if (!s->is_err()) data.successful_ops = 1; + ldout(s->cct, 30) << "log_usage: bucket_name=" << bucket_name + << " tenant=" << s->bucket_tenant + << ", bytes_sent=" << bytes_sent << ", bytes_received=" + << bytes_received << ", success=" << data.successful_ops << dendl; + entry.add(op_name, data); utime_t ts = ceph_clock_now(); -- 2.39.5