From 650486a067eb6dc15efb25df257ccbbb9894187a Mon Sep 17 00:00:00 2001
From: gabi <galim120@bezeqint.net>
Date: Wed, 15 Oct 2014 00:46:14 +0300
Subject: [PATCH] removed the use of str() in when building the log to improve
 perf even more

---
 example/bench.cpp                          |   6 +-
 include/c11log/details/fast_oss.h          |  24 ++--
 include/c11log/details/flush_helper.h      |   5 +-
 include/c11log/details/line_logger.h       |   6 +-
 include/c11log/details/log_msg.h           |  10 +-
 include/c11log/details/pattern_formatter.h | 133 ++++++++++-----------
 include/c11log/details/stack_buf.h         |  32 +++--
 include/c11log/logger.h                    |   5 +-
 include/c11log/sinks/async_sink.h          |   2 +-
 include/c11log/sinks/file_sinks.h          |   6 +-
 include/c11log/sinks/ostream_sink.h        |   3 +-
 11 files changed, 117 insertions(+), 115 deletions(-)

diff --git a/example/bench.cpp b/example/bench.cpp
index 988e2d21..3a4f438e 100644
--- a/example/bench.cpp
+++ b/example/bench.cpp
@@ -17,16 +17,16 @@ using namespace utils;
 
 int main(int argc, char* argv[])
 {
-    const unsigned int howmany = argc <= 1 ? 1000000 : atoi(argv[1]);
+    const unsigned int howmany = argc <= 1 ? 500000 : atoi(argv[1]);
 
     //std::string pattern = "%Y:%m:%d %H:%M:%S.%e ---> [%n:%l] %t";
     //auto formatter = std::make_shared<details::pattern_formatter>(pattern);
 
     logger cout_logger("bench", { std::make_shared<sinks::stderr_sink_mt>() });
-    cout_logger.info() << "Hello logger " << std::setw(10) << std::setfill('x') << 1234.55;
+    cout_logger.info() << "Hello logger " << 1234;
 
     auto nullsink = std::make_shared<sinks::null_sink_st>();
-    auto rotating = std::make_shared<sinks::rotating_file_sink_mt>("myrotating", "txt", 1024 * 1024 * 5, 5, 100);
+    //auto rotating = std::make_shared<sinks::rotating_file_sink_mt>("myrotating", "txt", 1024 * 1024 * 5, 5, 100);
 
     logger my_logger("my_logger", { nullsink });
 
diff --git a/include/c11log/details/fast_oss.h b/include/c11log/details/fast_oss.h
index 9744fb24..4dd21030 100644
--- a/include/c11log/details/fast_oss.h
+++ b/include/c11log/details/fast_oss.h
@@ -34,11 +34,10 @@ public:
         other.clear();
     }
 
-    stackbuf_t::bufpair_t buf() const
+    const stackbuf_t& buf() const
     {
-        return _stackbuf.get();
+        return _stackbuf;
     }
-
     std::size_t size() const
     {
         return _stackbuf.size();
@@ -91,7 +90,13 @@ public:
     std::string str()
     {
         auto buf = _dev.buf();
-        return std::string(buf.first, buf.second);
+        const char*data = buf.data();
+        return std::string(data, data+buf.size());
+    }
+
+    const stack_devicebuf::stackbuf_t& buf() const
+    {
+        return _dev.buf();
     }
 
 
@@ -111,22 +116,27 @@ public:
     void putc(char c)
     {
         _dev.sputc(c);
-        this->width(4);
     }
 
     // put int and pad with zeroes if smalled than min_width
-    void put_int(int n, int padding)
+    void write_int(int n, int padding)
     {
         std::string s;
         details::fast_itostr(n, s, padding);
         _dev.sputn(s.data(), s.size());
     }
 
-    void put_str(const std::string& s)
+    void write_str(const std::string& s)
     {
         _dev.sputn(s.data(), s.size());
     }
 
+    void write_fast_oss(const fast_oss& oss)
+    {
+        auto buf = oss.buf();
+        _dev.sputn(buf.data(), buf.size());
+    }
+
 
 private:
     stack_devicebuf _dev;
diff --git a/include/c11log/details/flush_helper.h b/include/c11log/details/flush_helper.h
index 7aed39f8..cb05b292 100644
--- a/include/c11log/details/flush_helper.h
+++ b/include/c11log/details/flush_helper.h
@@ -16,9 +16,10 @@ public:
 
     file_flush_helper(const file_flush_helper&) = delete;
 
-    void write(const std::string& msg, std::ofstream& ofs)
+    void write(const log_msg msg, std::ofstream& ofs)
     {
-        ofs.write(msg.data(), msg.size());
+        auto buf = msg.formatted.buf();
+        ofs.write(buf.data(), buf.size());
         if(--_flush_countdown == 0)
         {
             ofs.flush();
diff --git a/include/c11log/details/line_logger.h b/include/c11log/details/line_logger.h
index 86f04c82..1f684a5d 100644
--- a/include/c11log/details/line_logger.h
+++ b/include/c11log/details/line_logger.h
@@ -19,7 +19,6 @@ public:
     line_logger(logger* callback_logger, level::level_enum msg_level, bool enabled):
         _callback_logger(callback_logger),
         _log_msg(msg_level),
-        _oss(),
         _enabled(enabled)
     {}
 
@@ -32,7 +31,6 @@ public:
     line_logger(line_logger&& other) :
         _callback_logger(other._callback_logger),
         _log_msg(std::move(other._log_msg)),
-        _oss(std::move(other._oss)),
         _enabled(other._enabled)
     {
         other.disable();
@@ -46,7 +44,6 @@ public:
             _log_msg.logger_name = _callback_logger->name();
             _log_msg.time = log_clock::now();
             _log_msg.tm_time = details::os::localtime(log_clock::to_time_t(_log_msg.time));
-            _log_msg.raw = _oss.str();
             _callback_logger->_log_msg(_log_msg);
         }
     }
@@ -56,7 +53,7 @@ public:
     {
         if (_enabled)
         {
-            _oss << what;
+            _log_msg.raw << what;
         }
     }
 
@@ -77,7 +74,6 @@ public:
 private:
     logger* _callback_logger;
     log_msg _log_msg;
-    details::fast_oss _oss;
     bool _enabled;
 };
 } //Namespace details
diff --git a/include/c11log/details/log_msg.h b/include/c11log/details/log_msg.h
index 58f2cd38..9be54456 100644
--- a/include/c11log/details/log_msg.h
+++ b/include/c11log/details/log_msg.h
@@ -1,7 +1,7 @@
 #pragma once
 
-#include <chrono>
 #include "../common.h"
+#include "fast_oss.h"
 
 namespace c11log
 {
@@ -38,8 +38,8 @@ struct log_msg
         swap(l.level, r.level);
         swap(l.time, r.time);
         swap(l.tm_time, r.tm_time);
-        swap(l.raw, r.raw);
-        swap(l.formatted, r.formatted);
+        //swap(l.raw, r.raw);
+        //swap(l.formatted, r.formatted);
     }
 
 
@@ -60,8 +60,8 @@ struct log_msg
     level::level_enum level;
     log_clock::time_point time;
     std::tm tm_time;
-    std::string raw;
-    std::string formatted;
+    fast_oss raw;
+    fast_oss formatted;
 
 
 };
diff --git a/include/c11log/details/pattern_formatter.h b/include/c11log/details/pattern_formatter.h
index 58e932d0..b9d2166c 100644
--- a/include/c11log/details/pattern_formatter.h
+++ b/include/c11log/details/pattern_formatter.h
@@ -14,27 +14,27 @@
 namespace c11log
 {
 namespace details {
-class pattern_compiler
+class flag_formatter
 {
 public:
-    virtual void append(const details::log_msg& msg, details::fast_oss& oss) = 0;
+    virtual void format(details::log_msg& msg) = 0;
 };
 
 // log name appender
-class name_compiler :public pattern_compiler
+class name_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss << msg.logger_name;
+        msg.formatted << msg.logger_name;
     }
 };
 
 // log level appender
-class level_compiler :public pattern_compiler
+class level_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss << level::to_str(msg.level);
+        msg.formatted << level::to_str(msg.level);
     }
 };
 
@@ -43,122 +43,122 @@ class level_compiler :public pattern_compiler
 ///////////////////////////////////////////////////////////////////////
 
 // year - 4 digit
-class Y_compiler :public pattern_compiler
+class Y_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss.put_int(msg.tm_time.tm_year + 1900, 4);
+        msg.formatted.write_int(msg.tm_time.tm_year + 1900, 4);
     }
 };
 
 // year - 2 digit
-class y_compiler :public pattern_compiler
+class y_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss.put_int(msg.tm_time.tm_year, 2);
+        msg.formatted.write_int(msg.tm_time.tm_year, 2);
     }
 };
 // month 1-12
-class m_compiler :public pattern_compiler
+class m_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss.put_int(msg.tm_time.tm_mon + 1, 2);
+        msg.formatted.write_int(msg.tm_time.tm_mon + 1, 2);
     }
 };
 
 // day of month 1-31
-class d_compiler :public pattern_compiler
+class d_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss.put_int(msg.tm_time.tm_mday, 2);
+        msg.formatted.write_int(msg.tm_time.tm_mday, 2);
     }
 };
 
 // hours in 24 format  0-23
-class H_compiler :public pattern_compiler
+class H_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss.put_int(msg.tm_time.tm_hour, 2);
+        msg.formatted.write_int(msg.tm_time.tm_hour, 2);
     }
 };
 
 // hours in 12 format  1-12
-class I_compiler :public pattern_compiler
+class I_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss.put_int((msg.tm_time.tm_hour + 1) % 1, 2);
+        msg.formatted.write_int((msg.tm_time.tm_hour + 1) % 1, 2);
     }
 };
 
 // ninutes 0-59
-class M_compiler :public pattern_compiler
+class M_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss.put_int(msg.tm_time.tm_min, 2);
+        msg.formatted.write_int(msg.tm_time.tm_min, 2);
     }
 };
 
 // seconds 0-59
-class S_compiler :public pattern_compiler
+class S_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss.put_int(msg.tm_time.tm_sec, 2);
+        msg.formatted.write_int(msg.tm_time.tm_sec, 2);
     }
 };
 
 // milliseconds
-class e_compiler :public pattern_compiler
+class e_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
         auto duration = msg.time.time_since_epoch();
-        int millis = static_cast<int>(std::chrono::duration_cast<std::chrono::milliseconds>(duration).count() % 1000);
-        oss.put_int(millis, 3);
+        auto millis = std::chrono::duration_cast<std::chrono::milliseconds>(duration).count() % 1000;
+        msg.formatted.write_int(static_cast<int>(millis), 3);
     }
 };
 
 
-class t_compiler :public pattern_compiler
+class t_formatter :public flag_formatter
 {
-    void append(const details::log_msg& msg, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss.put_str(msg.raw);
+        msg.formatted.write_fast_oss(msg.raw);
     }
 };
 
-class ch_compiler :public pattern_compiler
+class ch_formatter :public flag_formatter
 {
 public:
-    explicit ch_compiler(char ch) : _ch(ch)
+    explicit ch_formatter(char ch) : _ch(ch)
     {}
-    void append(const details::log_msg&, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss.putc(_ch);
+        msg.formatted.putc(_ch);
     }
 private:
     char _ch;
 };
 
 
-class str_compiler :public pattern_compiler
+class str_formatter :public flag_formatter
 {
 public:
-    str_compiler()
+    str_formatter()
     {}
     void add_ch(char ch)
     {
         _str += ch;
     }
-    void append(const details::log_msg&, details::fast_oss& oss) override
+    void format(details::log_msg& msg) override
     {
-        oss << _str;
+        msg.formatted << _str;
     }
 private:
     std::string _str;
@@ -175,7 +175,7 @@ public:
     void format(details::log_msg& msg) override;
 private:
     const std::string _pattern;
-    std::vector<std::unique_ptr<details::pattern_compiler>> _compilers;
+    std::vector<std::unique_ptr<details::flag_formatter>> _formatters;
     void handle_flag(char flag);
     void compile_pattern(const std::string& pattern);
 };
@@ -204,7 +204,7 @@ inline void c11log::details::pattern_formatter::compile_pattern(const std::strin
         else
         {
             // chars not following the % sign should be displayed as is
-            _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::ch_compiler(*it)));
+            _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::ch_formatter(*it)));
         }
     }
 
@@ -215,56 +215,56 @@ inline void c11log::details::pattern_formatter::handle_flag(char flag)
     {
     // logger name
     case 'n':
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::name_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::name_formatter()));
         break;
     // message log level
     case 'l':
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::level_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::level_formatter()));
         break;
     // message text
     case('t') :
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::t_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::t_formatter()));
         break;
     // year
     case('Y') :
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::Y_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::Y_formatter()));
         break;
     // year 2 digits
     case('y') :
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::y_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::y_formatter()));
         break;
     // month
     case('m') :
         // minute
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::m_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::m_formatter()));
         break;
     // day in month
     case('d') :
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::d_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::d_formatter()));
         break;
     // hour (24)
     case('H') :
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::H_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::H_formatter()));
         break;
     // hour (12)
     case('I') :
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::I_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::I_formatter()));
         break;
     // minutes
     case('M') :
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::M_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::M_formatter()));
         break;
     // seconds
     case('S') :
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::S_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::S_formatter()));
         break;
     // milliseconds part
     case('e'):
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::e_compiler()));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::e_formatter()));
         break;
     // % sign
     case('%') :
-        _compilers.push_back(std::unique_ptr<details::pattern_compiler>(new details::ch_compiler('%')));
+        _formatters.push_back(std::unique_ptr<details::flag_formatter>(new details::ch_formatter('%')));
         break;
     }
 }
@@ -272,11 +272,10 @@ inline void c11log::details::pattern_formatter::handle_flag(char flag)
 
 inline void c11log::details::pattern_formatter::format(details::log_msg& msg)
 {
-    details::fast_oss oss;
-    for (auto &appender : _compilers)
+    for (auto &f : _formatters)
     {
-        appender->append(msg, oss);
+        f->format(msg);
     }
-    oss.write(details::os::eol(), details::os::eol_size());
-    msg.formatted = oss.str();
+    //write eol
+    msg.formatted.write(details::os::eol(), details::os::eol_size());
 }
diff --git a/include/c11log/details/stack_buf.h b/include/c11log/details/stack_buf.h
index 8ee5075d..0629daee 100644
--- a/include/c11log/details/stack_buf.h
+++ b/include/c11log/details/stack_buf.h
@@ -15,8 +15,6 @@ template<unsigned short STACK_SIZE>
 class stack_buf
 {
 public:
-    using bufpair_t = std::pair<const char*, std::size_t>;
-    using iterator = char const*;
     static const unsigned short stack_size = STACK_SIZE;
     stack_buf() :_v(), _stack_size(0) {}
     ~stack_buf() = default;
@@ -63,28 +61,28 @@ public:
         _v.clear();
     }
 
-    bufpair_t get() const
+    /* bufpair_t get() const
+     {
+         if (vector_used())
+             return bufpair_t(_v.data(), _v.size());
+         else
+             return bufpair_t(_stack_array.data(), _stack_size);
+     }*/
+
+    const char* data() const
     {
         if (vector_used())
-            return bufpair_t(_v.data(), _v.size());
+            return _v.data();
         else
-            return bufpair_t(_stack_array.data(), _stack_size);
-    }
-
-    iterator begin() const
-    {
-        return get().first;
-    }
-
-    iterator end() const
-    {
-        bufpair_t bpair = get();
-        return bpair.first + bpair.second;
+            return _stack_array.data();
     }
 
     std::size_t size() const
     {
-        return get().second;
+        if (vector_used())
+            return _v.size();
+        else
+            return _stack_size;
     }
 
 private:
diff --git a/include/c11log/logger.h b/include/c11log/logger.h
index 14c6d7c8..1abbb652 100644
--- a/include/c11log/logger.h
+++ b/include/c11log/logger.h
@@ -5,7 +5,7 @@
 // Upon each log write the logger:
 // 1. Checks if its log level is enough to log the message
 // 2. Format the message using the formatter function
-// 3. Pass the formatted message to it sinks to performa the actual logging
+// 3. Pass the formatted message to its sinks to performa the actual logging
 
 #include<vector>
 #include<memory>
@@ -68,8 +68,6 @@ private:
     void _log_msg(details::log_msg& msg);
     formatter_ptr  _default_formatter();
     const char* _default_pattern = "[%Y:%m:%d %H:%M:%S.%e] [%n:%l] %t";
-
-
 };
 }
 
@@ -183,7 +181,6 @@ inline c11log::logger::formatter_ptr c11log::logger::formatter() const
 }
 
 
-
 inline void c11log::logger::_variadic_log(c11log::details::line_logger&) {}
 
 template <typename First, typename... Rest>
diff --git a/include/c11log/sinks/async_sink.h b/include/c11log/sinks/async_sink.h
index 48a1abfa..9006043e 100644
--- a/include/c11log/sinks/async_sink.h
+++ b/include/c11log/sinks/async_sink.h
@@ -67,7 +67,7 @@ inline c11log::sinks::async_sink::~async_sink()
 
 inline void c11log::sinks::async_sink::_sink_it(const details::log_msg& msg)
 {
-    if(!_active || msg.formatted.empty())
+    if(!_active)
         return;
     _q.push(msg);
 }
diff --git a/include/c11log/sinks/file_sinks.h b/include/c11log/sinks/file_sinks.h
index 9eade65c..f732f92f 100644
--- a/include/c11log/sinks/file_sinks.h
+++ b/include/c11log/sinks/file_sinks.h
@@ -32,7 +32,7 @@ public:
 protected:
     void _sink_it(const details::log_msg& msg) override
     {
-        _flush_helper.write(msg.formatted, _ofstream);
+        _flush_helper.write(msg, _ofstream);
     }
 private:
     std::ofstream _ofstream;
@@ -71,7 +71,7 @@ protected:
             _rotate();
             _current_size = msg.formatted.size();
         }
-        _flush_helper.write(msg.formatted, _ofstream);
+        _flush_helper.write(msg, _ofstream);
     }
 
 
@@ -146,7 +146,7 @@ protected:
             _ofstream.open(_calc_filename(_base_filename, _extension));
             _midnight_tp = _calc_midnight_tp();
         }
-        _flush_helper.write(msg.formatted, _ofstream);
+        _flush_helper.write(msg, _ofstream);
     }
 
 private:
diff --git a/include/c11log/sinks/ostream_sink.h b/include/c11log/sinks/ostream_sink.h
index 507e343b..0531a935 100644
--- a/include/c11log/sinks/ostream_sink.h
+++ b/include/c11log/sinks/ostream_sink.h
@@ -24,7 +24,8 @@ public:
 protected:
     virtual void _sink_it(const details::log_msg& msg) override
     {
-        _ostream << msg.formatted;
+        auto buf = msg.formatted.buf();
+        _ostream.write(buf.data(), buf.size());
     }
     std::ostream& _ostream;
 };