From 91ae5291cc82533260a10d591df8783f4fff3f03 Mon Sep 17 00:00:00 2001
From: Tatsuhiro Tsujikawa <tatsuhiro.t@gmail.com>
Date: Wed, 21 Jan 2015 23:52:30 +0900
Subject: [PATCH] nghttpx: Cache string representation of time for logging

---
 src/shrpx_log.cc           | 23 +++++++++++++----------
 src/shrpx_worker_config.cc | 17 +++++++++++++++++
 src/shrpx_worker_config.h  |  6 ++++++
 3 files changed, 36 insertions(+), 10 deletions(-)

diff --git a/src/shrpx_log.cc b/src/shrpx_log.cc
index 918bad50..8a661323 100644
--- a/src/shrpx_log.cc
+++ b/src/shrpx_log.cc
@@ -122,16 +122,17 @@ Log::~Log() {
   char buf[4096];
   auto tty = wconf->errorlog_tty;
 
-  auto time_now = util::format_common_log(std::chrono::system_clock::now());
+  wconf->update_tstamp(std::chrono::system_clock::now());
+  auto &time_local = wconf->time_local_str;
 
   if (severity_ == NOTICE) {
-    rv = snprintf(buf, sizeof(buf), "%s PID%d [%s%s%s] %s\n", time_now.c_str(),
-                  get_config()->pid, tty ? SEVERITY_COLOR[severity_] : "",
-                  SEVERITY_STR[severity_], tty ? "\033[0m" : "",
-                  stream_.str().c_str());
+    rv = snprintf(buf, sizeof(buf), "%s PID%d [%s%s%s] %s\n",
+                  time_local.c_str(), get_config()->pid,
+                  tty ? SEVERITY_COLOR[severity_] : "", SEVERITY_STR[severity_],
+                  tty ? "\033[0m" : "", stream_.str().c_str());
   } else {
     rv = snprintf(buf, sizeof(buf), "%s PID%d [%s%s%s] %s%s:%d%s %s\n",
-                  time_now.c_str(), get_config()->pid,
+                  time_local.c_str(), get_config()->pid,
                   tty ? SEVERITY_COLOR[severity_] : "", SEVERITY_STR[severity_],
                   tty ? "\033[0m" : "", tty ? "\033[1;30m" : "", filename_,
                   linenum_, tty ? "\033[0m" : "", stream_.str().c_str());
@@ -171,6 +172,10 @@ void upstream_accesslog(const std::vector<LogFragment> &lfv, LogSpec *lgsp) {
   auto p = buf;
   auto avail = sizeof(buf) - 2;
 
+  wconf->update_tstamp(lgsp->time_now);
+  auto &time_local = wconf->time_local_str;
+  auto &time_iso8601 = wconf->time_iso8601_str;
+
   for (auto &lf : lfv) {
     switch (lf.type) {
     case SHRPX_LOGF_LITERAL:
@@ -180,12 +185,10 @@ void upstream_accesslog(const std::vector<LogFragment> &lfv, LogSpec *lgsp) {
       std::tie(p, avail) = copy(lgsp->remote_addr, avail, p);
       break;
     case SHRPX_LOGF_TIME_LOCAL:
-      std::tie(p, avail) =
-          copy(util::format_common_log(lgsp->time_now).c_str(), avail, p);
+      std::tie(p, avail) = copy(time_local.c_str(), avail, p);
       break;
     case SHRPX_LOGF_TIME_ISO8601:
-      std::tie(p, avail) =
-          copy(util::format_iso8601(lgsp->time_now).c_str(), avail, p);
+      std::tie(p, avail) = copy(time_iso8601.c_str(), avail, p);
       break;
     case SHRPX_LOGF_REQUEST:
       std::tie(p, avail) = copy(lgsp->method, avail, p);
diff --git a/src/shrpx_worker_config.cc b/src/shrpx_worker_config.cc
index 129f8f3e..4e95b23d 100644
--- a/src/shrpx_worker_config.cc
+++ b/src/shrpx_worker_config.cc
@@ -23,6 +23,9 @@
  * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE.
  */
 #include "shrpx_worker_config.h"
+#include "util.h"
+
+using namespace nghttp2;
 
 namespace shrpx {
 
@@ -35,4 +38,18 @@ thread_local
 #endif // NOTHREADS
     WorkerConfig *worker_config = new WorkerConfig();
 
+void
+WorkerConfig::update_tstamp(const std::chrono::system_clock::time_point &now) {
+  auto t0 = std::chrono::system_clock::to_time_t(time_str_updated_);
+  auto t1 = std::chrono::system_clock::to_time_t(now);
+  if (t0 == t1) {
+    return;
+  }
+
+  time_str_updated_ = now;
+
+  time_local_str = util::format_common_log(now);
+  time_iso8601_str = util::format_iso8601(now);
+}
+
 } // namespace shrpx
diff --git a/src/shrpx_worker_config.h b/src/shrpx_worker_config.h
index c30e4d39..1dad4b1d 100644
--- a/src/shrpx_worker_config.h
+++ b/src/shrpx_worker_config.h
@@ -27,6 +27,8 @@
 
 #include "shrpx.h"
 
+#include <chrono>
+
 namespace shrpx {
 
 namespace ssl {
@@ -37,6 +39,9 @@ struct TicketKeys;
 
 struct WorkerConfig {
   std::shared_ptr<TicketKeys> ticket_keys;
+  std::chrono::system_clock::time_point time_str_updated_;
+  std::string time_local_str;
+  std::string time_iso8601_str;
   ssl::CertLookupTree *cert_tree;
   int accesslog_fd;
   int errorlog_fd;
@@ -45,6 +50,7 @@ struct WorkerConfig {
   bool graceful_shutdown;
 
   WorkerConfig();
+  void update_tstamp(const std::chrono::system_clock::time_point &now);
 };
 
 // We need WorkerConfig per thread