From 31de198955695a7003c454fde503dfe66c9da860 Mon Sep 17 00:00:00 2001 From: "Adam C. Emerson" Date: Thu, 5 Oct 2017 18:30:56 -0400 Subject: [PATCH] log: Use log_clock, defaulting to coarse time Signed-off-by: Adam C. Emerson --- src/common/Graylog.cc | 3 ++- src/log/Entry.h | 14 +++++++------- src/log/Log.cc | 17 ++++++++++++----- src/log/Log.h | 4 +++- src/log/test.cc | 22 ++++++++++++++++++++++ 5 files changed, 46 insertions(+), 14 deletions(-) diff --git a/src/common/Graylog.cc b/src/common/Graylog.cc index 936605172df..b5fb2014a41 100644 --- 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 7e2f83401ae..d5c23233ee6 100644 --- 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 #include +#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 e8d7ec00e8e..c190363d7c5 100644 --- 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(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 c977ee8e358..9d3c6b31baf 100644 --- 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 d423e4125b9..6ec9e751b7e 100644 --- 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(); +} -- 2.39.5