SERVER-14900 Log operations that exceed slowMs on mongoS

24 files changed, 399 insertions, 169 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()) {
diff --git a/src/mongo/idl/basic_types.idl b/src/mongo/idl/basic_types.idl
index c761ad45303..673c43065c8 100644
--- a/src/mongo/idl/basic_types.idl
+++ b/src/mongo/idl/basic_types.idl
@@ -33,6 +33,16 @@ types:
         cpp_type: "std::int32_t"
         deserializer: "mongo::BSONElement::_numberInt"
 
+    safeInt32:
+        bson_serialization_type:
+                                - long
+                                - int
+                                - decimal
+                                - double
+        description: "Accepts any numerical type within int32 range"
+        cpp_type: std::int32_t
+        deserializer: "mongo::BSONElement::numberInt"
+
     safeInt64:
         bson_serialization_type:
                                 - long
@@ -41,7 +51,7 @@ types:
                                 - double
         description: "Accepts any numerical type within int64 range"
         cpp_type: std::int64_t
-        deserializer: "mongo::BSONElement::numberInt"
+        deserializer: "mongo::BSONElement::numberLong"
 
     long:
         bson_serialization_type: long
diff --git a/src/mongo/idl/idl_test.cpp b/src/mongo/idl/idl_test.cpp
index ab2e9328c3a..f7f986af9fe 100644
--- a/src/mongo/idl/idl_test.cpp
+++ b/src/mongo/idl/idl_test.cpp
@@ -990,7 +990,7 @@ TEST(IDLArrayTests, TestArraysOfComplexTypes) {
                             );
     auto testStruct = Complex_array_fields::parse(ctxt, testDoc);
 
-    assert_same_types<decltype(testStruct.getField1()), const std::vector<std::int64_t>&>();
+    assert_same_types<decltype(testStruct.getField1()), const std::vector<std::int32_t>&>();
     assert_same_types<decltype(testStruct.getField2()),
                       const std::vector<mongo::NamespaceString>&>();
     assert_same_types<decltype(testStruct.getField3()), const std::vector<mongo::AnyBasicType>&>();
@@ -1001,7 +1001,7 @@ TEST(IDLArrayTests, TestArraysOfComplexTypes) {
                       const std::vector<mongo::idl::import::One_string>&>();
 
     assert_same_types<decltype(testStruct.getField1o()),
-                      const boost::optional<std::vector<std::int64_t>>&>();
+                      const boost::optional<std::vector<std::int32_t>>&>();
     assert_same_types<decltype(testStruct.getField2o()),
                       const boost::optional<std::vector<mongo::NamespaceString>>&>();
     assert_same_types<decltype(testStruct.getField3o()),
@@ -1013,7 +1013,7 @@ TEST(IDLArrayTests, TestArraysOfComplexTypes) {
     assert_same_types<decltype(testStruct.getField6o()),
                       const boost::optional<std::vector<mongo::idl::import::One_string>>&>();
 
-    std::vector<std::int64_t> field1{1, 2, 3};
+    std::vector<std::int32_t> field1{1, 2, 3};
     ASSERT_TRUE(field1 == testStruct.getField1());
     std::vector<NamespaceString> field2{{"a", "b"}, {"c", "d"}};
     ASSERT_TRUE(field2 == testStruct.getField2());
diff --git a/src/mongo/idl/unittest.idl b/src/mongo/idl/unittest.idl
index 01475aeccdc..4b35bea4702 100644
--- a/src/mongo/idl/unittest.idl
+++ b/src/mongo/idl/unittest.idl
@@ -68,22 +68,6 @@ types:
 
 ##################################################################################################
 #
-# Test types that accept multiple serialization types
-#
-##################################################################################################
-
-    safeInt32:
-        description: Accepts any numerical type within int32 range
-        cpp_type: std::int64_t
-        bson_serialization_type: 
-                                - long
-                                - int
-                                - decimal
-                                - double
-        deserializer: "mongo::BSONElement::numberInt"
-
-##################################################################################################
-#
 # Test types used in parser chaining testing
 #
 ##################################################################################################
@@ -615,4 +599,18 @@ commands:
         type: string
         cpp_name: WellNamedCommand
         fields:
-            field1: int
\ No newline at end of file
+            field1: int
+
+    int_type_command:
+        description: Command with custom type int
+        namespace: type
+        type: int
+        fields:
+            field1: int
+
+    int_array_type_command:
+        description: Command with custom type for array of int
+        namespace: type
+        type: array<int>
+        fields:
+            field1: int
diff --git a/src/mongo/s/commands/SConscript b/src/mongo/s/commands/SConscript
index 7625bd96703..3501319d43b 100644
--- a/src/mongo/s/commands/SConscript
+++ b/src/mongo/s/commands/SConscript
@@ -96,6 +96,7 @@ env.Library(
     LIBDEPS=[
         '$BUILD_DIR/mongo/db/auth/authmongos',
         '$BUILD_DIR/mongo/db/commands/killcursors_common',
+        '$BUILD_DIR/mongo/db/commands/profile_common',
         '$BUILD_DIR/mongo/db/commands/write_commands_common',
         '$BUILD_DIR/mongo/db/ftdc/ftdc_server',
         '$BUILD_DIR/mongo/db/logical_session_cache_impl',
diff --git a/src/mongo/s/commands/cluster_aggregate.cpp b/src/mongo/s/commands/cluster_aggregate.cpp
index 06f9f6a2a84..e1a889aea61 100644
--- a/src/mongo/s/commands/cluster_aggregate.cpp
+++ b/src/mongo/s/commands/cluster_aggregate.cpp
@@ -38,6 +38,7 @@
 #include "mongo/db/auth/authorization_session.h"
 #include "mongo/db/client.h"
 #include "mongo/db/commands.h"
+#include "mongo/db/curop.h"
 #include "mongo/db/operation_context.h"
 #include "mongo/db/pipeline/document_source_change_stream.h"
 #include "mongo/db/pipeline/document_source_merge_cursors.h"
@@ -507,6 +508,7 @@ BSONObj establishMergingMongosCursor(OperationContext* opCtx,
 
     ClusterClientCursorParams params(requestedNss, ReadPreferenceSetting::get(opCtx));
 
+    params.originatingCommandObj = CurOp::get(opCtx)->opDescription().getOwned();
     params.tailableMode = pipelineForMerging->getContext()->tailableMode;
     params.mergePipeline = std::move(pipelineForMerging);
     params.remotes = std::move(cursors);
diff --git a/src/mongo/s/commands/cluster_profile_cmd.cpp b/src/mongo/s/commands/cluster_profile_cmd.cpp
index 6e611ca2956..9b6c273dd82 100644
--- a/src/mongo/s/commands/cluster_profile_cmd.cpp
+++ b/src/mongo/s/commands/cluster_profile_cmd.cpp
@@ -29,42 +29,35 @@
 #include "mongo/platform/basic.h"
 
 #include "mongo/db/commands.h"
+#include "mongo/db/commands/profile_common.h"
 
 namespace mongo {
 namespace {
 
-class ProfileCmd : public ErrmsgCommandDeprecated {
+class ProfileCmd : public ProfileCmdBase {
 public:
-    ProfileCmd() : ErrmsgCommandDeprecated("profile") {}
+    ProfileCmd() = default;
 
-    AllowedOnSecondary secondaryAllowed(ServiceContext*) const override {
-        return AllowedOnSecondary::kAlways;
+    // On mongoS, the 'profile' command is only used to change the global 'slowms' and 'sampleRate'
+    // parameters. Since it does not apply to any specific database but rather the mongoS as a
+    // whole, we require that it be run on the 'admin' database.
+    bool adminOnly() const final {
+        return true;
     }
 
-    virtual bool adminOnly() const {
-        return false;
-    }
-
-
-    virtual bool supportsWriteConcern(const BSONObj& cmd) const override {
-        return false;
-    }
-
-    virtual void addRequiredPrivileges(const std::string& dbname,
-                                       const BSONObj& cmdObj,
-                                       std::vector<Privilege>* out) const {
-        ActionSet actions;
-        actions.addAction(ActionType::enableProfiler);
-        out->push_back(Privilege(ResourcePattern::forDatabaseName(dbname), actions));
-    }
+protected:
+    int _applyProfilingLevel(OperationContext* opCtx,
+                             const std::string& dbName,
+                             int profilingLevel) const final {
+        // Because mongoS does not allow profiling, but only uses the 'profile' command to change
+        // 'slowms' and 'sampleRate' for logging purposes, we do not apply the profiling level here.
+        // Instead, we validate that the user is not attempting to set a "real" profiling level.
+        uassert(ErrorCodes::BadValue,
+                "Profiling is not permitted on mongoS: the 'profile' field should be 0 to change "
+                "'slowms' and 'sampleRate' settings for logging, or -1 to view current values",
+                profilingLevel == -1 || profilingLevel == 0);
 
-    virtual bool errmsgRun(OperationContext* opCtx,
-                           const std::string& dbname,
-                           const BSONObj& cmdObj,
-                           std::string& errmsg,
-                           BSONObjBuilder& result) {
-        errmsg = "profile currently not supported via mongos";
-        return false;
+        return 0;
     }
 
 } profileCmd;
diff --git a/src/mongo/s/commands/strategy.cpp b/src/mongo/s/commands/strategy.cpp
index 012520b71da..ca2b2e7816e 100644
--- a/src/mongo/s/commands/strategy.cpp
+++ b/src/mongo/s/commands/strategy.cpp
@@ -367,6 +367,7 @@ void runCommand(OperationContext* opCtx,
             command->incrementCommandsFailed();
             CommandHelpers::appendCommandStatus(bob, e.toStatus());
             LastError::get(opCtx->getClient()).setLastError(e.code(), e.reason());
+            CurOp::get(opCtx)->debug().errInfo = e.toStatus();
             return;
         }
 
@@ -509,6 +510,9 @@ DbResponse Strategy::clientCommand(OperationContext* opCtx, const Message& m) {
             LOG(1) << "Exception thrown while processing command on " << db
                    << " msg id: " << m.header().getId() << causedBy(redact(ex));
 
+            // Record the exception in CurOp.
+            CurOp::get(opCtx)->debug().errInfo = ex.toStatus();
+
             reply->reset();
             auto bob = reply->getInPlaceReplyBuilder(0);
             CommandHelpers::appendCommandStatus(bob, ex.toStatus());
diff --git a/src/mongo/s/query/SConscript b/src/mongo/s/query/SConscript
index 7070cb3cf1e..f461601d93f 100644
--- a/src/mongo/s/query/SConscript
+++ b/src/mongo/s/query/SConscript
@@ -141,6 +141,7 @@ env.Library(
     ],
     LIBDEPS=[
         "$BUILD_DIR/mongo/base",
+        "$BUILD_DIR/mongo/db/curop",
         "$BUILD_DIR/mongo/db/query/command_request_response",
         "cluster_client_cursor",
         "cluster_cursor_manager",
diff --git a/src/mongo/s/query/store_possible_cursor.cpp b/src/mongo/s/query/store_possible_cursor.cpp
index 38347a70a9e..7a6687b216c 100644
--- a/src/mongo/s/query/store_possible_cursor.cpp
+++ b/src/mongo/s/query/store_possible_cursor.cpp
@@ -33,6 +33,7 @@
 #include "mongo/base/status_with.h"
 #include "mongo/bson/bsonobj.h"
 #include "mongo/db/auth/authorization_session.h"
+#include "mongo/db/curop.h"
 #include "mongo/db/query/cursor_response.h"
 #include "mongo/s/query/cluster_client_cursor_impl.h"
 #include "mongo/s/query/cluster_client_cursor_params.h"
@@ -67,6 +68,7 @@ StatusWith<BSONObj> storePossibleCursor(OperationContext* opCtx,
                                 CursorResponse(incomingCursorResponse.getValue().getNSS(),
                                                incomingCursorResponse.getValue().getCursorId(),
                                                {}));
+    params.originatingCommandObj = CurOp::get(opCtx)->opDescription().getOwned();
     params.tailableMode = tailableMode;
 
     auto ccc = ClusterClientCursorImpl::make(opCtx, executor, std::move(params));
diff --git a/src/mongo/s/service_entry_point_mongos.cpp b/src/mongo/s/service_entry_point_mongos.cpp
index dc1f8312b97..7b2c10fbc9b 100644
--- a/src/mongo/s/service_entry_point_mongos.cpp
+++ b/src/mongo/s/service_entry_point_mongos.cpp
@@ -34,6 +34,7 @@
 
 #include "mongo/db/auth/authorization_session.h"
 #include "mongo/db/commands.h"
+#include "mongo/db/curop.h"
 #include "mongo/db/dbmessage.h"
 #include "mongo/db/lasterror.h"
 #include "mongo/db/operation_context.h"
@@ -84,12 +85,20 @@ DbResponse ServiceEntryPointMongos::handleRequest(OperationContext* opCtx, const
     LastError::get(client).startRequest();
     AuthorizationSession::get(opCtx->getClient())->startRequest(opCtx);
 
+    CurOp::get(opCtx)->ensureStarted();
+
     DbMessage dbm(message);
 
     // This is before the try block since it handles all exceptions that should not cause the
     // connection to close.
     if (op == dbMsg || (op == dbQuery && NamespaceString(dbm.getns()).isCommand())) {
-        return Strategy::clientCommand(opCtx, message);
+        auto dbResponse = Strategy::clientCommand(opCtx, message);
+
+        // Mark the op as complete, populate the response length, and log it if appropriate.
+        CurOp::get(opCtx)->completeAndLogOperation(
+            opCtx, logger::LogComponent::kCommand, dbResponse.response.size());
+
+        return dbResponse;
     }
 
     NamespaceString nss;
@@ -151,7 +160,13 @@ DbResponse ServiceEntryPointMongos::handleRequest(OperationContext* opCtx, const
 
         // We *always* populate the last error for now
         LastError::get(opCtx->getClient()).setLastError(ex.code(), ex.what());
+        CurOp::get(opCtx)->debug().errInfo = ex.toStatus();
     }
+
+    // Mark the op as complete, populate the response length, and log it if appropriate.
+    CurOp::get(opCtx)->completeAndLogOperation(
+        opCtx, logger::LogComponent::kCommand, dbResponse.response.size());
+
     return dbResponse;
 }
 
diff --git a/src/mongo/util/log.h b/src/mongo/util/log.h
index 6c73bd80832..8817a8b1c6a 100644
--- a/src/mongo/util/log.h
+++ b/src/mongo/util/log.h
@@ -163,8 +163,12 @@ inline LogstreamBuilder log(logger::LogComponent::Value componentValue) {
 /**
  * Runs the same logic as log()/warning()/error(), without actually outputting a stream.
  */
+inline bool shouldLog(logger::LogComponent logComponent, logger::LogSeverity severity) {
+    return logger::globalLogDomain()->shouldLog(logComponent, severity);
+}
+
 inline bool shouldLog(logger::LogSeverity severity) {
-    return logger::globalLogDomain()->shouldLog(::MongoLogDefaultComponent_component, severity);
+    return shouldLog(::MongoLogDefaultComponent_component, severity);
 }
 
 }  // namespace