Merge pull request #1230 from nghttp2/nghttpx-faster-logging

nghttpx: Get rid of std::stringstream from Log

src/shrpx_connection_handler.cc

@@ -613,8 +613,8 @@ void ConnectionHandler::handle_ocsp_complete() {
   auto status = WEXITSTATUS(rstatus);
   if (ocsp_.error || !WIFEXITED(rstatus) || status != 0) {
     LOG(WARN) << "ocsp query command for " << tls_ctx_data->cert_file
-              << " failed: error=" << ocsp_.error << ", rstatus=" << std::hex
-              << rstatus << std::dec << ", status=" << status;
+              << " failed: error=" << ocsp_.error << ", rstatus=" << log::hex
+              << rstatus << log::dec << ", status=" << status;
     ++ocsp_.next;
     proceed_next_cert_ocsp();
     return;

src/shrpx_log.cc

@@ -74,6 +74,44 @@ constexpr const char *SEVERITY_COLOR[] = {
 };
 } // namespace
 
+#ifndef NOTHREADS
+#  ifdef HAVE_THREAD_LOCAL
+namespace {
+thread_local LogBuffer logbuf_;
+} // namespace
+
+namespace {
+LogBuffer *get_logbuf() { return &logbuf_; }
+} // namespace
+#  else  // !HAVE_THREAD_LOCAL
+namespace {
+pthread_key_t lckey;
+pthread_once_t lckey_once = PTHREAD_ONCE_INIT;
+} // namespace
+
+namespace {
+void make_key() { pthread_key_create(&lckey, NULL); }
+} // namespace
+
+LogBuffer *get_logbuf() {
+  pthread_once(&lckey_once, make_key);
+  auto buf = static_cast<LogBuffer *>(pthread_getspecific(lckey));
+  if (!buf) {
+    buf = new LogBuffer();
+    pthread_setspecific(lckey, buf);
+  }
+  return buf;
+}
+#  endif // !HAVE_THREAD_LOCAL
+#else    // NOTHREADS
+namespace {
+LogBuffer *get_logbuf() {
+  static LogBuffer logbuf;
+  return &logbuf;
+}
+} // namespace
+#endif   // NOTHREADS
+
 int Log::severity_thres_ = NOTICE;
 
 void Log::set_severity_level(int severity) { severity_thres_ = severity; }
@@ -106,7 +144,15 @@ int severity_to_syslog_level(int severity) {
 }
 
 Log::Log(int severity, const char *filename, int linenum)
-    : filename_(filename), severity_(severity), linenum_(linenum) {}
+    : buf_(*get_logbuf()),
+      begin_(buf_.data()),
+      end_(begin_ + buf_.size()),
+      last_(begin_),
+      filename_(filename),
+      flags_(0),
+      severity_(severity),
+      linenum_(linenum),
+      full_(false) {}
 
 Log::~Log() {
   int rv;
@@ -127,12 +173,13 @@ Log::~Log() {
 
   if (errorconf.syslog) {
     if (severity_ == NOTICE) {
-      syslog(severity_to_syslog_level(severity_), "[%s] %s",
-             SEVERITY_STR[severity_].c_str(), stream_.str().c_str());
+      syslog(severity_to_syslog_level(severity_), "[%s] %.*s",
+             SEVERITY_STR[severity_].c_str(), static_cast<int>(rleft()),
+             begin_);
     } else {
-      syslog(severity_to_syslog_level(severity_), "[%s] %s (%s:%d)",
-             SEVERITY_STR[severity_].c_str(), stream_.str().c_str(), filename_,
-             linenum_);
+      syslog(severity_to_syslog_level(severity_), "[%s] %.*s (%s:%d)",
+             SEVERITY_STR[severity_].c_str(), static_cast<int>(rleft()), begin_,
+             filename_, linenum_);
     }
 
     return;
@@ -145,11 +192,11 @@ Log::~Log() {
 
   // Error log format: <datetime> <master-pid> <current-pid>
   // <thread-id> <level> (<filename>:<line>) <msg>
-  rv = snprintf(buf, sizeof(buf), "%s %d %d %s %s%s%s (%s:%d) %s\n",
+  rv = snprintf(buf, sizeof(buf), "%s %d %d %s %s%s%s (%s:%d) %.*s\n",
                 lgconf->tstamp->time_iso8601.c_str(), config->pid, lgconf->pid,
                 lgconf->thread_id.c_str(), tty ? SEVERITY_COLOR[severity_] : "",
                 SEVERITY_STR[severity_].c_str(), tty ? "\033[0m" : "",
-                filename_, linenum_, stream_.str().c_str());
+                filename_, linenum_, static_cast<int>(rleft()), begin_);
 
   if (rv < 0) {
     return;
@@ -161,6 +208,156 @@ Log::~Log() {
     ;
 }
 
+Log &Log::operator<<(const std::string &s) {
+  write_seq(std::begin(s), std::end(s));
+  return *this;
+}
+
+Log &Log::operator<<(const StringRef &s) {
+  write_seq(std::begin(s), std::end(s));
+  return *this;
+}
+
+Log &Log::operator<<(const char *s) {
+  write_seq(s, s + strlen(s));
+  return *this;
+}
+
+Log &Log::operator<<(const ImmutableString &s) {
+  write_seq(std::begin(s), std::end(s));
+  return *this;
+}
+
+Log &Log::operator<<(int64_t n) {
+  if (n >= 0) {
+    return *this << static_cast<uint64_t>(n);
+  }
+
+  if (flags_ & fmt_hex) {
+    write_hex(n);
+    return *this;
+  }
+
+  if (full_) {
+    return *this;
+  }
+
+  n *= -1;
+
+  size_t nlen = 0;
+  for (auto t = n; t; t /= 10, ++nlen)
+    ;
+  if (wleft() < 1 /* sign */ + nlen) {
+    full_ = true;
+    return *this;
+  }
+  *last_++ = '-';
+  *last_ += nlen;
+  update_full();
+
+  auto p = last_ - 1;
+  for (; n; n /= 10) {
+    *p-- = (n % 10) + '0';
+  }
+  return *this;
+}
+
+Log &Log::operator<<(uint64_t n) {
+  if (flags_ & fmt_hex) {
+    write_hex(n);
+    return *this;
+  }
+
+  if (full_) {
+    return *this;
+  }
+
+  if (n == 0) {
+    *last_++ = '0';
+    update_full();
+    return *this;
+  }
+  size_t nlen = 0;
+  for (auto t = n; t; t /= 10, ++nlen)
+    ;
+  if (wleft() < nlen) {
+    full_ = true;
+    return *this;
+  }
+
+  last_ += nlen;
+  update_full();
+
+  auto p = last_ - 1;
+  for (; n; n /= 10) {
+    *p-- = (n % 10) + '0';
+  }
+  return *this;
+}
+
+Log &Log::operator<<(double n) {
+  if (full_) {
+    return *this;
+  }
+
+  auto left = wleft();
+  auto rv = snprintf(reinterpret_cast<char *>(last_), left, "%.9f", n);
+  if (rv > static_cast<int>(left)) {
+    full_ = true;
+    return *this;
+  }
+
+  last_ += rv;
+  update_full();
+
+  return *this;
+}
+
+Log &Log::operator<<(long double n) {
+  if (full_) {
+    return *this;
+  }
+
+  auto left = wleft();
+  auto rv = snprintf(reinterpret_cast<char *>(last_), left, "%.9Lf", n);
+  if (rv > static_cast<int>(left)) {
+    full_ = true;
+    return *this;
+  }
+
+  last_ += rv;
+  update_full();
+
+  return *this;
+}
+
+Log &Log::operator<<(bool n) {
+  if (full_) {
+    return *this;
+  }
+
+  *last_++ = n ? '1' : '0';
+  update_full();
+
+  return *this;
+}
+
+Log &Log::operator<<(const void *p) {
+  if (full_) {
+    return *this;
+  }
+
+  write_hex(reinterpret_cast<uintptr_t>(p));
+
+  return *this;
+}
+
+namespace log {
+void hex(Log &log) { log.set_flags(Log::fmt_hex); };
+
+void dec(Log &log) { log.set_flags(Log::fmt_dec); };
+} // namespace log
+
 namespace {
 template <typename OutputIterator>
 std::pair<OutputIterator, OutputIterator> copy(const char *src, size_t srclen,
@@ -696,8 +893,9 @@ void log_chld(pid_t pid, int rstatus, const char *msg) {
 
   LOG(NOTICE) << msg << ": [" << pid << "] exited "
               << (WIFEXITED(rstatus) ? "normally" : "abnormally")
-              << " with status " << std::hex << rstatus << std::oct
-              << "; exit status " << WEXITSTATUS(rstatus)
+              << " with status " << log::hex << rstatus << log::dec
+              << "; exit status "
+              << (WIFEXITED(rstatus) ? WEXITSTATUS(rstatus) : 0)
               << (signalstr.empty() ? "" : signalstr.c_str());
 }
 

src/shrpx_log.h

@@ -29,7 +29,6 @@
 
 #include <sys/types.h>
 
-#include <sstream>
 #include <memory>
 #include <vector>
 #include <chrono>
@@ -38,6 +37,7 @@
 #include "shrpx_log_config.h"
 #include "tls.h"
 #include "template.h"
+#include "util.h"
 
 using namespace nghttp2;
 
@@ -90,26 +90,120 @@ struct DownstreamAddr;
 
 enum SeverityLevel { INFO, NOTICE, WARN, ERROR, FATAL };
 
+using LogBuffer = std::array<uint8_t, 4_k>;
+
 class Log {
 public:
   Log(int severity, const char *filename, int linenum);
   ~Log();
-  template <typename Type> Log &operator<<(Type s) {
-    stream_ << s;
+  Log &operator<<(const std::string &s);
+  Log &operator<<(const char *s);
+  Log &operator<<(const StringRef &s);
+  Log &operator<<(const ImmutableString &s);
+  Log &operator<<(int16_t n) { return *this << static_cast<int64_t>(n); }
+  Log &operator<<(int32_t n) { return *this << static_cast<int64_t>(n); }
+  Log &operator<<(int64_t n);
+  Log &operator<<(uint16_t n) { return *this << static_cast<uint64_t>(n); }
+  Log &operator<<(uint32_t n) { return *this << static_cast<uint64_t>(n); }
+  Log &operator<<(uint64_t n);
+  Log &operator<<(float n) { return *this << static_cast<double>(n); }
+  Log &operator<<(double n);
+  Log &operator<<(long double n);
+  Log &operator<<(bool n);
+  Log &operator<<(const void *p);
+  template <typename T> Log &operator<<(const std::shared_ptr<T> &ptr) {
+    return *this << ptr.get();
+  }
+  Log &operator<<(void (*func)(Log &log)) {
+    func(*this);
     return *this;
   }
+  template <typename InputIt> void write_seq(InputIt first, InputIt last) {
+    if (full_) {
+      return;
+    }
+
+    auto d = std::distance(first, last);
+    auto n = std::min(wleft(), static_cast<size_t>(d));
+    last_ = std::copy(first, first + n, last_);
+    update_full();
+  }
+
+  template <typename T> void write_hex(T n) {
+    if (full_) {
+      return;
+    }
+
+    if (n == 0) {
+      if (wleft() < 4 /* for "0x00" */) {
+        full_ = true;
+        return;
+      }
+      *last_++ = '0';
+      *last_++ = 'x';
+      *last_++ = '0';
+      *last_++ = '0';
+      update_full();
+      return;
+    }
+
+    size_t nlen = 0;
+    for (auto t = n; t; t >>= 8, ++nlen)
+      ;
+
+    nlen *= 2;
+
+    if (wleft() < 2 /* for "0x" */ + nlen) {
+      full_ = true;
+      return;
+    }
+
+    *last_++ = '0';
+    *last_++ = 'x';
+
+    last_ += nlen;
+    update_full();
+
+    auto p = last_ - 1;
+    for (; n; n >>= 8) {
+      uint8_t b = n & 0xff;
+      *p-- = util::LOWER_XDIGITS[b & 0xf];
+      *p-- = util::LOWER_XDIGITS[b >> 4];
+    }
+  }
   static void set_severity_level(int severity);
   static int set_severity_level_by_name(const StringRef &name);
   static bool log_enabled(int severity) { return severity >= severity_thres_; }
 
+  enum {
+    fmt_dec = 0x00,
+    fmt_hex = 0x01,
+  };
+
+  void set_flags(int flags) { flags_ = flags; }
+
 private:
-  std::stringstream stream_;
+  size_t rleft() { return last_ - begin_; }
+  size_t wleft() { return end_ - last_; }
+  void update_full() { full_ = last_ == end_; }
+
+  LogBuffer &buf_;
+  uint8_t *begin_;
+  uint8_t *end_;
+  uint8_t *last_;
   const char *filename_;
+  uint32_t flags_;
   int severity_;
   int linenum_;
+  bool full_;
   static int severity_thres_;
 };
 
+namespace log {
+void hex(Log &log);
+void dec(Log &log);
+} // namespace log
+
 #define TTY_HTTP_HD (log_config()->errorlog_tty ? "\033[1;34m" : "")
 #define TTY_RST (log_config()->errorlog_tty ? "\033[0m" : "")
 

src/shrpx_tls.cc

@@ -591,7 +591,7 @@ int sct_add_cb(SSL *ssl, unsigned int ext_type, unsigned int context,
 
   if (LOG_ENABLED(INFO)) {
     LOG(INFO) << "sct_add_cb is called, chainidx=" << chainidx << ", x=" << x
-              << ", context=" << std::hex << context;
+              << ", context=" << log::hex << context;
   }
 
   // We only have SCTs for leaf certificate.
@@ -1856,7 +1856,7 @@ void try_cache_tls_session(TLSSessionCache *cache, SSL_SESSION *session,
 
   if (LOG_ENABLED(INFO)) {
     LOG(INFO) << "Update client cache entry "
-              << "timestamp = " << std::fixed << std::setprecision(6) << t;
+              << "timestamp = " << t;
   }
 
   cache->session_data = serialize_ssl_session(session);