Merge pull request #18141 from adamemerson/wip-log-time

log: Use the coarse real time clock in log timestamps

Reviewed-by: Sage Weil <sage@redhat.com>
Reviewed-by: Kefu Chai <kchai@redhat.com>

src/common/Graylog.cc

@@ -77,7 +77,8 @@ void Graylog::log_entry(Entry const * const e)
     m_formatter->dump_string("host", m_hostname);
     m_formatter->dump_string("short_message", s);
     m_formatter->dump_string("_app", "ceph");
-    m_formatter->dump_float("timestamp", e->m_stamp.sec() + (e->m_stamp.usec() / 1000000.0));
+    auto t = ceph::logging::log_clock::to_timeval(e->m_stamp);
+    m_formatter->dump_float("timestamp", t.tv_sec + (t.tv_usec / 1000000.0));
     m_formatter->dump_unsigned("_thread", (uint64_t)e->m_thread);
     m_formatter->dump_int("_level", e->m_prio);
     if (m_subs != NULL)

src/common/ceph_context.cc

@@ -208,6 +208,7 @@ class LogObs : public md_config_obs_t {
       "err_to_graylog",
       "log_graylog_host",
       "log_graylog_port",
+      "log_coarse_timestamps",
       "fsid",
       "host",
       NULL
@@ -260,6 +261,10 @@ class LogObs : public md_config_obs_t {
       log->graylog()->set_destination(conf->log_graylog_host, conf->log_graylog_port);
     }
 
+    if (changed.find("log_coarse_timestamps") != changed.end()) {
+      log->set_coarse_timestamps(conf->_get_val<bool>("log_coarse_timestamps"));
+    }
+
     // metadata
     if (log->graylog() && changed.count("host")) {
       log->graylog()->set_hostname(conf->host);

src/common/ceph_time.cc

@@ -14,6 +14,7 @@
 
 // For ceph_timespec
 #include "ceph_time.h"
+#include "log/LogClock.h"
 #include "config.h"
 
 #if defined(__APPLE__)
@@ -80,6 +81,7 @@ namespace ceph {
       const struct ceph_timespec& ts) {
       return time_point(seconds(ts.tv_sec) + nanoseconds(ts.tv_nsec));
     }
+
   }
 
   using std::chrono::duration_cast;

src/common/config.cc

@@ -726,8 +726,16 @@ void md_config_t::_apply_changes(std::ostream *oss)
 void md_config_t::call_all_observers()
 {
   std::map<md_config_obs_t*,std::set<std::string> > obs;
+  // Have the scope of the lock extend to the scope of
+  // handle_conf_change since that function expects to be called with
+  // the lock held. (And the comment in config.h says that is the
+  // expected behavior.)
+  //
+  // An alternative might be to pass a std::unique_lock to
+  // handle_conf_change and have a version of get_var that can take it
+  // by reference and lock as appropriate.
+  Mutex::Locker l(lock);
   {
-    Mutex::Locker l(lock);
 
     expand_all_meta();
 

src/common/config.h

@@ -162,6 +162,7 @@ struct md_config_t {
   int _get_val(const std::string &key, char **buf, int len) const;
   Option::value_t get_val_generic(const std::string &key) const;
   template<typename T> T get_val(const std::string &key) const;
+  template<typename T> T _get_val(const std::string &key) const;
 
   void get_all_keys(std::vector<std::string> *keys) const;
 
@@ -338,6 +339,12 @@ template<typename T> T md_config_t::get_val(const std::string &key) const {
   return boost::apply_visitor(gtv, generic_val);
 }
 
+template<typename T> T md_config_t::_get_val(const std::string &key) const {
+  Option::value_t generic_val = this->_get_val(key);
+  get_typed_value_visitor<T> gtv;
+  return boost::apply_visitor(gtv, generic_val);
+}
+
 inline std::ostream& operator<<(std::ostream& o, const boost::blank& ) {
       return o << "INVALID_CONFIG_VALUE";
 }

src/common/options.cc

@@ -389,6 +389,13 @@ std::vector<Option> get_global_options() {
     .set_description("port number for the remote graylog server")
     .add_see_also("log_graylog_host"),
 
+    Option("log_coarse_timestamps", Option::TYPE_BOOL, Option::LEVEL_ADVANCED)
+    .set_default(true)
+    .set_description("timestamp log entries from coarse system clock "
+		     "to improve performance")
+    .add_service("common")
+    .add_tag("performance")
+    .add_tag("service"),
 
 
     // unmodified

src/log/Entry.h

@@ -4,17 +4,17 @@
 #ifndef __CEPH_LOG_ENTRY_H
 #define __CEPH_LOG_ENTRY_H
 
-#include "include/utime.h"
 #include "common/PrebufferedStreambuf.h"
 #include <pthread.h>
 #include <string>
+#include "log/LogClock.h"
 
 
 namespace ceph {
 namespace logging {
 
 struct Entry {
-  utime_t m_stamp;
+  log_time m_stamp;
   pthread_t m_thread;
   short m_prio, m_subsys;
   Entry *m_next;
@@ -31,7 +31,7 @@ struct Entry {
       m_buf_len(sizeof(m_static_buf)),
       m_exp_len(NULL)
   {}
-  Entry(utime_t s, pthread_t t, short pr, short sub,
+  Entry(log_time s, pthread_t t, short pr, short sub,
   const char *msg = NULL)
       : m_stamp(s), m_thread(t), m_prio(pr), m_subsys(sub),
         m_next(NULL),
@@ -40,11 +40,11 @@ struct Entry {
         m_exp_len(NULL)
     {
       if (msg) {
-        ostream os(&m_streambuf);
+	std::ostream os(&m_streambuf);
         os << msg;
       }
     }
-  Entry(utime_t s, pthread_t t, short pr, short sub, char* buf, size_t buf_len, size_t* exp_len,
+  Entry(log_time s, pthread_t t, short pr, short sub, char* buf, size_t buf_len, size_t* exp_len,
 	const char *msg = NULL)
     : m_stamp(s), m_thread(t), m_prio(pr), m_subsys(sub),
       m_next(NULL),
@@ -53,7 +53,7 @@ struct Entry {
       m_exp_len(exp_len)
   {
     if (msg) {
-      ostream os(&m_streambuf);
+      std::ostream os(&m_streambuf);
       os << msg;
     }
   }
@@ -74,7 +74,7 @@ struct Entry {
   }
 
   void set_str(const std::string &s) {
-    ostream os(&m_streambuf);
+    std::ostream os(&m_streambuf);
     os << s;
   }
 

src/log/Log.cc

@@ -17,6 +17,7 @@
 #include "include/on_exit.h"
 
 #include "Entry.h"
+#include "LogClock.h"
 #include "SubsystemMap.h"
 
 #define DEFAULT_MAX_NEW    100
@@ -94,6 +95,12 @@ Log::~Log()
 
 
 ///
+void Log::set_coarse_timestamps(bool coarse) {
+  if (coarse)
+    clock.coarsen();
+  else
+    clock.refine();
+}
 
 void Log::set_flush_on_exit()
 {
@@ -222,16 +229,16 @@ void Log::submit_entry(Entry *e)
 }
 
 
-Entry *Log::create_entry(int level, int subsys)
+Entry *Log::create_entry(int level, int subsys, const char* msg)
 {
   if (true) {
-    return new Entry(ceph_clock_now(),
+    return new Entry(clock.now(),
 		     pthread_self(),
-		     level, subsys);
+		     level, subsys, msg);
   } else {
     // kludge for perf testing
     Entry *e = m_recent.dequeue();
-    e->m_stamp = ceph_clock_now();
+    e->m_stamp = clock.now();
     e->m_thread = pthread_self();
     e->m_prio = level;
     e->m_subsys = subsys;
@@ -246,13 +253,13 @@ Entry *Log::create_entry(int level, int subsys, size_t* expected_size)
                                "Log hint");
     size_t size = __atomic_load_n(expected_size, __ATOMIC_RELAXED);
     void *ptr = ::operator new(sizeof(Entry) + size);
-    return new(ptr) Entry(ceph_clock_now(),
+    return new(ptr) Entry(clock.now(),
        pthread_self(), level, subsys,
        reinterpret_cast<char*>(ptr) + sizeof(Entry), size, expected_size);
   } else {
     // kludge for perf testing
     Entry *e = m_recent.dequeue();
-    e->m_stamp = ceph_clock_now();
+    e->m_stamp = clock.now();
     e->m_thread = pthread_self();
     e->m_prio = level;
     e->m_subsys = subsys;
@@ -311,7 +318,7 @@ void Log::_flush(EntryQueue *t, EntryQueue *requeue, bool crash)
 
       if (crash)
 	buflen += snprintf(buf, buf_size, "%6d> ", -t->m_len);
-      buflen += e->m_stamp.sprintf(buf + buflen, buf_size-buflen);
+      buflen += append_time(e->m_stamp, buf + buflen, buf_size - buflen);
       buflen += snprintf(buf + buflen, buf_size-buflen, " %lx %2d ",
 			(unsigned long)e->m_thread, e->m_prio);
 

src/log/Log.h

@@ -18,6 +18,7 @@ class Entry;
 class Log : private Thread
 {
   Log **m_indirect_this;
+  log_clock clock;
 
   SubsystemMap *m_subs;
 
@@ -58,11 +59,12 @@ class Log : private Thread
   void _log_message(const char *s, bool crash);
 
 public:
-  explicit Log(SubsystemMap *s);
+  Log(SubsystemMap *s);
   ~Log() override;
 
   void set_flush_on_exit();
 
+  void set_coarse_timestamps(bool coarse);
   void set_max_new(int n);
   void set_max_recent(int n);
   void set_log_file(std::string fn);
@@ -82,7 +84,7 @@ class Log : private Thread
 
   shared_ptr<Graylog> graylog() { return m_graylog; }
 
-  Entry *create_entry(int level, int subsys);
+  Entry *create_entry(int level, int subsys, const char* msg = nullptr);
   Entry *create_entry(int level, int subsys, size_t* expected_size);
   void submit_entry(Entry *e);