diff options
author | Bernard Gorman <bernard.gorman@gmail.com> | 2018-03-21 21:08:20 +0000 |
---|---|---|
committer | Bernard Gorman <bernard.gorman@gmail.com> | 2018-03-22 03:36:43 +0000 |
commit | 40d59f4bc8eec0fc585edec0f2c8833f09a4a853 (patch) | |
tree | f5654a7274c4925ad3be8d46e305f8478894c445 /src/mongo/db | |
parent | b7178eca18c1a56b05eb206fa9d202345c128df5 (diff) | |
download | mongo-40d59f4bc8eec0fc585edec0f2c8833f09a4a853.tar.gz |
SERVER-14900 Log operations that exceed slowMs on mongoS
Diffstat (limited to 'src/mongo/db')
-rw-r--r-- | src/mongo/db/commands/SConscript | 12 | ||||
-rw-r--r-- | src/mongo/db/commands/dbcommands.cpp | 99 | ||||
-rw-r--r-- | src/mongo/db/commands/profile.idl | 38 | ||||
-rw-r--r-- | src/mongo/db/commands/profile_common.cpp | 88 | ||||
-rw-r--r-- | src/mongo/db/commands/profile_common.h | 76 | ||||
-rw-r--r-- | src/mongo/db/concurrency/lock_state.cpp | 7 | ||||
-rw-r--r-- | src/mongo/db/concurrency/lock_state.h | 1 | ||||
-rw-r--r-- | src/mongo/db/concurrency/locker.h | 6 | ||||
-rw-r--r-- | src/mongo/db/concurrency/locker_noop.h | 4 | ||||
-rw-r--r-- | src/mongo/db/curop.cpp | 45 | ||||
-rw-r--r-- | src/mongo/db/curop.h | 14 | ||||
-rw-r--r-- | src/mongo/db/ops/write_ops_exec.cpp | 17 | ||||
-rw-r--r-- | src/mongo/db/service_entry_point_common.cpp | 31 |
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()) { |