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.

  • Could you share the benchmark code? – user673679 Apr 13 at 12:50
  • The benchmark code is in the main.cpp file. Bear in mind that the benchmark was performed without using the get_time_string(). – seepp Apr 13 at 13:14
  • Hmm. So is that output something you put together manually? If you're comparing printing just one line with the logger vs cout, and then exiting the program, then you're creating the static logger (a std::ostringstream) every time... – user673679 Apr 13 at 13:23
  • So I'm just running one block and commenting the other out. I apologise if my benchmark is unscrupulous, I've never really put one together before. How could it be improved? Should I be logging many more things at a time? – seepp Apr 13 at 13:41
  • I'll put some more details in an answer in a few hours (some other stuff to do first). (Also, I should have said "starting a thread" above, instead of creating a std::ostringstream above, my bad). – user673679 Apr 13 at 13:51
up vote 2 down vote accepted

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.

  • Thank you those are all good points. I'll start working on them. – seepp Apr 13 at 22:16

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.

  • Thank you for suggesting that. I'll update print_routine() function. – seepp Apr 13 at 22:21
  • condition_variable is certainly a useful tool, though I'm curious about the performance aspects. For me, it actually slowed down the main thread a bit. – user673679 Apr 14 at 6:18
  • 1
    @user673679 I can actually think of a couple reasons why that might be the case. Perhaps it would be better to, when writing a log entry, move the string out of the queue, release the lock, write the string, reacquire the lock, then repeat until the queue is empty. This is assuming writing/printing the log takes much longer than running some other bits of code. – Altainia Apr 15 at 3:06

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).

  • Thanks for the suggetion. I actually opted to move all the time unnecessary stuff in logstream to the print_routine() function(). Would it be more beneficial to have a switch statement there like in get_level_string() or use references like you suggest to an already set up array? – seepp Apr 13 at 13:12

Your Answer

 

By clicking "Post Your Answer", you acknowledge that you have read our updated terms of service, privacy policy and cookie policy, and that your continued use of the website is subject to these policies.

Not the answer you're looking for? Browse other questions tagged or ask your own question.