From 86b6aca9fa1940e85bba87261d1494ef2c208a4a Mon Sep 17 00:00:00 2001 From: nehakhatri5 Date: Tue, 18 Dec 2018 13:21:27 +1100 Subject: SERVER-38240 Added storage statistics information into the slowop log messages. --- src/mongo/db/curop.cpp | 9 ++ src/mongo/db/curop.h | 3 + src/mongo/db/storage/recovery_unit.h | 34 +++++- .../wiredtiger/wiredtiger_recovery_unit.cpp | 116 +++++++++++++++++++-- .../storage/wiredtiger/wiredtiger_recovery_unit.h | 37 ++++++- .../db/storage/wiredtiger/wiredtiger_util.cpp | 82 +-------------- src/mongo/db/storage/wiredtiger/wiredtiger_util.h | 14 +-- src/mongo/db/transaction_metrics_observer.cpp | 17 ++- src/mongo/db/transaction_metrics_observer.h | 8 +- src/mongo/db/transaction_participant.cpp | 15 ++- 10 files changed, 221 insertions(+), 114 deletions(-) (limited to 'src') diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp index 8ad2499e9b7..e76a248547f 100644 --- a/src/mongo/db/curop.cpp +++ b/src/mongo/db/curop.cpp @@ -406,6 +406,7 @@ bool CurOp::completeAndLogOperation(OperationContext* opCtx, if (shouldLogOp || (shouldSample && _debug.executionTimeMicros > slowMs * 1000LL)) { auto lockerInfo = opCtx->lockState()->getLockerInfo(_lockStatsBase); + _debug.storageStats = opCtx->recoveryUnit()->getOperationStatistics(); log(component) << _debug.report(client, *this, (lockerInfo ? &lockerInfo->stats : nullptr)); } @@ -673,6 +674,10 @@ string OpDebug::report(Client* client, s << " locks:" << locks.obj().toString(); } + if (storageStats) { + s << " storage:" << storageStats->toBSON().toString(); + } + if (iscommand) { s << " protocol:" << getProtoString(networkOp); } @@ -747,6 +752,10 @@ void OpDebug::append(const CurOp& curop, lockStats.report(&locks); } + if (storageStats) { + b.append("storage", storageStats->toBSON()); + } + if (!errInfo.isOK()) { b.appendNumber("ok", 0.0); if (!errInfo.reason().empty()) { diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h index 5ed26b8a34e..3c63a58656d 100644 --- a/src/mongo/db/curop.h +++ b/src/mongo/db/curop.h @@ -204,6 +204,9 @@ public: // Stores additive metrics. AdditiveMetrics additiveMetrics; + + // Stores storage statistics. + std::shared_ptr storageStats; }; /** diff --git a/src/mongo/db/storage/recovery_unit.h b/src/mongo/db/storage/recovery_unit.h index 8f735b5a7ea..183b0ec857f 100644 --- a/src/mongo/db/storage/recovery_unit.h +++ b/src/mongo/db/storage/recovery_unit.h @@ -46,6 +46,36 @@ namespace mongo { class BSONObjBuilder; class OperationContext; +/** + * Storage statistics management class, with interfaces to provide the statistics in the BSON format + * and an operator to add the statistics values. + */ +class StorageStats { + MONGO_DISALLOW_COPYING(StorageStats); + +public: + StorageStats() = default; + + virtual ~StorageStats(){}; + + /** + * Provides the storage statistics in the form of a BSONObj. + */ + virtual BSONObj toBSON() = 0; + + /** + * Add the statistics values. + */ + virtual StorageStats& operator+=(const StorageStats&) = 0; + + /** + * Provides the ability to create an instance of this class outside of the storage integration + * layer. + */ + virtual std::shared_ptr getCopy() = 0; +}; + + /** * A RecoveryUnit is responsible for ensuring that data is persisted. * All on-disk information must be mutated through this interface. @@ -244,8 +274,8 @@ public: /** * Fetches the storage level statistics. */ - virtual BSONObj getOperationStatistics() const { - return {}; + virtual std::shared_ptr getOperationStatistics() const { + return (nullptr); } /** diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp index bb649e339bc..2e91e3fc381 100644 --- a/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp +++ b/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.cpp @@ -85,6 +85,104 @@ std::string toString(WiredTigerRecoveryUnit::State state) { } // namespace +using Section = WiredTigerOperationStats::Section; + +std::map> WiredTigerOperationStats::_statNameMap = { + {WT_STAT_SESSION_BYTES_READ, std::make_pair("bytesRead"_sd, Section::DATA)}, + {WT_STAT_SESSION_BYTES_WRITE, std::make_pair("bytesWritten"_sd, Section::DATA)}, + {WT_STAT_SESSION_LOCK_DHANDLE_WAIT, std::make_pair("handleLock"_sd, Section::WAIT)}, + {WT_STAT_SESSION_READ_TIME, std::make_pair("timeReadingMicros"_sd, Section::DATA)}, + {WT_STAT_SESSION_WRITE_TIME, std::make_pair("timeWritingMicros"_sd, Section::DATA)}, + {WT_STAT_SESSION_LOCK_SCHEMA_WAIT, std::make_pair("schemaLock"_sd, Section::WAIT)}, + {WT_STAT_SESSION_CACHE_TIME, std::make_pair("cache"_sd, Section::WAIT)}}; + +std::shared_ptr WiredTigerOperationStats::getCopy() { + std::shared_ptr copy = std::make_shared(); + *copy += *this; + return copy; +} + +void WiredTigerOperationStats::fetchStats(WT_SESSION* session, + const std::string& uri, + const std::string& config) { + invariant(session); + + WT_CURSOR* c = nullptr; + const char* cursorConfig = config.empty() ? nullptr : config.c_str(); + int ret = session->open_cursor(session, uri.c_str(), nullptr, cursorConfig, &c); + uassert(ErrorCodes::CursorNotFound, "Unable to open statistics cursor", ret == 0); + + invariant(c); + ON_BLOCK_EXIT(c->close, c); + + const char* desc; + uint64_t value; + uint64_t key; + while (c->next(c) == 0 && c->get_key(c, &key) == 0) { + fassert(51035, c->get_value(c, &desc, nullptr, &value) == 0); + _stats[key] = WiredTigerUtil::castStatisticsValue(value); + } + + // Reset the statistics so that the next fetch gives the recent values. + invariantWTOK(c->reset(c)); +} + +BSONObj WiredTigerOperationStats::toBSON() { + BSONObjBuilder bob; + std::unique_ptr dataSection; + std::unique_ptr waitSection; + + for (auto const& stat : _stats) { + // Find the user consumable name for this statistic. + auto statIt = _statNameMap.find(stat.first); + invariant(statIt != _statNameMap.end()); + + auto statName = statIt->second.first; + Section subs = statIt->second.second; + long long val = stat.second; + // Add this statistic only if higher than zero. + if (val > 0) { + // Gather the statistic into its own subsection in the BSONObj. + switch (subs) { + case Section::DATA: + if (!dataSection) + dataSection = std::make_unique(); + + dataSection->append(statName, val); + break; + case Section::WAIT: + if (!waitSection) + waitSection = std::make_unique(); + + waitSection->append(statName, val); + break; + default: + MONGO_UNREACHABLE; + } + } + } + + if (dataSection) + bob.append("data", dataSection->obj()); + if (waitSection) + bob.append("timeWaitingMicros", waitSection->obj()); + + return bob.obj(); +} + +WiredTigerOperationStats& WiredTigerOperationStats::operator+=( + const WiredTigerOperationStats& other) { + for (auto const& otherStat : other._stats) { + _stats[otherStat.first] += otherStat.second; + } + return (*this); +} + +StorageStats& WiredTigerOperationStats::operator+=(const StorageStats& other) { + *this += checked_cast(other); + return (*this); +} + WiredTigerRecoveryUnit::WiredTigerRecoveryUnit(WiredTigerSessionCache* sc) : WiredTigerRecoveryUnit(sc, sc->getKVEngine()->getOplogManager()) {} @@ -582,23 +680,19 @@ void WiredTigerRecoveryUnit::beginIdle() { } } -BSONObj WiredTigerRecoveryUnit::getOperationStatistics() const { - BSONObjBuilder bob; +std::shared_ptr WiredTigerRecoveryUnit::getOperationStatistics() const { + std::shared_ptr statsPtr(nullptr); + if (!_session) - return bob.obj(); + return statsPtr; WT_SESSION* s = _session->getSession(); invariant(s); - Status status = WiredTigerUtil::exportOperationStatsInfoToBSON( - s, "statistics:session", "statistics=(fast)", &bob); - if (!status.isOK()) { - bob.append("error", "unable to retrieve storage statistics"); - bob.append("code", static_cast(status.code())); - bob.append("reason", status.reason()); - } + statsPtr = std::make_shared(); + statsPtr->fetchStats(s, "statistics:session", "statistics=(fast)"); - return bob.obj(); + return statsPtr; } void WiredTigerRecoveryUnit::_setState(State newState) { diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h b/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h index 186a948283f..421552c47e9 100644 --- a/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h +++ b/src/mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h @@ -51,6 +51,41 @@ namespace mongo { class BSONObjBuilder; +class WiredTigerOperationStats final : public StorageStats { +public: + /** + * There are two types of statistics provided by WiredTiger engine - data and wait. + */ + enum class Section { DATA, WAIT }; + + BSONObj toBSON() final; + + StorageStats& operator+=(const StorageStats&) final; + + WiredTigerOperationStats& operator+=(const WiredTigerOperationStats&); + + /** + * Fetches an operation's storage statistics from WiredTiger engine. + */ + void fetchStats(WT_SESSION*, const std::string&, const std::string&); + + std::shared_ptr getCopy() final; + +private: + /** + * Each statistic in WiredTiger has an integer key, which this map associates with a section + * (either DATA or WAIT) and user-readable name. + */ + static std::map> _statNameMap; + + /** + * Stores the value for each statistic returned by a WiredTiger cursor. Each statistic is + * associated with an integer key, which can be mapped to a name and section using the + * '_statNameMap'. + */ + std::map _stats; +}; + class WiredTigerRecoveryUnit final : public RecoveryUnit { public: WiredTigerRecoveryUnit(WiredTigerSessionCache* sc); @@ -118,7 +153,7 @@ public: return _readOnce; }; - BSONObj getOperationStatistics() const override; + std::shared_ptr getOperationStatistics() const override; // ---- WT STUFF diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp index 7b5b418fbd6..12ea893ba01 100644 --- a/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp +++ b/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp @@ -643,7 +643,7 @@ Status WiredTigerUtil::exportTableToBSON(WT_SESSION* session, suffix = "num"; } - long long v = _castStatisticsValue(value); + long long v = castStatisticsValue(value); if (prefix.size() == 0) { bob->appendNumber(desc, v); @@ -664,86 +664,6 @@ Status WiredTigerUtil::exportTableToBSON(WT_SESSION* session, return Status::OK(); } -Status WiredTigerUtil::exportOperationStatsInfoToBSON(WT_SESSION* session, - const std::string& uri, - const std::string& config, - BSONObjBuilder* bob) { - invariant(session); - invariant(bob); - - // Map the statistics to a name and type desired for user consumption. There are two types of - // operation statistics - data and wait. - enum class Section { DATA, WAIT }; - static std::map> statNameMap = { - {WT_STAT_SESSION_BYTES_READ, std::make_pair("bytesRead", Section::DATA)}, - {WT_STAT_SESSION_BYTES_WRITE, std::make_pair("bytesWritten", Section::DATA)}, - {WT_STAT_SESSION_LOCK_DHANDLE_WAIT, std::make_pair("handleLock", Section::WAIT)}, - {WT_STAT_SESSION_READ_TIME, std::make_pair("timeReadingMicros", Section::DATA)}, - {WT_STAT_SESSION_WRITE_TIME, std::make_pair("timeWritingMicros", Section::DATA)}, - {WT_STAT_SESSION_LOCK_SCHEMA_WAIT, std::make_pair("schemaLock", Section::WAIT)}, - {WT_STAT_SESSION_CACHE_TIME, std::make_pair("cache", Section::WAIT)}}; - - WT_CURSOR* c = nullptr; - const char* cursorConfig = config.empty() ? nullptr : config.c_str(); - int ret = session->open_cursor(session, uri.c_str(), nullptr, cursorConfig, &c); - if (ret != 0) { - return Status(ErrorCodes::CursorNotFound, - str::stream() << "unable to open cursor at URI " << uri << ". reason: " - << wiredtiger_strerror(ret)); - } - invariant(c); - ON_BLOCK_EXIT(c->close, c); - - BSONObjBuilder* dataSection = nullptr; - BSONObjBuilder* waitSection = nullptr; - const char* desc; - uint64_t value; - uint64_t key; - while (c->next(c) == 0 && c->get_key(c, &key) == 0) { - fassert(51035, c->get_value(c, &desc, nullptr, &value) == 0); - - StringData statName; - // Find the user consumable name for this statistic. - auto statIt = statNameMap.find(key); - invariant(statIt != statNameMap.end()); - statName = statIt->second.first; - - Section subs = statIt->second.second; - long long casted_val = _castStatisticsValue(value); - - // Add this statistic only if higher than zero. - if (casted_val > 0) { - // Gather the statistic into its own subsection in the BSONObj. - switch (subs) { - case Section::DATA: - if (!dataSection) - dataSection = new BSONObjBuilder(); - - dataSection->append(statName, casted_val); - break; - case Section::WAIT: - if (!waitSection) - waitSection = new BSONObjBuilder(); - - waitSection->append(statName, casted_val); - break; - default: - return Status(ErrorCodes::BadValue, - str::stream() << "Unexpected storage statistics type."); - } - } - } - - if (dataSection) - bob->append("data", dataSection->obj()); - if (waitSection) - bob->append("timeWaitingMicros", waitSection->obj()); - - // Reset the statistics so that the next fetch gives the recent values. - c->reset(c); - return Status::OK(); -} - void WiredTigerUtil::appendSnapshotWindowSettings(WiredTigerKVEngine* engine, WiredTigerSession* session, BSONObjBuilder* bob) { diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_util.h b/src/mongo/db/storage/wiredtiger/wiredtiger_util.h index 2f0185cef59..6905d4e4994 100644 --- a/src/mongo/db/storage/wiredtiger/wiredtiger_util.h +++ b/src/mongo/db/storage/wiredtiger/wiredtiger_util.h @@ -150,14 +150,6 @@ public: const std::string& config, BSONObjBuilder* bob); - /** - * Fetches the operation statistics, converts those into a BSONObj and resets the statistics - * at the end. - */ - static Status exportOperationStatsInfoToBSON(WT_SESSION* s, - const std::string& uri, - const std::string& config, - BSONObjBuilder* bob); /** * Appends information about the storage engine's currently available snapshots and the settings * that affect that window of maintained history. @@ -281,14 +273,14 @@ public: static Status setTableLogging(WT_SESSION* session, const std::string& uri, bool on); -private: /** * Casts unsigned 64-bit statistics value to T. * If original value exceeds maximum value of T, return max(T). */ template - static T _castStatisticsValue(uint64_t statisticsValue); + static T castStatisticsValue(uint64_t statisticsValue); +private: /** * Casts unsigned 64-bit statistics value to T. * If original value exceeds 'maximumResultType', return 'maximumResultType'. @@ -354,7 +346,7 @@ StatusWith WiredTigerUtil::getStatisticsValueAs(WT_SESSION* session, // static template -ResultType WiredTigerUtil::_castStatisticsValue(uint64_t statisticsValue) { +ResultType WiredTigerUtil::castStatisticsValue(uint64_t statisticsValue) { return _castStatisticsValue(statisticsValue, std::numeric_limits::max()); } diff --git a/src/mongo/db/transaction_metrics_observer.cpp b/src/mongo/db/transaction_metrics_observer.cpp index 5731fa6954e..1afed3897a9 100644 --- a/src/mongo/db/transaction_metrics_observer.cpp +++ b/src/mongo/db/transaction_metrics_observer.cpp @@ -194,12 +194,25 @@ void TransactionMetricsObserver::onAbortInactive( } } -void TransactionMetricsObserver::onTransactionOperation(Client* client, - OpDebug::AdditiveMetrics additiveMetrics) { +void TransactionMetricsObserver::onTransactionOperation( + Client* client, + OpDebug::AdditiveMetrics additiveMetrics, + std::shared_ptr storageStats) { // Add the latest operation stats to the aggregate OpDebug::AdditiveMetrics object stored in the // SingleTransactionStats instance on the TransactionMetricsObserver. _singleTransactionStats.getOpDebug()->additiveMetrics.add(additiveMetrics); + // If there are valid storage statistics for this operation, put those in the + // SingleTransactionStats instance either by creating a new storageStats instance or by adding + // into an existing storageStats instance stored in SingleTransactionStats. + if (storageStats) { + if (!_singleTransactionStats.getOpDebug()->storageStats) { + _singleTransactionStats.getOpDebug()->storageStats = storageStats->getCopy(); + } else { + *_singleTransactionStats.getOpDebug()->storageStats += *storageStats; + } + } + // Update the LastClientInfo object stored in the SingleTransactionStats instance on the // TransactionMetricsObserver with this Client's information. This is the last client that ran a // transaction operation on the txnParticipant. diff --git a/src/mongo/db/transaction_metrics_observer.h b/src/mongo/db/transaction_metrics_observer.h index 6600615ceac..77f402a3cd0 100644 --- a/src/mongo/db/transaction_metrics_observer.h +++ b/src/mongo/db/transaction_metrics_observer.h @@ -115,10 +115,12 @@ public: TickSource::Tick curTick); /** - * Updates relevant metrics when an operation running on the transaction completes. An operation - * may be a read/write operation, or an abort/commit command. + * Updates relevant metrics and storage statistics when an operation running on the transaction + * completes. An operation may be a read/write operation, or an abort/commit command. */ - void onTransactionOperation(Client* client, OpDebug::AdditiveMetrics additiveMetrics); + void onTransactionOperation(Client* client, + OpDebug::AdditiveMetrics additiveMetrics, + std::shared_ptr storageStats); /** * Returns a read-only reference to the SingleTransactionStats object stored in this diff --git a/src/mongo/db/transaction_participant.cpp b/src/mongo/db/transaction_participant.cpp index 2dd2dba889f..d2c2fb75f2b 100644 --- a/src/mongo/db/transaction_participant.cpp +++ b/src/mongo/db/transaction_participant.cpp @@ -654,7 +654,9 @@ void TransactionParticipant::_stashActiveTransaction(WithLock, OperationContext* auto tickSource = opCtx->getServiceContext()->getTickSource(); _transactionMetricsObserver.onStash(ServerTransactionsMetrics::get(opCtx), tickSource); _transactionMetricsObserver.onTransactionOperation( - opCtx->getClient(), CurOp::get(opCtx)->debug().additiveMetrics); + opCtx->getClient(), + CurOp::get(opCtx)->debug().additiveMetrics, + CurOp::get(opCtx)->debug().storageStats); } invariant(!_txnResourceStash); @@ -1083,7 +1085,9 @@ void TransactionParticipant::_finishCommitTransaction(WithLock lk, OperationCont &Top::get(getGlobalServiceContext()), isCommittingWithPrepare); _transactionMetricsObserver.onTransactionOperation( - opCtx->getClient(), CurOp::get(opCtx)->debug().additiveMetrics); + opCtx->getClient(), + CurOp::get(opCtx)->debug().additiveMetrics, + CurOp::get(opCtx)->debug().storageStats); } // We must clear the recovery unit and locker so any post-transaction writes can run without @@ -1168,7 +1172,9 @@ void TransactionParticipant::_abortActiveTransaction(stdx::unique_lock lm(_metricsMutex); _transactionMetricsObserver.onTransactionOperation( - opCtx->getClient(), CurOp::get(opCtx)->debug().additiveMetrics); + opCtx->getClient(), + CurOp::get(opCtx)->debug().additiveMetrics, + CurOp::get(opCtx)->debug().storageStats); } // We reserve an oplog slot before aborting the transaction so that no writes that are causally @@ -1541,6 +1547,9 @@ std::string TransactionParticipant::_transactionInfoForLog( lockStats->report(&locks); s << " locks:" << locks.obj().toString(); + if (singleTransactionStats.getOpDebug()->storageStats) + s << " storage:" << singleTransactionStats.getOpDebug()->storageStats->toBSON().toString(); + // Total duration of the transaction. s << " " << duration_cast(singleTransactionStats.getDuration(tickSource, curTick)); -- cgit v1.2.1