SERVER-47446 Measure cpu time taken by operations

5 files changed, 424 insertions, 0 deletions

diff --git a/src/mongo/db/SConscript b/src/mongo/db/SConscript
index 3b17ae7a09e..5f86b4cbd21 100644
--- a/src/mongo/db/SConscript
+++ b/src/mongo/db/SConscript
@@ -453,6 +453,7 @@ env.Library(
         'default_baton.cpp',
         'operation_context.cpp',
         'operation_context_group.cpp',
+        'operation_cpu_timer.cpp',
         'operation_key_manager.cpp',
         'service_context.cpp',
         'server_recovery.cpp',
@@ -2247,6 +2248,7 @@ envWithAsio.CppUnitTest(
         'op_observer_impl_test.cpp',
         'op_observer_registry_test.cpp',
         'operation_context_test.cpp',
+        'operation_cpu_timer_test.cpp',
         'operation_time_tracker_test.cpp',
         'persistent_task_store_test.cpp',
         'range_arithmetic_test.cpp',
diff --git a/src/mongo/db/client.cpp b/src/mongo/db/client.cpp
index a9678bee962..53fdaf2052c 100644
--- a/src/mongo/db/client.cpp
+++ b/src/mongo/db/client.cpp
@@ -42,6 +42,7 @@
 #include "mongo/base/status.h"
 #include "mongo/db/lasterror.h"
 #include "mongo/db/operation_context.h"
+#include "mongo/db/operation_cpu_timer.h"
 #include "mongo/db/service_context.h"
 #include "mongo/stdx/thread.h"
 #include "mongo/util/concurrency/thread_name.h"
@@ -156,12 +157,18 @@ bool haveClient() {
 
 ServiceContext::UniqueClient Client::releaseCurrent() {
     invariant(haveClient());
+    if (auto opCtx = currentClient->_opCtx)
+        if (auto timer = OperationCPUTimer::get(opCtx))
+            timer->onThreadDetach();
     return std::move(currentClient);
 }
 
 void Client::setCurrent(ServiceContext::UniqueClient client) {
     invariantNoCurrentClient();
     currentClient = std::move(client);
+    if (auto opCtx = currentClient->_opCtx)
+        if (auto timer = OperationCPUTimer::get(opCtx))
+            timer->onThreadAttach();
 }
 
 /**
diff --git a/src/mongo/db/operation_cpu_timer.cpp b/src/mongo/db/operation_cpu_timer.cpp
new file mode 100644
index 00000000000..7627c8af11c
--- /dev/null
+++ b/src/mongo/db/operation_cpu_timer.cpp
@@ -0,0 +1,173 @@
+/**
+ *    Copyright (C) 2020-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 <boost/optional.hpp>
+#include <fmt/format.h>
+
+#if defined(__linux__)
+#include <time.h>
+#endif  // defined(__linux__)
+
+#include "mongo/db/operation_cpu_timer.h"
+
+#include "mongo/base/error_codes.h"
+#include "mongo/db/client.h"
+#include "mongo/db/operation_context.h"
+#include "mongo/stdx/thread.h"
+#include "mongo/util/assert_util.h"
+#include "mongo/util/errno_util.h"
+#include "mongo/util/fail_point.h"
+
+namespace mongo {
+
+#if defined(__linux__)
+
+namespace {
+
+using namespace fmt::literals;
+
+MONGO_FAIL_POINT_DEFINE(hangCPUTimerAfterOnThreadAttach);
+MONGO_FAIL_POINT_DEFINE(hangCPUTimerAfterOnThreadDetach);
+
+class PosixTimer final : public OperationCPUTimer {
+public:
+    Nanoseconds getElapsed() const override;
+
+    void start() override;
+    void stop() override;
+
+    void onThreadAttach() override;
+    void onThreadDetach() override;
+
+private:
+    bool _timerIsRunning() const;
+    bool _isAttachedToCurrentThread() const;
+
+    // Returns the elapsed time since the creation of the current thread.
+    Nanoseconds _getThreadTime() const;
+
+    // Holds the value returned by `_getThreadTime()` at the time of starting/resuming the timer.
+    boost::optional<Nanoseconds> _startedOn;
+    boost::optional<stdx::thread::id> _threadId;
+    Nanoseconds _elapsedBeforeInterrupted = Nanoseconds(0);
+};
+
+Nanoseconds PosixTimer::getElapsed() const {
+    invariant(_isAttachedToCurrentThread(), "Not attached to current thread");
+    auto elapsed = _elapsedBeforeInterrupted;
+    if (_timerIsRunning())
+        elapsed += _getThreadTime() - _startedOn.get();
+    return elapsed;
+}
+
+bool PosixTimer::_timerIsRunning() const {
+    return _startedOn.has_value();
+}
+
+bool PosixTimer::_isAttachedToCurrentThread() const {
+    return _threadId.has_value() && _threadId.get() == stdx::this_thread::get_id();
+}
+
+void PosixTimer::start() {
+    invariant(!_timerIsRunning(), "Timer has already started");
+
+    _startedOn = _getThreadTime();
+    _threadId = stdx::this_thread::get_id();
+    _elapsedBeforeInterrupted = Nanoseconds(0);
+}
+
+void PosixTimer::stop() {
+    invariant(_timerIsRunning(), "Timer is not running");
+    invariant(_isAttachedToCurrentThread());
+
+    _elapsedBeforeInterrupted = getElapsed();
+    _startedOn.reset();
+}
+
+void PosixTimer::onThreadAttach() {
+    if (!_timerIsRunning())
+        return;
+
+    invariant(!_threadId.has_value(), "Timer has already been attached");
+    _threadId = stdx::this_thread::get_id();
+    _startedOn = _getThreadTime();
+
+    hangCPUTimerAfterOnThreadAttach.pauseWhileSet();
+}
+
+void PosixTimer::onThreadDetach() {
+    if (!_timerIsRunning())
+        return;
+
+    invariant(_threadId.has_value(), "Timer is not attached");
+    _threadId.reset();
+    _elapsedBeforeInterrupted = _getThreadTime() - _startedOn.get();
+
+    hangCPUTimerAfterOnThreadDetach.pauseWhileSet();
+}
+
+Nanoseconds PosixTimer::_getThreadTime() const {
+    struct timespec t;
+    if (auto ret = clock_gettime(CLOCK_THREAD_CPUTIME_ID, &t); ret != 0) {
+        int ec = errno;
+        internalAssert(Status(ErrorCodes::InternalError,
+                              "Unable to get time: {}"_format(errnoWithDescription(ec))));
+    }
+    return Seconds(t.tv_sec) + Nanoseconds(t.tv_nsec);
+}
+
+static auto getCPUTimer = OperationContext::declareDecoration<PosixTimer>();
+
+}  // namespace
+
+OperationCPUTimer* OperationCPUTimer::get(OperationContext* opCtx) {
+    invariant(Client::getCurrent() && Client::getCurrent()->getOperationContext() == opCtx,
+              "Operation not attached to the current thread");
+
+    // Checks for time support on POSIX platforms. In particular, it checks for support in presence
+    // of SMP systems.
+    static bool isTimeSupported = [] {
+        clockid_t cid;
+        return clock_getcpuclockid(0, &cid) == 0;
+    }();
+
+    if (!isTimeSupported)
+        return nullptr;
+    return &getCPUTimer(opCtx);
+}
+
+#else  // not defined(__linux__)
+
+OperationCPUTimer* OperationCPUTimer::get(OperationContext*) {
+    return nullptr;
+}
+
+#endif  // defined(__linux__)
+
+}  // namespace mongo
diff --git a/src/mongo/db/operation_cpu_timer.h b/src/mongo/db/operation_cpu_timer.h
new file mode 100644
index 00000000000..0cd0b88acba
--- /dev/null
+++ b/src/mongo/db/operation_cpu_timer.h
@@ -0,0 +1,71 @@
+/**
+ *    Copyright (C) 2020-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 "mongo/util/duration.h"
+
+namespace mongo {
+
+class OperationContext;
+
+/**
+ * Implements the CPU timer for platforms that support CPU consumption tracking. Consider the
+ * following when using the timer:
+ *
+ * All methods may only be invoked on the thread associated with the operation.
+ *
+ * To access the timer, the operation must be associated with a client, and the client must be
+ * attached to the current thread.
+ *
+ * The timer is initially stopped, measures elapsed time between the invocations of `start()`
+ * and `stop()`, and resets on consequent invocations of `start()`.
+ *
+ * To reset a timer, it should be stopped first and then started again.
+ *
+ * The timer is paused when the operation's client is detached from the current thread, and will
+ * not resume until the client is reattached to a thread.
+ */
+class OperationCPUTimer {
+public:
+    /**
+     * Returns `nullptr` if the platform does not support tracking of CPU consumption.
+     */
+    static OperationCPUTimer* get(OperationContext*);
+
+    virtual Nanoseconds getElapsed() const = 0;
+
+    virtual void start() = 0;
+    virtual void stop() = 0;
+
+    virtual void onThreadAttach() = 0;
+    virtual void onThreadDetach() = 0;
+};
+
+}  // namespace mongo
diff --git a/src/mongo/db/operation_cpu_timer_test.cpp b/src/mongo/db/operation_cpu_timer_test.cpp
new file mode 100644
index 00000000000..e498ce168b6
--- /dev/null
+++ b/src/mongo/db/operation_cpu_timer_test.cpp
@@ -0,0 +1,171 @@
+/**
+ *    Copyright (C) 2020-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/db/operation_cpu_timer.h"
+#include "mongo/db/service_context_test_fixture.h"
+#include "mongo/platform/atomic_word.h"
+#include "mongo/stdx/thread.h"
+#include "mongo/unittest/barrier.h"
+#include "mongo/unittest/death_test.h"
+#include "mongo/unittest/unittest.h"
+#include "mongo/util/time_support.h"
+
+namespace mongo {
+
+class OperationCPUTimerTest : public ServiceContextTest {
+public:
+    auto makeClient() const {
+        return getGlobalServiceContext()->makeClient("AlternativeClient");
+    }
+
+    auto getTimer() const {
+        return OperationCPUTimer::get(_opCtx.get());
+    }
+
+    void setUp() {
+        _opCtx = getGlobalServiceContext()->makeOperationContext(Client::getCurrent());
+    }
+
+    void busyWait(Nanoseconds delay) const {
+        AtomicWord<bool> mayJoin{false};
+        stdx::thread blocker([&] {
+            sleepFor(delay);
+            mayJoin.store(true);
+        });
+        while (!mayJoin.load()) {
+            // Busy wait for the blocker thread.
+        }
+        blocker.join();
+    }
+
+private:
+    ServiceContext::UniqueOperationContext _opCtx;
+};
+
+#if defined(__linux__)
+
+TEST_F(OperationCPUTimerTest, TestTimer) {
+    auto timer = getTimer();
+
+    timer->start();
+    busyWait(Nanoseconds(100));  // A small delay to make sure the timer advances.
+    ASSERT_GT(timer->getElapsed(), Nanoseconds(0));
+    timer->stop();
+
+    const auto elapsedAfterStop = timer->getElapsed();
+    busyWait(Microseconds(1));  // A relatively longer delay to ensure the timer doesn't proceed.
+    const auto elapsedAfterSleep = timer->getElapsed();
+    ASSERT_EQ(elapsedAfterStop, elapsedAfterSleep);
+}
+
+TEST_F(OperationCPUTimerTest, TestReset) {
+    auto timer = getTimer();
+
+    timer->start();
+    busyWait(Microseconds(1));  // Introducing some delay for the timer to measure.
+    timer->stop();
+    auto elapsedAfterStop = timer->getElapsed();
+    ASSERT_GTE(elapsedAfterStop, Microseconds(1));
+
+    timer->start();
+    auto elapsedAfterReset = timer->getElapsed();
+    ASSERT_LT(elapsedAfterReset, elapsedAfterStop);
+}
+
+TEST_F(OperationCPUTimerTest, TestTimerDetachAndAttachHandlers) {
+    unittest::Barrier failPointsReady{2};
+    stdx::thread observer([&] {
+        FailPointEnableBlock fpAttach("hangCPUTimerAfterOnThreadAttach");
+        {
+            FailPointEnableBlock fpDetach("hangCPUTimerAfterOnThreadDetach");
+            failPointsReady.countDownAndWait();
+            fpDetach->waitForTimesEntered(1);
+        }
+        fpAttach->waitForTimesEntered(1);
+    });
+
+    auto timer = getTimer();
+    timer->start();
+
+    failPointsReady.countDownAndWait();
+    {
+        auto client = makeClient();
+        AlternativeClientRegion acr(client);
+    }
+
+    timer->stop();
+    observer.join();
+}
+
+DEATH_TEST_F(OperationCPUTimerTest,
+             AccessTimerForDetachedOperation,
+             "Operation not attached to the current thread") {
+    auto client = Client::releaseCurrent();
+    getTimer();
+}
+
+DEATH_TEST_F(OperationCPUTimerTest, StopTimerBeforeStart, "Timer is not running") {
+    getTimer()->stop();
+}
+
+DEATH_TEST_F(OperationCPUTimerTest, StartTimerMultipleTimes, "Timer has already started") {
+    getTimer()->start();
+    getTimer()->start();
+}
+
+DEATH_TEST_F(OperationCPUTimerTest, OnAttachForAttachedTimer, "Timer has already been attached") {
+    auto timer = getTimer();
+    timer->start();
+    timer->onThreadAttach();
+}
+
+DEATH_TEST_F(OperationCPUTimerTest, OnDetachForDetachedTimer, "Timer is not attached") {
+    auto timer = getTimer();
+    timer->start();
+    auto client = Client::releaseCurrent();
+    timer->onThreadDetach();
+}
+
+DEATH_TEST_F(OperationCPUTimerTest, GetElapsedForPausedTimer, "Not attached to current thread") {
+    auto timer = getTimer();
+    timer->start();
+    auto client = Client::releaseCurrent();
+    timer->getElapsed();
+}
+
+#else
+
+TEST_F(OperationCPUTimerTest, TimerNotSetIfNotSupported) {
+    auto timer = getTimer();
+    ASSERT(timer == nullptr);
+}
+
+#endif  // defined(__linux__)
+
+}  // namespace mongo