9 files changed, 539 insertions, 18 deletions

diff --git a/jstests/auth/user_cache_acquisition_stats.js b/jstests/auth/user_cache_acquisition_stats.js
new file mode 100644
index 00000000000..a2f9996d127
--- /dev/null
+++ b/jstests/auth/user_cache_acquisition_stats.js
@@ -0,0 +1,153 @@
+/**
+ * Test that user cache acquisition stats are appropriately
+ * updated whenever a UserHandle is acquired via the user cache.
+ * @tags: [
+ *   requires_replication,
+ *   requires_sharding
+ * ]
+ */
+
+(function() {
+'use strict';
+
+load("jstests/libs/parallel_shell_helpers.js");
+
+function hasCommandLogEntry(conn, id, command, attributes, count) {
+    let expectedLog = {command: command};
+    if (Object.keys(attributes).length > 0) {
+        expectedLog = Object.assign({}, expectedLog, attributes);
+    }
+    checkLog.containsRelaxedJson(conn, id, expectedLog, count);
+}
+
+function hasNoCommandLogEntry(conn, id, command, attributes) {
+    let expectedLog = {command: command};
+    if (Object.keys(attributes).length > 0) {
+        expectedLog = Object.assign({}, expectedLog, attributes);
+    }
+    checkLog.containsRelaxedJson(conn, id, expectedLog, 0);
+}
+
+function runTest(conn, mode) {
+    // Set the authUserCacheSleep failpoint. This causes the server to sleep for 1 second
+    // every time it accesses the user cache, which provides a lower bound when checking the stats'
+    // accuracy.
+    const adminDB = conn.getDB('admin');
+    assert.commandWorked(adminDB.runCommand({
+        configureFailPoint: 'authUserCacheSleep',
+        mode: 'alwaysOn',
+    }));
+
+    // Create an admin user and authenticate as the admin user.
+    assert.commandWorked(adminDB.runCommand({createUser: 'admin', pwd: 'pwd', roles: ['root']}));
+    assert(adminDB.auth('admin', 'pwd'));
+
+    // Check that authenticating as admin results in the expected log lines with the user cache
+    // acquisition stats.
+    const waitTimeRegex = new RegExp('^[1-9][0-9]{6,}$', 'i');
+    const logID = 51803;
+    let expectedIsMasterCommandLog = {isMaster: 1.0};
+    let expectedCommandWithUserCacheAttrs = {
+        authorization: {
+            startedUserCacheAcquisitionAttempts: 1,
+            completedUserCacheAcquisitionAttempts: 1,
+            userCacheWaitTimeMicros: waitTimeRegex,
+        },
+    };
+    hasCommandLogEntry(
+        conn, logID, expectedIsMasterCommandLog, expectedCommandWithUserCacheAttrs, 1);
+
+    // Set logging level to 1 so that all operations are logged upon completion.
+    assert.commandWorked(adminDB.runCommand({setParameter: 1, logLevel: 1}));
+
+    // Create another database to write to and a new user with the "readWrite" and "userAdmin" roles
+    // on that database.
+    const testDB = conn.getDB('test');
+    // Set profiling level to 2 so that profiling is enabled for the standalone test.
+    if (mode === 'Standalone') {
+        testDB.setProfilingLevel(0);
+        testDB.system.profile.drop();
+        testDB.setProfilingLevel(2);
+    }
+
+    assert.commandWorked(
+        testDB.runCommand({createUser: 'testUser', pwd: 'pwd', roles: ['readWrite', 'userAdmin']}));
+
+    // Launch a parallel shell to perform an insert operation while authenticated as 'testUser'.
+    let awaitOps = startParallelShell(function() {
+        const testDB = db.getSiblingDB('test');
+        assert(testDB.auth('testUser', 'pwd'));
+        // Insert a document into testCollection and then run a find command on it. These should
+        // both succeed due to testUser's readWrite role and should not require user cache accesses.
+        assert.writeOK(testDB.coll.insert({x: 1}, {writeConcern: {w: 'majority'}}));
+        assert.commandWorked(testDB.runCommand({find: 'coll'}));
+
+        // Replace testUser's 'readWrite' role with a 'read' role and try a find operation.
+        assert.commandWorked(testDB.runCommand({
+            revokeRolesFromUser: 'testUser',
+            roles: ['readWrite'],
+            writeConcern: {w: 'majority'}
+        }));
+        assert.commandWorked(testDB.runCommand(
+            {grantRolesToUser: 'testUser', roles: ['read'], writeConcern: {w: 'majority'}}));
+        assert.commandWorked(testDB.runCommand({find: 'coll'}));
+    }, conn.port);
+
+    awaitOps();
+
+    // Check that there's a log for the successful insert command that does NOT contain
+    // authorization stats (since it didn't access the user cache).
+    let expectedInsertCommandLog = {insert: "coll"};
+    let unexpectedCommandWithoutUserCacheAttrs = {
+        authorization: {
+            startedUserCacheAcquisitionAttempts: 0,
+            completedUserCacheAcquisitionAttempts: 0,
+            userCacheWaitTimeMicros: 0,
+        },
+    };
+    hasCommandLogEntry(conn, logID, expectedInsertCommandLog, {}, 1);
+    hasNoCommandLogEntry(
+        conn, logID, expectedInsertCommandLog, unexpectedCommandWithoutUserCacheAttrs);
+
+    // Check that there's a log for the successful find command that does NOT contain authorization
+    // stats (since it didn't access the user cache).
+    let expectedFindCommandLog = {find: "coll"};
+    hasCommandLogEntry(conn, logID, expectedFindCommandLog, {}, 2);
+    hasNoCommandLogEntry(
+        conn, logID, expectedFindCommandLog, unexpectedCommandWithoutUserCacheAttrs);
+
+    // Check that there's a log for the successful find command that had to access to the user
+    // cache.
+    hasCommandLogEntry(conn, logID, expectedFindCommandLog, expectedCommandWithUserCacheAttrs);
+
+    // Check that there is also a document for the successful find command with authorization stats
+    // in system.profile when profiling is enabled on standalones.
+    if (mode === 'Standalone') {
+        const query = {
+            "command.find": "coll",
+            "authorization.startedUserCacheAcquisitionAttempts": 1,
+            "authorization.completedUserCacheAcquisitionAttempts": 1,
+            "authorization.userCacheWaitTimeMicros": {"$gte": 1000000}
+        };
+        assert.eq(1, testDB.system.profile.find(query).toArray().length);
+    }
+}
+
+// Standalone
+{
+    const mongod = MongoRunner.runMongod({auth: ''});
+    jsTest.log('Starting user_cache_acquisition_stats.js Standalone');
+    runTest(mongod, 'Standalone');
+    jsTest.log('SUCCESS user_cache_acquisition_stats.js Standalone');
+    MongoRunner.stopMongod(mongod);
+}
+
+// Sharded Cluster
+{
+    const st = new ShardingTest({mongos: [{auth: null}], config: [{auth: null}], shards: 1});
+    jsTest.log('Starting user_cache_acquisition_stats.js Sharding');
+    runTest(st.s0, 'Sharded');
+    jsTest.log('SUCCESS user_cache_acquisition_stats.js Sharding');
+    st.stop();
+}
+})();
\ No newline at end of file
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;
 };
 
diff --git a/src/mongo/shell/check_log.js b/src/mongo/shell/check_log.js
index 8aa426698bd..4db75d72d5d 100644
--- a/src/mongo/shell/check_log.js
+++ b/src/mongo/shell/check_log.js
@@ -75,8 +75,16 @@ checkLog = (function() {
         return false;
     };
 
+    /*
+     * Acts just like checkContainsOnceJson but introduces the `expectedCount and `isRelaxed params.
+     * `isRelaxed` is used to determine how object attributes are handled for matching purposes. If
+     * `isRelaxed` is true, then only the fields included in the object in attrsDict will be checked
+     * for in the corresponding object in the log. Otherwise, the objects will be checked for
+     * complete equality. In addition, the `expectedCount` param ensures that the log appears
+     * exactly as many times as expected.
+     */
     const checkContainsWithCountJson = function(
-        conn, id, attrsDict, expectedCount, severity = null) {
+        conn, id, attrsDict, expectedCount, severity = null, isRelaxed = false) {
         const logMessages = getGlobalLog(conn);
         if (logMessages === null) {
             return false;
@@ -93,7 +101,7 @@ checkLog = (function() {
                 throw ex;
             }
 
-            if (_compareLogs(obj, id, severity, attrsDict)) {
+            if (_compareLogs(obj, id, severity, attrsDict, isRelaxed)) {
                 count++;
             }
         }
@@ -127,19 +135,19 @@ checkLog = (function() {
      * Calls the 'getLog' function at regular intervals on the provided connection 'conn' until
      * the provided 'msg' is found in the logs, or it times out. Throws an exception on timeout.
      */
-    let contains = function(conn, msg, timeout = 5 * 60 * 1000, retryIntervalMS = 300) {
+    let contains = function(conn, msg, timeoutMillis = 5 * 60 * 1000, retryIntervalMS = 300) {
         // Don't run the hang analyzer because we don't expect contains() to always succeed.
         assert.soon(
             function() {
                 return checkContainsOnce(conn, msg);
             },
             'Could not find log entries containing the following message: ' + msg,
-            timeout,
+            timeoutMillis,
             retryIntervalMS,
             {runHangAnalyzer: false});
     };
 
-    let containsJson = function(conn, id, attrsDict, timeout = 5 * 60 * 1000) {
+    let containsJson = function(conn, id, attrsDict, timeoutMillis = 5 * 60 * 1000) {
         // Don't run the hang analyzer because we don't expect contains() to always succeed.
         assert.soon(
             function() {
@@ -147,7 +155,26 @@ checkLog = (function() {
             },
             'Could not find log entries containing the following id: ' + id +
                 ', and attrs: ' + tojson(attrsDict),
-            timeout,
+            timeoutMillis,
+            300,
+            {runHangAnalyzer: false});
+    };
+
+    /*
+     * Calls checkContainsWithCountJson with the `isRelaxed` parameter set to true at regular
+     * intervals on the provided connection 'conn' until a log with id 'id' and all of the
+     * attributes in 'attrsDict' is found `expectedCount` times or the timeout (in ms) is reached.
+     */
+    let containsRelaxedJson = function(
+        conn, id, attrsDict, expectedCount = 1, timeoutMillis = 5 * 60 * 1000) {
+        // Don't run the hang analyzer because we don't expect contains() to always succeed.
+        assert.soon(
+            function() {
+                return checkContainsWithCountJson(conn, id, attrsDict, expectedCount, null, true);
+            },
+            'Could not find log entries containing the following id: ' + id +
+                ', and attrs: ' + tojson(attrsDict),
+            timeoutMillis,
             300,
             {runHangAnalyzer: false});
     };
@@ -160,7 +187,7 @@ checkLog = (function() {
      * 'expectedCount'. Early returns when at least 'expectedCount' entries are found.
      */
     let containsWithCount = function(
-        conn, msg, expectedCount, timeout = 5 * 60 * 1000, exact = true) {
+        conn, msg, expectedCount, timeoutMillis = 5 * 60 * 1000, exact = true) {
         let expectedStr = exact ? 'exactly ' : 'at least ';
         assert.soon(
             function() {
@@ -190,7 +217,7 @@ checkLog = (function() {
             },
             'Did not find ' + expectedStr + expectedCount + ' log entries containing the ' +
                 'following message: ' + msg,
-            timeout,
+            timeoutMillis,
             300);
     };
 
@@ -198,8 +225,9 @@ checkLog = (function() {
      * Similar to containsWithCount, but checks whether there are at least 'expectedCount'
      * instances of 'msg' in the logs.
      */
-    let containsWithAtLeastCount = function(conn, msg, expectedCount, timeout = 5 * 60 * 1000) {
-        containsWithCount(conn, msg, expectedCount, timeout, /*exact*/ false);
+    let containsWithAtLeastCount = function(
+        conn, msg, expectedCount, timeoutMillis = 5 * 60 * 1000) {
+        containsWithCount(conn, msg, expectedCount, timeoutMillis, /*exact*/ false);
     };
 
     /*
@@ -255,23 +283,38 @@ checkLog = (function() {
         return (Array.isArray(value) ? `[${serialized.join(',')}]` : `{${serialized.join(',')}}`);
     };
 
-    // Internal helper to compare objects filed by field.
-    const _deepEqual = function(object1, object2) {
+    /**
+     * Internal helper to compare objects filed by field. object1 is considered as the object
+     * from the log, while object2 is considered as the expected object from the test. If
+     * `isRelaxed` is true, then object1 must contain all of the fields in object2, but can contain
+     * other fields as well. By default, this checks for an exact match between object1 and object2.
+     */
+    const _deepEqual = function(object1, object2, isRelaxed = false) {
         if (object1 == null || object2 == null) {
             return false;
         }
         const keys1 = Object.keys(object1);
         const keys2 = Object.keys(object2);
 
-        if (keys1.length !== keys2.length) {
+        if (!isRelaxed && (keys1.length !== keys2.length)) {
             return false;
         }
 
-        for (const key of keys1) {
+        for (const key of keys2) {
             const val1 = object1[key];
             const val2 = object2[key];
+            // Check if val2 is a regex that needs to be matched.
+            if (val2 instanceof RegExp) {
+                if (!val2.test(val1)) {
+                    return false;
+                } else {
+                    continue;
+                }
+            }
+            // If they are any other type of object, then recursively call _deepEqual(). Otherwise
+            // perform a simple equality check.
             const areObjects = _isObject(val1) && _isObject(val2);
-            if (areObjects && !_deepEqual(val1, val2) || !areObjects && val1 !== val2) {
+            if (areObjects && !_deepEqual(val1, val2, isRelaxed) || !areObjects && val1 !== val2) {
                 return false;
             }
         }
@@ -284,8 +327,13 @@ checkLog = (function() {
         return object != null && typeof object === 'object';
     };
 
-    // Internal helper to check if a log's id, severity, and attributes match with what's expected.
-    const _compareLogs = function(obj, id, severity, attrsDict) {
+    /*
+     * Internal helper to check if a log's id, severity, and attributes match with what's expected.
+     * If `isRelaxed` is true, then the `_deepEqual()` helper function will only check that the
+     * fields specified in the attrsDict attribute are equal to those in the corresponding attribute
+     * of obj. Otherwise, `_deepEqual()` checks that both subobjects are identical.
+     */
+    const _compareLogs = function(obj, id, severity, attrsDict, isRelaxed = false) {
         if (obj.id !== id) {
             return false;
         }
@@ -300,7 +348,7 @@ checkLog = (function() {
                     return false;
                 }
             } else if (obj.attr[attrKey] !== attrValue && typeof obj.attr[attrKey] == "object") {
-                if (!_deepEqual(obj.attr[attrKey], attrValue)) {
+                if (!_deepEqual(obj.attr[attrKey], attrValue, isRelaxed)) {
                     return false;
                 }
             } else {
@@ -320,6 +368,7 @@ checkLog = (function() {
         checkContainsOnceJsonStringMatch: checkContainsOnceJsonStringMatch,
         contains: contains,
         containsJson: containsJson,
+        containsRelaxedJson: containsRelaxedJson,
         containsWithCount: containsWithCount,
         containsWithAtLeastCount: containsWithAtLeastCount,
         formatAsLogLine: formatAsLogLine,