SERVER-54074 Log start and end of changes to table log settings

13 files changed, 87 insertions, 0 deletions

diff --git a/src/mongo/db/db.cpp b/src/mongo/db/db.cpp
index 2b481fd9d4d..2a55dffc86d 100644
--- a/src/mongo/db/db.cpp
+++ b/src/mongo/db/db.cpp
@@ -461,6 +461,10 @@ ExitCode _initAndListen(int listenPort) {
         exitCleanly(EXIT_NEED_DOWNGRADE);
     }
 
+    // Notify the storage engine that startup is completed before repair exits below, as repair sets
+    // the upgrade flag to true.
+    serviceContext->getStorageEngine()->notifyStartupComplete();
+
     if (storageGlobalParams.upgrade) {
         log() << "finished checking dbs";
         exitCleanly(EXIT_CLEAN);
diff --git a/src/mongo/db/service_context_d_test_fixture.cpp b/src/mongo/db/service_context_d_test_fixture.cpp
index 5df95627c9c..e4d400f5138 100644
--- a/src/mongo/db/service_context_d_test_fixture.cpp
+++ b/src/mongo/db/service_context_d_test_fixture.cpp
@@ -77,6 +77,7 @@ ServiceContextMongoDTest::ServiceContextMongoDTest(std::string engine, RepairAct
     storageGlobalParams.dbpath = _tempDir.path();
 
     initializeStorageEngine(serviceContext, StorageEngineInitFlags::kNone);
+    serviceContext->getStorageEngine()->notifyStartupComplete();
 
     // Set up UUID Catalog observer. This is necessary because the Collection destructor contains an
     // invariant to ensure the UUID corresponding to that Collection object is no longer associated
diff --git a/src/mongo/db/storage/kv/kv_engine.h b/src/mongo/db/storage/kv/kv_engine.h
index 848fe379c8c..b9f17d8dd65 100644
--- a/src/mongo/db/storage/kv/kv_engine.h
+++ b/src/mongo/db/storage/kv/kv_engine.h
@@ -54,6 +54,20 @@ class SnapshotManager;
 
 class KVEngine {
 public:
+    /**
+     * During the startup process, the storage engine is one of the first components to be started
+     * up and fully initialized. But that fully initialized storage engine may not be recognized as
+     * the end for the remaining storage startup tasks that still need to be performed.
+     *
+     * For example, after the storage engine has been fully initialized, we need to access it in
+     * order to set up all of the collections and indexes based on the metadata, or perform some
+     * corrective measures on the data files, etc.
+     *
+     * When all of the storage startup tasks are completed as a whole, then this function is called
+     * by the external force managing the startup process.
+     */
+    virtual void notifyStartupComplete() {}
+
     virtual RecoveryUnit* newRecoveryUnit() = 0;
 
     // ---------
diff --git a/src/mongo/db/storage/kv/kv_storage_engine.cpp b/src/mongo/db/storage/kv/kv_storage_engine.cpp
index e3dd6d5a319..4dc5a5f73fb 100644
--- a/src/mongo/db/storage/kv/kv_storage_engine.cpp
+++ b/src/mongo/db/storage/kv/kv_storage_engine.cpp
@@ -478,6 +478,10 @@ KVStorageEngine::~KVStorageEngine() {}
 
 void KVStorageEngine::finishInit() {}
 
+void KVStorageEngine::notifyStartupComplete() {
+    _engine->notifyStartupComplete();
+}
+
 RecoveryUnit* KVStorageEngine::newRecoveryUnit() {
     if (!_engine) {
         // shutdown
diff --git a/src/mongo/db/storage/kv/kv_storage_engine.h b/src/mongo/db/storage/kv/kv_storage_engine.h
index 5ac73546bdf..5cc977d25c1 100644
--- a/src/mongo/db/storage/kv/kv_storage_engine.h
+++ b/src/mongo/db/storage/kv/kv_storage_engine.h
@@ -83,6 +83,8 @@ public:
 
     virtual void finishInit();
 
+    virtual void notifyStartupComplete();
+
     virtual RecoveryUnit* newRecoveryUnit();
 
     virtual void listDatabases(std::vector<std::string>* out) const;
diff --git a/src/mongo/db/storage/storage_engine.h b/src/mongo/db/storage/storage_engine.h
index e63437f97b1..ed73b248d45 100644
--- a/src/mongo/db/storage/storage_engine.h
+++ b/src/mongo/db/storage/storage_engine.h
@@ -153,6 +153,20 @@ public:
     virtual void finishInit() {}
 
     /**
+     * During the startup process, the storage engine is one of the first components to be started
+     * up and fully initialized. But that fully initialized storage engine may not be recognized as
+     * the end for the remaining storage startup tasks that still need to be performed.
+     *
+     * For example, after the storage engine has been fully initialized, we need to access it in
+     * order to set up all of the collections and indexes based on the metadata, or perform some
+     * corrective measures on the data files, etc.
+     *
+     * When all of the storage startup tasks are completed as a whole, then this function is called
+     * by the external force managing the startup process.
+     */
+    virtual void notifyStartupComplete() {}
+
+    /**
      * Returns a new interface to the storage engine's recovery unit.  The recovery
      * unit is the durability interface.  For details, see recovery_unit.h
      *
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp
index 0e1fb9b1b43..d87094e0fa1 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp
@@ -641,6 +641,10 @@ WiredTigerKVEngine::~WiredTigerKVEngine() {
     _sessionCache.reset(NULL);
 }
 
+void WiredTigerKVEngine::notifyStartupComplete() {
+    WiredTigerUtil::notifyStartupComplete();
+}
+
 void WiredTigerKVEngine::appendGlobalStats(BSONObjBuilder& b) {
     BSONObjBuilder bb(b.subobjStart("concurrentTransactions"));
     {
@@ -724,6 +728,8 @@ void WiredTigerKVEngine::_openWiredTiger(const std::string& path, const std::str
 
 void WiredTigerKVEngine::cleanShutdown() {
     log() << "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 ad0b18a5c1f..31c138cc938 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.h
@@ -81,6 +81,8 @@ public:
 
     virtual ~WiredTigerKVEngine();
 
+    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 5ecd65fa828..d1602b24024 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine_test.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine_test.cpp
@@ -61,6 +61,7 @@ public:
             getGlobalServiceContext(),
             std::unique_ptr<repl::ReplicationCoordinator>(new repl::ReplicationCoordinatorMock(
                 getGlobalServiceContext(), repl::ReplSettings())));
+        _engine->notifyStartupComplete();
     }
 
     virtual ~WiredTigerKVHarnessHelper() {
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 47d5fcebbe7..9a9a7e48efa 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
@@ -88,6 +88,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 54b4346008a..649189876d5 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
@@ -88,6 +88,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 9b328f7ff46..b274d85e44b 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_util.cpp
@@ -53,6 +53,9 @@ namespace mongo {
 
 using std::string;
 
+stdx::mutex WiredTigerUtil::_tableLoggingInfoMutex;
+WiredTigerUtil::TableLoggingInfo WiredTigerUtil::_tableLoggingInfo;
+
 Status wtRCToStatus_slow(int retCode, const char* prefix) {
     if (retCode == 0)
         return Status::OK();
@@ -533,6 +536,22 @@ int WiredTigerUtil::verifyTable(OperationContext* opCtx,
     return (session->verify)(session, uri.c_str(), NULL);
 }
 
+void WiredTigerUtil::notifyStartupComplete() {
+    stdx::lock_guard<stdx::mutex> lk(_tableLoggingInfoMutex);
+    invariant(_tableLoggingInfo.isInitializing);
+    _tableLoggingInfo.isInitializing = false;
+
+    if (!_tableLoggingInfo.isFirstTable) {
+        // Only log this if there were existing tables during startup.
+        log() << "Finished adjusting the table logging settings for existing WiredTiger tables";
+    }
+}
+
+void WiredTigerUtil::resetTableLoggingInfo() {
+    stdx::lock_guard<stdx::mutex> lk(_tableLoggingInfoMutex);
+    _tableLoggingInfo = TableLoggingInfo();
+}
+
 bool WiredTigerUtil::useTableLogging(NamespaceString ns, bool replEnabled) {
     if (!replEnabled) {
         // All tables on standalones are logged.
@@ -571,6 +590,14 @@ Status WiredTigerUtil::setTableLogging(OperationContext* opCtx, const std::strin
 }
 
 Status WiredTigerUtil::setTableLogging(WT_SESSION* session, const std::string& uri, bool on) {
+    {
+        stdx::lock_guard<stdx::mutex> lk(_tableLoggingInfoMutex);
+        if (_tableLoggingInfo.isFirstTable && _tableLoggingInfo.isInitializing) {
+            log() << "Starting to check the table logging settings for existing WiredTiger tables";
+            _tableLoggingInfo.isFirstTable = false;
+        }
+    }
+
     std::string setting;
     if (on) {
         setting = "log=(enabled=true)";
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_util.h b/src/mongo/db/storage/wiredtiger/wiredtiger_util.h
index 68c4ba5fb6a..4368458829a 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 = NULL);
 
+    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,12 @@ private:
      */
     template <typename T>
     static T _castStatisticsValue(uint64_t statisticsValue, T maximumResultType);
+
+    static stdx::mutex _tableLoggingInfoMutex;
+    static struct TableLoggingInfo {
+        bool isInitializing = true;
+        bool isFirstTable = true;
+    } _tableLoggingInfo;
 };
 
 class WiredTigerConfigParser {