SERVER-30831 Log dropped writes at a limited rate when dbCheck health log buffer is full

3 files changed, 52 insertions, 7 deletions

diff --git a/src/mongo/db/concurrency/deferred_writer.cpp b/src/mongo/db/concurrency/deferred_writer.cpp
index 0ffa4a7c353..fe2551bb568 100644
--- a/src/mongo/db/concurrency/deferred_writer.cpp
+++ b/src/mongo/db/concurrency/deferred_writer.cpp
@@ -41,7 +41,7 @@
 namespace mongo {
 
 namespace {
-auto kLogInterval = stdx::chrono::hours(1);
+auto kLogInterval = stdx::chrono::minutes(1);
 }
 
 void DeferredWriter::_logFailure(const Status& status) {
@@ -51,6 +51,16 @@ void DeferredWriter::_logFailure(const Status& status) {
     }
 }
 
+void DeferredWriter::_logDroppedEntry() {
+    _droppedEntries += 1;
+    if (TimePoint::clock::now() - _lastLoggedDrop > kLogInterval) {
+        log() << "Deferred write buffer for " << _nss.toString() << " is full. " << _droppedEntries
+              << " entries have been dropped.";
+        _lastLoggedDrop = stdx::chrono::system_clock::now();
+        _droppedEntries = 0;
+    }
+}
+
 Status DeferredWriter::_makeCollection(OperationContext* opCtx) {
     BSONObjBuilder builder;
     builder.append("create", _nss.coll());
@@ -122,6 +132,7 @@ DeferredWriter::DeferredWriter(NamespaceString nss, CollectionOptions opts, int6
       _maxNumBytes(maxSize),
       _nss(nss),
       _numBytes(0),
+      _droppedEntries(0),
       _lastLogged(TimePoint::clock::now() - kLogInterval) {}
 
 DeferredWriter::~DeferredWriter() {}
@@ -160,6 +171,7 @@ bool DeferredWriter::insertDocument(BSONObj obj) {
     if (_numBytes + obj.objsize() >= _maxNumBytes) {
         // If not, drop it.  We always drop new entries rather than old ones; that way the caller
         // knows at the time of the call that the entry was dropped.
+        _logDroppedEntry();
         return false;
     }
 
@@ -170,4 +182,9 @@ bool DeferredWriter::insertDocument(BSONObj obj) {
     return true;
 }
 
+int64_t DeferredWriter::getDroppedEntries() {
+    return _droppedEntries;
+}
+
+
 }  // namespace mongo
diff --git a/src/mongo/db/concurrency/deferred_writer.h b/src/mongo/db/concurrency/deferred_writer.h
index c6721bff0c2..f4d32abe58c 100644
--- a/src/mongo/db/concurrency/deferred_writer.h
+++ b/src/mongo/db/concurrency/deferred_writer.h
@@ -102,6 +102,11 @@ public:
      */
     bool insertDocument(BSONObj obj);
 
+    /**
+     * Get the number of dropped writes due to a full buffer since the last log
+     */
+    int64_t getDroppedEntries();
+
 private:
     /**
      * Log failure, but only if a certain interval has passed since the last log.
@@ -109,6 +114,12 @@ private:
     void _logFailure(const Status& status);
 
     /**
+     * Log number of entries dropped because of a full buffer. Rate limited and
+     * each successful log resets the counter.
+     */
+    void _logDroppedEntry();
+
+    /**
      * Create the backing collection if it doesn't exist.
      *
      * Return whether creation succeeded.
@@ -153,12 +164,19 @@ private:
     int64_t _numBytes;
 
     /**
+     * The number of deffered entries that have been dropped. Resets when the
+     * rate-limited system log is written out.
+     */
+    int64_t _droppedEntries;
+
+    /**
      * Time we last logged that we can't write to the underlying collection.
      *
      * Ensures we don't flood the log with such entries.
      */
     using TimePoint = stdx::chrono::time_point<stdx::chrono::system_clock>;
     TimePoint _lastLogged;
+    TimePoint _lastLoggedDrop;
 };
 
 }  // namespace mongo
diff --git a/src/mongo/dbtests/deferred_writer.cpp b/src/mongo/dbtests/deferred_writer.cpp
index 6a7641bd033..45be735114a 100644
--- a/src/mongo/dbtests/deferred_writer.cpp
+++ b/src/mongo/dbtests/deferred_writer.cpp
@@ -282,6 +282,10 @@ public:
 
 /**
  * Test that the DeferredWriter rejects documents over the buffer size.
+ * When this happens, check that the logging counter resets after the first
+ * write.
+ * Note: This test assumes that the logging interval is sufficiently large
+ * and that the first dropped write is the ONLY one logged.
  */
 class DeferredWriterTestCap : public DeferredWriterTestBase {
 public:
@@ -294,12 +298,16 @@ public:
         // Keep track of what we add.
         int bytesAdded = 0;
         int nAdded = 0;
-        bool hitCap = false;
+        int nDropped = 0;
 
         ensureEmpty();
         {
             auto gw = getWriter(CollectionOptions(), bufferSize);
             auto writer = gw.get();
+
+            // Start with 0 dropped entries
+            ASSERT_EQ(0, writer->getDroppedEntries());
+
             // Don't let it flush the buffer while we're working.
             Lock::GlobalWrite lock(_opCtx.get());
             for (int i = 0; i < maxDocs; ++i) {
@@ -308,19 +316,21 @@ public:
                 if (bytesAdded + obj.objsize() > bufferSize) {
                     // Should return false when we exceed the buffer size.
                     ASSERT(!writer->insertDocument(obj));
-                    hitCap = true;
+                    ++nDropped;
                 } else {
                     ASSERT(writer->insertDocument(obj));
                     bytesAdded += obj.objsize();
                     ++nAdded;
                 }
+                // Check that the first dropped write (assuming a long
+                // interval) resets the internal counter by 1.
+                if (nDropped >= 1) {
+                    ASSERT_EQ(nDropped, 1 + writer->getDroppedEntries());
+                }
             }
-
-            // These documents should definitely exceed the buffer size.
-            ASSERT(hitCap);
         }
         // Make sure it didn't add any of the rejected documents.
-        ASSERT_EQ(readCollection().size(), (size_t)nAdded);
+        ASSERT_EQ(readCollection().size(), static_cast<size_t>(nAdded));
     }
 };