SERVER-43322 Report oplog processing and truncation data in serverStatus

(cherry picked from commit abaa6d3ce507a3524d5fdea8f95578dd9b08b44c)
(partially cherry picked from commit 62378f4e12644c250ccb894cf6b92d27b77b16fd)

6 files changed, 77 insertions, 2 deletions

diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_init.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_init.cpp
index d3ff71e7284..9bb43858b34 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_init.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_init.cpp
@@ -122,6 +122,7 @@ public:
         new WiredTigerEngineRuntimeConfigParameter(kv);
         new WiredTigerMaxCacheOverflowSizeGBParameter(
             kv, wiredTigerGlobalOptions.maxCacheOverflowFileSizeGB);
+        new OplogStonesServerStatusSection();
 
         KVStorageEngineOptions options;
         options.directoryPerDB = params.directoryperdb;
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp
index 3ead7a72deb..3d158ed7c4f 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp
@@ -62,6 +62,7 @@
 #include "mongo/util/mongoutils/str.h"
 #include "mongo/util/scopeguard.h"
 #include "mongo/util/time_support.h"
+#include "mongo/util/timer.h"
 
 namespace mongo {
 
@@ -283,6 +284,12 @@ void WiredTigerRecordStore::OplogStones::setMinBytesPerStone(int64_t size) {
 
 void WiredTigerRecordStore::OplogStones::_calculateStones(OperationContext* opCtx,
                                                           size_t numStonesToKeep) {
+    const std::uint64_t startWaitTime = curTimeMicros64();
+    ON_BLOCK_EXIT([&] {
+        auto waitTime = curTimeMicros64() - startWaitTime;
+        log() << "WiredTiger record store oplog processing took " << waitTime / 1000 << "ms";
+        _totalTimeProcessing.fetchAndAdd(waitTime);
+    });
     long long numRecords = _rs->numRecords(opCtx);
     long long dataSize = _rs->dataSize(opCtx);
 
@@ -312,6 +319,7 @@ void WiredTigerRecordStore::OplogStones::_calculateStones(OperationContext* opCt
 }
 
 void WiredTigerRecordStore::OplogStones::_calculateStonesByScanning(OperationContext* opCtx) {
+    _processBySampling.store(false);  // process by scanning
     log() << "Scanning the oplog to determine where to place markers for truncation";
 
     long long numRecords = 0;
@@ -339,6 +347,8 @@ void WiredTigerRecordStore::OplogStones::_calculateStonesByScanning(OperationCon
 void WiredTigerRecordStore::OplogStones::_calculateStonesBySampling(OperationContext* opCtx,
                                                                     int64_t estRecordsPerStone,
                                                                     int64_t estBytesPerStone) {
+    log() << "Sampling the oplog to determine where to place markers for truncation";
+    _processBySampling.store(true);  // process by sampling
     Timestamp earliestOpTime;
     Timestamp latestOpTime;
 
@@ -687,6 +697,14 @@ void WiredTigerRecordStore::postConstructorInit(OperationContext* opCtx) {
     }
 }
 
+void WiredTigerRecordStore::getOplogTruncateStats(BSONObjBuilder& builder) const {
+    if (_oplogStones) {
+        _oplogStones->getOplogStonesStats(builder);
+    }
+    builder.append("totalTimeTruncatingMicros", _totalTimeTruncating.load());
+    builder.append("truncateCount", _truncateCount.load());
+}
+
 const char* WiredTigerRecordStore::name() const {
     return _engineName.c_str();
 }
@@ -1021,6 +1039,7 @@ bool WiredTigerRecordStore::yieldAndAwaitOplogDeletionRequest(OperationContext*
 }
 
 void WiredTigerRecordStore::reclaimOplog(OperationContext* opCtx) {
+    Timer timer;
     while (auto stone = _oplogStones->peekOldestStoneIfNeeded()) {
         invariant(stone->lastRecord.isNormal());
 
@@ -1066,6 +1085,12 @@ void WiredTigerRecordStore::reclaimOplog(OperationContext* opCtx) {
     LOG(1) << "Finished truncating the oplog, it now contains approximately "
            << _sizeInfo->numRecords.load() << " records totaling to " << _sizeInfo->dataSize.load()
            << " bytes";
+
+    auto elapsedMicros = timer.micros();
+    auto elapsedMillis = elapsedMicros / 1000;
+    _totalTimeTruncating.fetchAndAdd(elapsedMicros);
+    _truncateCount.fetchAndAdd(1);
+    log() << "WiredTiger record store oplog truncation finished in: " << elapsedMillis << "ms";
 }
 
 Status WiredTigerRecordStore::insertRecords(OperationContext* opCtx,
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.h b/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.h
index 75dbe9c46ba..7e31c90a84b 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.h
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_record_store.h
@@ -117,6 +117,8 @@ public:
 
     WiredTigerRecordStore(WiredTigerKVEngine* kvEngine, OperationContext* opCtx, Params params);
 
+    void getOplogTruncateStats(BSONObjBuilder& builder) const;
+
     virtual ~WiredTigerRecordStore();
 
     virtual void postConstructorInit(OperationContext* opCtx);
@@ -361,6 +363,9 @@ private:
 
     // Non-null if this record store is underlying the active oplog.
     std::shared_ptr<OplogStones> _oplogStones;
+
+    AtomicInt64 _totalTimeTruncating;  // Cumulative amount of time spent truncating the oplog.
+    AtomicInt64 _truncateCount;        // Cumulative number of truncates of the oplog.
 };
 
 
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_record_store_oplog_stones.h b/src/mongo/db/storage/wiredtiger/wiredtiger_record_store_oplog_stones.h
index 600b92836ec..a4e4c5de325 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_record_store_oplog_stones.h
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_record_store_oplog_stones.h
@@ -70,6 +70,11 @@ public:
 
     void awaitHasExcessStonesOrDead();
 
+    void getOplogStonesStats(BSONObjBuilder& builder) const {
+        builder.append("totalTimeProcessingMicros", _totalTimeProcessing.load());
+        builder.append("processingMethod", _processBySampling.load() ? "sampling" : "scanning");
+    }
+
     boost::optional<OplogStones::Stone> peekOldestStoneIfNeeded() const;
 
     void popOldestStone();
@@ -141,8 +146,11 @@ private:
     // deque of oplog stones.
     int64_t _minBytesPerStone;
 
-    AtomicInt64 _currentRecords;  // Number of records in the stone being filled.
-    AtomicInt64 _currentBytes;    // Number of bytes in the stone being filled.
+    AtomicInt64 _currentRecords;       // Number of records in the stone being filled.
+    AtomicInt64 _currentBytes;         // Number of bytes in the stone being filled.
+    AtomicInt64 _totalTimeProcessing;  // Amount of time spent scanning and/or sampling the
+                                       // oplog during start up, if any.
+    AtomicBool _processBySampling;     // Whether the oplog was sampled or scanned.
 
     mutable stdx::mutex _mutex;  // Protects against concurrent access to the deque of oplog stones.
     std::deque<OplogStones::Stone> _stones;  // front = oldest, back = newest.
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_server_status.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_server_status.cpp
index 195789f23dd..a50b7ea6cf4 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_server_status.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_server_status.cpp
@@ -37,6 +37,8 @@
 #include "mongo/base/checked_cast.h"
 #include "mongo/bson/bsonobjbuilder.h"
 #include "mongo/db/concurrency/d_concurrency.h"
+#include "mongo/db/db_raii.h"
+#include "mongo/db/namespace_string.h"
 #include "mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h"
 #include "mongo/db/storage/wiredtiger/wiredtiger_record_store.h"
 #include "mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h"
@@ -45,6 +47,7 @@
 #include "mongo/util/assert_util.h"
 #include "mongo/util/scopeguard.h"
 
+
 namespace mongo {
 
 using std::string;
@@ -83,4 +86,26 @@ BSONObj WiredTigerServerStatusSection::generateSection(OperationContext* opCtx,
     return bob.obj();
 }
 
+OplogStonesServerStatusSection::OplogStonesServerStatusSection()
+    : ServerStatusSection("oplogTruncation") {}
+
+bool OplogStonesServerStatusSection::includeByDefault() const {
+    return true;
+}
+
+BSONObj OplogStonesServerStatusSection::generateSection(OperationContext* opCtx,
+                                                        const BSONElement& configElement) const {
+    BSONObjBuilder builder;
+    {
+        AutoGetCollectionForReadCommand ctx(opCtx, NamespaceString::kRsOplogNamespace);
+        Collection* oplogColl = ctx.getCollection();
+        if (oplogColl) {
+            auto oplogRS = checked_cast<WiredTigerRecordStore*>(oplogColl->getRecordStore());
+            oplogRS->getOplogTruncateStats(builder);
+        }
+    }
+    return builder.obj();
+}
+
+
 }  // namespace mongo
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_server_status.h b/src/mongo/db/storage/wiredtiger/wiredtiger_server_status.h
index 5e66dd2f0e5..36be197df96 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_server_status.h
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_server_status.h
@@ -52,4 +52,15 @@ private:
     WiredTigerKVEngine* _engine;
 };
 
+/**
+ * Adds oplog stones statistics to the results of db.serverStatus().
+ */
+class OplogStonesServerStatusSection : public ServerStatusSection {
+public:
+    OplogStonesServerStatusSection();
+    bool includeByDefault() const override;
+    BSONObj generateSection(OperationContext* opCtx,
+                            const BSONElement& configElement) const override;
+};
+
 }  // namespace mongo