From 98064037f9eadf30aadaa5f2c8ca90904455cb9f Mon Sep 17 00:00:00 2001 From: =?utf8?q?Rados=C5=82aw=20Zarzy=C5=84ski?= Date: Fri, 27 May 2022 19:31:18 +0200 Subject: [PATCH] crimson/osd: add support for slowest historic op tracking MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit Signed-off-by: Radosław Zarzyński --- src/crimson/admin/osd_admin.cc | 25 ++++++ src/crimson/admin/osd_admin.h | 1 + src/crimson/common/operation.h | 4 + src/crimson/osd/osd.cc | 2 + src/crimson/osd/osd_operation.cc | 80 +++++++++++++++++-- src/crimson/osd/osd_operation.h | 14 +++- .../osd/osd_operations/client_request.h | 8 ++ 7 files changed, 127 insertions(+), 7 deletions(-) diff --git a/src/crimson/admin/osd_admin.cc b/src/crimson/admin/osd_admin.cc index eba4c4c1769c1..24c901b287df8 100644 --- a/src/crimson/admin/osd_admin.cc +++ b/src/crimson/admin/osd_admin.cc @@ -483,4 +483,29 @@ private: template std::unique_ptr make_asok_hook(const crimson::osd::OSDOperationRegistry& op_registry); + +class DumpSlowestHistoricOpsHook : public AdminSocketHook { +public: + explicit DumpSlowestHistoricOpsHook(const crimson::osd::OSDOperationRegistry& op_registry) : + AdminSocketHook{"dump_historic_slow_ops", "", "show slowest recent ops"}, + op_registry(op_registry) + {} + seastar::future call(const cmdmap_t&, + std::string_view format, + ceph::bufferlist&& input) const final + { + logger().warn("{}", __func__); + unique_ptr f{Formatter::create(format, "json-pretty", "json-pretty")}; + f->open_object_section("historic_slow_ops"); + op_registry.dump_slowest_historic_client_requests(f.get()); + f->close_section(); + f->dump_int("num_ops", 0); + return seastar::make_ready_future(std::move(f)); + } +private: + const crimson::osd::OSDOperationRegistry& op_registry; +}; +template std::unique_ptr +make_asok_hook(const crimson::osd::OSDOperationRegistry& op_registry); + } // namespace crimson::admin diff --git a/src/crimson/admin/osd_admin.h b/src/crimson/admin/osd_admin.h index 5ae6187c8e1dd..b3e0adc2a91cf 100644 --- a/src/crimson/admin/osd_admin.h +++ b/src/crimson/admin/osd_admin.h @@ -19,6 +19,7 @@ class OsdStatusHook; class SendBeaconHook; class DumpInFlightOpsHook; class DumpHistoricOpsHook; +class DumpSlowestHistoricOpsHook; template std::unique_ptr make_asok_hook(Args&&... args); diff --git a/src/crimson/common/operation.h b/src/crimson/common/operation.h index 90e7d157fa8ef..60b5d59e28dd8 100644 --- a/src/crimson/common/operation.h +++ b/src/crimson/common/operation.h @@ -120,6 +120,10 @@ struct TimeEvent : Event { void dump(ceph::Formatter *f) const { detail::dump_time_event(typeid(T).name(), internal_backend.timestamp, f); } + + auto get_timestamp() const { + return internal_backend.timestamp; + } }; diff --git a/src/crimson/osd/osd.cc b/src/crimson/osd/osd.cc index fe16c203195df..4db655e81e959 100644 --- a/src/crimson/osd/osd.cc +++ b/src/crimson/osd/osd.cc @@ -551,6 +551,8 @@ seastar::future<> OSD::start_asok_admin() std::as_const(get_shard_services().registry))); asok->register_command(make_asok_hook( std::as_const(get_shard_services().registry))); + asok->register_command(make_asok_hook( + std::as_const(get_shard_services().registry))); }); } diff --git a/src/crimson/osd/osd_operation.cc b/src/crimson/osd/osd_operation.cc index afc06ae379848..c2f6908c82511 100644 --- a/src/crimson/osd/osd_operation.cc +++ b/src/crimson/osd/osd_operation.cc @@ -32,10 +32,27 @@ void OSDOperationRegistry::do_stop() /* add_ref= */ false }; }); + last_of_recents = std::end(historic_registry); // to_ref_down is going off } -void OSDOperationRegistry::put_historic(const ClientRequest& op) { +OSDOperationRegistry::OSDOperationRegistry() +{ + constexpr auto historic_reg_index = + static_cast(OperationTypeCode::historic_client_request); + auto& historic_registry = get_registry(); + last_of_recents = std::begin(historic_registry); +} + +static auto get_duration(const ClientRequest& client_request) +{ + // TODO: consider enhancing `CompletionEvent` with computing duration + // once -- when it's enetered. + return client_request.get_completed() - client_request.get_started(); +} + +void OSDOperationRegistry::put_historic(const ClientRequest& op) +{ // unlink the op from the client request registry. this is a part of // the re-link procedure. finally it will be in historic registry. constexpr auto client_reg_index = @@ -44,7 +61,6 @@ void OSDOperationRegistry::put_historic(const ClientRequest& op) { static_cast(OperationTypeCode::historic_client_request); auto& client_registry = get_registry(); auto& historic_registry = get_registry(); - historic_registry.splice(std::end(historic_registry), client_registry, client_registry.iterator_to(op)); @@ -57,11 +73,29 @@ void OSDOperationRegistry::put_historic(const ClientRequest& op) { // NOTE: Operation uses the auto-unlink feature of boost::intrusive. // NOTE: the cleaning happens in OSDOperationRegistry::do_stop() using crimson::common::local_conf; - if (historic_registry.size() > local_conf()->osd_op_history_size) { - const auto& oldest_historic_op = - static_cast(historic_registry.front()); + if (num_recent_ops >= local_conf()->osd_op_history_size) { + ++last_of_recents; + ++num_slow_ops; + } else { + ++num_recent_ops; + } + if (num_slow_ops > local_conf()->osd_op_history_slow_op_size) { + // we're interested in keeping slowest ops. if the slow op history + // is disabled, the list will have only one element, so the full-blown + // search will boil down into `.front()`. + const auto fastest_historic_iter = std::min_element( + std::cbegin(historic_registry), last_of_recents, + [] (const auto& lop, const auto& rop) { + const auto& lclient_request = static_cast(lop); + const auto& rclient_request = static_cast(rop); + return get_duration(lclient_request) < get_duration(rclient_request); + }); + assert(fastest_historic_iter != std::end(historic_registry)); + const auto& fastest_historic_op = + static_cast(*fastest_historic_iter); // clear a previously "leaked" op - ClientRequest::ICRef(&oldest_historic_op, /* add_ref= */false); + ClientRequest::ICRef(&fastest_historic_op, /* add_ref= */false); + --num_slow_ops; } } @@ -97,6 +131,40 @@ size_t OSDOperationRegistry::dump_historic_client_requests(ceph::Formatter* f) c return ops_count; } +size_t OSDOperationRegistry::dump_slowest_historic_client_requests(ceph::Formatter* f) const +{ + const auto& historic_client_registry = + get_registry(OperationTypeCode::historic_client_request)>(); //ClientRequest::type)>(); + f->open_object_section("op_history"); + f->dump_int("size", historic_client_registry.size()); + // TODO: f->dump_int("duration", history_duration.load()); + // the intrusive list is configured to not store the size + std::multimap> sorted_slowest_ops; + // iterating over the entire registry as a slow op could be also + // in the "recently added" part. + std::transform(std::begin(historic_client_registry), + std::end(historic_client_registry), + std::inserter(sorted_slowest_ops, std::end(sorted_slowest_ops)), + [] (const Operation& op) { + const auto& cop = static_cast(op); + return std::make_pair(get_duration(cop), &cop); + }); + f->open_array_section("ops"); + using crimson::common::local_conf; + size_t ops_count = 0; + for (auto it = std::begin(sorted_slowest_ops); + ops_count < local_conf()->osd_op_history_slow_op_size + && it != std::end(sorted_slowest_ops); + ++it, ++ops_count) + { + it->second->dump(f); + } + f->close_section(); + return ops_count; +} + OperationThrottler::OperationThrottler(ConfigProxy &conf) : scheduler(crimson::osd::scheduler::make_scheduler(conf)) { diff --git a/src/crimson/osd/osd_operation.h b/src/crimson/osd/osd_operation.h index a9cd48cae124d..2f9a69d39e6ae 100644 --- a/src/crimson/osd/osd_operation.h +++ b/src/crimson/osd/osd_operation.h @@ -104,6 +104,7 @@ class TrackableOperationT : public OperationT { return static_cast(this); } +protected: template decltype(auto) get_event() { // all out derivates are supposed to define the list of tracking @@ -112,7 +113,11 @@ class TrackableOperationT : public OperationT { return std::get(that()->tracking_events); } -protected: + template + decltype(auto) get_event() const { + return std::get(that()->tracking_events); + } + using OperationT::OperationT; struct StartEvent : TimeEvent {}; @@ -170,13 +175,20 @@ protected: struct OSDOperationRegistry : OperationRegistryT< static_cast(OperationTypeCode::last_op) > { + OSDOperationRegistry(); + void do_stop() override; void put_historic(const class ClientRequest& op); size_t dump_client_requests(ceph::Formatter* f) const; size_t dump_historic_client_requests(ceph::Formatter* f) const; + size_t dump_slowest_historic_client_requests(ceph::Formatter* f) const; +private: + op_list::const_iterator last_of_recents; + size_t num_recent_ops = 0; + size_t num_slow_ops = 0; }; /** * Throttles set of currently running operations diff --git a/src/crimson/osd/osd_operations/client_request.h b/src/crimson/osd/osd_operations/client_request.h index 15827ad9ebd8c..82ccbe5f38f3b 100644 --- a/src/crimson/osd/osd_operations/client_request.h +++ b/src/crimson/osd/osd_operations/client_request.h @@ -155,6 +155,14 @@ public: friend class LttngBackend; friend class HistoricBackend; + + auto get_started() const { + return get_event().get_timestamp(); + }; + + auto get_completed() const { + return get_event().get_timestamp(); + }; }; } -- 2.39.5