diff options
Diffstat (limited to 'src/mongo')
| -rw-r--r-- | src/mongo/executor/SConscript | 1 | ||||
| -rw-r--r-- | src/mongo/executor/split_timer.h | 204 | ||||
| -rw-r--r-- | src/mongo/executor/split_timer_test.cpp | 230 | ||||
| -rw-r--r-- | src/mongo/transport/session_workflow.cpp | 317 |
4 files changed, 598 insertions, 154 deletions
diff --git a/src/mongo/executor/SConscript b/src/mongo/executor/SConscript index d4d706ec871..a4b691b7084 100644 --- a/src/mongo/executor/SConscript +++ b/src/mongo/executor/SConscript @@ -332,6 +332,7 @@ env.CppUnitTest( 'network_interface_mock_test_fixture.cpp', 'network_interface_tl_test.cpp', 'scoped_task_executor_test.cpp', + 'split_timer_test.cpp', 'task_executor_cursor_test.cpp', 'thread_pool_task_executor_test.cpp', ], diff --git a/src/mongo/executor/split_timer.h b/src/mongo/executor/split_timer.h new file mode 100644 index 00000000000..32f956ed8dc --- /dev/null +++ b/src/mongo/executor/split_timer.h @@ -0,0 +1,204 @@ +/** + * Copyright (C) 2022-present MongoDB, Inc. + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the Server Side Public License, version 1, + * as published by MongoDB, Inc. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * Server Side Public License for more details. + * + * You should have received a copy of the Server Side Public License + * along with this program. If not, see + * <http://www.mongodb.com/licensing/server-side-public-license>. + * + * As a special exception, the copyright holders give permission to link the + * code of portions of this program with the OpenSSL library under certain + * conditions as described in each individual source file and distribute + * linked combinations including the program with the OpenSSL library. You + * must comply with the Server Side Public License in all respects for + * all of the code used other than as permitted herein. If you modify file(s) + * with this exception, you may extend this exception to your version of the + * file(s), but you are not obligated to do so. If you do not wish to do so, + * delete this exception statement from your version. If you delete this + * exception statement from all source files in the program, then also delete + * it in the license file. + */ + +#pragma once + +#include <array> +#include <boost/optional.hpp> +#include <fmt/format.h> + +#include "mongo/base/string_data.h" +#include "mongo/bson/bsonobjbuilder.h" +#include "mongo/logv2/log.h" +#include "mongo/util/duration.h" +#include "mongo/util/timer.h" + +#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kNetwork + +namespace mongo { + +namespace split_timer_detail { + +/** + * Takes an invokable `f` and a pack of optionals `as...`. + * Invokes `f(*as...)`, returning the result as an optional. + * If any of `as...` are disengaged, then `f` is not + * invoked, and a disengaged result is returned. + */ +template <typename F, + typename... As, + typename R = std::invoke_result_t<F, decltype(*std::declval<As>())...>> +boost::optional<R> applyViaOptionals(F&& f, As&&... as) { + if (!(as && ...)) + return {}; + return std::invoke(f, *as...); +} + +/** Rule of Zero utility. Starts true, becomes false when moved from or dismissed. */ +class UniqueActive { +public: + UniqueActive() = default; + + UniqueActive(UniqueActive&& other) noexcept : _active{other.dismiss()} {} + + UniqueActive& operator=(UniqueActive&& other) noexcept { + if (this != &other) + _active = other.dismiss(); + return *this; + } + + explicit operator bool() const { + return _active; + } + + /** Returns true if dismiss changed this object's state. */ + bool dismiss() { + return std::exchange(_active, false); + } + +private: + bool _active = true; +}; +} // namespace split_timer_detail + +/** + * Acts as a split timer which captures times elapsed at various points throughout a single + * SessionWorkflow loop. The SessionWorkflow loop is expected to construct this + * object when timing should begin, call this object's `notify` function at + * appropriate times throughout the workflow, and destroy it when the loop work is done. + * + * Requirements on Policy: + * - TimeSplitIdType and IntervalIdType packed enums. + * - static constexpr properties: + * - size_t numIntervalIds and numTimesplitIds for enum extents. + * - toIdx(e) to convert these enums to size_t. + * - getName(e) to convert these enums to StringData (intervals should end in "Millis"). + * - TimeSplitIdType getStartSplit(IntervalIdType). + * - TimeSplitIdType getEndSplit(IntervalIdType). + * - nonstatic onStart and onFinish member functions, taking a pointer to this SplitTimer. + * - nonstatic makeTimer to initialize Timer. + */ +template <typename Policy> +class SplitTimer { +private: + template <typename E> + static constexpr size_t _idx(E e) { + return Policy::toIdx(e); + } + +public: + using TimeSplitIdType = typename Policy::TimeSplitIdType; + using IntervalIdType = typename Policy::IntervalIdType; + + SplitTimer() : SplitTimer{Policy{}} {} + SplitTimer(Policy policy) : _policy{std::move(policy)} { + _policy.onStart(this); + } + + SplitTimer& operator=(SplitTimer&&) = default; + SplitTimer(SplitTimer&&) = default; + + /** + * Idempotent: if already inactive (moved-from), does nothing. + * If active: sets to inactive, captures the elapsed time for the `done` + * TimeSplitId, logs any necessary metrics. + */ + ~SplitTimer() { + if (!_active) + return; + _policy.onFinish(this); + } + + /** + * Captures the elapsed time and associates it with `split`. A second call with the same `split` + * will overwrite the previous. It is expected that this gets called for all splits other than + * TimerSplit::start and TimerSplit::done. + */ + void notify(TimeSplitIdType split) { + using namespace fmt::literals; + invariant(!_topSplit || _idx(*_topSplit) <= _idx(split), + "Notify out of order: {} then {}"_format(_policy.getName(*_topSplit), + _policy.getName(split))); + _topSplit = split; + + _splits[_idx(split)] = _timer.elapsed(); + } + + /** + * Returns the time elapsed between the two splits corresponding to `start` and `end`. + * If either is disengaged, a disengaged optional will be returned. + */ + boost::optional<Microseconds> getSplitInterval(IntervalIdType id) const { + return split_timer_detail::applyViaOptionals(std::minus<>{}, + _splits[_idx(_policy.getEndSplit(id))], + _splits[_idx(_policy.getStartSplit(id))]); + } + + /** + * Appends the intervals defined in Policy::intervalDefs to `builder`. + * Logs the whole builder if there's a problem. + */ + void appendIntervals(BSONObjBuilder& builder) const { + using namespace fmt::literals; + for (size_t i = 0; i != Policy::numIntervalIds; ++i) { + IntervalIdType iId{i}; + auto dt = getSplitInterval(iId); + if (!dt) + continue; + if (*dt < Microseconds{0}) + LOGV2_FATAL(6983001, + "Negative time interval", + "dt"_attr = dt->toString(), + "splits"_attr = _splitsToBSON()); + builder.append(_policy.getName(iId), durationCount<Milliseconds>(*dt)); + } + } + +private: + using SplitsArray = std::array<boost::optional<Microseconds>, Policy::numTimeSplitIds>; + + BSONObj _splitsToBSON() const { + BSONObjBuilder bob; + for (size_t i = 0; i != Policy::numTimeSplitIds; ++i) { + TimeSplitIdType ts{i}; + auto&& t = _splits[_idx(ts)]; + bob.append(_policy.getName(ts), t ? t->toString() : ""); + } + return bob.obj(); + } + + Policy _policy; + split_timer_detail::UniqueActive _active; + Timer _timer = _policy.makeTimer(); + SplitsArray _splits; + boost::optional<TimeSplitIdType> _topSplit; +}; +} // namespace mongo + +#undef MONGO_LOGV2_DEFAULT_COMPONENT diff --git a/src/mongo/executor/split_timer_test.cpp b/src/mongo/executor/split_timer_test.cpp new file mode 100644 index 00000000000..4f5b3695b1f --- /dev/null +++ b/src/mongo/executor/split_timer_test.cpp @@ -0,0 +1,230 @@ +/** + * Copyright (C) 2022-present MongoDB, Inc. + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the Server Side Public License, version 1, + * as published by MongoDB, Inc. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * Server Side Public License for more details. + * + * You should have received a copy of the Server Side Public License + * along with this program. If not, see + * <http://www.mongodb.com/licensing/server-side-public-license>. + * + * As a special exception, the copyright holders give permission to link the + * code of portions of this program with the OpenSSL library under certain + * conditions as described in each individual source file and distribute + * linked combinations including the program with the OpenSSL library. You + * must comply with the Server Side Public License in all respects for + * all of the code used other than as permitted herein. If you modify file(s) + * with this exception, you may extend this exception to your version of the + * file(s), but you are not obligated to do so. If you do not wish to do so, + * delete this exception statement from your version. If you delete this + * exception statement from all source files in the program, then also delete + * it in the license file. + */ + +#include "mongo/executor/split_timer.h" + +#include <array> +#include <boost/optional.hpp> +#include <fmt/format.h> + +#include "mongo/base/string_data.h" +#include "mongo/unittest/assert_that.h" +#include "mongo/unittest/unittest.h" +#include "mongo/util/duration.h" +#include "mongo/util/tick_source_mock.h" + +namespace mongo { +namespace { + +namespace m = unittest::match; +using namespace fmt::literals; + +/** Match that `x` converts to `true` and that `*x` matches `m`. */ +template <typename M> +class WhenDereferenced : public m::Matcher { +public: + explicit WhenDereferenced(M&& m) : _m{std::move(m)} {} + + std::string describe() const { + return "WhenDereferenced({})"_format(_m.describe()); + } + + template <typename X> + m::MatchResult match(const X& x) const { + if (!x) + return {false, "converts to a false bool value"}; + return _m.match(*x); + } + +private: + M _m; +}; + +/** Match that `static_cast<bool>(x)` matches `m`. */ +template <typename M> +class WhenBool : public m::Matcher { +public: + explicit WhenBool(M&& m) : _m{std::move(m)} {} + + std::string describe() const { + return "WhenBool({})"_format(_m.describe()); + } + + template <typename X> + m::MatchResult match(const X& x) const { + return _m.match(static_cast<bool>(x)); + } + +private: + M _m; +}; + +enum class SomeTimeSplitId : size_t { + a, + b, + c, +}; + +enum class SomeIntervalId : size_t { + ab, + ac, +}; + +struct IDef { + SomeIntervalId iId; + StringData name; + SomeTimeSplitId start; + SomeTimeSplitId end; +}; + +static constexpr auto iDefs = std::array{ + IDef{SomeIntervalId::ab, "abMillis"_sd, SomeTimeSplitId::a, SomeTimeSplitId::b}, + IDef{SomeIntervalId::ac, "acMillis"_sd, SomeTimeSplitId::a, SomeTimeSplitId::c}, +}; + +struct SomePolicy { + using TimeSplitIdType = SomeTimeSplitId; + using IntervalIdType = SomeIntervalId; + + static constexpr size_t numTimeSplitIds = 3; + static constexpr size_t numIntervalIds = 2; + + static constexpr size_t toIdx(TimeSplitIdType e) { + return static_cast<size_t>(e); + } + static constexpr size_t toIdx(IntervalIdType e) { + return static_cast<size_t>(e); + } + + static constexpr StringData getName(TimeSplitIdType e) { + constexpr auto arr = std::array{"a"_sd, "b"_sd, "c"_sd}; + return arr[toIdx(e)]; + } + static constexpr StringData getName(IntervalIdType e) { + return iDefs[toIdx(e)].name; + } + + static constexpr TimeSplitIdType getStartSplit(IntervalIdType e) { + return iDefs[toIdx(e)].start; + } + static constexpr TimeSplitIdType getEndSplit(IntervalIdType e) { + return iDefs[toIdx(e)].end; + } + + void onStart(SplitTimer<SomePolicy>* t) { + mockOnStart(t); + } + void onFinish(SplitTimer<SomePolicy>* t) { + mockOnFinish(t); + } + + Timer makeTimer() { + return Timer{clock}; + } + + std::function<void(SplitTimer<SomePolicy>*)> mockOnStart; + std::function<void(SplitTimer<SomePolicy>*)> mockOnFinish; + TickSource* clock; +}; + +class SplitTimerTest : public unittest::Test { +public: + SplitTimerTest() { + policy.mockOnStart = [&](auto&&...) { ++starts; }; + policy.mockOnFinish = [&](auto&&...) { ++finishes; }; + policy.clock = &clock; + } + + template <typename Pol> + BSONObj makeSplitTimerReport(const SplitTimer<Pol>& splitTimer) { + BSONObjBuilder bob; + splitTimer.appendIntervals(bob); + return bob.obj(); + }; + + int starts = 0; + int finishes = 0; + TickSourceMock<Milliseconds> clock; + SomePolicy policy; +}; + +TEST_F(SplitTimerTest, BasicGetSplitInterval) { + struct Trial { + Milliseconds ab; + Milliseconds ac; + Milliseconds err = Milliseconds{5}; + }; + static constexpr auto trials = std::array{ + Trial{Milliseconds{0}, Milliseconds{0}}, + Trial{Milliseconds{0}, Milliseconds{10}}, + Trial{Milliseconds{10}, Milliseconds{30}}, + }; + auto matchDerefRange = [](auto lo, auto hi) { + return WhenDereferenced(m::AllOf(m::Ge(lo), m::Le(hi))); + }; + + for (auto&& [ab, ac, err] : trials) { + starts = 0; + finishes = 0; + { + SplitTimer t{policy}; + ASSERT_EQ(starts, 1); + ASSERT_THAT(t.getSplitInterval(SomeIntervalId::ab), WhenBool(m::Eq(false))); + t.notify(SomeTimeSplitId::a); + + clock.advance(ab); + t.notify(SomeTimeSplitId::b); + ASSERT_THAT(t.getSplitInterval(SomeIntervalId::ab), + matchDerefRange(ab - err, ab + err)); + ASSERT_THAT(t.getSplitInterval(SomeIntervalId::ac), WhenBool(m::Eq(false))); + + clock.advance(ac - ab); + t.notify(SomeTimeSplitId::c); + ASSERT_THAT(t.getSplitInterval(SomeIntervalId::ac), + matchDerefRange(ac - err, ac + err)); + + ASSERT_EQ(finishes, 0); + } + ASSERT_EQ(finishes, 1); + } +} + +TEST_F(SplitTimerTest, BSONFormatting) { + SplitTimer t{policy}; + t.notify(SomeTimeSplitId::a); + clock.advance(Milliseconds{10}); + t.notify(SomeTimeSplitId::b); + clock.advance(Milliseconds{20}); + t.notify(SomeTimeSplitId::c); + ASSERT_BSONOBJ_EQ(makeSplitTimerReport(t), + BSONObjBuilder{}.append("abMillis", 10).append("acMillis", 30).obj()); +} + +} // namespace +} // namespace mongo diff --git a/src/mongo/transport/session_workflow.cpp b/src/mongo/transport/session_workflow.cpp index 4f9b6c8e578..b96d5a430d0 100644 --- a/src/mongo/transport/session_workflow.cpp +++ b/src/mongo/transport/session_workflow.cpp @@ -42,6 +42,7 @@ #include "mongo/db/query/kill_cursors_gen.h" #include "mongo/db/stats/counters.h" #include "mongo/db/traffic_recorder.h" +#include "mongo/executor/split_timer.h" #include "mongo/logv2/log.h" #include "mongo/platform/atomic_word.h" #include "mongo/platform/mutex.h" @@ -61,15 +62,168 @@ #include "mongo/util/net/ssl_manager.h" #include "mongo/util/net/ssl_peer_info.h" -#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kNetwork - +#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kExecutor namespace mongo { namespace transport { namespace { + MONGO_FAIL_POINT_DEFINE(doNotSetMoreToCome); MONGO_FAIL_POINT_DEFINE(beforeCompressingExhaustResponse); +namespace metrics_detail { + +/** Applies X(id) for each SplitId */ +#define EXPAND_TIME_SPLIT_IDS(X) \ + X(started) \ + X(receivedWork) \ + X(processedWork) \ + X(sentResponse) \ + X(done) \ + /**/ + +/** + * Applies X(id, startSplit, endSplit) for each IntervalId. + * + * This table defines the intervals of a per-command `SessionWorkflow` loop + * iteration as reported to a `SplitTimer`. The splits are time points, and the + * `intervals` are durations between notable pairs of them. + * + * [started] + * | [receivedWork] + * | | [processedWork] + * | | | [sentResponse] + * | | | | [done] + * |<------------->| total + * | |<--------->| active + * |<->| | | | receivedWork + * | |<->| | | processWork + * | | |<->| | sendResponse + * | | | |<->| finalize + */ +#define EXPAND_INTERVAL_IDS(X) \ + X(total, started, done) \ + X(active, receivedWork, done) \ + X(receiveWork, started, receivedWork) \ + X(processWork, receivedWork, processedWork) \ + X(sendResponse, processedWork, sentResponse) \ + X(finalize, sentResponse, done) \ + /**/ + +#define X_ID(id, ...) id, +enum class IntervalId : size_t { EXPAND_INTERVAL_IDS(X_ID) }; +enum class TimeSplitId : size_t { EXPAND_TIME_SPLIT_IDS(X_ID) }; +#undef X_ID + +/** Trait for the count of the elements in a packed enum. */ +template <typename T> +static constexpr size_t enumExtent = 0; + +#define X_COUNT(...) +1 +template <> +constexpr inline size_t enumExtent<IntervalId> = EXPAND_INTERVAL_IDS(X_COUNT); +template <> +constexpr inline size_t enumExtent<TimeSplitId> = EXPAND_TIME_SPLIT_IDS(X_COUNT); +#undef X_COUNT + +struct TimeSplitDef { + TimeSplitId id; + StringData name; +}; + +struct IntervalDef { + IntervalId id; + StringData name; + TimeSplitId start; + TimeSplitId end; +}; + +constexpr inline auto timeSplitDefs = std::array{ +#define X(id) TimeSplitDef{TimeSplitId::id, #id ""_sd}, + EXPAND_TIME_SPLIT_IDS(X) +#undef X +}; + +constexpr inline auto intervalDefs = std::array{ +#define X(id, start, end) \ + IntervalDef{IntervalId::id, #id "Millis"_sd, TimeSplitId::start, TimeSplitId::end}, + EXPAND_INTERVAL_IDS(X) +#undef X +}; + +#undef EXPAND_TIME_SPLIT_IDS +#undef EXPAND_INTERVAL_IDS + +struct SplitTimerPolicy { + using TimeSplitIdType = TimeSplitId; + using IntervalIdType = IntervalId; + + static constexpr size_t numTimeSplitIds = enumExtent<TimeSplitIdType>; + static constexpr size_t numIntervalIds = enumExtent<IntervalIdType>; + + template <typename E> + static constexpr size_t toIdx(E e) { + return static_cast<size_t>(e); + } + + static constexpr StringData getName(IntervalIdType iId) { + return intervalDefs[toIdx(iId)].name; + } + + static constexpr TimeSplitIdType getStartSplit(IntervalIdType iId) { + return intervalDefs[toIdx(iId)].start; + } + + static constexpr TimeSplitIdType getEndSplit(IntervalIdType iId) { + return intervalDefs[toIdx(iId)].end; + } + + static constexpr StringData getName(TimeSplitIdType tsId) { + return timeSplitDefs[toIdx(tsId)].name; + } + + void onStart(SplitTimer<SplitTimerPolicy>* splitTimer) { + splitTimer->notify(TimeSplitIdType::started); + } + + void onFinish(SplitTimer<SplitTimerPolicy>* splitTimer) { + splitTimer->notify(TimeSplitIdType::done); + auto t = splitTimer->getSplitInterval(IntervalIdType::active); + if (MONGO_likely(!t || *t < Milliseconds{serverGlobalParams.slowMS.load()})) + return; + BSONObjBuilder bob; + splitTimer->appendIntervals(bob); + LOGV2(6983000, "Slow SessionWorkflow loop", "elapsed"_attr = bob.obj()); + } + + Timer makeTimer() { + return Timer{}; + } +}; + +class SessionWorkflowMetrics { +public: + void start() { + _t.emplace(); + } + void received() { + _t->notify(TimeSplitId::receivedWork); + } + void processed() { + _t->notify(TimeSplitId::processedWork); + } + void sent() { + _t->notify(TimeSplitId::sentResponse); + } + void finish() { + _t.reset(); + } + +private: + boost::optional<SplitTimer<SplitTimerPolicy>> _t; +}; +} // namespace metrics_detail + /** * Given a request and its already generated response, checks for exhaust flags. If exhaust is * allowed, produces the subsequent request message, and modifies the response message to indicate @@ -146,153 +300,8 @@ bool killExhaust(const Message& in, ServiceEntryPoint* sep, Client* client) { } return false; } -} // namespace - -/** - * Acts as a split timer which captures times elapsed at various points throughout a single - * SessionWorkflow loop. The SessionWorkflow loop itself is expected to (1) construct this object - * when timing should begin, and (2) call this object's `notifySplit` function at appropriate times - * throughout the workflow. - */ -class SessionWorkflowMetrics { - /** - * NOTE: when updating these, ensure: - * - These are all contiguous. - * - NumEntries is the highest constant. - * - The public constexprs are up to date. - * - The ranges in logSlowLoop are still correct. - */ - using Started_T = std::integral_constant<size_t, 0>; - using SourcedWork_T = std::integral_constant<size_t, 1>; - using ProcessedWork_T = std::integral_constant<size_t, 2>; - using SentResponse_T = std::integral_constant<size_t, 3>; - using Done_T = std::integral_constant<size_t, 4>; - using NumEntries_T = std::integral_constant<size_t, 5>; - static constexpr NumEntries_T NumEntries{}; - -public: - /** - * These constants act as tags for moments in a single SessionWorkflow loop. - */ - static constexpr Started_T Started{}; - static constexpr SourcedWork_T SourcedWork{}; - static constexpr ProcessedWork_T ProcessedWork{}; - static constexpr SentResponse_T SentResponse{}; - static constexpr Done_T Done{}; - - template <typename Split_T> - struct SplitInRange { - static constexpr bool value = Split_T::value >= Started && Split_T::value < NumEntries; - }; - - SessionWorkflowMetrics() { - _splits[Started] = Microseconds{0}; - } - - SessionWorkflowMetrics(SessionWorkflowMetrics&& other) { - *this = std::move(other); - } - SessionWorkflowMetrics& operator=(SessionWorkflowMetrics&& other) { - if (&other == this) { - return *this; - } - - _isFinalized = other._isFinalized; - _timer = std::move(other._timer); - _splits = std::move(other._splits); - - // The moved-from object should avoid extraneous logging. - other._isFinalized = true; - - return *this; - } - - ~SessionWorkflowMetrics() { - finalize(); - } - - /** - * Captures the elapsed time and associates it with `split`. A second call with the same `split` - * will overwrite the previous. It is expected that this gets called for all splits other than - * Start and Done. - */ - template <typename Split_T, typename std::enable_if_t<SplitInRange<Split_T>::value, int> = 0> - void notifySplit(Split_T split) { - _splits[split] = _timer.elapsed(); - } - - /** - * If not already finalized, captures the elapsed time for the `Done` Split and outputs metrics - * as a log if the criteria for logging is met. Calling `finalize` explicitly is not required - * because it is invoked by the destructor, however an early call can be done if this object's - * destruction needs to be defered for any reason. - */ - void finalize() { - if (_isFinalized) - return; - _isFinalized = true; - notifySplit(Done); - - auto activeTime = microsBetween(SourcedWork, SentResponse).value_or(Microseconds{0}); - if (MONGO_unlikely(durationCount<Milliseconds>(activeTime) >= - serverGlobalParams.slowMS.load())) { - logSlowLoop(); - } - } - -private: - bool _isFinalized{false}; - Timer _timer{}; - std::array<boost::optional<Microseconds>, NumEntries> _splits{}; - - /** - * Returns the time elapsed between the two splits corresponding to `startIdx` and `endIdx`. - * The split time for `startIdx` is assumed to have happened before the split at `endIdx`. - * Both `startIdx` and `endIdx` are assumed to have had captured times. If not, an optional with - * no value will be returned. - */ - boost::optional<Microseconds> microsBetween(size_t startIdx, size_t endIdx) const { - auto atEnd = _splits[endIdx]; - auto atStart = _splits[startIdx]; - if (!atStart || !atEnd) - return {}; - return *atEnd - *atStart; - } - - /** - * Appends an attribute to `attr` corresponding to a range. Returns whether a negative range was - * encountered. - */ - template <size_t N> - bool addAttr(const char (&name)[N], - size_t startIdx, - size_t endIdx, - logv2::DynamicAttributes& attr) { - if (auto optTime = microsBetween(startIdx, endIdx)) { - attr.add(name, duration_cast<Milliseconds>(*optTime)); - return *optTime < Microseconds{0}; - } - return false; - } - - void logSlowLoop() { - bool neg = false; - logv2::DynamicAttributes attr; - - neg |= addAttr("totalElapsed", Started, Done, attr); - neg |= addAttr("activeElapsed", SourcedWork, Done, attr); - neg |= addAttr("sourceWorkElapsed", Started, SourcedWork, attr); - neg |= addAttr("processWorkElapsed", SourcedWork, ProcessedWork, attr); - neg |= addAttr("sendResponseElapsed", ProcessedWork, SentResponse, attr); - neg |= addAttr("finalizeElapsed", SentResponse, Done, attr); - if (neg) { - attr.add("note", "Negative time range found. This indicates something went wrong."); - } - - LOGV2(6983000, "Slow SessionWorkflow loop", attr); - } -}; +} // namespace class SessionWorkflow::Impl { public: @@ -404,7 +413,7 @@ private: std::unique_ptr<WorkItem> _work; std::unique_ptr<WorkItem> _nextWork; /**< created by exhaust responses */ - boost::optional<SessionWorkflowMetrics> _metrics{}; + metrics_detail::SessionWorkflowMetrics _metrics; }; class SessionWorkflow::Impl::WorkItem { @@ -654,7 +663,7 @@ void SessionWorkflow::Impl::startNewLoop(const Status& executorStatus) { return; } - _metrics = SessionWorkflowMetrics(); + _metrics.start(); makeReadyFutureWith([this] { if (_nextWork) { @@ -662,18 +671,18 @@ void SessionWorkflow::Impl::startNewLoop(const Status& executorStatus) { } else { receiveMessage(); } - _metrics->notifySplit(SessionWorkflowMetrics::SourcedWork); + _metrics.received(); return processMessage(); }) .then([this] { - _metrics->notifySplit(SessionWorkflowMetrics::ProcessedWork); + _metrics.processed(); if (_work->hasOut()) { sendMessage(); - _metrics->notifySplit(SessionWorkflowMetrics::SentResponse); + _metrics.sent(); } }) .getAsync([this, anchor = shared_from_this()](Status status) { - _metrics = {}; + _metrics.finish(); scheduleNewLoop(std::move(status)); }); } |