removed the use of str() in when building the log to improve perf even more

This commit is contained in:
gabi 2014-10-15 00:46:14 +03:00
parent 41db99556a
commit 650486a067
11 changed files with 117 additions and 115 deletions

View File

@ -17,16 +17,16 @@ using namespace utils;
int main(int argc, char* argv[]) 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"; //std::string pattern = "%Y:%m:%d %H:%M:%S.%e ---> [%n:%l] %t";
//auto formatter = std::make_shared<details::pattern_formatter>(pattern); //auto formatter = std::make_shared<details::pattern_formatter>(pattern);
logger cout_logger("bench", { std::make_shared<sinks::stderr_sink_mt>() }); 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 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 }); logger my_logger("my_logger", { nullsink });

View File

@ -34,11 +34,10 @@ public:
other.clear(); other.clear();
} }
stackbuf_t::bufpair_t buf() const const stackbuf_t& buf() const
{ {
return _stackbuf.get(); return _stackbuf;
} }
std::size_t size() const std::size_t size() const
{ {
return _stackbuf.size(); return _stackbuf.size();
@ -91,7 +90,13 @@ public:
std::string str() std::string str()
{ {
auto buf = _dev.buf(); 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) void putc(char c)
{ {
_dev.sputc(c); _dev.sputc(c);
this->width(4);
} }
// put int and pad with zeroes if smalled than min_width // 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; std::string s;
details::fast_itostr(n, s, padding); details::fast_itostr(n, s, padding);
_dev.sputn(s.data(), s.size()); _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()); _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: private:
stack_devicebuf _dev; stack_devicebuf _dev;

View File

@ -16,9 +16,10 @@ public:
file_flush_helper(const file_flush_helper&) = delete; 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) if(--_flush_countdown == 0)
{ {
ofs.flush(); ofs.flush();

View File

@ -19,7 +19,6 @@ public:
line_logger(logger* callback_logger, level::level_enum msg_level, bool enabled): line_logger(logger* callback_logger, level::level_enum msg_level, bool enabled):
_callback_logger(callback_logger), _callback_logger(callback_logger),
_log_msg(msg_level), _log_msg(msg_level),
_oss(),
_enabled(enabled) _enabled(enabled)
{} {}
@ -32,7 +31,6 @@ public:
line_logger(line_logger&& other) : line_logger(line_logger&& other) :
_callback_logger(other._callback_logger), _callback_logger(other._callback_logger),
_log_msg(std::move(other._log_msg)), _log_msg(std::move(other._log_msg)),
_oss(std::move(other._oss)),
_enabled(other._enabled) _enabled(other._enabled)
{ {
other.disable(); other.disable();
@ -46,7 +44,6 @@ public:
_log_msg.logger_name = _callback_logger->name(); _log_msg.logger_name = _callback_logger->name();
_log_msg.time = log_clock::now(); _log_msg.time = log_clock::now();
_log_msg.tm_time = details::os::localtime(log_clock::to_time_t(_log_msg.time)); _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); _callback_logger->_log_msg(_log_msg);
} }
} }
@ -56,7 +53,7 @@ public:
{ {
if (_enabled) if (_enabled)
{ {
_oss << what; _log_msg.raw << what;
} }
} }
@ -77,7 +74,6 @@ public:
private: private:
logger* _callback_logger; logger* _callback_logger;
log_msg _log_msg; log_msg _log_msg;
details::fast_oss _oss;
bool _enabled; bool _enabled;
}; };
} //Namespace details } //Namespace details

View File

@ -1,7 +1,7 @@
#pragma once #pragma once
#include <chrono>
#include "../common.h" #include "../common.h"
#include "fast_oss.h"
namespace c11log namespace c11log
{ {
@ -38,8 +38,8 @@ struct log_msg
swap(l.level, r.level); swap(l.level, r.level);
swap(l.time, r.time); swap(l.time, r.time);
swap(l.tm_time, r.tm_time); swap(l.tm_time, r.tm_time);
swap(l.raw, r.raw); //swap(l.raw, r.raw);
swap(l.formatted, r.formatted); //swap(l.formatted, r.formatted);
} }
@ -60,8 +60,8 @@ struct log_msg
level::level_enum level; level::level_enum level;
log_clock::time_point time; log_clock::time_point time;
std::tm tm_time; std::tm tm_time;
std::string raw; fast_oss raw;
std::string formatted; fast_oss formatted;
}; };

View File

@ -14,27 +14,27 @@
namespace c11log namespace c11log
{ {
namespace details { namespace details {
class pattern_compiler class flag_formatter
{ {
public: 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 // 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 // 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 // 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 // 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 // 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 // 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 // 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 // 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 // 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 // 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 // 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(); auto duration = msg.time.time_since_epoch();
int millis = static_cast<int>(std::chrono::duration_cast<std::chrono::milliseconds>(duration).count() % 1000); auto millis = std::chrono::duration_cast<std::chrono::milliseconds>(duration).count() % 1000;
oss.put_int(millis, 3); 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: 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: private:
char _ch; char _ch;
}; };
class str_compiler :public pattern_compiler class str_formatter :public flag_formatter
{ {
public: public:
str_compiler() str_formatter()
{} {}
void add_ch(char ch) void add_ch(char ch)
{ {
_str += 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: private:
std::string _str; std::string _str;
@ -175,7 +175,7 @@ public:
void format(details::log_msg& msg) override; void format(details::log_msg& msg) override;
private: private:
const std::string _pattern; 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 handle_flag(char flag);
void compile_pattern(const std::string& pattern); void compile_pattern(const std::string& pattern);
}; };
@ -204,7 +204,7 @@ inline void c11log::details::pattern_formatter::compile_pattern(const std::strin
else else
{ {
// chars not following the % sign should be displayed as is // 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 // logger name
case 'n': 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; break;
// message log level // message log level
case 'l': 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; break;
// message text // message text
case('t') : 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; break;
// year // year
case('Y') : 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; break;
// year 2 digits // year 2 digits
case('y') : 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; break;
// month // month
case('m') : case('m') :
// minute // 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; break;
// day in month // day in month
case('d') : 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; break;
// hour (24) // hour (24)
case('H') : 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; break;
// hour (12) // hour (12)
case('I') : 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; break;
// minutes // minutes
case('M') : 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; break;
// seconds // seconds
case('S') : 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; break;
// milliseconds part // milliseconds part
case('e'): 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; break;
// % sign // % sign
case('%') : 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; 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) inline void c11log::details::pattern_formatter::format(details::log_msg& msg)
{ {
details::fast_oss oss; for (auto &f : _formatters)
for (auto &appender : _compilers)
{ {
appender->append(msg, oss); f->format(msg);
} }
oss.write(details::os::eol(), details::os::eol_size()); //write eol
msg.formatted = oss.str(); msg.formatted.write(details::os::eol(), details::os::eol_size());
} }

View File

@ -15,8 +15,6 @@ template<unsigned short STACK_SIZE>
class stack_buf class stack_buf
{ {
public: public:
using bufpair_t = std::pair<const char*, std::size_t>;
using iterator = char const*;
static const unsigned short stack_size = STACK_SIZE; static const unsigned short stack_size = STACK_SIZE;
stack_buf() :_v(), _stack_size(0) {} stack_buf() :_v(), _stack_size(0) {}
~stack_buf() = default; ~stack_buf() = default;
@ -63,28 +61,28 @@ public:
_v.clear(); _v.clear();
} }
bufpair_t get() const /* bufpair_t get() const
{ {
if (vector_used()) if (vector_used())
return bufpair_t(_v.data(), _v.size()); return bufpair_t(_v.data(), _v.size());
else else
return bufpair_t(_stack_array.data(), _stack_size); return bufpair_t(_stack_array.data(), _stack_size);
} }*/
iterator begin() const const char* data() const
{ {
return get().first; if (vector_used())
} return _v.data();
else
iterator end() const return _stack_array.data();
{
bufpair_t bpair = get();
return bpair.first + bpair.second;
} }
std::size_t size() const std::size_t size() const
{ {
return get().second; if (vector_used())
return _v.size();
else
return _stack_size;
} }
private: private:

View File

@ -5,7 +5,7 @@
// Upon each log write the logger: // Upon each log write the logger:
// 1. Checks if its log level is enough to log the message // 1. Checks if its log level is enough to log the message
// 2. Format the message using the formatter function // 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<vector>
#include<memory> #include<memory>
@ -68,8 +68,6 @@ private:
void _log_msg(details::log_msg& msg); void _log_msg(details::log_msg& msg);
formatter_ptr _default_formatter(); formatter_ptr _default_formatter();
const char* _default_pattern = "[%Y:%m:%d %H:%M:%S.%e] [%n:%l] %t"; 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&) {} inline void c11log::logger::_variadic_log(c11log::details::line_logger&) {}
template <typename First, typename... Rest> template <typename First, typename... Rest>

View File

@ -67,7 +67,7 @@ inline c11log::sinks::async_sink::~async_sink()
inline void c11log::sinks::async_sink::_sink_it(const details::log_msg& msg) inline void c11log::sinks::async_sink::_sink_it(const details::log_msg& msg)
{ {
if(!_active || msg.formatted.empty()) if(!_active)
return; return;
_q.push(msg); _q.push(msg);
} }

View File

@ -32,7 +32,7 @@ public:
protected: protected:
void _sink_it(const details::log_msg& msg) override void _sink_it(const details::log_msg& msg) override
{ {
_flush_helper.write(msg.formatted, _ofstream); _flush_helper.write(msg, _ofstream);
} }
private: private:
std::ofstream _ofstream; std::ofstream _ofstream;
@ -71,7 +71,7 @@ protected:
_rotate(); _rotate();
_current_size = msg.formatted.size(); _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)); _ofstream.open(_calc_filename(_base_filename, _extension));
_midnight_tp = _calc_midnight_tp(); _midnight_tp = _calc_midnight_tp();
} }
_flush_helper.write(msg.formatted, _ofstream); _flush_helper.write(msg, _ofstream);
} }
private: private:

View File

@ -24,7 +24,8 @@ public:
protected: protected:
virtual void _sink_it(const details::log_msg& msg) override 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; std::ostream& _ostream;
}; };