SERVER-43664 Speedup WiredTiger storage engine startup for many tables by optimizing WiredTigerUtil::setTableLogging()

7 files changed, 201 insertions, 13 deletions

diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp
index b4ba68b9b58..1553c1740fe 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp
@@ -769,6 +769,10 @@ void WiredTigerKVEngine::startAsyncThreads() {
     }
 }
 
+void WiredTigerKVEngine::notifyStartupComplete() {
+    WiredTigerUtil::notifyStartupComplete();
+}
+
 void WiredTigerKVEngine::appendGlobalStats(BSONObjBuilder& b) {
     BSONObjBuilder bb(b.subobjStart("concurrentTransactions"));
     {
@@ -880,6 +884,8 @@ void WiredTigerKVEngine::_openWiredTiger(const std::string& path, const std::str
 
 void WiredTigerKVEngine::cleanShutdown() {
     LOGV2(22317, "WiredTigerKVEngine shutting down");
+    WiredTigerUtil::resetTableLoggingInfo();
+
     if (!_readOnly)
         syncSizeInfo(true);
     if (!_conn) {
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h
index afa082cdb2c..9327ae7454f 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h
@@ -105,6 +105,8 @@ public:
 
     void startAsyncThreads() override;
 
+    void notifyStartupComplete() override;
+
     void setRecordStoreExtraOptions(const std::string& options);
     void setSortedDataInterfaceExtraOptions(const std::string& options);
 
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine_test.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine_test.cpp
index 67c125f0813..b870c017798 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine_test.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine_test.cpp
@@ -63,6 +63,7 @@ public:
         repl::ReplicationCoordinator::set(
             context,
             std::make_unique<repl::ReplicationCoordinatorMock>(context, repl::ReplSettings()));
+        _engine->notifyStartupComplete();
     }
 
     virtual KVEngine* restartEngine() override {
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_prefixed_record_store_test.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_prefixed_record_store_test.cpp
index ed8f8b72d36..aabe631120d 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_prefixed_record_store_test.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_prefixed_record_store_test.cpp
@@ -86,6 +86,7 @@ public:
             getGlobalServiceContext(),
             std::unique_ptr<repl::ReplicationCoordinator>(new repl::ReplicationCoordinatorMock(
                 getGlobalServiceContext(), repl::ReplSettings())));
+        _engine->notifyStartupComplete();
     }
 
     PrefixedWiredTigerHarnessHelper(StringData extraStrings) : _dbpath("wt_test") {}
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_standard_record_store_test.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_standard_record_store_test.cpp
index 43e6b615cc8..cc9a6fdae75 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_standard_record_store_test.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_standard_record_store_test.cpp
@@ -86,6 +86,7 @@ public:
         repl::ReplicationCoordinator::set(serviceContext(),
                                           std::make_unique<repl::ReplicationCoordinatorMock>(
                                               serviceContext(), repl::ReplSettings()));
+        _engine.notifyStartupComplete();
     }
 
     ~WiredTigerHarnessHelper() {}
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp
index 9dbd5896ca0..e94e94dcc10 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp
@@ -35,23 +35,97 @@
 
 #include <limits>
 
+#include <boost/filesystem.hpp>
+#include <boost/filesystem/path.hpp>
+
 #include "mongo/base/simple_string_data_comparator.h"
 #include "mongo/bson/bsonobjbuilder.h"
 #include "mongo/db/concurrency/write_conflict_exception.h"
 #include "mongo/db/snapshot_window_options_gen.h"
+#include "mongo/db/storage/storage_file_util.h"
 #include "mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h"
 #include "mongo/db/storage/wiredtiger/wiredtiger_recovery_unit.h"
 #include "mongo/db/storage/wiredtiger/wiredtiger_session_cache.h"
 #include "mongo/logv2/log.h"
 #include "mongo/util/assert_util.h"
+#include "mongo/util/fail_point.h"
 #include "mongo/util/processinfo.h"
 #include "mongo/util/scopeguard.h"
 #include "mongo/util/str.h"
 
 namespace mongo {
 
+MONGO_FAIL_POINT_DEFINE(crashAfterUpdatingFirstTableLoggingSettings);
+
+namespace {
+
+const std::string kTableChecksFileName = "_wt_table_checks";
+
+/**
+ * Returns true if the 'kTableChecksFileName' file exists in the dbpath.
+ *
+ * Must be called before createTableChecksFile() or removeTableChecksFile() to get accurate results.
+ */
+bool hasPreviouslyIncompleteTableChecks() {
+    auto path = boost::filesystem::path(storageGlobalParams.dbpath) /
+        boost::filesystem::path(kTableChecksFileName);
+
+    return boost::filesystem::exists(path);
+}
+
+/**
+ * Creates the 'kTableChecksFileName' file in the dbpath.
+ */
+void createTableChecksFile() {
+    auto path = boost::filesystem::path(storageGlobalParams.dbpath) /
+        boost::filesystem::path(kTableChecksFileName);
+
+    boost::filesystem::ofstream fileStream(path);
+    fileStream << "This file indicates that a WiredTiger table check operation is in progress or "
+                  "incomplete."
+               << std::endl;
+    if (fileStream.fail()) {
+        LOGV2_FATAL_NOTRACE(4366400,
+                            "Failed to write to file",
+                            "file"_attr = path.generic_string(),
+                            "error"_attr = errnoWithDescription());
+    }
+    fileStream.close();
+
+    fassertNoTrace(4366401, fsyncFile(path));
+    fassertNoTrace(4366402, fsyncParentDirectory(path));
+}
+
+/**
+ * Removes the 'kTableChecksFileName' file in the dbpath, if it exists.
+ */
+void removeTableChecksFile() {
+    auto path = boost::filesystem::path(storageGlobalParams.dbpath) /
+        boost::filesystem::path(kTableChecksFileName);
+
+    if (!boost::filesystem::exists(path)) {
+        return;
+    }
+
+    boost::system::error_code errorCode;
+    boost::filesystem::remove(path, errorCode);
+
+    if (errorCode) {
+        LOGV2_FATAL_NOTRACE(4366403,
+                            "Failed to remove file",
+                            "file"_attr = path.generic_string(),
+                            "error"_attr = errorCode.message());
+    }
+}
+
+}  // namespace
+
 using std::string;
 
+Mutex WiredTigerUtil::_tableLoggingInfoMutex =
+    MONGO_MAKE_LATCH("WiredTigerUtil::_tableLoggingInfoMutex");
+WiredTigerUtil::TableLoggingInfo WiredTigerUtil::_tableLoggingInfo;
+
 Status wtRCToStatus_slow(int retCode, const char* prefix) {
     if (retCode == 0)
         return Status::OK();
@@ -576,6 +650,23 @@ int WiredTigerUtil::verifyTable(OperationContext* opCtx,
     return (session->verify)(session, uri.c_str(), nullptr);
 }
 
+void WiredTigerUtil::notifyStartupComplete() {
+    {
+        stdx::lock_guard<Latch> lk(_tableLoggingInfoMutex);
+        invariant(_tableLoggingInfo.isInitializing);
+        _tableLoggingInfo.isInitializing = false;
+    }
+
+    if (!storageGlobalParams.readOnly) {
+        removeTableChecksFile();
+    }
+}
+
+void WiredTigerUtil::resetTableLoggingInfo() {
+    stdx::lock_guard<Latch> lk(_tableLoggingInfoMutex);
+    _tableLoggingInfo = TableLoggingInfo();
+}
+
 bool WiredTigerUtil::useTableLogging(NamespaceString ns, bool replEnabled) {
     if (!replEnabled) {
         // All tables on standalones are logged.
@@ -610,13 +701,88 @@ Status WiredTigerUtil::setTableLogging(OperationContext* opCtx, const std::strin
 }
 
 Status WiredTigerUtil::setTableLogging(WT_SESSION* session, const std::string& uri, bool on) {
-    std::string setting;
-    if (on) {
-        setting = "log=(enabled=true)";
-    } else {
-        setting = "log=(enabled=false)";
+    invariant(!storageGlobalParams.readOnly);
+    stdx::lock_guard<Latch> lk(_tableLoggingInfoMutex);
+
+    // Update the table logging settings regardless if we're no longer starting up the process.
+    if (!_tableLoggingInfo.isInitializing) {
+        return _setTableLogging(session, uri, on);
+    }
+
+    // During the start up process, the table logging settings are checked for each table to verify
+    // that they are set appropriately. We can speed this process up by assuming that the logging
+    // setting is identical for each table.
+    // We cross reference the logging settings for the first table and if it isn't correctly set, we
+    // change the logging settings for all tables during start up.
+    // In the event that the server wasn't shutdown cleanly, the logging settings will be modified
+    // for all tables as a safety precaution, or if repair mode is running.
+    if (_tableLoggingInfo.isFirstTable && hasPreviouslyIncompleteTableChecks()) {
+        _tableLoggingInfo.hasPreviouslyIncompleteTableChecks = true;
+    }
+
+    if (storageGlobalParams.repair || _tableLoggingInfo.hasPreviouslyIncompleteTableChecks) {
+        if (_tableLoggingInfo.isFirstTable) {
+            _tableLoggingInfo.isFirstTable = false;
+            if (!_tableLoggingInfo.hasPreviouslyIncompleteTableChecks) {
+                createTableChecksFile();
+            }
+
+            LOGV2(4366405,
+                  "Modifying the table logging settings for all existing WiredTiger tables",
+                  "loggingEnabled"_attr = on,
+                  "repair"_attr = storageGlobalParams.repair,
+                  "hasPreviouslyIncompleteTableChecks"_attr =
+                      _tableLoggingInfo.hasPreviouslyIncompleteTableChecks);
+        }
+
+        return _setTableLogging(session, uri, on);
+    }
+
+    if (!_tableLoggingInfo.isFirstTable) {
+        if (_tableLoggingInfo.changeTableLogging) {
+            return _setTableLogging(session, uri, on);
+        }
+
+        // The table logging settings do not need to be modified.
+        return Status::OK();
     }
 
+    invariant(_tableLoggingInfo.isFirstTable);
+    invariant(!_tableLoggingInfo.hasPreviouslyIncompleteTableChecks);
+    _tableLoggingInfo.isFirstTable = false;
+
+    // Check if the first tables logging settings need to be modified.
+    const std::string setting = on ? "log=(enabled=true)" : "log=(enabled=false)";
+    const std::string existingMetadata = getMetadataCreate(session, uri).getValue();
+    if (existingMetadata.find(setting) != std::string::npos) {
+        // The table is running with the expected logging settings.
+        LOGV2(4366408,
+              "No table logging settings modifications are required for existing WiredTiger tables",
+              "loggingEnabled"_attr = on);
+        return Status::OK();
+    }
+
+    // The first table is running with the incorrect logging settings. All tables will need to have
+    // their logging settings modified.
+    _tableLoggingInfo.changeTableLogging = true;
+    createTableChecksFile();
+
+    LOGV2(4366406,
+          "Modifying the table logging settings for all existing WiredTiger tables",
+          "loggingEnabled"_attr = on);
+
+    Status status = _setTableLogging(session, uri, on);
+
+    if (MONGO_unlikely(crashAfterUpdatingFirstTableLoggingSettings.shouldFail())) {
+        LOGV2_FATAL_NOTRACE(
+            4366407, "Crashing due to 'crashAfterUpdatingFirstTableLoggingSettings' fail point");
+    }
+    return status;
+}
+
+Status WiredTigerUtil::_setTableLogging(WT_SESSION* session, const std::string& uri, bool on) {
+    const std::string setting = on ? "log=(enabled=true)" : "log=(enabled=false)";
+
     // This method does some "weak" parsing to see if the table is in the expected logging
     // state. Only attempt to alter the table when a change is needed. This avoids grabbing heavy
     // locks in WT when creating new tables for collections and indexes. Those tables are created
@@ -638,19 +804,14 @@ Status WiredTigerUtil::setTableLogging(WT_SESSION* session, const std::string& u
         return Status::OK();
     }
 
-    LOGV2_DEBUG(22432,
-                1,
-                "Changing table logging settings. Uri: {uri} Enable? {on}",
-                "uri"_attr = uri,
-                "on"_attr = on);
+    LOGV2_DEBUG(
+        22432, 1, "Changing table logging settings", "uri"_attr = uri, "loggingEnabled"_attr = on);
     int ret = session->alter(session, uri.c_str(), setting.c_str());
     if (ret) {
         LOGV2_FATAL(50756,
-                    "Failed to update log setting. Uri: {uri} Enable? {enable} Ret: {error} MD: "
-                    "{metadata} Msg: {message}",
                     "Failed to update log setting",
                     "uri"_attr = uri,
-                    "enable"_attr = on,
+                    "loggingEnabled"_attr = on,
                     "error"_attr = ret,
                     "metadata"_attr = redact(existingMetadata),
                     "message"_attr = session->strerror(session, ret));
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_util.h b/src/mongo/db/storage/wiredtiger/wiredtiger_util.h
index e1e1a190b28..5150c19e153 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_util.h
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_util.h
@@ -253,6 +253,10 @@ public:
                            const std::string& uri,
                            std::vector<std::string>* errors = nullptr);
 
+    static void notifyStartupComplete();
+
+    static void resetTableLoggingInfo();
+
     static bool useTableLogging(NamespaceString ns, bool replEnabled);
 
     static Status setTableLogging(OperationContext* opCtx, const std::string& uri, bool on);
@@ -273,6 +277,18 @@ private:
      */
     template <typename T>
     static T _castStatisticsValue(uint64_t statisticsValue, T maximumResultType);
+
+    static Status _setTableLogging(WT_SESSION* session, const std::string& uri, bool on);
+
+    // Used to keep track of the table logging setting modifications during start up. The mutex must
+    // be held prior to accessing any of the member variables in the struct.
+    static Mutex _tableLoggingInfoMutex;
+    static struct TableLoggingInfo {
+        bool isInitializing = true;
+        bool isFirstTable = true;
+        bool changeTableLogging = false;
+        bool hasPreviouslyIncompleteTableChecks = false;
+    } _tableLoggingInfo;
 };
 
 class WiredTigerConfigParser {