PSMDB-810 improve logging #695

igorsol · 2021-02-12T17:24:45Z

No description provided.

akira-kurogane

Hi Igor. As you suggested in our slack chat, I think the special logging should be a log level 0.

akira-kurogane

Thanks for changing the log level to 0 Igor.

I have some edit suggestions again though sorry.

akira-kurogane · 2021-02-16T05:41:28Z

src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp

+        log() << "Hot backup copying {} bytes from '{}' to '{}'"_format(
+            fsize, srcFile.string(), destFile.string());


Suggested change

log() << "Hot backup copying {} bytes from '{}' to '{}'"_format(

fsize, srcFile.string(), destFile.string());

log() << "Beginning copy of {}/{} files in backup snapshot: {}, {} bytes"_format(

fcCtr++, filesList.size(), srcFile.filename(), fsize);

(The fcCtr variable needs to be defined just a bit above of course.)

As for the destFile I think the destination directory only needs to be shown once as the backup process begins. (The destination incidentally also appears in the argument values of the "command: createBackup" log message when it finishes.)

I wish we could print the user-recognizable collection or index namespace string, when a file is a user-data table, but I don't find a map of "idents" -> namespaces. Only private member "NSToIdentMap _idents;" in the DurableCatalogImpl class, so we'd also have to change that class to access.

pull request updated

akira-kurogane · 2021-02-16T05:49:11Z

src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp

+        } else {
+            log() << "Source file size is: {} bytes"_format(fs::file_size(srcFile));
+        }
+


Suggested change

} else {

log() << "Source file size is: {} bytes"_format(fs::file_size(srcFile));

}

}

Truncating the byte size log line from here because the preceding edit suggestion would include it there.

My idea was to show current size of the file. It may be different from the size reported in another message (that size is captured when file list is generated)

Thanks for catching the fcCtr increment bug.

Regarding showing the size of the file it is true, it might become notably bigger during the backup. And that is so interesting to DBAs worried about file size growth that I first drafted an edit where it would warn() (not log) if the file size had grown (> +10% && > +100MB).

I don't think it's helpful for users to just be informed what the size is if it is not the same size as what is copied. I think they will see it as an error and report it.

But then I discarded that draft because the $backupCursor work will probably require us doing this all again, didn't seem worthwhile now.

akira-kurogane · 2021-02-16T23:08:09Z

src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp

+        } else {
+            log() << "Source file size is: {} bytes"_format(fs::file_size(srcFile));
+        }
+


Thanks for catching the fcCtr increment bug.

akira-kurogane · 2021-02-16T23:20:18Z

src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp

+        } else {
+            log() << "Source file size is: {} bytes"_format(fs::file_size(srcFile));
+        }
+


Regarding showing the size of the file it is true, it might become notably bigger during the backup. And that is so interesting to DBAs worried about file size growth that I first drafted an edit where it would warn() (not log) if the file size had grown (> +10% && > +100MB).

I don't think it's helpful for users to just be informed what the size is if it is not the same size as what is copied. I think they will see it as an error and report it.

But then I discarded that draft because the $backupCursor work will probably require us doing this all again, didn't seem worthwhile now.

Copilot

Pull Request Overview

This PR improves logging in the WiredTiger storage engine's hot backup functionality by adding detailed progress tracking and enhanced error reporting. The changes provide better visibility into backup operations and more informative error messages when issues occur.

Adds progress logging showing current file copy status with file counts and sizes
Enhances error handling with detailed context including file paths and error codes
Improves file stream management by ensuring proper closure

_{Tip: Customize your code reviews with copilot-instructions.md. Create the file or learn how to get started.
You can also share your feedback on Copilot code review for a chance to win a $100 gift card. Take the survey.}

Copilot · 2025-08-19T12:51:03Z

src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp

@@ -1491,6 +1491,8 @@ static void copy_file_size(const boost::filesystem::path& srcFile, const boost::
        dst.write(bufptr, cnt);
        fsize -= cnt;
    }
+
+    dst.close();


The dst.close() call is redundant and potentially problematic. The ofstream destructor will automatically close the file when the function exits, and calling close() explicitly here could mask exceptions that occur during the write operations since close() is called outside the try-catch block that handles the file operations.

Suggested change

dst.close();

Copilot · 2025-08-19T12:51:04Z

src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp

+        if (!fs::exists(srcFile)) {
+            log() << "Source file does not exist: {}"_format(srcFile.string());
+        } else {
+            log() << "Source file size is: {} bytes"_format(fs::file_size(srcFile));


The fs::file_size() call can throw an exception if the file doesn't exist or there are permission issues, but it's not wrapped in a try-catch block. This could cause the backup operation to fail unexpectedly. Consider wrapping this call in a try-catch block or checking file existence first.

Suggested change

log() << "Source file size is: {} bytes"_format(fs::file_size(srcFile));

try {

log() << "Source file size is: {} bytes"_format(fs::file_size(srcFile));

} catch (const fs::filesystem_error& ex) {

log() << "Could not get source file size for '{}': {}"_format(srcFile.string(), ex.what());

}

Copilot · 2025-08-19T12:51:04Z

src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp

    for (auto&& file : filesList) {
        fs::path srcFile{std::get<0>(file)};
        fs::path destFile{std::get<1>(file)};
        auto fsize{std::get<2>(file)};

+        log() << "Beginning copy of {}/{} files in backup snapshot: {}, {} bytes"_format(
+            ++fcCtr, filesList.size(), srcFile.string(), fsize);


[nitpick] Logging every file copy operation could generate excessive log output for large backups with many files. Consider using a higher log level (e.g., debug) or throttling the logging to only show progress at intervals (e.g., every 100 files or every 10%).

Suggested change

++fcCtr, filesList.size(), srcFile.string(), fsize);

LOG(1) << "Beginning copy of " << (fcCtr + 1) << "/" << filesList.size()

<< " files in backup snapshot: " << srcFile.string() << ", " << fsize << " bytes";

if ((fcCtr % 100 == 0) || (fcCtr + 1 == filesList.size())) {

log() << "Backup progress: copying file " << (fcCtr + 1) << " of " << filesList.size();

}

++fcCtr;

Can you focus on improving log messages so they are more user / support friendly?

igorsol added 2 commits February 12, 2021 19:15

PSMDB-810 explicitly close destination file to avoid error swallowing

598a093

PSMDB-810 output more information in case of exception while copying

bec98c3

akira-kurogane reviewed Feb 15, 2021

View reviewed changes

igorsol force-pushed the psmdb-810 branch from d958235 to 0157ba8 Compare February 15, 2021 10:13

akira-kurogane suggested changes Feb 16, 2021

View reviewed changes

PSMDB-810 log more info during hot backup

3dd2a6e

igorsol force-pushed the psmdb-810 branch from 0157ba8 to 3dd2a6e Compare February 16, 2021 16:39

akira-kurogane approved these changes Feb 17, 2021

View reviewed changes

igorsol added v4.2 enhancement labels Jul 13, 2023

radoslawszulgo requested a review from Copilot August 19, 2025 12:49

Copilot AI reviewed Aug 19, 2025

View reviewed changes

		log() << "Hot backup copying {} bytes from '{}' to '{}'"_format(
		fsize, srcFile.string(), destFile.string());

-            ++fcCtr, filesList.size(), srcFile.string(), fsize);
+        LOG(1) << "Beginning copy of " << (fcCtr + 1) << "/" << filesList.size()
+               << " files in backup snapshot: " << srcFile.string() << ", " << fsize << " bytes";
+        if ((fcCtr % 100 == 0) || (fcCtr + 1 == filesList.size())) {
+            log() << "Backup progress: copying file " << (fcCtr + 1) << " of " << filesList.size();
+        }
+        ++fcCtr;

PSMDB-810 improve logging #695

Are you sure you want to change the base?

PSMDB-810 improve logging #695

Uh oh!

Conversation

igorsol commented Feb 12, 2021

Uh oh!

akira-kurogane left a comment

Choose a reason for hiding this comment

Uh oh!

akira-kurogane left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Pull Request Overview

Uh oh!

Copilot AI Aug 19, 2025

Choose a reason for hiding this comment

Uh oh!

Copilot AI Aug 19, 2025

Choose a reason for hiding this comment

Uh oh!

Copilot AI Aug 19, 2025

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!