C++ Threaded Logger

Question

What is it?

It's a fairly simple logger which utilises a thread.

How it works

Note: this a pretty terrible explanation, perhaps it would be easier to look at the code.

The logger class is a singleton, which contains the function log(). Upon logs()'s first use a static logger instance is created. The function then returns a logstream object (constructed with a reference to the logger), which is a derivative of std::ostringstream. This object is used to format the message. Upon its destruction it sends the formatted std::string back to the logger using the push() function, which locks a mutex and then appends the std::string to a private std::queue belonging to the logger.

When the logger is constructed it creates a thread running the print_routine() function, which is a loop that locks a mutex and prints all the contents of the std::queue, and then sleeps for a set interval. Upon destruction it tells the routine to finish by setting the bool print to false and joins the thread.

Code

log_enum.h

#ifndef ANDROMEDA_LOG_ENUM_H
#define ANDROMEDA_LOG_ENUM_H

namespace andromeda {

enum class log_level {
    info,
    warning,
    severe,
    fatal
};

}

#endif

logger.h

#ifndef ANDROMEDA_LOGGER_H
#define ANDROMEDA_LOGGER_H

#include <sstream>
#include <mutex>
#include <queue>
#include <chrono>
#include <thread>

#include "log_enum.h"

namespace andromeda {
    class logger;
}

#include "logstream.h"

namespace andromeda {

class logger {
    std::queue<std::string> m_q;
    std::mutex m_q_mu;

    std::mutex m_stdout_mu;
    std::mutex m_stderr_mu;

    std::thread m_print_thread;
    bool m_print = true;
    static void print_routine(logger *instance, std::chrono::duration<double, std::milli> interval);    

    logger();
    ~logger();
public:
    logger(logger const&) = delete;
    void operator=(logger const&) = delete;

    static logstream log(log_level level = log_level::info) {
        static logger m_handler;
        return logstream(m_handler, level);
    }

    void push(std::string fmt_msg);
};

}

#endif

logger.cpp

#include "logger.h"

#include <iostream>

namespace andromeda {

logger::logger()
{
    m_print_thread = std::thread(print_routine, this, std::chrono::milliseconds(16));
}

logger::~logger()
{
    m_print = false;
    m_print_thread.join();
}

void logger::push(std::string fmt_msg)
{
    std::lock_guard<std::mutex> lock(m_q_mu);
    m_q.push(fmt_msg);
}

void logger::print_routine(logger *instance, std::chrono::duration<double, std::milli> interval)
{
    while(instance->m_print || !instance->m_q.empty()) {
        auto t1 = std::chrono::steady_clock::now();
        {
            std::lock_guard<std::mutex> lock(instance->m_q_mu);
            while(!instance->m_q.empty()) {
                std::cout << instance->m_q.front() << std::endl;
                instance->m_q.pop();
            }
        }
        auto t2 = std::chrono::steady_clock::now();
        std::chrono::duration<double, std::milli> time_took = t2 - t1;
        //sleep
        if(time_took < interval && instance->m_print) {
            std::this_thread::sleep_for(interval - time_took);
        }
    }
}

}

logstream.h

#ifndef ANDROMEDA_LOGSTREAM_H
#define ANDROMEDA_LOGSTREAM_H

#include <sstream>

#include "log_enum.h"

namespace andromeda {

class logger;

class logstream : public std::ostringstream {
    logger& m_logger;
    log_level m_level;

    std::string get_level_string();
    std::string get_time_string();
public:
    logstream(logger& log, log_level);
    ~logstream();
};

}

#endif

logstream.cpp

#include "logstream.h"

#include <ctime>
#include "logger.h"

namespace andromeda {

logstream::logstream(logger& log, log_level level) : m_logger(log), m_level(level)
{}

logstream::~logstream()
{
    //note: not using time yet because it adds 0.015 ms
    //m_logger.push(get_time_string() + get_level_string() + str());
    m_logger.push(get_level_string() + str());

}

std::string logstream::get_level_string()
{
    std::string temp;
    switch(m_level) {
        case log_level::info: temp = "[INFO]"; break;
        case log_level::warning: temp = "[WARNING]"; break;
        case log_level::severe: temp = "[SEVERE]"; break;
        case log_level::fatal: temp = "[FATAL]"; break;
    }
    return temp;    //copy ellision should be guaranteed with a C++17 compiler
}

std::string logstream::get_time_string()
{
    std::time_t t = std::time(nullptr);
#ifdef _WIN32
    std::tm time;
    localtime_s(&time, &t);
#else
    std::tm time = *std::localtime(&t);
#endif
    char t_str[20];
    std::strftime(t_str, sizeof(t_str), "%T", &time);

    return ("[" + std::string(t_str) + "]");
}

}

main.cpp

#include "logger/logger.h"

#include <iostream>

int main(int argc, char **argv) {
    {
        using namespace andromeda;
        auto t1 = std::chrono::steady_clock::now();
        logger::log() << "Hello World";
        auto t2 = std::chrono::steady_clock::now();

        /*
        auto t3 = std::chrono::steady_clock::now();
        std::cout << "Hello World" << std::endl;
        auto t4 = std::chrono::steady_clock::now();
        */

        std::chrono::duration<double, std::milli> d1 = t2 - t1;
        //std::chrono::duration<double, std::milli> d2 = t4 - t3;
        logger::log() << "logger took " << d1.count() << "ms";
        //std::cout << "cout took " << d2.count() << "ms" << std::endl;

        //This line is here to make test whether everything is printed before program exit
        logger::log(log_level::fatal) << "end of program test: " << 33;
    }
    return 0;
}

Benchmark

I ran a benchmark of this logger vs std::cout without using the time.

run 1: logger = 0.02925ms  and cout = 0.007725ms -> log/cout = 3.77
run 2: logger = 0.028469ms and cout = 0.008442ms -> log/cout = 3.37
run 3: logger = 0.027484ms and cout = 0.016155ms -> log/cout = 1.7
run 4: logger = 0.028764ms and cout = 0.007859ms -> log/cout = 3.66
run 5: logger = 0.027457ms and cout = 0.008173ms -> log.cout = 3.36

On average the logger was 3.172 times slower than std::cout. Is tha bad?

What I'm aiming for

I'm aiming for it to be reasonably fast, thread-safe and cross-platform.

What I think could be improved

I think the get_time_string() could be improved. At the moment it worsens performance by about 50%. Another things is the detail. I think it might be a good idea to perhaps include the source and thread id. One last minor thing is the log_level. I don't have much experience so I don't know how many different levels are required for bigger projects.

Any feedback is appreciated.

Answer 1

Benchmarking

It's better to have more datapoints, rather than fewer in a benchmark. So it's best to execute code multiple times and take an average (or just measure the total), than to run it once.

Also (as mentioned above) the first time logger::log() is called, the static variable is initialised, creating a new thread. So a better benchmark would be something like:

    logger::log(); // get thread creation out of the way...

    auto runs = 500;

    auto t1 = std::chrono::high_resolution_clock::now();

    for (auto i = 0; i != runs; ++i)
        logger::log() << "Hello World";

    auto t2 = std::chrono::high_resolution_clock::now();

which for me gives 0.812507ms. (The first call to logger::log() takes around 1.31655ms, btw).

Routing the same thing directly to std::cout takes ~500ms!

---

One extra note: comparing the time taken by the logger in the main thread with the time taken by std::cout is comparing two different things. The logger call creates / copies / concatenates some strings and adds them to a queue, whereas cout is actually sending stuff to standard output.

Since the logger is doing the same work with cout in another thread anyway, we should treat the time taken by the logger::log() calls in the main thread as overhead added on top of cout.

We could isolate that overhead and profile it. (Running under a profiler with the number of runs at 500000, and commenting out a line in logger.cpp: //std::cout << instance->m_q.front() << std::endl; gives decent indications as to what takes the most time).

Beyond checking the overhead on the other thread, or pure curiosity, there's not much point. An overhead of 0.8ms on ~500ms of work is probably fine.

---

Code - minor inefficiencies

• get_level_string() and get_time_string() can both be const.

Since we're focused on performance...

• The level strings could be static members of the logstream class, which removes the need to create them every time.

• Rather than using a temporary buffer, we can use std::strftime to write directly into a std::string, something like:

  std::string result(21, '[');
  auto charsWritten = std::strftime(&result[1], result.size() - 1, "%T", &time);
  result[1 + charsWritten] = ']';
  result.resize(1 + charsWritten + 1);
  return result;
  

• Concatenating multiple strings (e.g. m_logger.push(get_time_string() + get_level_string() + str()); can be inefficient, due to creating intermediate string objects which may need multiple allocations. This can be avoided by creating an output string object, .reserve()ing the necessary size, and using the += operator to copy each one into the output string.

• m_q.push(std::move(fmt_msg)); avoid a copy!

• get_level_string() and get_time_string() can both be const.

These are all minor things though. A profiler will tell you what actually needs changing.

Answer 2

Threading

I would advise you learn about std::condition_variable.

Basically, you can have a thread wait for a condition variable to be triggered instead of having to constantly poll your queue to see if there's data to be read. This can improve performance as you can react as soon as there's new data instead of (potentially) a delay of your wait time. Also, you will use less CPU this way. Consider the following:

void logger::push(std::string fmt_msg)
{
  std::unique_lock<std::mutex> lg(m_q_mu);
  m_q.push(fmt_msg);
  m_cv.notify_all(); //where m_cv is a std::condition_variable belonging to logger. Calling notify_all will cause any thread that's sleeping on this condition variable to wake up.
}

In your print_routine method, then...

void logger::print_routine(logger* instance)
{
  std::unique_lock<std::mutex> lg(m_q_mu)
  while(instance->m_print)
  {
    for(auto& str : instance->m_q)
    {
      std::cout << q << '\n';
    }
    instance->m_q.clear();
    m_cv.wait(lg, [instance]{return !instance->m_print || !instance->m_q.empty();});
    //Upon calling wait, the mutex locked by lg will be unlocked and the thread will sleep until it's notified.
    //When that happens, it will re-lock the mutex and run the predicate.
    //If it returns true (which will happen if m_print is now false or if there's now something in the queue) then wait will end. Otherwise, the mutex will be unlocked again and the thread will go back to sleep.
    //So, once wait ends, either m_print is false or the queue is not empty.
    //If m_print is false, the while loop will then see so and exit.
    //If m_print is not false, the while loop will continue, which will mean printing out the messages in the queue and then clearing it, then waiting again.
  }
}

Finally, to stop printing...

logger::~logger()
{
  m_print = false;
  m_cv.notify_all();
  if(m_print_thread.joinable())
  {
    m_print_thread.join();
  }
}

---

Unused code

I don't see the two m_stdout_mu and m_stderr_mu mutexes being used anywhere.

Answer 3

In logstream::get_level_string rather than copy a literal into a std::string and then copy that as the return value you could return a reference to a static public array containing the strings (which had been set up by the constructor).