log: cache recent threads up to a day

In general, a pthread implementation reuses thread ids routinely so the
circular_buffer is there to help us see what the thread name was historically
(capped at 4 entries).

However, to guard against this map from growing without bound, discard entries
that are more than a day old. This would happen if a thread logged an Entry and
has since disappeared for more than a day.

Signed-off-by: Patrick Donnelly <[email protected]>

Author: batrick

src/log/Log.cc

@@ -373,6 +373,7 @@ void Log::_flush_logbuf()
 
 void Log::_flush(EntryVector& t, bool crash)
 {
+  auto now = mono_clock::now();
   long len = 0;
   if (t.empty()) {
     assert(m_log_buf.empty());
@@ -444,10 +445,29 @@ void Log::_flush(EntryVector& t, bool crash)
       m_journald->log_entry(e);
     }
 
+    {
+      auto [it, _] = m_recent_thread_names.try_emplace(e.m_thread, now, DEFAULT_MAX_THREAD_NAMES);
+      auto& [t, names] = it->second;
+      if (names.size() == 0 || names.front() != e.m_thread_name.data()) {
+        names.push_front(e.m_thread_name.data());
+      }
+      t = now;
+    }
+
     m_recent.push_back(std::move(e));
   }
   t.clear();
 
+  for (auto it = m_recent_thread_names.begin(); it != m_recent_thread_names.end(); ) {
+    auto t = it->second.first;
+    auto since = now - t;
+    if (since > std::chrono::seconds(60*60*24)) {
+      it = m_recent_thread_names.erase(it);
+    } else {
+      ++it;
+    }
+  }
+
   _flush_logbuf();
 }
 
@@ -494,15 +514,10 @@ void Log::dump_recent()
   _flush(m_flush, false);
 
   _log_message("--- begin dump of recent events ---", true);
-  std::map<pthread_t, std::set<std::string> > recent_pthread_ids;
   {
     EntryVector t;
     t.insert(t.end(), std::make_move_iterator(m_recent.begin()), std::make_move_iterator(m_recent.end()));
     m_recent.clear();
-    for (const auto& e : t) {
-      auto& set = recent_pthread_ids[e.m_thread];
-      set.insert(e.m_thread_name.data());
-    }
     _flush(t, true);
   }
 
@@ -517,13 +532,14 @@ void Log::dump_recent()
 			   m_stderr_log, m_stderr_crash), true);
 
   _log_message("--- pthread ID / name mapping for recent threads ---", true);
-  for (const auto& [pthread_id, pthread_names] : recent_pthread_ids)
+  for (const auto& [tid, t_names] : m_recent_thread_names)
   {
+    [[maybe_unused]] auto [t, names] = t_names;
     // we want the ID to be printed in the same format as we use for a log entry.
     // The reason is easier grepping.
     auto msg = fmt::format("  {:x} / {}",
-      tid_to_int(pthread_id),
-      fmt::join(pthread_names, ", "));
+      tid_to_int(tid),
+      fmt::join(names, ", "));
     _log_message(msg, true);
   }
 

src/log/Log.h

@@ -7,13 +7,15 @@
 #include <boost/circular_buffer.hpp>
 
 #include <condition_variable>
+#include <map>
 #include <memory>
 #include <mutex>
 #include <queue>
 #include <string>
 #include <string_view>
 
 #include "common/Thread.h"
+#include "common/ceph_time.h"
 #include "common/likely.h"
 
 #include "log/Entry.h"
@@ -86,9 +88,14 @@ class Log : private Thread
 
 private:
   using EntryRing = boost::circular_buffer<ConcreteEntry>;
+  using mono_clock = ceph::coarse_mono_clock;
+  using mono_time = ceph::coarse_mono_time;
+
+  using RecentThreadNames = std::map<pthread_t, std::pair<mono_time, boost::circular_buffer<std::string> > >;
 
   static const std::size_t DEFAULT_MAX_NEW = 100;
   static const std::size_t DEFAULT_MAX_RECENT = 10000;
+  static constexpr std::size_t DEFAULT_MAX_THREAD_NAMES = 4;
 
   Log **m_indirect_this;
 
@@ -102,6 +109,7 @@ class Log : private Thread
   pthread_t m_queue_mutex_holder;
   pthread_t m_flush_mutex_holder;
 
+  RecentThreadNames m_recent_thread_names; // protected by m_flush_mutex
   EntryVector m_new;    ///< new entries
   EntryRing m_recent; ///< recent (less new) entries we've already written at low detail
   EntryVector m_flush; ///< entries to be flushed (here to optimize heap allocations)