From 17a95c223e807cc5e2a008d8ce375319d3f03e13 Mon Sep 17 00:00:00 2001 From: Sage Weil Date: Tue, 27 Mar 2012 10:44:52 -0700 Subject: [PATCH] log: use PrebufferedStreambuf It's faster than ostringstream! Signed-off-by: Sage Weil --- src/Makefile.am | 1 + src/common/dout.h | 5 ++-- src/log/Entry.h | 22 +++++++++++++---- src/log/Log.cc | 63 +++++++++++++++++++++++++++++------------------ 4 files changed, 59 insertions(+), 32 deletions(-) diff --git a/src/Makefile.am b/src/Makefile.am index b77c867ae5b7b..8cc1c3b0d9634 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -931,6 +931,7 @@ libcommon_files = \ auth/RotatingKeyRing.cc \ common/LogClient.cc \ common/LogEntry.cc \ + common/PrebufferedStreambuf.cc \ common/BackTrace.cc \ common/perf_counters.cc \ common/admin_socket.cc \ diff --git a/src/common/dout.h b/src/common/dout.h index f4c317538eee2..e6099315567d6 100644 --- a/src/common/dout.h +++ b/src/common/dout.h @@ -49,9 +49,9 @@ inline std::ostream& operator<<(std::ostream& out, _bad_endl_use_dendl_t) { char __array[((v >= -1) && (v <= 200)) ? 0 : -1] __attribute__((unused)); \ } \ ceph::log::Entry *_dout_e = cct->_log->create_entry(v, sub); \ - ostringstream _dout_ss; \ + ostream _dout_os(&_dout_e->m_streambuf); \ CephContext *_dout_cct = cct; \ - std::ostream* _dout = &_dout_ss; + std::ostream* _dout = &_dout_os; #define lsubdout(cct, sub, v) dout_impl(cct, ceph_subsys_##sub, v) dout_prefix #define ldout(cct, v) dout_impl(cct, dout_subsys, v) dout_prefix @@ -62,7 +62,6 @@ inline std::ostream& operator<<(std::ostream& out, _bad_endl_use_dendl_t) { #define lgeneric_derr(cct) dout_impl(cct, ceph_subsys_, -1) *_dout #define dendl std::flush; \ - _dout_e->m_str = _dout_ss.str(); \ _dout_cct->_log->submit_entry(_dout_e); \ } \ } while (0) diff --git a/src/log/Entry.h b/src/log/Entry.h index 5dde3dfd6b320..138d122183277 100644 --- a/src/log/Entry.h +++ b/src/log/Entry.h @@ -5,9 +5,11 @@ #define __CEPH_LOG_ENTRY_H #include "include/utime.h" +#include "common/PrebufferedStreambuf.h" #include #include +#define CEPH_LOG_ENTRY_PREALLOC 80 namespace ceph { namespace log { @@ -18,16 +20,26 @@ struct Entry { short m_prio, m_subsys; Entry *m_next; - char m_static_buf[80]; - std::string m_str; + char m_static_buf[CEPH_LOG_ENTRY_PREALLOC]; + PrebufferedStreambuf m_streambuf; + Entry() + : m_next(NULL), m_streambuf(m_static_buf, sizeof(m_static_buf)) + {} Entry(utime_t 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) + m_next(NULL), + m_streambuf(m_static_buf, sizeof(m_static_buf)) { - if (msg) - m_str = msg; + if (msg) { + ostream os(&m_streambuf); + os << msg; + } + } + + std::string get_str() const { + return m_streambuf.get_str(); } }; diff --git a/src/log/Log.cc b/src/log/Log.cc index d224bd813a3d6..03c03cd1c7aa7 100644 --- a/src/log/Log.cc +++ b/src/log/Log.cc @@ -17,6 +17,8 @@ #define DEFAULT_MAX_NEW 1000 #define DEFAULT_MAX_RECENT 10000 +#define PREALLOC 1000000 + namespace ceph { namespace log { @@ -55,6 +57,11 @@ Log::Log(SubsystemMap *s) ret = pthread_cond_init(&m_cond, NULL); assert(ret == 0); + + // kludge for prealloc testing + if (false) + for (int i=0; i < PREALLOC; i++) + m_recent.enqueue(new Entry); } Log::~Log() @@ -116,9 +123,19 @@ void Log::submit_entry(Entry *e) Entry *Log::create_entry(int level, int subsys) { - return new Entry(ceph_clock_now(NULL), + if (true) { + return new Entry(ceph_clock_now(NULL), pthread_self(), level, subsys); + } else { + // kludge for perf testing + Entry *e = m_recent.dequeue(); + e->m_stamp = ceph_clock_now(NULL); + e->m_thread = pthread_self(); + e->m_prio = level; + e->m_subsys = subsys; + return e; + } } void Log::flush() @@ -135,40 +152,38 @@ void Log::flush() void Log::_flush(EntryQueue *t, EntryQueue *requeue, bool crash) { Entry *e; + char buf[80]; while ((e = t->dequeue()) != NULL) { unsigned sub = e->m_subsys; - ostringstream ss; - ss << e->m_stamp - << ' ' - << std::hex << e->m_thread << std::dec - << ' ' - << std::setw(2) << std::setfill('0') << e->m_prio << std::setw(0) - /* - << ':' - << std::setiosflags(ios::left) - << std::setw(m_subs->get_max_subsys_len()) << std::setfill(' ') << m_subs->get_name(sub) - << std::setiosflags(ios::right) - */ - << ' '; - - if ((crash || m_subs->get_log_level(sub) >= e->m_prio)) { - if (m_fd >= 0) { - int r = safe_write(m_fd, ss.str().data(), ss.str().size()); + bool do_fd = m_fd >= 0 && (crash || m_subs->get_log_level(sub) >= e->m_prio); + bool do_syslog = (crash ? m_syslog_crash : m_syslog_log) >= e->m_prio; + bool do_stderr = (crash ? m_stderr_crash : m_stderr_log) >= e->m_prio; + + if (do_fd || do_syslog || do_stderr) { + int buflen = e->m_stamp.sprintf(buf, sizeof(buf)); + buflen += sprintf(buf + buflen, " %lx %2d ", + (unsigned long)e->m_thread, e->m_prio); + + // FIXME: this is slow + string s = e->get_str(); + + if (do_fd) { + int r = safe_write(m_fd, buf, buflen); if (r >= 0) - r = safe_write(m_fd, e->m_str.data(), e->m_str.size()); + r = safe_write(m_fd, s.data(), s.size()); if (r >= 0) - r = safe_write(m_fd, "\n", 1); + r = write(m_fd, "\n", 1); if (r < 0) cerr << "problem writing to " << m_log_file << ": " << cpp_strerror(r) << std::endl; } - if ((crash ? m_syslog_crash : m_syslog_log) >= e->m_prio) { - syslog(LOG_USER, "%s%s", ss.str().c_str(), e->m_str.c_str()); + if (do_syslog) { + syslog(LOG_USER, "%s%s", buf, s.c_str()); } - if ((crash ? m_stderr_crash : m_stderr_log) >= e->m_prio) { - cerr << ss.str() << e->m_str << std::endl; + if (do_stderr) { + cerr << buf << s << std::endl; } } -- 2.39.5