flush helper count writes instead of time

This commit is contained in:
gabime 2014-03-14 14:35:46 +02:00
parent 9d687d1634
commit 38670cef27
14 changed files with 139 additions and 94 deletions

View File

@ -1,4 +1,4 @@
#!/bin/bash #!/bin/bash
find . -name "*\.h" -o -name "*\.cpp"|xargs astyle -A8 find . -name "*\.h" -o -name "*\.cpp"|xargs astyle -A1

View File

@ -20,7 +20,7 @@ int main(int argc, char* argv[])
{ {
if(argc || argv) {}; if(argc || argv) {};
//auto fsink = std::make_shared<sinks::rotating_file_sink>("log", "txt", 1024*1024*50 , 5, seconds(1)); auto fsink = std::make_shared<sinks::rotating_file_sink>("log", "txt", 1024*1024*50 , 5, 0);
auto null_sink = std::make_shared<sinks::null_sink>(); auto null_sink = std::make_shared<sinks::null_sink>();
@ -29,11 +29,11 @@ int main(int argc, char* argv[])
cout_logger.info() << "Hello cout logger!"; cout_logger.info() << "Hello cout logger!";
logger my_logger ("my_logger", {null_sink}); logger my_logger ("my_logger", {fsink});
auto start = system_clock::now(); auto start = system_clock::now();
const unsigned int howmany = 10000000; const unsigned int howmany = 5000000;
for(unsigned int i = 0; i < howmany ; i++) for(unsigned int i = 0; i < howmany ; i++)
my_logger.info() << "Hello logger " << i; my_logger.info() << "Hello logger " << i;

View File

@ -38,13 +38,15 @@ inline void bench(const std::string& fn_name, const std::chrono::milliseconds &d
seconds print_interval(1); seconds print_interval(1);
auto start_time = the_clock::now(); auto start_time = the_clock::now();
auto lastPrintTime = start_time; auto lastPrintTime = start_time;
while (true) { while (true)
{
fn(); fn();
++counter; ++counter;
auto now = the_clock::now(); auto now = the_clock::now();
if (now - start_time >= duration) if (now - start_time >= duration)
break; break;
if (now - lastPrintTime >= print_interval) { if (now - lastPrintTime >= print_interval)
{
std::cout << fn_name << ": " << format(counter) << " per sec" << std::endl; std::cout << fn_name << ": " << format(counter) << " per sec" << std::endl;
counter = 0; counter = 0;
lastPrintTime = the_clock::now(); lastPrintTime = the_clock::now();

View File

@ -9,7 +9,8 @@ typedef std::chrono::system_clock log_clock;
namespace level namespace level
{ {
typedef enum { typedef enum
{
DEBUG, DEBUG,
INFO, INFO,
WARNING, WARNING,
@ -17,13 +18,11 @@ typedef enum {
FATAL, FATAL,
NONE = 99 NONE = 99
} level_enum; } level_enum;
const char* to_str(level_enum l);
}
}
static const char* level_names[] { "debug", "info", "warning", "error", "fatal" }; static const char* level_names[] { "debug", "info", "warning", "error", "fatal" };
inline const char* c11log::level::to_str(c11log::level::level_enum l) inline const char* to_str(c11log::level::level_enum l)
{ {
return level_names[l]; return level_names[l];
} }
}
}

View File

@ -26,13 +26,15 @@ public:
explicit blocking_queue(size_type max_size) : explicit blocking_queue(size_type max_size) :
_max_size(max_size), _max_size(max_size),
_q(), _q(),
_mutex() { _mutex()
{
} }
blocking_queue(const blocking_queue&) = delete; blocking_queue(const blocking_queue&) = delete;
blocking_queue& operator=(const blocking_queue&) = delete; blocking_queue& operator=(const blocking_queue&) = delete;
~blocking_queue() = default; ~blocking_queue() = default;
size_type size() { size_type size()
{
std::lock_guard<std::mutex> lock(_mutex); std::lock_guard<std::mutex> lock(_mutex);
return _q.size(); return _q.size();
} }
@ -41,16 +43,20 @@ public:
// If the queue is full, block the calling thread util there is room or timeout have passed. // If the queue is full, block the calling thread util there is room or timeout have passed.
// Return: false on timeout, true on successful push. // Return: false on timeout, true on successful push.
template<typename Duration_Rep, typename Duration_Period, typename TT> template<typename Duration_Rep, typename Duration_Period, typename TT>
bool push(TT&& item, const std::chrono::duration<Duration_Rep, Duration_Period>& timeout) { bool push(TT&& item, const std::chrono::duration<Duration_Rep, Duration_Period>& timeout)
{
std::unique_lock<std::mutex> ul(_mutex); std::unique_lock<std::mutex> ul(_mutex);
if (_q.size() >= _max_size) { if (_q.size() >= _max_size)
if (!_item_popped_cond.wait_until(ul, clock::now() + timeout, [this]() { {
if (!_item_popped_cond.wait_until(ul, clock::now() + timeout, [this]()
{
return this->_q.size() < this->_max_size; return this->_q.size() < this->_max_size;
})) }))
return false; return false;
} }
_q.push(std::forward<TT>(item)); _q.push(std::forward<TT>(item));
if (_q.size() <= 1) { if (_q.size() <= 1)
{
ul.unlock(); //So the notified thread will have better chance to accuire the lock immediatly.. ul.unlock(); //So the notified thread will have better chance to accuire the lock immediatly..
_item_pushed_cond.notify_one(); _item_pushed_cond.notify_one();
} }
@ -60,7 +66,8 @@ public:
// Push copy of item into the back of the queue. // Push copy of item into the back of the queue.
// If the queue is full, block the calling thread until there is room. // If the queue is full, block the calling thread until there is room.
template<typename TT> template<typename TT>
void push(TT&& item) { void push(TT&& item)
{
while (!push(std::forward<TT>(item), std::chrono::hours(1))); while (!push(std::forward<TT>(item), std::chrono::hours(1)));
} }
@ -68,17 +75,21 @@ public:
// If the queue is empty, block the calling thread util there is item to pop or timeout have passed. // If the queue is empty, block the calling thread util there is item to pop or timeout have passed.
// Return: false on timeout , true on successful pop/ // Return: false on timeout , true on successful pop/
template<class Duration_Rep, class Duration_Period> template<class Duration_Rep, class Duration_Period>
bool pop(T& item, const std::chrono::duration<Duration_Rep, Duration_Period>& timeout) { bool pop(T& item, const std::chrono::duration<Duration_Rep, Duration_Period>& timeout)
{
std::unique_lock<std::mutex> ul(_mutex); std::unique_lock<std::mutex> ul(_mutex);
if (_q.empty()) { if (_q.empty())
if (!_item_pushed_cond.wait_until(ul, clock::now() + timeout, [this]() { {
if (!_item_pushed_cond.wait_until(ul, clock::now() + timeout, [this]()
{
return !this->_q.empty(); return !this->_q.empty();
})) }))
return false; return false;
} }
item = std::move(_q.front()); item = std::move(_q.front());
_q.pop(); _q.pop();
if (_q.size() >= _max_size - 1) { if (_q.size() >= _max_size - 1)
{
ul.unlock(); //So the notified thread will have better chance to accuire the lock immediatly.. ul.unlock(); //So the notified thread will have better chance to accuire the lock immediatly..
_item_popped_cond.notify_one(); _item_popped_cond.notify_one();
} }
@ -87,12 +98,14 @@ public:
// Pop a copy of the front item in the queue into the given item ref. // Pop a copy of the front item in the queue into the given item ref.
// If the queue is empty, block the calling thread util there is item to pop. // If the queue is empty, block the calling thread util there is item to pop.
void pop(T& item) { void pop(T& item)
{
while (!pop(item, std::chrono::hours(1))); while (!pop(item, std::chrono::hours(1)));
} }
// Clear the queue // Clear the queue
void clear() { void clear()
{
{ {
std::unique_lock<std::mutex> ul(_mutex); std::unique_lock<std::mutex> ul(_mutex);
queue_t().swap(_q); queue_t().swap(_q);

View File

@ -22,25 +22,30 @@ public:
str_devicebuf& operator=(str_devicebuf&&) = delete; str_devicebuf& operator=(str_devicebuf&&) = delete;
const std::string& str_ref() const { const std::string& str_ref() const
{
return _str; return _str;
} }
void clear() { void clear()
{
_str.clear(); _str.clear();
} }
protected: protected:
virtual int sync() override { virtual int sync() override
{
return 0; return 0;
} }
virtual std::streamsize xsputn(const char_type* s, std::streamsize count) override { virtual std::streamsize xsputn(const char_type* s, std::streamsize count) override
{
_str.append(s, static_cast<unsigned int>(count)); _str.append(s, static_cast<unsigned int>(count));
return count; return count;
} }
virtual int_type overflow(int_type ch) override { virtual int_type overflow(int_type ch) override
{
if (ch != traits_type::eof()) if (ch != traits_type::eof())
_str.append((char*)&ch, 1); _str.append((char*)&ch, 1);
return 1; return 1;
@ -59,12 +64,11 @@ public:
fast_oss(fast_oss&& other) = delete; fast_oss(fast_oss&& other) = delete;
fast_oss& operator=(const fast_oss& other) = delete; fast_oss& operator=(const fast_oss& other) = delete;
const std::string& str_ref() const { const std::string& str_ref() const
{
return _dev.str_ref(); return _dev.str_ref();
} }
private: private:
str_devicebuf _dev; str_devicebuf _dev;
}; };

View File

@ -1,36 +1,31 @@
#pragma once #pragma once
#include <chrono>
#include <iostream>
// Flush to file every X writes.. // Flush to file every X writes..
namespace c11log namespace c11log
{ {
namespace details namespace details
{ {
class file_flush_helper class file_flush_helper
{ {
public: public:
explicit file_flush_helper(const std::chrono::milliseconds &flush_every): _flush_every(flush_every), _last_flush() {}; explicit file_flush_helper(const std::size_t flush_every):
_flush_every(flush_every),
_write_counter(0) {};
void write(std::ofstream& ofs, const std::string& msg) { void write(std::ofstream& ofs, const std::string& msg)
{
ofs.write(msg.c_str(), msg.size());
ofs << msg; if(++_write_counter == _flush_every)
//If zero - flush every time {
if(_flush_every == std::chrono::milliseconds::min()) {
ofs.flush(); ofs.flush();
} else { _write_counter = 0;
auto now = std::chrono::system_clock::now();
if(now - _last_flush >= _flush_every) {
ofs.flush();
_last_flush = now;
}
} }
} }
private: private:
std::chrono::milliseconds _flush_every; const std::size_t _flush_every;
std::chrono::system_clock::time_point _last_flush; std::size_t _write_counter;
}; };
} }
} }

View File

@ -22,8 +22,10 @@ public:
_callback_logger(callback_logger), _callback_logger(callback_logger),
_oss(), _oss(),
_level(msg_level), _level(msg_level),
_enabled(enabled) { _enabled(enabled)
if(enabled) { {
if(enabled)
{
callback_logger->_formatter->format_header(callback_logger->_logger_name, callback_logger->_formatter->format_header(callback_logger->_logger_name,
msg_level, msg_level,
log_clock::now(), log_clock::now(),
@ -40,12 +42,15 @@ public:
// The move ctor should only be called on start of logging line, // The move ctor should only be called on start of logging line,
// where no logging happened yet for this line so no need to copy the string from the other // where no logging happened yet for this line so no need to copy the string from the other
_oss(), _oss(),
_level(other._level) { _level(other._level)
{
}; };
~line_logger() { ~line_logger()
if (_enabled) { {
if (_enabled)
{
_oss << '\n'; _oss << '\n';
_callback_logger->_log_it(_oss.str_ref(), _level); _callback_logger->_log_it(_oss.str_ref(), _level);
} }
@ -53,7 +58,8 @@ public:
template<typename T> template<typename T>
line_logger&& operator<<(const T& msg) && { line_logger&& operator<<(const T& msg) &&
{
if (_enabled) if (_enabled)
_oss << msg; _oss << msg;
return std::move(*this); return std::move(*this);

View File

@ -31,7 +31,8 @@ class default_formatter: public formatter
{ {
public: public:
// Format: [2013-12-29 01:04:42.900] [logger_name:Info] Message body // Format: [2013-12-29 01:04:42.900] [logger_name:Info] Message body
void format_header(const std::string& logger_name, level::level_enum level, const log_clock::time_point& tp, std::ostream& dest) override { void format_header(const std::string& logger_name, level::level_enum level, const log_clock::time_point& tp, std::ostream& dest) override
{
_format_time(tp, dest); _format_time(tp, dest);
if(!logger_name.empty()) if(!logger_name.empty())
dest << " [" << logger_name << ":" << c11log::level::to_str(level) << "] "; dest << " [" << logger_name << ":" << c11log::level::to_str(level) << "] ";
@ -61,7 +62,8 @@ inline void c11log::formatters::default_formatter::_format_time(const log_clock:
auto tm_now = details::os::localtime(log_clock::to_time_t(tp)); auto tm_now = details::os::localtime(log_clock::to_time_t(tp));
using namespace c11log::details::os; using namespace c11log::details::os;
if(last_tm != tm_now) { if(last_tm != tm_now)
{
#ifdef _MSC_VER #ifdef _MSC_VER
::sprintf_s ::sprintf_s
#else #else

View File

@ -33,8 +33,8 @@ public:
using sinks_vector_t = std::vector<sink_ptr>; using sinks_vector_t = std::vector<sink_ptr>;
using sinks_init_list = std::initializer_list<sink_ptr>; using sinks_init_list = std::initializer_list<sink_ptr>;
logger(const std::string& name, formatter_ptr f, sinks_init_list sinks_list); logger(const std::string& name, formatter_ptr, sinks_init_list);
logger(const std::string& name, sinks_init_list sinks_list); logger(const std::string& name, sinks_init_list);
logger(sinks_init_list sinks_list); logger(sinks_init_list sinks_list);

View File

@ -67,9 +67,12 @@ inline void c11log::sinks::async_sink::_thread_loop()
static std::chrono::seconds pop_timeout { 1 }; static std::chrono::seconds pop_timeout { 1 };
std::string msg; std::string msg;
while (_active) { while (_active)
if (_q.pop(msg, pop_timeout)) { {
for (auto &sink : _sinks) { if (_q.pop(msg, pop_timeout))
{
for (auto &sink : _sinks)
{
sink->log(msg, static_cast<level::level_enum>(_level.load())); sink->log(msg, static_cast<level::level_enum>(_level.load()));
if (!_active) if (!_active)
return; return;
@ -92,7 +95,8 @@ inline void c11log::sinks::async_sink::remove_sink(logger::sink_ptr sink_ptr)
inline void c11log::sinks::async_sink::shutdown(const std::chrono::seconds &timeout) inline void c11log::sinks::async_sink::shutdown(const std::chrono::seconds &timeout)
{ {
auto until = std::chrono::system_clock::now() + timeout; auto until = std::chrono::system_clock::now() + timeout;
while (_q.size() > 0 && std::chrono::system_clock::now() < until) { while (_q.size() > 0 && std::chrono::system_clock::now() < until)
{
std::this_thread::sleep_for(std::chrono::milliseconds(200)); std::this_thread::sleep_for(std::chrono::milliseconds(200));
} }
_shutdown(); _shutdown();
@ -100,7 +104,8 @@ inline void c11log::sinks::async_sink::shutdown(const std::chrono::seconds &time
inline void c11log::sinks::async_sink::_shutdown() inline void c11log::sinks::async_sink::_shutdown()
{ {
if(_active) { if(_active)
{
_active = false; _active = false;
if (_back_thread.joinable()) if (_back_thread.joinable())
_back_thread.join(); _back_thread.join();

View File

@ -14,20 +14,24 @@ class base_sink
{ {
public: public:
base_sink() = default; base_sink() = default;
base_sink(level::level_enum l):_level(l) { base_sink(level::level_enum l):_level(l)
{
}; };
virtual ~base_sink() = default; virtual ~base_sink() = default;
base_sink(const base_sink&) = delete; base_sink(const base_sink&) = delete;
base_sink& operator=(const base_sink&) = delete; base_sink& operator=(const base_sink&) = delete;
void log(const std::string &msg, level::level_enum level) { void log(const std::string &msg, level::level_enum level)
if (level >= _level) { {
if (level >= _level)
{
_sink_it(msg); _sink_it(msg);
} }
}; };
void set_level(level::level_enum level) { void set_level(level::level_enum level)
{
_level = level; _level = level;
} }
@ -39,7 +43,8 @@ protected:
class null_sink:public base_sink class null_sink:public base_sink
{ {
protected: protected:
void _sink_it(const std::string& ) override { void _sink_it(const std::string& ) override
{
} }
}; };
} }

View File

@ -19,7 +19,8 @@ public:
virtual ~console_sink() = default; virtual ~console_sink() = default;
protected: protected:
virtual void _sink_it(const std::string& msg) override { virtual void _sink_it(const std::string& msg) override
{
std::lock_guard<std::mutex> lock(_mutex); std::lock_guard<std::mutex> lock(_mutex);
_ostream << msg; _ostream << msg;
} }

View File

@ -12,20 +12,22 @@ namespace sinks
{ {
/* /*
* Trivial file sink with single file as target * Thread safe, trivial file sink with single file as target
*/ */
class simple_file_sink : public base_sink class simple_file_sink : public base_sink
{ {
public: public:
explicit simple_file_sink(const std::string &filename, explicit simple_file_sink(const std::string &filename,
const std::string& extension, const std::string& extension,
const std::chrono::milliseconds &flush_every=std::chrono::milliseconds::zero()) const std::size_t flush_every=0)
: _mutex(), : _mutex(),
_ofstream(filename + "." + extension, std::ofstream::binary|std::ofstream::app), _ofstream(filename + "." + extension, std::ofstream::binary|std::ofstream::app),
_flush_helper(flush_every) { _flush_helper(flush_every)
{
} }
protected: protected:
void _sink_it(const std::string& msg) override { void _sink_it(const std::string& msg) override
{
std::lock_guard<std::mutex> lock(_mutex); std::lock_guard<std::mutex> lock(_mutex);
_flush_helper.write(_ofstream, msg); _flush_helper.write(_ofstream, msg);
} }
@ -37,14 +39,14 @@ private:
/* /*
* Thread safe, size limited file sink * Thread safe, rotating file sink based on size
*/ */
class rotating_file_sink : public base_sink class rotating_file_sink : public base_sink
{ {
public: public:
rotating_file_sink(const std::string &base_filename, const std::string &extension, rotating_file_sink(const std::string &base_filename, const std::string &extension,
size_t max_size, size_t max_files, const std::size_t max_size, const std::size_t max_files,
const std::chrono::milliseconds &flush_every = std::chrono::milliseconds::zero()): const std::size_t flush_every=0):
_base_filename(base_filename), _base_filename(base_filename),
_extension(extension), _extension(extension),
_max_size(max_size), _max_size(max_size),
@ -52,14 +54,17 @@ public:
_current_size(0), _current_size(0),
_mutex(), _mutex(),
_ofstream(_calc_filename(_base_filename, 0, _extension), std::ofstream::binary), _ofstream(_calc_filename(_base_filename, 0, _extension), std::ofstream::binary),
_flush_helper(flush_every) { _flush_helper(flush_every)
{
} }
protected: protected:
void _sink_it(const std::string& msg) override { void _sink_it(const std::string& msg) override
{
std::lock_guard<std::mutex> lock(_mutex); std::lock_guard<std::mutex> lock(_mutex);
_current_size += msg.length(); _current_size += msg.length();
if (_current_size > _max_size) { if (_current_size > _max_size)
{
_rotate(); _rotate();
_current_size = msg.length(); _current_size = msg.length();
} }
@ -68,7 +73,8 @@ protected:
private: private:
static std::string _calc_filename(const std::string& filename, std::size_t index, const std::string& extension) { static std::string _calc_filename(const std::string& filename, std::size_t index, const std::string& extension)
{
std::ostringstream oss; std::ostringstream oss;
if (index) if (index)
oss << filename << "." << index << "." << extension; oss << filename << "." << index << "." << extension;
@ -83,10 +89,12 @@ private:
// log n-2.txt -> log.n-1.txt // log n-2.txt -> log.n-1.txt
// ... // ...
// log.txt -> log.1.txt // log.txt -> log.1.txt
void _rotate() { void _rotate()
{
_ofstream.close(); _ofstream.close();
//Remove oldest file //Remove oldest file
for (auto i = _max_files; i > 0; --i) { for (auto i = _max_files; i > 0; --i)
{
auto src = _calc_filename(_base_filename, i - 1, _extension); auto src = _calc_filename(_base_filename, i - 1, _extension);
auto target = _calc_filename(_base_filename, i, _extension); auto target = _calc_filename(_base_filename, i, _extension);
if (i == _max_files) if (i == _max_files)
@ -106,26 +114,29 @@ private:
}; };
/* /*
* Thread safe file sink that closes the log file at midnight and opens new one * Thread safe, rotating file sink based on date. rotates at midnight
*/ */
class daily_file_sink:public base_sink class daily_file_sink:public base_sink
{ {
public: public:
explicit daily_file_sink(const std::string& base_filename, explicit daily_file_sink(const std::string& base_filename,
const std::string& extension, const std::string& extension,
const std::chrono::milliseconds &flush_every = std::chrono::milliseconds::zero()): const std::size_t flush_every=0):
_base_filename(base_filename), _base_filename(base_filename),
_extension(extension), _extension(extension),
_midnight_tp (_calc_midnight_tp() ), _midnight_tp (_calc_midnight_tp() ),
_mutex(), _mutex(),
_ofstream(_calc_filename(_base_filename, _extension), std::ofstream::binary|std::ofstream::app), _ofstream(_calc_filename(_base_filename, _extension), std::ofstream::binary|std::ofstream::app),
_flush_helper(flush_every) { _flush_helper(flush_every)
{
} }
protected: protected:
void _sink_it(const std::string& msg) override { void _sink_it(const std::string& msg) override
{
std::lock_guard<std::mutex> lock(_mutex); std::lock_guard<std::mutex> lock(_mutex);
if (std::chrono::system_clock::now() >= _midnight_tp) { if (std::chrono::system_clock::now() >= _midnight_tp)
{
_ofstream.close(); _ofstream.close();
_ofstream.open(_calc_filename(_base_filename, _extension)); _ofstream.open(_calc_filename(_base_filename, _extension));
_midnight_tp = _calc_midnight_tp(); _midnight_tp = _calc_midnight_tp();
@ -135,7 +146,8 @@ protected:
private: private:
// Return next midnight's time_point // Return next midnight's time_point
static std::chrono::system_clock::time_point _calc_midnight_tp() { static std::chrono::system_clock::time_point _calc_midnight_tp()
{
using namespace std::chrono; using namespace std::chrono;
auto now = system_clock::now(); auto now = system_clock::now();
time_t tnow = std::chrono::system_clock::to_time_t(now); time_t tnow = std::chrono::system_clock::to_time_t(now);
@ -146,7 +158,8 @@ private:
} }
//Create filename for the form basename.YYYY-MM-DD.extension //Create filename for the form basename.YYYY-MM-DD.extension
static std::string _calc_filename(const std::string& basename, const std::string& extension) { static std::string _calc_filename(const std::string& basename, const std::string& extension)
{
std::tm tm = c11log::details::os::localtime(); std::tm tm = c11log::details::os::localtime();
std::ostringstream oss; std::ostringstream oss;
oss << basename << '.'; oss << basename << '.';