diff options
Diffstat (limited to 'src/mongo/db/curop.cpp')
| -rw-r--r-- | src/mongo/db/curop.cpp | 199 |
1 files changed, 33 insertions, 166 deletions
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp index 23fd1495598..556128f6d87 100644 --- a/src/mongo/db/curop.cpp +++ b/src/mongo/db/curop.cpp @@ -35,7 +35,6 @@ #include "mongo/db/curop.h" -#include "mongo/util/duration.h" #include <iomanip> #include "mongo/bson/mutable/document.h" @@ -51,9 +50,6 @@ #include "mongo/db/profile_filter.h" #include "mongo/db/query/getmore_command_gen.h" #include "mongo/db/query/plan_summary_stats.h" -#include "mongo/db/query/query_stats/query_stats.h" -#include "mongo/db/stats/timer_stats.h" -#include "mongo/db/storage/storage_engine_parameters_gen.h" #include "mongo/logv2/log.h" #include "mongo/rpc/metadata/client_metadata.h" #include "mongo/rpc/metadata/impersonated_user_metadata.h" @@ -63,6 +59,7 @@ #include "mongo/util/net/socket_utils.h" #include "mongo/util/str.h" #include "mongo/util/system_tick_source.h" +#include <mongo/db/stats/timer_stats.h> namespace mongo { @@ -324,18 +321,6 @@ void CurOp::setGenericOpRequestDetails(OperationContext* opCtx, _ns = nss.ns(); } -void CurOp::setEndOfOpMetrics(long long nreturned) { - _debug.additiveMetrics.nreturned = nreturned; - // A non-none queryStatsInfo.keyHash indicates the current query is being tracked for queryStats - // and therefore the executionTime needs to be recorded as part of that effort. executionTime is - // set with the final executionTime in completeAndLogOperation, but for query stats collection - // we want it set before incrementing cursor metrics using OpDebug's AdditiveMetrics. The value - // set here will be overwritten later in completeAndLogOperation. - if (_debug.queryStatsInfo.keyHash) { - _debug.additiveMetrics.executionTime = elapsedTimeExcludingPauses(); - } -} - void CurOp::setMessage_inlock(StringData message) { if (_progressMeter.isActive()) { LOGV2_ERROR(20527, @@ -432,10 +417,9 @@ bool CurOp::completeAndLogOperation(OperationContext* opCtx, // Obtain the total execution time of this operation. done(); - _debug.additiveMetrics.executionTime = - duration_cast<Microseconds>(elapsedTimeExcludingPauses()); - const auto executionTimeMillis = - durationCount<Milliseconds>(*_debug.additiveMetrics.executionTime); + _debug.executionTime = duration_cast<Microseconds>(elapsedTimeExcludingPauses()); + + const auto executionTimeMillis = durationCount<Milliseconds>(_debug.executionTime); if (_debug.isReplOplogGetMore) { oplogGetMoreStats.recordMillis(executionTimeMillis); @@ -478,11 +462,9 @@ bool CurOp::completeAndLogOperation(OperationContext* opCtx, Lock::GlobalLock lk(opCtx, MODE_IS, Date_t::now() + Milliseconds(500), - Lock::InterruptBehavior::kLeaveUnlocked, - true /* skipRSTLLock */); + Lock::InterruptBehavior::kLeaveUnlocked); if (lk.isLocked()) { - _debug.storageStats = - opCtx->recoveryUnit()->computeOperationStatisticsSinceLastCall(); + _debug.storageStats = opCtx->recoveryUnit()->getOperationStatistics(); } else { LOGV2_WARNING_OPTIONS( 20525, @@ -735,15 +717,6 @@ void CurOp::reportState(OperationContext* opCtx, BSONObjBuilder* builder, bool t if (_debug.dataThroughputAverage) { builder->append("dataThroughputAverage", *_debug.dataThroughputAverage); } - - if (auto start = _waitForWriteConcernStart.load(); start > 0) { - auto end = _waitForWriteConcernEnd.load(); - auto elapsedTimeTotal = - duration_cast<Microseconds>(debug().waitForWriteConcernDurationMillis); - elapsedTimeTotal += computeElapsedTimeTotal(start, end); - builder->append("waitForWriteConcernDurationMillis", - durationCount<Milliseconds>(elapsedTimeTotal)); - } } namespace { @@ -837,18 +810,10 @@ void OpDebug::report(OperationContext* opCtx, pAttrs->addDeepCopy("planSummary", curop.getPlanSummary().toString()); } - if (planningTime > Microseconds::zero()) { - pAttrs->add("planningTimeMicros", durationCount<Microseconds>(planningTime)); - } - if (prepareConflictDurationMillis > Milliseconds::zero()) { pAttrs->add("prepareConflictDuration", prepareConflictDurationMillis); } - if (totalOplogSlotDurationMicros > Microseconds::zero()) { - pAttrs->add("totalOplogSlotDuration", totalOplogSlotDurationMicros); - } - if (dataThroughputLastSecond) { pAttrs->add("dataThroughputLastSecondMBperSec", *dataThroughputLastSecond); } @@ -879,7 +844,6 @@ void OpDebug::report(OperationContext* opCtx, pAttrs->add("replanReason", redact(*replanReason)); } OPDEBUG_TOATTR_HELP_OPTIONAL("nMatched", additiveMetrics.nMatched); - OPDEBUG_TOATTR_HELP_OPTIONAL("nBatches", additiveMetrics.nBatches); OPDEBUG_TOATTR_HELP_OPTIONAL("nModified", additiveMetrics.nModified); OPDEBUG_TOATTR_HELP_OPTIONAL("ninserted", additiveMetrics.ninserted); OPDEBUG_TOATTR_HELP_OPTIONAL("ndeleted", additiveMetrics.ndeleted); @@ -894,7 +858,7 @@ void OpDebug::report(OperationContext* opCtx, additiveMetrics.temporarilyUnavailableErrors); pAttrs->add("numYields", curop.numYields()); - OPDEBUG_TOATTR_HELP_OPTIONAL("nreturned", additiveMetrics.nreturned); + OPDEBUG_TOATTR_HELP(nreturned); if (queryHash) { pAttrs->addDeepCopy("queryHash", zeroPaddedHex(*queryHash)); @@ -904,9 +868,7 @@ void OpDebug::report(OperationContext* opCtx, } if (classicEngineUsed) { - pAttrs->add("queryFramework", classicEngineUsed.value() ? "classic" : "sbe"); - } else if (cqfUsed) { - pAttrs->add("queryFramework", "cqf"); + pAttrs->add("queryExecutionEngine", classicEngineUsed.get() ? "classic" : "sbe"); } if (!errInfo.isOK()) { @@ -959,10 +921,6 @@ void OpDebug::report(OperationContext* opCtx, pAttrs->add("writeConcern", writeConcern->toBSON()); } - if (waitForWriteConcernDurationMillis > Milliseconds::zero()) { - pAttrs->add("waitForWriteConcernDuration", waitForWriteConcernDurationMillis); - } - if (storageStats) { pAttrs->add("storage", storageStats->toBSON()); } @@ -985,16 +943,7 @@ void OpDebug::report(OperationContext* opCtx, pAttrs->add("remoteOpWaitMillis", durationCount<Milliseconds>(*remoteOpWaitTime)); } - // durationMillis should always be present for any operation - pAttrs->add( - "durationMillis", - durationCount<Milliseconds>(additiveMetrics.executionTime.value_or(Microseconds{0}))); -} - -void OpDebug::reportStorageStats(logv2::DynamicAttributes* pAttrs) const { - if (storageStats) { - pAttrs->add("storage", storageStats->toBSON()); - } + pAttrs->add("durationMillis", durationCount<Milliseconds>(executionTime)); } #define OPDEBUG_APPEND_NUMBER2(b, x, y) \ @@ -1055,7 +1004,6 @@ void OpDebug::append(OperationContext* opCtx, b.append("replanReason", *replanReason); } OPDEBUG_APPEND_OPTIONAL(b, "nMatched", additiveMetrics.nMatched); - OPDEBUG_APPEND_OPTIONAL(b, "nBatches", additiveMetrics.nBatches); OPDEBUG_APPEND_OPTIONAL(b, "nModified", additiveMetrics.nModified); OPDEBUG_APPEND_OPTIONAL(b, "ninserted", additiveMetrics.ninserted); OPDEBUG_APPEND_OPTIONAL(b, "ndeleted", additiveMetrics.ndeleted); @@ -1073,7 +1021,7 @@ void OpDebug::append(OperationContext* opCtx, OPDEBUG_APPEND_OPTIONAL(b, "dataThroughputAverage", dataThroughputAverage); b.appendNumber("numYield", curop.numYields()); - OPDEBUG_APPEND_OPTIONAL(b, "nreturned", additiveMetrics.nreturned); + OPDEBUG_APPEND_NUMBER(b, nreturned); if (queryHash) { b.append("queryHash", zeroPaddedHex(*queryHash)); @@ -1083,9 +1031,7 @@ void OpDebug::append(OperationContext* opCtx, } if (classicEngineUsed) { - b.append("queryFramework", classicEngineUsed.value() ? "classic" : "sbe"); - } else if (cqfUsed) { - b.append("queryFramework", "cqf"); + b.append("queryExecutionEngine", classicEngineUsed.get() ? "classic" : "sbe"); } { @@ -1147,24 +1093,12 @@ void OpDebug::append(OperationContext* opCtx, b.append("remoteOpWaitMillis", durationCount<Milliseconds>(*remoteOpWaitTime)); } - // millis should always be present for any operation - b.appendNumber( - "millis", - durationCount<Milliseconds>(additiveMetrics.executionTime.value_or(Microseconds{0}))); + b.appendNumber("millis", durationCount<Milliseconds>(executionTime)); if (!curop.getPlanSummary().empty()) { b.append("planSummary", curop.getPlanSummary()); } - if (totalOplogSlotDurationMicros > Microseconds::zero()) { - b.appendNumber("totalOplogSlotDurationMicros", - durationCount<Microseconds>(totalOplogSlotDurationMicros)); - } - - if (planningTime > Microseconds::zero()) { - b.appendNumber("planningTimeMicros", durationCount<Microseconds>(planningTime)); - } - if (!execStats.isEmpty()) { b.append("execStats", std::move(execStats)); } @@ -1316,9 +1250,6 @@ std::function<BSONObj(ProfileFilter::Args)> OpDebug::appendStaged(StringSet requ addIfNeeded("nMatched", [](auto field, auto args, auto& b) { OPDEBUG_APPEND_OPTIONAL(b, field, args.op.additiveMetrics.nMatched); }); - addIfNeeded("nBatches", [](auto field, auto args, auto& b) { - OPDEBUG_APPEND_OPTIONAL(b, field, args.op.additiveMetrics.nBatches); - }); addIfNeeded("nModified", [](auto field, auto args, auto& b) { OPDEBUG_APPEND_OPTIONAL(b, field, args.op.additiveMetrics.nModified); }); @@ -1362,7 +1293,7 @@ std::function<BSONObj(ProfileFilter::Args)> OpDebug::appendStaged(StringSet requ b.appendNumber(field, args.curop.numYields()); }); addIfNeeded("nreturned", [](auto field, auto args, auto& b) { - OPDEBUG_APPEND_OPTIONAL(b, field, args.op.additiveMetrics.nreturned); + OPDEBUG_APPEND_NUMBER2(b, field, args.op.nreturned); }); addIfNeeded("queryHash", [](auto field, auto args, auto& b) { @@ -1376,11 +1307,9 @@ std::function<BSONObj(ProfileFilter::Args)> OpDebug::appendStaged(StringSet requ } }); - addIfNeeded("queryFramework", [](auto field, auto args, auto& b) { + addIfNeeded("queryExecutionEngine", [](auto field, auto args, auto& b) { if (args.op.classicEngineUsed) { - b.append("queryFramework", args.op.classicEngineUsed.value() ? "classic" : "sbe"); - } else if (args.op.cqfUsed) { - b.append("queryFramework", "cqf"); + b.append("queryExecutionEngine", args.op.classicEngineUsed.get() ? "classic" : "sbe"); } }); @@ -1466,14 +1395,10 @@ std::function<BSONObj(ProfileFilter::Args)> OpDebug::appendStaged(StringSet requ // the profiler (OpDebug::append) and the log file (OpDebug::report), so for the profile filter // we support both names. addIfNeeded("millis", [](auto field, auto args, auto& b) { - b.appendNumber(field, - durationCount<Milliseconds>( - args.op.additiveMetrics.executionTime.value_or(Microseconds{0}))); + b.appendNumber(field, durationCount<Milliseconds>(args.op.executionTime)); }); addIfNeeded("durationMillis", [](auto field, auto args, auto& b) { - b.appendNumber(field, - durationCount<Milliseconds>( - args.op.additiveMetrics.executionTime.value_or(Microseconds{0}))); + b.appendNumber(field, durationCount<Milliseconds>(args.op.executionTime)); }); addIfNeeded("planSummary", [](auto field, auto args, auto& b) { @@ -1482,17 +1407,6 @@ std::function<BSONObj(ProfileFilter::Args)> OpDebug::appendStaged(StringSet requ } }); - addIfNeeded("totalOplogSlotDurationMicros", [](auto field, auto args, auto& b) { - if (args.op.totalOplogSlotDurationMicros > Nanoseconds::zero()) { - b.appendNumber(field, - durationCount<Microseconds>(args.op.totalOplogSlotDurationMicros)); - } - }); - - addIfNeeded("planningTimeMicros", [](auto field, auto args, auto& b) { - b.appendNumber(field, durationCount<Microseconds>(args.op.planningTime)); - }); - addIfNeeded("execStats", [](auto field, auto args, auto& b) { if (!args.op.execStats.isEmpty()) { b.append(field, args.op.execStats); @@ -1561,9 +1475,6 @@ BSONObj OpDebug::makeMongotDebugStatsObject() const { cursorBuilder.append("timeWaitingMillis", msWaitingForMongot.get()); } cursorBuilder.append("batchNum", mongotBatchNum); - if (!mongotCountVal.isEmpty()) { - cursorBuilder.append("resultCount", mongotCountVal); - } return cursorBuilder.obj(); } @@ -1620,12 +1531,12 @@ void OpDebug::appendResolvedViewsInfo(BSONObjBuilder& builder) const { namespace { /** - * Adds two boost::optionals of the same type with an operator+() together. Returns boost::none if - * both 'lhs' and 'rhs' are uninitialized, or the sum of 'lhs' and 'rhs' if they are both - * initialized. Returns 'lhs' if only 'rhs' is uninitialized and vice-versa. + * Adds two boost::optional long longs together. Returns boost::none if both 'lhs' and 'rhs' are + * uninitialized, or the sum of 'lhs' and 'rhs' if they are both initialized. Returns 'lhs' if only + * 'rhs' is uninitialized and vice-versa. */ -template <typename T> -boost::optional<T> addOptionals(const boost::optional<T>& lhs, const boost::optional<T>& rhs) { +boost::optional<long long> addOptionalLongs(const boost::optional<long long>& lhs, + const boost::optional<long long>& rhs) { if (!rhs) { return lhs; } @@ -1634,29 +1545,24 @@ boost::optional<T> addOptionals(const boost::optional<T>& lhs, const boost::opti } // namespace void OpDebug::AdditiveMetrics::add(const AdditiveMetrics& otherMetrics) { - keysExamined = addOptionals(keysExamined, otherMetrics.keysExamined); - docsExamined = addOptionals(docsExamined, otherMetrics.docsExamined); - nMatched = addOptionals(nMatched, otherMetrics.nMatched); - nreturned = addOptionals(nreturned, otherMetrics.nreturned); - nBatches = addOptionals(nBatches, otherMetrics.nBatches); - nModified = addOptionals(nModified, otherMetrics.nModified); - ninserted = addOptionals(ninserted, otherMetrics.ninserted); - ndeleted = addOptionals(ndeleted, otherMetrics.ndeleted); - nUpserted = addOptionals(nUpserted, otherMetrics.nUpserted); - keysInserted = addOptionals(keysInserted, otherMetrics.keysInserted); - keysDeleted = addOptionals(keysDeleted, otherMetrics.keysDeleted); + keysExamined = addOptionalLongs(keysExamined, otherMetrics.keysExamined); + docsExamined = addOptionalLongs(docsExamined, otherMetrics.docsExamined); + nMatched = addOptionalLongs(nMatched, otherMetrics.nMatched); + nModified = addOptionalLongs(nModified, otherMetrics.nModified); + ninserted = addOptionalLongs(ninserted, otherMetrics.ninserted); + ndeleted = addOptionalLongs(ndeleted, otherMetrics.ndeleted); + nUpserted = addOptionalLongs(nUpserted, otherMetrics.nUpserted); + keysInserted = addOptionalLongs(keysInserted, otherMetrics.keysInserted); + keysDeleted = addOptionalLongs(keysDeleted, otherMetrics.keysDeleted); prepareReadConflicts.fetchAndAdd(otherMetrics.prepareReadConflicts.load()); writeConflicts.fetchAndAdd(otherMetrics.writeConflicts.load()); temporarilyUnavailableErrors.fetchAndAdd(otherMetrics.temporarilyUnavailableErrors.load()); - executionTime = addOptionals(executionTime, otherMetrics.executionTime); } void OpDebug::AdditiveMetrics::reset() { keysExamined = boost::none; docsExamined = boost::none; nMatched = boost::none; - nreturned = boost::none; - nBatches = boost::none; nModified = boost::none; ninserted = boost::none; ndeleted = boost::none; @@ -1666,20 +1572,17 @@ void OpDebug::AdditiveMetrics::reset() { prepareReadConflicts.store(0); writeConflicts.store(0); temporarilyUnavailableErrors.store(0); - executionTime = boost::none; } bool OpDebug::AdditiveMetrics::equals(const AdditiveMetrics& otherMetrics) const { return keysExamined == otherMetrics.keysExamined && docsExamined == otherMetrics.docsExamined && - nMatched == otherMetrics.nMatched && nreturned == otherMetrics.nreturned && - nBatches == otherMetrics.nBatches && nModified == otherMetrics.nModified && + nMatched == otherMetrics.nMatched && nModified == otherMetrics.nModified && ninserted == otherMetrics.ninserted && ndeleted == otherMetrics.ndeleted && nUpserted == otherMetrics.nUpserted && keysInserted == otherMetrics.keysInserted && keysDeleted == otherMetrics.keysDeleted && prepareReadConflicts.load() == otherMetrics.prepareReadConflicts.load() && writeConflicts.load() == otherMetrics.writeConflicts.load() && - temporarilyUnavailableErrors.load() == otherMetrics.temporarilyUnavailableErrors.load() && - executionTime == otherMetrics.executionTime; + temporarilyUnavailableErrors.load() == otherMetrics.temporarilyUnavailableErrors.load(); } void OpDebug::AdditiveMetrics::incrementWriteConflicts(long long n) { @@ -1704,20 +1607,6 @@ void OpDebug::AdditiveMetrics::incrementKeysDeleted(long long n) { *keysDeleted += n; } -void OpDebug::AdditiveMetrics::incrementNreturned(long long n) { - if (!nreturned) { - nreturned = 0; - } - *nreturned += n; -} - -void OpDebug::AdditiveMetrics::incrementNBatches() { - if (!nBatches) { - nBatches = 0; - } - ++(*nBatches); -} - void OpDebug::AdditiveMetrics::incrementNinserted(long long n) { if (!ninserted) { ninserted = 0; @@ -1732,13 +1621,6 @@ void OpDebug::AdditiveMetrics::incrementNUpserted(long long n) { *nUpserted += n; } -void OpDebug::AdditiveMetrics::incrementExecutionTime(Microseconds n) { - if (!executionTime) { - executionTime = Microseconds{0}; - } - *executionTime += n; -} - void OpDebug::AdditiveMetrics::incrementPrepareReadConflicts(long long n) { prepareReadConflicts.fetchAndAdd(n); } @@ -1749,8 +1631,6 @@ string OpDebug::AdditiveMetrics::report() const { OPDEBUG_TOSTRING_HELP_OPTIONAL("keysExamined", keysExamined); OPDEBUG_TOSTRING_HELP_OPTIONAL("docsExamined", docsExamined); OPDEBUG_TOSTRING_HELP_OPTIONAL("nMatched", nMatched); - OPDEBUG_TOSTRING_HELP_OPTIONAL("nreturned", nreturned); - OPDEBUG_TOSTRING_HELP_OPTIONAL("nBatches", nBatches); OPDEBUG_TOSTRING_HELP_OPTIONAL("nModified", nModified); OPDEBUG_TOSTRING_HELP_OPTIONAL("ninserted", ninserted); OPDEBUG_TOSTRING_HELP_OPTIONAL("ndeleted", ndeleted); @@ -1760,9 +1640,6 @@ string OpDebug::AdditiveMetrics::report() const { OPDEBUG_TOSTRING_HELP_ATOMIC("prepareReadConflicts", prepareReadConflicts); OPDEBUG_TOSTRING_HELP_ATOMIC("writeConflicts", writeConflicts); OPDEBUG_TOSTRING_HELP_ATOMIC("temporarilyUnavailableErrors", temporarilyUnavailableErrors); - if (executionTime) { - s << " durationMillis:" << durationCount<Milliseconds>(*executionTime); - } return s.str(); } @@ -1771,8 +1648,6 @@ void OpDebug::AdditiveMetrics::report(logv2::DynamicAttributes* pAttrs) const { OPDEBUG_TOATTR_HELP_OPTIONAL("keysExamined", keysExamined); OPDEBUG_TOATTR_HELP_OPTIONAL("docsExamined", docsExamined); OPDEBUG_TOATTR_HELP_OPTIONAL("nMatched", nMatched); - OPDEBUG_TOATTR_HELP_OPTIONAL("nreturned", nreturned); - OPDEBUG_TOATTR_HELP_OPTIONAL("nBatches", nBatches); OPDEBUG_TOATTR_HELP_OPTIONAL("nModified", nModified); OPDEBUG_TOATTR_HELP_OPTIONAL("ninserted", ninserted); OPDEBUG_TOATTR_HELP_OPTIONAL("ndeleted", ndeleted); @@ -1782,9 +1657,6 @@ void OpDebug::AdditiveMetrics::report(logv2::DynamicAttributes* pAttrs) const { OPDEBUG_TOATTR_HELP_ATOMIC("prepareReadConflicts", prepareReadConflicts); OPDEBUG_TOATTR_HELP_ATOMIC("writeConflicts", writeConflicts); OPDEBUG_TOATTR_HELP_ATOMIC("temporarilyUnavailableErrors", temporarilyUnavailableErrors); - if (executionTime) { - pAttrs->add("durationMillis", durationCount<Milliseconds>(*executionTime)); - } } BSONObj OpDebug::AdditiveMetrics::reportBSON() const { @@ -1792,8 +1664,6 @@ BSONObj OpDebug::AdditiveMetrics::reportBSON() const { OPDEBUG_APPEND_OPTIONAL(b, "keysExamined", keysExamined); OPDEBUG_APPEND_OPTIONAL(b, "docsExamined", docsExamined); OPDEBUG_APPEND_OPTIONAL(b, "nMatched", nMatched); - OPDEBUG_APPEND_OPTIONAL(b, "nreturned", nreturned); - OPDEBUG_APPEND_OPTIONAL(b, "nBatches", nBatches); OPDEBUG_APPEND_OPTIONAL(b, "nModified", nModified); OPDEBUG_APPEND_OPTIONAL(b, "ninserted", ninserted); OPDEBUG_APPEND_OPTIONAL(b, "ndeleted", ndeleted); @@ -1803,9 +1673,6 @@ BSONObj OpDebug::AdditiveMetrics::reportBSON() const { OPDEBUG_APPEND_ATOMIC(b, "prepareReadConflicts", prepareReadConflicts); OPDEBUG_APPEND_ATOMIC(b, "writeConflicts", writeConflicts); OPDEBUG_APPEND_ATOMIC(b, "temporarilyUnavailableErrors", temporarilyUnavailableErrors); - if (executionTime) { - b.appendNumber("durationMillis", durationCount<Milliseconds>(*executionTime)); - } return b.obj(); } |
