log: Use log_clock, defaulting to coarse time

Signed-off-by: Adam C. Emerson <aemerson@redhat.com>

diff --git a/src/common/Graylog.cc b/src/common/Graylog.cc
index 936605172df31b3f9378298379201a514e25b05f..b5fb2014a41c160f5f5655235d3abc409af1c351 100644 (file)
--- a/src/common/Graylog.cc
+++ b/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)

diff --git a/src/log/Entry.h b/src/log/Entry.h
index 7e2f83401ae6120f3425f3f40c7d14701a98f10b..d5c23233ee64b5c90fba94f195c4fedc3b0a4bb2 100644 (file)
--- a/src/log/Entry.h
+++ b/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;
   }
 

diff --git a/src/log/Log.cc b/src/log/Log.cc
index e8d7ec00e8e506eb6a2812f925e70d49c707dcc1..c190363d7c5fe9862d083c3c3df05f1076afcfae 100644 (file)
--- a/src/log/Log.cc
+++ b/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()
 {
@@ -225,13 +232,13 @@ void Log::submit_entry(Entry *e)
 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, 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);
 

diff --git a/src/log/Log.h b/src/log/Log.h
index c977ee8e358ede6688602f099053d9320892f0fe..9d3c6b31baf3a09202ebaa67e42e3c5c7f12429f 100644 (file)
--- a/src/log/Log.h
+++ b/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);

diff --git a/src/log/test.cc b/src/log/test.cc
index d423e4125b9e30781bd52125b85e2f34f911f78c..6ec9e751b7e79e2402c4ae68810b4bce6be695c2 100644 (file)
--- a/src/log/test.cc
+++ b/src/log/test.cc
@@ -229,3 +229,25 @@ TEST(Log, LargeLog)
   log.flush();
   log.stop();
 }
+
+// Make sure nothing bad happens when we switch
+
+TEST(Log, TimeSwitch)
+{
+  SubsystemMap subs;
+  subs.add(1, "foo", 20, 10);
+  Log log(&subs);
+  log.start();
+  log.set_log_file("/tmp/time_switch_log");
+  log.reopen_log_file();
+  int l = 10;
+  bool coarse = true;
+  for (auto i = 0U; i < 300; ++i) {
+    log.submit_entry(
+      log.create_entry(l, 1, "SQUID THEFT! PUNISHABLE BY DEATH!"));
+    if (i % 50)
+      log.set_coarse_timestamps(coarse = !coarse);
+  }
+  log.flush();
+  log.stop();
+}