SERVER-14900 Log operations that exceed slowMs on mongoS

13 files changed, 319 insertions, 119 deletions

diff --git a/src/mongo/db/commands/SConscript b/src/mongo/db/commands/SConscript
index d6aeba17592..4bdfa97fbfe 100644
--- a/src/mongo/db/commands/SConscript
+++ b/src/mongo/db/commands/SConscript
@@ -265,6 +265,7 @@ env.Library(
         'dcommands_fcv',
         'fsync_locked',
         'killcursors_common',
+        'profile_common',
         'write_commands_common',
     ],
     LIBDEPS_PRIVATE=[
@@ -301,6 +302,17 @@ env.Library(
 )
 
 env.Library(
+    target='profile_common',
+    source=[
+        'profile_common.cpp',
+        env.Idlc('profile.idl')[0],
+    ],
+    LIBDEPS=[
+        '$BUILD_DIR/mongo/db/commands',
+    ]
+)
+
+env.Library(
     target="list_collections_filter",
     source=[
         'list_collections_filter.cpp',
diff --git a/src/mongo/db/commands/dbcommands.cpp b/src/mongo/db/commands/dbcommands.cpp
index 10954efc526..15187ac16e4 100644
--- a/src/mongo/db/commands/dbcommands.cpp
+++ b/src/mongo/db/commands/dbcommands.cpp
@@ -55,6 +55,8 @@
 #include "mongo/db/catalog_raii.h"
 #include "mongo/db/clientcursor.h"
 #include "mongo/db/commands.h"
+#include "mongo/db/commands/profile_common.h"
+#include "mongo/db/commands/profile_gen.h"
 #include "mongo/db/commands/server_status.h"
 #include "mongo/db/commands/shutdown.h"
 #include "mongo/db/concurrency/write_conflict_exception.h"
@@ -294,105 +296,36 @@ public:
     }
 } cmdRepairDatabase;
 
-/* set db profiling level
-   todo: how do we handle profiling information put in the db with replication?
-         sensibly or not?
+/**
+ * Sets the profiling level, logging/profiling threshold, and logging/profiling sample rate for the
+ * given database.
 */
-class CmdProfile : public ErrmsgCommandDeprecated {
+class CmdProfile : public ProfileCmdBase {
 public:
-    AllowedOnSecondary secondaryAllowed(ServiceContext*) const override {
-        return AllowedOnSecondary::kAlways;
-    }
-
-    std::string help() const override {
-        return "enable or disable performance profiling\n"
-               "{ profile : <n> }\n"
-               "0=off 1=log slow ops 2=log all\n"
-               "-1 to get current values\n"
-               "http://docs.mongodb.org/manual/reference/command/profile/#dbcmd.profile";
-    }
-
-
-    virtual bool supportsWriteConcern(const BSONObj& cmd) const override {
-        return false;
-    }
-
-    virtual Status checkAuthForCommand(Client* client,
-                                       const std::string& dbname,
-                                       const BSONObj& cmdObj) const {
-        AuthorizationSession* authzSession = AuthorizationSession::get(client);
-
-        if (cmdObj.firstElement().numberInt() == -1 && !cmdObj.hasField("slowms") &&
-            !cmdObj.hasField("sampleRate")) {
-            // If you just want to get the current profiling level you can do so with just
-            // read access to system.profile, even if you can't change the profiling level.
-            if (authzSession->isAuthorizedForActionsOnResource(
-                    ResourcePattern::forExactNamespace(NamespaceString(dbname, "system.profile")),
-                    ActionType::find)) {
-                return Status::OK();
-            }
-        }
-
-        if (authzSession->isAuthorizedForActionsOnResource(ResourcePattern::forDatabaseName(dbname),
-                                                           ActionType::enableProfiler)) {
-            return Status::OK();
-        }
-
-        return Status(ErrorCodes::Unauthorized, "unauthorized");
-    }
-
-    CmdProfile() : ErrmsgCommandDeprecated("profile") {}
-
-    bool errmsgRun(OperationContext* opCtx,
-                   const string& dbname,
-                   const BSONObj& cmdObj,
-                   string& errmsg,
-                   BSONObjBuilder& result) {
-        BSONElement firstElement = cmdObj.firstElement();
-        int profilingLevel = firstElement.numberInt();
-
-        // If profilingLevel is 0, 1, or 2, needs to be locked exclusively,
-        // because creates the system.profile collection in the local database.
+    CmdProfile() = default;
 
+protected:
+    int _applyProfilingLevel(OperationContext* opCtx,
+                             const std::string& dbName,
+                             int profilingLevel) const final {
         const bool readOnly = (profilingLevel < 0 || profilingLevel > 2);
         const LockMode dbMode = readOnly ? MODE_S : MODE_X;
 
-        Status status = Status::OK();
-
-        AutoGetDb ctx(opCtx, dbname, dbMode);
+        AutoGetDb ctx(opCtx, dbName, dbMode);
         Database* db = ctx.getDb();
 
-        result.append("was", db ? db->getProfilingLevel() : serverGlobalParams.defaultProfile);
-        result.append("slowms", serverGlobalParams.slowMS);
-        result.append("sampleRate", serverGlobalParams.sampleRate);
+        auto oldLevel = (db ? db->getProfilingLevel() : serverGlobalParams.defaultProfile);
 
         if (!readOnly) {
             if (!db) {
                 // When setting the profiling level, create the database if it didn't already exist.
                 // When just reading the profiling level, we do not create the database.
-                db = dbHolder().openDb(opCtx, dbname);
+                db = dbHolder().openDb(opCtx, dbName);
             }
-            status = db->setProfilingLevel(opCtx, profilingLevel);
-        }
-
-        const BSONElement slow = cmdObj["slowms"];
-        if (slow.isNumber()) {
-            serverGlobalParams.slowMS = slow.numberInt();
-        }
-
-        double newSampleRate;
-        uassertStatusOK(bsonExtractDoubleFieldWithDefault(
-            cmdObj, "sampleRate"_sd, serverGlobalParams.sampleRate, &newSampleRate));
-        uassert(ErrorCodes::BadValue,
-                "sampleRate must be between 0.0 and 1.0 inclusive",
-                newSampleRate >= 0.0 && newSampleRate <= 1.0);
-        serverGlobalParams.sampleRate = newSampleRate;
-
-        if (!status.isOK()) {
-            errmsg = status.reason();
+            uassertStatusOK(db->setProfilingLevel(opCtx, profilingLevel));
         }
 
-        return status.isOK();
+        return oldLevel;
     }
 
 } cmdProfile;
diff --git a/src/mongo/db/commands/profile.idl b/src/mongo/db/commands/profile.idl
new file mode 100644
index 00000000000..5104aa0e1a4
--- /dev/null
+++ b/src/mongo/db/commands/profile.idl
@@ -0,0 +1,38 @@
+# Copyright (C) 2018 MongoDB Inc.
+#
+# This program is free software: you can redistribute it and/or  modify
+# it under the terms of the GNU Affero General Public License, version 3,
+# as published by the Free Software Foundation.
+#
+# 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
+# GNU Affero General Public License for more details.
+#
+# You should have received a copy of the GNU Affero General Public License
+# along with this program.  If not, see <http://www.gnu.org/licenses/>.
+#
+
+global:
+  cpp_namespace: "mongo"
+
+imports:
+    - "mongo/idl/basic_types.idl"
+
+commands:
+
+  profile:
+    description: "Parser for the 'profile' command."
+    cpp_name: ProfileCmdRequest
+    strict: false
+    namespace: type
+    type: safeInt32
+    fields:
+      slowms:
+        type: safeInt32
+        description: "The threshold, in milliseconds, at which ops are profiled and logged."
+        optional: true
+      sampleRate:
+        type: double
+        description: "The fraction of eligible ops, in the range [0,1), to be logged/profiled."
+        optional: true
diff --git a/src/mongo/db/commands/profile_common.cpp b/src/mongo/db/commands/profile_common.cpp
new file mode 100644
index 00000000000..2d46d264286
--- /dev/null
+++ b/src/mongo/db/commands/profile_common.cpp
@@ -0,0 +1,88 @@
+/**
+ * Copyright (C) 2018 MongoDB Inc.
+ *
+ * This program is free software: you can redistribute it and/or  modify
+ * it under the terms of the GNU Affero General Public License, version 3,
+ * as published by the Free Software Foundation.
+ *
+ * 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
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * 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 GNU Affero General 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/authorization_session.h"
+#include "mongo/db/commands/profile_common.h"
+#include "mongo/db/commands/profile_gen.h"
+#include "mongo/idl/idl_parser.h"
+
+namespace mongo {
+
+Status ProfileCmdBase::checkAuthForCommand(Client* client,
+                                           const std::string& dbName,
+                                           const BSONObj& cmdObj) const {
+    AuthorizationSession* authzSession = AuthorizationSession::get(client);
+
+    auto request = ProfileCmdRequest::parse(IDLParserErrorContext("profile"), cmdObj);
+    const auto profilingLevel = request.getCommandParameter();
+
+    if (profilingLevel < 0 && !request.getSlowms() && !request.getSampleRate()) {
+        // If the user just wants to view the current values of 'slowms' and 'sampleRate', they
+        // only need read rights on system.profile, even if they can't change the profiling level.
+        if (authzSession->isAuthorizedForActionsOnResource(
+                ResourcePattern::forExactNamespace({dbName, "system.profile"}), ActionType::find)) {
+            return Status::OK();
+        }
+    }
+
+    return authzSession->isAuthorizedForActionsOnResource(ResourcePattern::forDatabaseName(dbName),
+                                                          ActionType::enableProfiler)
+        ? Status::OK()
+        : Status(ErrorCodes::Unauthorized, "unauthorized");
+}
+
+bool ProfileCmdBase::run(OperationContext* opCtx,
+                         const std::string& dbName,
+                         const BSONObj& cmdObj,
+                         BSONObjBuilder& result) {
+    auto request = ProfileCmdRequest::parse(IDLParserErrorContext("profile"), cmdObj);
+    const auto profilingLevel = request.getCommandParameter();
+
+    // Delegate to _applyProfilingLevel to set the profiling level appropriately whether we are on
+    // mongoD or mongoS.
+    int oldLevel = _applyProfilingLevel(opCtx, dbName, profilingLevel);
+
+    result.append("was", oldLevel);
+    result.append("slowms", serverGlobalParams.slowMS);
+    result.append("sampleRate", serverGlobalParams.sampleRate);
+
+    if (auto slowms = request.getSlowms()) {
+        serverGlobalParams.slowMS = *slowms;
+    }
+    if (auto sampleRate = request.getSampleRate()) {
+        uassert(ErrorCodes::BadValue,
+                "'sampleRate' must be between 0.0 and 1.0 inclusive",
+                *sampleRate >= 0.0 && *sampleRate <= 1.0);
+        serverGlobalParams.sampleRate = *sampleRate;
+    }
+
+    return true;
+}
+}  // namespace mongo
diff --git a/src/mongo/db/commands/profile_common.h b/src/mongo/db/commands/profile_common.h
new file mode 100644
index 00000000000..20dbcdbcb76
--- /dev/null
+++ b/src/mongo/db/commands/profile_common.h
@@ -0,0 +1,76 @@
+/**
+ * Copyright (C) 2018 MongoDB Inc.
+ *
+ * This program is free software: you can redistribute it and/or  modify
+ * it under the terms of the GNU Affero General Public License, version 3,
+ * as published by the Free Software Foundation.
+ *
+ * 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
+ * GNU Affero General Public License for more details.
+ *
+ * You should have received a copy of the GNU Affero General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * 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 GNU Affero General 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/base/status.h"
+#include "mongo/db/commands.h"
+
+namespace mongo {
+/**
+ * An abstract base class which implements all functionality common to the mongoD and mongoS
+ * 'profile' command, and defines a number of virtual functions through which it delegates any
+ * op-specific work to its derived classes.
+ */
+class ProfileCmdBase : public BasicCommand {
+public:
+    ProfileCmdBase() : BasicCommand("profile") {}
+    virtual ~ProfileCmdBase() {}
+
+    AllowedOnSecondary secondaryAllowed(ServiceContext*) const final {
+        return AllowedOnSecondary::kAlways;
+    }
+
+    std::string help() const final {
+        return "controls the behaviour of the performance profiler, the fraction of eligible "
+               "operations which are sampled for logging/profiling, and the threshold duration at "
+               "which ops become eligible. See "
+               "http://docs.mongodb.org/manual/reference/command/profile";
+    }
+
+    bool supportsWriteConcern(const BSONObj& cmd) const final {
+        return false;
+    }
+
+    Status checkAuthForCommand(Client* client,
+                               const std::string& dbname,
+                               const BSONObj& cmdObj) const final;
+
+    bool run(OperationContext* opCtx,
+             const std::string& dbName,
+             const BSONObj& cmdObj,
+             BSONObjBuilder& result) final;
+
+protected:
+    // Applies the given profiling level, or throws if the profiling level could not be set. On
+    // success, returns an integer indicating the previous profiling level.
+    virtual int _applyProfilingLevel(OperationContext* opCtx,
+                                     const std::string& dbName,
+                                     int profilingLevel) const = 0;
+};
+}  // namespace mongo
diff --git a/src/mongo/db/concurrency/lock_state.cpp b/src/mongo/db/concurrency/lock_state.cpp
index 6e9c5932305..eaedc2f3f3f 100644
--- a/src/mongo/db/concurrency/lock_state.cpp
+++ b/src/mongo/db/concurrency/lock_state.cpp
@@ -602,6 +602,13 @@ void LockerImpl<IsForMMAPV1>::getLockerInfo(LockerInfo* lockerInfo) const {
 }
 
 template <bool IsForMMAPV1>
+boost::optional<Locker::LockerInfo> LockerImpl<IsForMMAPV1>::getLockerInfo() const {
+    Locker::LockerInfo lockerInfo;
+    getLockerInfo(&lockerInfo);
+    return std::move(lockerInfo);
+}
+
+template <bool IsForMMAPV1>
 bool LockerImpl<IsForMMAPV1>::saveLockStateAndUnlock(Locker::LockSnapshot* stateOut) {
     // We shouldn't be saving and restoring lock state from inside a WriteUnitOfWork.
     invariant(!inAWriteUnitOfWork());
diff --git a/src/mongo/db/concurrency/lock_state.h b/src/mongo/db/concurrency/lock_state.h
index 27ca6a39bac..1083d4c25ca 100644
--- a/src/mongo/db/concurrency/lock_state.h
+++ b/src/mongo/db/concurrency/lock_state.h
@@ -172,6 +172,7 @@ public:
     virtual ResourceId getWaitingResource() const;
 
     virtual void getLockerInfo(LockerInfo* lockerInfo) const;
+    virtual boost::optional<LockerInfo> getLockerInfo() const final;
 
     virtual bool saveLockStateAndUnlock(LockSnapshot* stateOut);
 
diff --git a/src/mongo/db/concurrency/locker.h b/src/mongo/db/concurrency/locker.h
index d90b8916289..8d98b123f72 100644
--- a/src/mongo/db/concurrency/locker.h
+++ b/src/mongo/db/concurrency/locker.h
@@ -287,6 +287,12 @@ public:
     virtual void getLockerInfo(LockerInfo* lockerInfo) const = 0;
 
     /**
+     * Returns boost::none if this is an instance of LockerNoop, or a populated LockerInfo
+     * otherwise.
+     */
+    virtual boost::optional<LockerInfo> getLockerInfo() const = 0;
+
+    /**
      * LockSnapshot captures the state of all resources that are locked, what modes they're
      * locked in, and how many times they've been locked in that mode.
      */
diff --git a/src/mongo/db/concurrency/locker_noop.h b/src/mongo/db/concurrency/locker_noop.h
index c86b90e7cbd..7a66fa84687 100644
--- a/src/mongo/db/concurrency/locker_noop.h
+++ b/src/mongo/db/concurrency/locker_noop.h
@@ -149,6 +149,10 @@ public:
         MONGO_UNREACHABLE;
     }
 
+    virtual boost::optional<LockerInfo> getLockerInfo() const {
+        return boost::none;
+    }
+
     virtual bool saveLockStateAndUnlock(LockSnapshot* stateOut) {
         MONGO_UNREACHABLE;
     }
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index 3eb90f98ff2..447ae7a6d34 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -39,6 +39,7 @@
 #include "mongo/db/client.h"
 #include "mongo/db/commands.h"
 #include "mongo/db/commands/server_status_metric.h"
+#include "mongo/db/concurrency/locker.h"
 #include "mongo/db/json.h"
 #include "mongo/db/query/getmore_request.h"
 #include "mongo/db/query/plan_summary_stats.h"
@@ -287,10 +288,14 @@ void CurOp::setGenericOpRequestDetails(OperationContext* opCtx,
                                        const Command* command,
                                        BSONObj cmdObj,
                                        NetworkOp op) {
+    // Set the _isCommand flags based on network op only. For legacy writes on mongoS, we resolve
+    // them to OpMsgRequests and then pass them into the Commands path, so having a valid Command*
+    // here does not guarantee that the op was issued from the client using a command protocol.
+    const bool isCommand = (op == dbMsg || op == dbCommand || (op == dbQuery && nss.isCommand()));
     auto logicalOp = (command ? command->getLogicalOp() : networkOpToLogicalOp(op));
 
     stdx::lock_guard<Client> clientLock(*opCtx->getClient());
-    _isCommand = _debug.iscommand = (command != nullptr);
+    _isCommand = _debug.iscommand = isCommand;
     _logicalOp = _debug.logicalOp = logicalOp;
     _networkOp = _debug.networkOp = op;
     _opDescription = cmdObj;
@@ -338,6 +343,38 @@ void CurOp::raiseDbProfileLevel(int dbProfileLevel) {
     _dbprofile = std::max(dbProfileLevel, _dbprofile);
 }
 
+bool CurOp::completeAndLogOperation(OperationContext* opCtx,
+                                    logger::LogComponent component,
+                                    boost::optional<size_t> responseLength,
+                                    boost::optional<long long> slowMsOverride,
+                                    bool forceLog) {
+    // Log the operation if it is eligible according to the current slowMS and sampleRate settings.
+    const bool shouldLogOp = (forceLog || shouldLog(component, logger::LogSeverity::Debug(1)));
+    const long long slowMs = slowMsOverride.value_or(serverGlobalParams.slowMS);
+
+    const auto client = opCtx->getClient();
+
+    // Record the size of the response returned to the client, if applicable.
+    if (responseLength) {
+        _debug.responseLength = *responseLength;
+    }
+
+    // Obtain the total execution time of this operation.
+    _end = curTimeMicros64();
+    _debug.executionTimeMicros = durationCount<Microseconds>(elapsedTimeExcludingPauses());
+
+    const bool shouldSample =
+        client->getPrng().nextCanonicalDouble() < serverGlobalParams.sampleRate;
+
+    if (shouldLogOp || (shouldSample && _debug.executionTimeMicros > slowMs * 1000LL)) {
+        const auto lockerInfo = opCtx->lockState()->getLockerInfo();
+        log(component) << _debug.report(client, *this, (lockerInfo ? &lockerInfo->stats : nullptr));
+    }
+
+    // Return 'true' if this operation should also be added to the profiler.
+    return shouldDBProfile(shouldSample);
+}
+
 Command::ReadWriteType CurOp::getReadWriteType() const {
     if (_command) {
         return _command->getReadWriteType();
@@ -463,7 +500,7 @@ StringData getProtoString(int op) {
 
 string OpDebug::report(Client* client,
                        const CurOp& curop,
-                       const SingleThreadedLockStats& lockStats) const {
+                       const SingleThreadedLockStats* lockStats) const {
     StringBuilder s;
     if (iscommand)
         s << "command ";
@@ -557,9 +594,9 @@ string OpDebug::report(Client* client,
         s << " reslen:" << responseLength;
     }
 
-    {
+    if (lockStats) {
         BSONObjBuilder locks;
-        lockStats.report(&locks);
+        lockStats->report(&locks);
         s << " locks:" << locks.obj().toString();
     }
 
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index bdb30791060..2cdefe4d859 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -55,7 +55,7 @@ public:
 
     std::string report(Client* client,
                        const CurOp& curop,
-                       const SingleThreadedLockStats& lockStats) const;
+                       const SingleThreadedLockStats* lockStats) const;
 
     /**
      * Appends information about the current operation to "builder"
@@ -186,6 +186,18 @@ public:
                                     BSONObj cmdObj,
                                     NetworkOp op);
 
+    /**
+     * Marks the operation end time, records the length of the client response if a valid response
+     * exists, and then - subject to the current values of slowMs and sampleRate - logs this CurOp
+     * to file under the given LogComponent. Returns 'true' if, in addition to being logged, this
+     * operation should also be profiled.
+     */
+    bool completeAndLogOperation(OperationContext* opCtx,
+                                 logger::LogComponent logComponent,
+                                 boost::optional<size_t> responseLength = boost::none,
+                                 boost::optional<long long> slowMsOverride = boost::none,
+                                 bool forceLog = false);
+
     bool haveOpDescription() const {
         return !_opDescription.isEmpty();
     }
diff --git a/src/mongo/db/ops/write_ops_exec.cpp b/src/mongo/db/ops/write_ops_exec.cpp
index c2bca26f027..51518f6884e 100644
--- a/src/mongo/db/ops/write_ops_exec.cpp
+++ b/src/mongo/db/ops/write_ops_exec.cpp
@@ -114,19 +114,10 @@ void finishCurOp(OperationContext* opCtx, CurOp* curOp) {
                    << ": " << curOp->debug().errInfo.toString();
         }
 
-        const bool logAll = logger::globalLogDomain()->shouldLog(logger::LogComponent::kCommand,
-                                                                 logger::LogSeverity::Debug(1));
-        const bool logSlow = executionTimeMicros > (serverGlobalParams.slowMS * 1000LL);
-
-        const bool shouldSample = serverGlobalParams.sampleRate == 1.0
-            ? true
-            : opCtx->getClient()->getPrng().nextCanonicalDouble() < serverGlobalParams.sampleRate;
-
-        if (logAll || (shouldSample && logSlow)) {
-            Locker::LockerInfo lockerInfo;
-            opCtx->lockState()->getLockerInfo(&lockerInfo);
-            log() << curOp->debug().report(opCtx->getClient(), *curOp, lockerInfo.stats);
-        }
+        // Mark the op as complete, and log it if appropriate. Returns a boolean indicating whether
+        // this op should be sampled for profiling.
+        const bool shouldSample =
+            curOp->completeAndLogOperation(opCtx, logger::LogComponent::kCommand);
 
         // Do not profile individual statements in a write command if we are in a transaction.
         auto session = OperationContextSession::get(opCtx);
diff --git a/src/mongo/db/service_entry_point_common.cpp b/src/mongo/db/service_entry_point_common.cpp
index 3bf3ec2515a..60beeb4a7f9 100644
--- a/src/mongo/db/service_entry_point_common.cpp
+++ b/src/mongo/db/service_entry_point_common.cpp
@@ -1107,8 +1107,8 @@ DbResponse ServiceEntryPointCommon::handleRequest(OperationContext* opCtx,
 
     OpDebug& debug = currentOp.debug();
 
-    long long logThresholdMs = serverGlobalParams.slowMS;
-    bool shouldLogOpDebug = shouldLog(logger::LogSeverity::Debug(1));
+    boost::optional<long long> slowMsOverride;
+    bool forceLog = false;
 
     DbResponse dbresponse;
     if (op == dbMsg || op == dbCommand || (op == dbQuery && isCommand)) {
@@ -1117,18 +1117,18 @@ DbResponse ServiceEntryPointCommon::handleRequest(OperationContext* opCtx,
         invariant(!isCommand);
         dbresponse = receivedQuery(opCtx, nsString, c, m);
     } else if (op == dbGetMore) {
-        dbresponse = receivedGetMore(opCtx, m, currentOp, &shouldLogOpDebug);
+        dbresponse = receivedGetMore(opCtx, m, currentOp, &forceLog);
     } else {
         // The remaining operations do not return any response. They are fire-and-forget.
         try {
             if (op == dbKillCursors) {
                 currentOp.ensureStarted();
-                logThresholdMs = 10;
+                slowMsOverride = 10;
                 receivedKillCursors(opCtx, m);
             } else if (op != dbInsert && op != dbUpdate && op != dbDelete) {
                 log() << "    operation isn't supported: " << static_cast<int>(op);
                 currentOp.done();
-                shouldLogOpDebug = true;
+                forceLog = true;
             } else {
                 if (!opCtx->getClient()->isInDirectClient()) {
                     uassert(18663,
@@ -1159,9 +1159,14 @@ DbResponse ServiceEntryPointCommon::handleRequest(OperationContext* opCtx,
             debug.errInfo = ue.toStatus();
         }
     }
-    currentOp.ensureStarted();
-    currentOp.done();
-    debug.executionTimeMicros = durationCount<Microseconds>(currentOp.elapsedTimeExcludingPauses());
+
+    // Mark the op as complete, and log it if appropriate. Returns a boolean indicating whether
+    // this op should be sampled for profiling.
+    const bool shouldSample = currentOp.completeAndLogOperation(opCtx,
+                                                                logger::LogComponent::kCommand,
+                                                                dbresponse.response.size(),
+                                                                slowMsOverride,
+                                                                forceLog);
 
     Top::get(opCtx->getServiceContext())
         .incrementGlobalLatencyStats(
@@ -1169,16 +1174,6 @@ DbResponse ServiceEntryPointCommon::handleRequest(OperationContext* opCtx,
             durationCount<Microseconds>(currentOp.elapsedTimeExcludingPauses()),
             currentOp.getReadWriteType());
 
-    const bool shouldSample = serverGlobalParams.sampleRate == 1.0
-        ? true
-        : c.getPrng().nextCanonicalDouble() < serverGlobalParams.sampleRate;
-
-    if (shouldLogOpDebug || (shouldSample && debug.executionTimeMicros > logThresholdMs * 1000LL)) {
-        Locker::LockerInfo lockerInfo;
-        opCtx->lockState()->getLockerInfo(&lockerInfo);
-        log() << debug.report(&c, currentOp, lockerInfo.stats);
-    }
-
     if (currentOp.shouldDBProfile(shouldSample)) {
         // Performance profiling is on
         if (opCtx->lockState()->isReadLocked()) {