log: use PrebufferedStreambuf

It's faster than ostringstream!

Signed-off-by: Sage Weil <sage@newdream.net>

2 files changed, 56 insertions, 29 deletions

diff --git a/src/log/Entry.h b/src/log/Entry.h
index 5dde3dfd6b3..138d1221832 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 <pthread.h>
 #include <string>
 
+#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 d224bd813a3..03c03cd1c7a 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;
       }
     }