SERVER-38240 Added storage statistics information into the slowop log messages.

10 files changed, 221 insertions, 114 deletions

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> 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
@@ -47,6 +47,36 @@ 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<StorageStats> 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<StorageStats> 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<int, std::pair<StringData, Section>> 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<StorageStats> WiredTigerOperationStats::getCopy() {
+    std::shared_ptr<WiredTigerOperationStats> copy = std::make_shared<WiredTigerOperationStats>();
+    *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<long long>(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<BSONObjBuilder> dataSection;
+    std::unique_ptr<BSONObjBuilder> 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<BSONObjBuilder>();
+
+                    dataSection->append(statName, val);
+                    break;
+                case Section::WAIT:
+                    if (!waitSection)
+                        waitSection = std::make_unique<BSONObjBuilder>();
+
+                    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<const WiredTigerOperationStats&>(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<StorageStats> WiredTigerRecoveryUnit::getOperationStatistics() const {
+    std::shared_ptr<WiredTigerOperationStats> 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<int>(status.code()));
-        bob.append("reason", status.reason());
-    }
+    statsPtr = std::make_shared<WiredTigerOperationStats>();
+    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<StorageStats> 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<int, std::pair<StringData, Section>> _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<int, long long> _stats;
+};
+
 class WiredTigerRecoveryUnit final : public RecoveryUnit {
 public:
     WiredTigerRecoveryUnit(WiredTigerSessionCache* sc);
@@ -118,7 +153,7 @@ public:
         return _readOnce;
     };
 
-    BSONObj getOperationStatistics() const override;
+    std::shared_ptr<StorageStats> 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<long long>(value);
+        long long v = castStatisticsValue<long long>(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<int, std::pair<StringData, Section>> 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<long long>(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
@@ -151,14 +151,6 @@ public:
                                     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 <typename T>
-    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<ResultType> WiredTigerUtil::getStatisticsValueAs(WT_SESSION* session,
 
 // static
 template <typename ResultType>
-ResultType WiredTigerUtil::_castStatisticsValue(uint64_t statisticsValue) {
+ResultType WiredTigerUtil::castStatisticsValue(uint64_t statisticsValue) {
     return _castStatisticsValue<ResultType>(statisticsValue,
                                             std::numeric_limits<ResultType>::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> 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> 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<stdx::mut
     if (!_txnState.isNone(lock)) {
         stdx::lock_guard<stdx::mutex> 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<Milliseconds>(singleTransactionStats.getDuration(tickSource, curTick));