Log detailed messages when flipping between blocking/un-blocking write operations.

2 files changed, 87 insertions, 38 deletions

diff --git a/searchcore/src/tests/proton/server/disk_mem_usage_filter/disk_mem_usage_filter_test.cpp b/searchcore/src/tests/proton/server/disk_mem_usage_filter/disk_mem_usage_filter_test.cpp
index a08a64cea8c..5d8a647f675 100644
--- a/searchcore/src/tests/proton/server/disk_mem_usage_filter/disk_mem_usage_filter_test.cpp
+++ b/searchcore/src/tests/proton/server/disk_mem_usage_filter/disk_mem_usage_filter_test.cpp
@@ -74,10 +74,9 @@ TEST_F("Check that disk limit can be reached", Fixture)
     f.triggerDiskLimit();
     f.testWrite("diskLimitReached: { "
                 "action: \"add more content nodes\", "
-                "reason: \""
-                "disk used (0.9) > disk limit (0.8)"
-                "\", "
-                "capacity: 100, free: 20, available: 10, diskLimit: 0.8}");
+                "reason: \"disk used (0.9) > disk limit (0.8)\", "
+                "stats: { "
+                "capacity: 100, free: 20, available: 10, diskUsed: 0.9, diskLimit: 0.8}}");
 }
 
 TEST_F("Check that memory limit can be reached", Fixture)
@@ -86,12 +85,11 @@ TEST_F("Check that memory limit can be reached", Fixture)
     f.triggerMemoryLimit();
     f.testWrite("memoryLimitReached: { "
                 "action: \"add more content nodes\", "
-                "reason: \""
-                "memory used (0.875) > memory limit (0.8)"
-                "\", "
+                "reason: \"memory used (0.875) > memory limit (0.8)\", "
+                "stats: { "
                 "mapped: { virt: 58720259, rss: 58720258}, "
                 "anonymous: { virt: 58720257, rss: 58720256}, "
-                "physicalMemory: 67108864, memoryLimit : 0.8}");
+                "physicalMemory: 67108864, memoryUsed: 0.875, memoryLimit: 0.8}}");
 }
 
 TEST_F("Check that both disk limit and memory limit can be reached", Fixture)
@@ -101,18 +99,16 @@ TEST_F("Check that both disk limit and memory limit can be reached", Fixture)
     f.triggerDiskLimit();
     f.testWrite("memoryLimitReached: { "
                 "action: \"add more content nodes\", "
-                "reason: \""
-                "memory used (0.875) > memory limit (0.8)"
-                "\", "
+                "reason: \"memory used (0.875) > memory limit (0.8)\", "
+                "stats: { "
                 "mapped: { virt: 58720259, rss: 58720258}, "
                 "anonymous: { virt: 58720257, rss: 58720256}, "
-                "physicalMemory: 67108864, memoryLimit : 0.8}, "
+                "physicalMemory: 67108864, memoryUsed: 0.875, memoryLimit: 0.8}}, "
                 "diskLimitReached: { "
                 "action: \"add more content nodes\", "
-                "reason: \""
-                "disk used (0.9) > disk limit (0.8)"
-                "\", "
-                "capacity: 100, free: 20, available: 10, diskLimit: 0.8}");
+                "reason: \"disk used (0.9) > disk limit (0.8)\", "
+                "stats: { "
+                "capacity: 100, free: 20, available: 10, diskUsed: 0.9, diskLimit: 0.8}}");
 }
 
 TEST_MAIN() { TEST_RUN_ALL(); }
diff --git a/searchcore/src/vespa/searchcore/proton/server/disk_mem_usage_filter.cpp b/searchcore/src/vespa/searchcore/proton/server/disk_mem_usage_filter.cpp
index 907a79250e1..d489f477df2 100644
--- a/searchcore/src/vespa/searchcore/proton/server/disk_mem_usage_filter.cpp
+++ b/searchcore/src/vespa/searchcore/proton/server/disk_mem_usage_filter.cpp
@@ -2,30 +2,55 @@
 
 #include "disk_mem_usage_filter.h"
 #include "i_disk_mem_usage_listener.h"
+#include <vespa/log/log.h>
+
+LOG_SETUP(".proton.server.disk_mem_usage_filter");
 
 namespace proton {
 
 namespace {
 
 void
+makeMemoryStatsMessage(std::ostream &os,
+                       double memoryUsed,
+                       double memoryLimit,
+                       const vespalib::ProcessMemoryStats &memoryStats,
+                       uint64_t physicalMemory)
+{
+    os << "stats: { ";
+    os << "mapped: { virt: " << memoryStats.getMappedVirt() << ", rss: " << memoryStats.getMappedRss() << "}, ";
+    os << "anonymous: { virt: " << memoryStats.getAnonymousVirt() << ", rss: " << memoryStats.getAnonymousRss() << "}, ";
+    os << "physicalMemory: " << physicalMemory << ", ";
+    os << "memoryUsed: " << memoryUsed << ", ";
+    os << "memoryLimit: " << memoryLimit << "}";
+}
+
+void
 makeMemoryLimitMessage(std::ostream &os,
                        double memoryUsed,
                        double memoryLimit,
                        const vespalib::ProcessMemoryStats &memoryStats,
                        uint64_t physicalMemory)
 {
-    os << "memoryLimitReached: { "
-            "action: \"add more content nodes\", "
-            "reason: \""
-            "memory used (" << memoryUsed << ") > "
-            "memory limit (" << memoryLimit << ")"
-            "\", mapped: { virt: " <<
-            memoryStats.getMappedVirt() << ", rss: " <<
-            memoryStats.getMappedRss() << "}, anonymous: { virt: " <<
-            memoryStats.getAnonymousVirt() << ", rss: " <<
-            memoryStats.getAnonymousRss() << "}, physicalMemory: " <<
-            physicalMemory << ", memoryLimit : " <<
-            memoryLimit << "}";
+    os << "memoryLimitReached: { ";
+    os << "action: \"add more content nodes\", ";
+    os << "reason: \"memory used (" << memoryUsed << ") > memory limit (" << memoryLimit << ")\", ";
+    makeMemoryStatsMessage(os, memoryUsed, memoryLimit, memoryStats, physicalMemory);
+    os << "}";
+}
+
+void
+makeDiskStatsMessage(std::ostream &os,
+                     double diskUsed,
+                     double diskLimit,
+                     const DiskMemUsageFilter::space_info &diskStats)
+{
+    os << "stats: { ";
+    os << "capacity: " << diskStats.capacity << ", ";
+    os << "free: " << diskStats.free << ", ";
+    os << "available: " << diskStats.available << ", ";
+    os << "diskUsed: " << diskUsed << ", ";
+    os << "diskLimit: " << diskLimit << "}";
 }
 
 void
@@ -34,16 +59,31 @@ makeDiskLimitMessage(std::ostream &os,
                      double diskLimit,
                      const DiskMemUsageFilter::space_info &diskStats)
 {
-    os << "diskLimitReached: { "
-            "action: \"add more content nodes\", "
-            "reason: \""
-            "disk used (" << diskUsed << ") > "
-            "disk limit (" << diskLimit << ")"
-            "\", capacity: " <<
-            diskStats.capacity << ", free: " <<
-            diskStats.free << ", available: " <<
-            diskStats.available << ", diskLimit: " <<
-            diskLimit << "}";
+    os << "diskLimitReached: { ";
+    os << "action: \"add more content nodes\", ";
+    os << "reason: \"disk used (" << diskUsed << ") > disk limit (" << diskLimit << ")\", ";
+    makeDiskStatsMessage(os, diskUsed, diskLimit, diskStats);
+    os << "}";
+}
+
+
+vespalib::string
+makeUnblockingMessage(double memoryUsed,
+                      double memoryLimit,
+                      const vespalib::ProcessMemoryStats &memoryStats,
+                      uint64_t physicalMemory,
+                      double diskUsed,
+                      double diskLimit,
+                      const DiskMemUsageFilter::space_info &diskStats)
+{
+    std::ostringstream os;
+    os << "memoryLimitOK: { ";
+    makeMemoryStatsMessage(os, memoryUsed, memoryLimit, memoryStats, physicalMemory);
+    os << "}, ";
+    os << "diskLimitOK: { ";
+    makeDiskStatsMessage(os, diskUsed, diskLimit, diskStats);
+    os << "}";
+    return os.str();
 }
 
 }
@@ -68,9 +108,22 @@ DiskMemUsageFilter::recalcState(const Guard &guard)
         makeDiskLimitMessage(message, diskUsed, _config._diskLimit, _diskStats);
     }
     if (hasMessage) {
+        if (_acceptWrite) {
+            LOG(warning, "Write operations are now blocked: '%s'", message.str().c_str());
+        }
         _state = State(false, message.str());
         _acceptWrite = false;
     } else {
+        if (!_acceptWrite) {
+            vespalib::string unblockMsg = makeUnblockingMessage(memoryUsed,
+                                                                _config._memoryLimit,
+                                                                _memoryStats,
+                                                                _physicalMemory,
+                                                                diskUsed,
+                                                                _config._diskLimit,
+                                                                _diskStats);
+            LOG(info, "Write operations are now un-blocked: '%s'", unblockMsg.c_str());
+        }
         _state = State();
         _acceptWrite = true;
     }