SERVER-46412: Track, log, and profile user cache acquisition stats in CurOp

7 files changed, 319 insertions, 0 deletions

diff --git a/src/mongo/db/SConscript b/src/mongo/db/SConscript
index 7ba70521a78..5800419fe31 100644
--- a/src/mongo/db/SConscript
+++ b/src/mongo/db/SConscript
@@ -164,6 +164,7 @@ env.Library(
     ],
     LIBDEPS_PRIVATE=[
         'auth/auth',
+        'auth/user_cache_acquisition_stats',
         'prepare_conflict_tracker',
         'stats/resource_consumption_metrics',
     ],
diff --git a/src/mongo/db/auth/SConscript b/src/mongo/db/auth/SConscript
index b2d90c009d7..22ee3ed3f6d 100644
--- a/src/mongo/db/auth/SConscript
+++ b/src/mongo/db/auth/SConscript
@@ -156,6 +156,7 @@ env.Library(
         '$BUILD_DIR/mongo/base/secure_allocator',
         '$BUILD_DIR/mongo/bson/util/bson_extract',
         '$BUILD_DIR/mongo/db/common',
+        '$BUILD_DIR/mongo/db/curop',
         '$BUILD_DIR/mongo/db/global_settings',
         '$BUILD_DIR/mongo/db/namespace_string',
         '$BUILD_DIR/mongo/idl/feature_flag',
@@ -464,6 +465,17 @@ env.Library(
     ],
 )
 
+env.Library(
+    target='user_cache_acquisition_stats',
+    source=[
+        'user_cache_acquisition_stats.cpp'
+    ],
+    LIBDEPS_PRIVATE=[
+        '$BUILD_DIR/mongo/base',
+        'auth',
+    ],
+)
+
 env.CppUnitTest(
     target='db_auth_test',
     source=[
diff --git a/src/mongo/db/auth/authorization_manager_impl.cpp b/src/mongo/db/auth/authorization_manager_impl.cpp
index 807c17ef80b..3f0ba427cc8 100644
--- a/src/mongo/db/auth/authorization_manager_impl.cpp
+++ b/src/mongo/db/auth/authorization_manager_impl.cpp
@@ -52,6 +52,7 @@
 #include "mongo/db/auth/sasl_options.h"
 #include "mongo/db/auth/user_document_parser.h"
 #include "mongo/db/auth/user_management_commands_parser.h"
+#include "mongo/db/curop.h"
 #include "mongo/db/global_settings.h"
 #include "mongo/db/mongod_options.h"
 #include "mongo/logv2/log.h"
@@ -455,6 +456,7 @@ Status AuthorizationManagerImpl::getRoleDescriptionsForDB(
 
 namespace {
 MONGO_FAIL_POINT_DEFINE(authUserCacheBypass);
+MONGO_FAIL_POINT_DEFINE(authUserCacheSleep);
 }  // namespace
 
 StatusWith<UserHandle> AuthorizationManagerImpl::acquireUser(OperationContext* opCtx,
@@ -491,7 +493,17 @@ StatusWith<UserHandle> AuthorizationManagerImpl::acquireUser(OperationContext* o
         return userHandle;
     }
 
+    // Track wait time and user cache access statistics for the current op for logging. An extra
+    // second of delay is added via the failpoint for testing.
+    auto userCacheAcquisitionStats = CurOp::get(opCtx)->getMutableUserCacheAcquisitionStats(
+        opCtx->getClient(), opCtx->getServiceContext()->getTickSource());
+    if (authUserCacheSleep.shouldFail()) {
+        sleepsecs(1);
+    }
+
     auto cachedUser = _userCache.acquire(opCtx, request);
+
+    userCacheAcquisitionStats.recordCacheAccessEnd();
     invariant(cachedUser);
 
     LOGV2_DEBUG(20226, 1, "Returning user from cache", "user"_attr = userName);
diff --git a/src/mongo/db/auth/user_cache_acquisition_stats.cpp b/src/mongo/db/auth/user_cache_acquisition_stats.cpp
new file mode 100644
index 00000000000..9b0df3cd452
--- /dev/null
+++ b/src/mongo/db/auth/user_cache_acquisition_stats.cpp
@@ -0,0 +1,65 @@
+/**
+ *    Copyright (C) 2021-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/platform/basic.h"
+
+#include "mongo/db/auth/user_cache_acquisition_stats.h"
+
+#include "mongo/util/duration.h"
+#include "mongo/util/system_tick_source.h"
+
+namespace mongo {
+
+constexpr auto kActiveAcquisitionAttemptsName = "startedUserCacheAcquisitionAttempts"_sd;
+constexpr auto kCompletedAcquisitionAttemptsName = "completedUserCacheAcquisitionAttempts"_sd;
+constexpr auto kWaitTimeName = "userCacheWaitTimeMicros"_sd;
+
+void UserCacheAcquisitionStats::report(BSONObjBuilder* builder, TickSource* tickSource) const {
+    builder->append(kActiveAcquisitionAttemptsName, std::int64_t(_totalStartedAcquisitionAttempts));
+    builder->append(kCompletedAcquisitionAttemptsName,
+                    std::int64_t(_totalCompletedAcquisitionAttempts));
+    builder->append(kWaitTimeName, durationCount<Microseconds>(_timeElapsed(tickSource)));
+}
+
+void UserCacheAcquisitionStats::toString(StringBuilder* sb, TickSource* tickSource) const {
+    *sb << "{ " << kActiveAcquisitionAttemptsName << ": " << _totalStartedAcquisitionAttempts
+        << ", ";
+    *sb << kCompletedAcquisitionAttemptsName << ": " << _totalCompletedAcquisitionAttempts << ", ";
+    *sb << kWaitTimeName << ": " << durationCount<Microseconds>(_timeElapsed(tickSource)) << " }";
+}
+
+Microseconds UserCacheAcquisitionStats::_timeElapsed(TickSource* tickSource) const {
+    if (_cacheAccessEndTime <= _cacheAccessStartTime) {
+        return tickSource->ticksTo<Microseconds>(tickSource->getTicks()) - _cacheAccessStartTime;
+    }
+
+    return _cacheAccessEndTime - _cacheAccessStartTime;
+}
+
+}  // namespace mongo
diff --git a/src/mongo/db/auth/user_cache_acquisition_stats.h b/src/mongo/db/auth/user_cache_acquisition_stats.h
new file mode 100644
index 00000000000..75f24b2a747
--- /dev/null
+++ b/src/mongo/db/auth/user_cache_acquisition_stats.h
@@ -0,0 +1,173 @@
+/**
+ *    Copyright (C) 2021-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 <memory>
+
+#include "mongo/bson/bsonobjbuilder.h"
+#include "mongo/db/client.h"
+#include "mongo/util/tick_source.h"
+
+namespace mongo {
+
+/**
+ * Tracks and stores statistics related to user cache access on a per-operation
+ * basis. These statistics are tracked and reported from within CurOp.
+ */
+class UserCacheAcquisitionStats {
+    using AccessInterval = std::pair<Microseconds, Microseconds>;
+
+    /*
+     * The RAII handle has access to private members of UserCacheAcquisitionStats but only exposes
+     * _recordCacheAccessStart() and _recordCacheAccessEnd().
+     */
+    friend class UserCacheAcquisitionStatsHandle;
+
+public:
+    UserCacheAcquisitionStats() = default;
+    ~UserCacheAcquisitionStats() = default;
+    UserCacheAcquisitionStats(const UserCacheAcquisitionStats&) = delete;
+    UserCacheAcquisitionStats& operator=(const UserCacheAcquisitionStats&) = delete;
+
+    /**
+     * Returns true if the cache has been accessed during the operation and has stats that should
+     * be reported.
+     */
+    bool shouldReport() const {
+        return _totalStartedAcquisitionAttempts != 0 || _totalCompletedAcquisitionAttempts != 0;
+    }
+
+    /**
+     * Marshals all statistics into BSON for reporting.
+     */
+    void report(BSONObjBuilder* builder, TickSource* tickSource) const;
+
+    /**
+     * Marshals all statistics into a string for reporting.
+     */
+    void toString(StringBuilder* sb, TickSource* tickSource) const;
+
+private:
+    /**
+     * Records the start time of a new cache access attempt.
+     */
+    void _recordCacheAccessStart(Client* client, TickSource* tickSource) {
+        stdx::lock_guard<Client> lk(*client);
+        _cacheAccessStartTime = tickSource->ticksTo<Microseconds>(tickSource->getTicks());
+        ++_totalStartedAcquisitionAttempts;
+    }
+
+    /**
+     * Records the completion of a cache access attempt by setting the end time. The start time must
+     * already be set.
+     */
+    void _recordCacheAccessEnd(Client* client, TickSource* tickSource) {
+        stdx::lock_guard<Client> lk(*client);
+        invariant(_cacheAccessStartTime != Microseconds{0});
+        _cacheAccessEndTime = tickSource->ticksTo<Microseconds>(tickSource->getTicks());
+        ++_totalCompletedAcquisitionAttempts;
+    }
+
+    /**
+     * Computes and returns total time spent on all cache accesses.
+     */
+    Microseconds _timeElapsed(TickSource* tickSource) const;
+
+    /**
+     * Total number of started attempts to get a user from the cache.
+     */
+    std::uint64_t _totalStartedAcquisitionAttempts{0};
+
+    /**
+     * Total number of completed user cache accesses.
+     */
+    std::uint64_t _totalCompletedAcquisitionAttempts{0};
+
+    /**
+     * Start and end times of user cache access. If the access is still
+     * pending, then the end time will be 0.
+     */
+    Microseconds _cacheAccessStartTime{Microseconds{0}};
+    Microseconds _cacheAccessEndTime{Microseconds{0}};
+};
+
+/**
+ * RAII handle that is used to mutate a UserCacheAcquisitionStats object. It automatically records
+ * the start of a cache access attempt upon construction and provides access to
+ * UserCacheAcquisitionStats::recordCacheAccessEnd(). Additionally, it guarantees that an ongoing
+ * user cache attempt will be recorded as complete as soon as the handle goes out of scope. This
+ * ensures that UserCacheAcquisitionStats::recordCacheAccessEnd() will be called even if an
+ * exception is thrown.
+ */
+class UserCacheAcquisitionStatsHandle {
+public:
+    UserCacheAcquisitionStatsHandle() = delete;
+
+    UserCacheAcquisitionStatsHandle(UserCacheAcquisitionStats* statsParam,
+                                    Client* client,
+                                    TickSource* tickSource)
+        : _stats(statsParam), _client(client), _tickSource(tickSource) {
+        _stats->_recordCacheAccessStart(_client, _tickSource);
+    }
+
+    UserCacheAcquisitionStatsHandle(const UserCacheAcquisitionStatsHandle&) = delete;
+    UserCacheAcquisitionStatsHandle& operator=(const UserCacheAcquisitionStatsHandle&) = delete;
+
+    UserCacheAcquisitionStatsHandle(UserCacheAcquisitionStatsHandle&& handle)
+        : _stats(std::exchange(handle._stats, nullptr)),
+          _client(std::move(handle._client)),
+          _tickSource(std::move(handle._tickSource)) {}
+
+    UserCacheAcquisitionStatsHandle& operator=(UserCacheAcquisitionStatsHandle&& handle) {
+        _stats = std::exchange(handle._stats, nullptr);
+        _client = std::move(handle._client);
+        _tickSource = std::move(handle._tickSource);
+
+        return *this;
+    }
+
+    ~UserCacheAcquisitionStatsHandle() {
+        recordCacheAccessEnd();
+    }
+
+    void recordCacheAccessEnd() {
+        if (_stats) {
+            _stats->_recordCacheAccessEnd(_client, _tickSource);
+        }
+        _stats = nullptr;
+    }
+
+private:
+    UserCacheAcquisitionStats* _stats;
+    Client* _client;
+    TickSource* _tickSource;
+};
+
+}  // namespace mongo
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index 6a2e0aead94..29e63a3a1e9 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -936,6 +936,14 @@ string OpDebug::report(OperationContext* opCtx, const SingleThreadedLockStats* l
         s << " locks:" << locks.obj().toString();
     }
 
+    auto userCacheAcquisitionStats = curop.getReadOnlyUserCacheAcquisitionStats();
+    if (userCacheAcquisitionStats->shouldReport()) {
+        StringBuilder userCacheAcquisitionStatsBuilder;
+        userCacheAcquisitionStats->toString(&userCacheAcquisitionStatsBuilder,
+                                            opCtx->getServiceContext()->getTickSource());
+        s << " authorization:" << userCacheAcquisitionStatsBuilder.str();
+    }
+
     BSONObj flowControlObj = makeFlowControlObject(flowControlStats);
     if (flowControlObj.nFields() > 0) {
         s << " flowControl:" << flowControlObj.toString();
@@ -1107,6 +1115,14 @@ void OpDebug::report(OperationContext* opCtx,
         pAttrs->add("locks", locks.obj());
     }
 
+    auto userCacheAcquisitionStats = curop.getReadOnlyUserCacheAcquisitionStats();
+    if (userCacheAcquisitionStats->shouldReport()) {
+        BSONObjBuilder userCacheAcquisitionStatsBuilder;
+        userCacheAcquisitionStats->report(&userCacheAcquisitionStatsBuilder,
+                                          opCtx->getServiceContext()->getTickSource());
+        pAttrs->add("authorization", userCacheAcquisitionStatsBuilder.obj());
+    }
+
     BSONObj flowControlObj = makeFlowControlObject(flowControlStats);
     if (flowControlObj.nFields() > 0) {
         pAttrs->add("flowControl", flowControlObj);
@@ -1231,6 +1247,15 @@ void OpDebug::append(OperationContext* opCtx,
     }
 
     {
+        auto userCacheAcquisitionStats = curop.getReadOnlyUserCacheAcquisitionStats();
+        if (userCacheAcquisitionStats->shouldReport()) {
+            BSONObjBuilder userCacheAcquisitionStatsBuilder(b.subobjStart("authorization"));
+            userCacheAcquisitionStats->report(&userCacheAcquisitionStatsBuilder,
+                                              opCtx->getServiceContext()->getTickSource());
+        }
+    }
+
+    {
         BSONObj flowControlMetrics = makeFlowControlObject(flowControlStats);
         BSONObjBuilder flowControlBuilder(b.subobjStart("flowControl"));
         flowControlBuilder.appendElements(flowControlMetrics);
@@ -1488,6 +1513,15 @@ std::function<BSONObj(ProfileFilter::Args)> OpDebug::appendStaged(StringSet requ
         }
     });
 
+    addIfNeeded("authorization", [](auto field, auto args, auto& b) {
+        auto userCacheAcquisitionStats = args.curop.getReadOnlyUserCacheAcquisitionStats();
+        if (userCacheAcquisitionStats->shouldReport()) {
+            BSONObjBuilder userCacheAcquisitionStatsBuilder(b.subobjStart(field));
+            userCacheAcquisitionStats->report(&userCacheAcquisitionStatsBuilder,
+                                              args.opCtx->getServiceContext()->getTickSource());
+        }
+    });
+
     addIfNeeded("flowControl", [](auto field, auto args, auto& b) {
         BSONObj flowControlMetrics =
             makeFlowControlObject(args.opCtx->lockState()->getFlowControlStats());
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index 84feaace21c..44530fcfbfd 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -32,6 +32,7 @@
 
 #include "mongo/config.h"
 #include "mongo/db/auth/authorization_session.h"
+#include "mongo/db/auth/user_cache_acquisition_stats.h"
 #include "mongo/db/catalog/collection_catalog.h"
 #include "mongo/db/clientcursor.h"
 #include "mongo/db/commands.h"
@@ -420,6 +421,25 @@ public:
     }
 
     /**
+     * Returns a const pointer to the authorization user cache statistics for the current operation.
+     * This can only be used for reading (i.e., when logging or profiling).
+     */
+    const UserCacheAcquisitionStats* getReadOnlyUserCacheAcquisitionStats() const {
+        return &_userCacheAcquisitionStats;
+    }
+
+    /**
+     * Returns an instance of UserCacheAcquisitionStatsHandle. By doing so, it automatically records
+     * the start of the user cache access attempt upon creation. If the cache access is not
+     * completed and recorded normally before it is about to be destroyed (i.e., due to an
+     * exception), it will be automatically recorded as complete then.
+     */
+    UserCacheAcquisitionStatsHandle getMutableUserCacheAcquisitionStats(Client* client,
+                                                                        TickSource* tickSource) {
+        return UserCacheAcquisitionStatsHandle(&_userCacheAcquisitionStats, client, tickSource);
+    }
+
+    /**
      * Gets the name of the namespace on which the current operation operates.
      */
     NamespaceString getNSS() const {
@@ -815,6 +835,8 @@ private:
     boost::optional<SingleThreadedLockStats>
         _lockStatsBase;  // This is the snapshot of lock stats taken when curOp is constructed.
 
+    UserCacheAcquisitionStats _userCacheAcquisitionStats;
+
     TickSource* _tickSource = nullptr;
 };