4
\$\begingroup\$

What it does

The code creates a logger class which instantiates a circular buffer at construction and uses producer-consumer style approach using condition_variable to log and print the messages to stdout.

Code

logger.h

#pragma once

#include <chrono>
#include <condition_variable>
#include <cstdio>
#include <iomanip>
#include <iostream>
#include <memory>
#include <mutex>
#include <sstream>
#include <stdio.h>
#include <string>
#include <sys/time.h>
#include <thread>
#include <utility>
#include <vector>

namespace TIME
{
void get_time(char*);
} // namespace TIME

class my_logger
{
    static constexpr size_t TIME_BUF_SIZE = 19;
    static constexpr size_t MESSAGE_BUFFER_SIZE = 300;
    static constexpr size_t BUFFER_SIZE = 500;
    static constexpr size_t MESSAGE_PRINT_THRESHOLD = 450;
    static_assert(MESSAGE_PRINT_THRESHOLD < BUFFER_SIZE,
                  "Message print threshold must be smaller than msg buffer size");

    std::vector<std::array<char, MESSAGE_BUFFER_SIZE>> m_to_print;
    size_t m_head;
    size_t m_tail;

    std::mutex mu_buffer;
    std::condition_variable m_consumer_cond_var;
    std::condition_variable m_producer_cond_var;
    std::atomic<bool> m_continue_logging;

    std::thread m_printing_thread;

public:
    my_logger();
    ~my_logger();

    void logging_thread();

    size_t msg_count() const
    {
        if(m_tail >= m_head)
            return m_tail - m_head;
        return m_tail + BUFFER_SIZE - m_head;
    }

    template <typename... Args>
    void log(const char* format, const char msg_type[], Args... args)
    {
        std::unique_lock lg(mu_buffer);
        // m_producer_cond_var.wait(lg, [this] { return msg_count() <= MESSAGE_PRINT_THRESHOLD; });
        auto buf_ptr = m_to_print[m_tail].data();
        const size_t N = std::strlen(msg_type);
        TIME::get_time(buf_ptr);
        std::snprintf(buf_ptr + TIME_BUF_SIZE - 1, N + 1, "%s", msg_type);
        std::snprintf(buf_ptr + TIME_BUF_SIZE + N - 1,
                      MESSAGE_BUFFER_SIZE - N - TIME_BUF_SIZE + 1,
                      format,
                      std::forward<Args>(args)...);
        m_tail = (m_tail + 1) % BUFFER_SIZE;

        if(msg_count() > MESSAGE_PRINT_THRESHOLD)
        {
            lg.unlock();
            m_consumer_cond_var.notify_one(); // notify the single consumer
        }
    }

    template <typename... Args>
    void info(const char* format, Args... args)
    {
        log(format, " [INFO] ", std::forward<Args>(args)...);
    }

    template <typename... Args>
    void warn(const char* format, Args... args)
    {
        log(format, " [WARN] ", std::forward<Args>(args)...);
    }

    template <typename... Args>
    void error(const char* format, Args... args)
    {
        log(format, " [ERROR] ", std::forward<Args>(args)...);
    }
};

logger.cpp

#include "logger.h"
#include <algorithm>
#include <mutex>

namespace TIME
{
void get_time(char* buf)
{
    auto currentTime = std::chrono::high_resolution_clock::now();
    auto nanoSeconds = std::chrono::time_point_cast<std::chrono::nanoseconds>(currentTime);

    auto nanoSecondsCount = nanoSeconds.time_since_epoch().count();

    // Convert nanoseconds to seconds and fractional seconds
    auto fracSeconds = nanoSecondsCount % 1'000'000'000;

    // Convert seconds to std::time_t
    std::time_t time = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());

    // Convert time to struct tm in local time zone
    std::tm* tm = std::localtime(&time);

    std::strftime(buf, 9, "%H:%M:%S.", std::localtime(&time));
    std::snprintf(buf + 9, 10, "%09lld", fracSeconds);
}
} // namespace TIME

my_logger::my_logger()
    : m_head(0)
    , m_tail(0)
    , m_continue_logging(true)
{
    m_to_print.assign(BUFFER_SIZE, {});
    m_printing_thread = std::thread(&my_logger::logging_thread, this);
}

void my_logger::logging_thread()
{
    while(m_continue_logging)
    {
        std::unique_lock lg(mu_buffer);
        m_consumer_cond_var.wait(lg, [this] { return m_head != m_tail; });
        while(m_head != m_tail)
        {
            std::printf("%s\n", m_to_print[m_head].data());
            m_head = (m_head + 1) % BUFFER_SIZE;
        }

        lg.unlock();
        m_producer_cond_var.notify_all(); //notify all producers
    }
}

my_logger::~my_logger()
{
    m_continue_logging = false;
    m_consumer_cond_var.notify_one();
    if(m_printing_thread.joinable())
        m_printing_thread.join();
}

Benchmarking code

#include "logger.h"
#include <chrono>
#include <fstream>
#include <string>

int main(int argc, char* argv[])
{
    if(argc != 2)
    {
        std::cerr << "Usage: logger <file>";
        return 1;
    }

    constexpr unsigned RUNS = 33333;
    const std::string benchmark_file_path = argv[1];
    std::fstream file(benchmark_file_path, std::ios::out | std::ios::app);
    if(!file.is_open())
    {
        std::cerr << "Couldn't open " << benchmark_file_path << "\n";
        return 1;
    }

    auto start = std::chrono::high_resolution_clock::now();
    {
        my_logger logger;
        for(size_t i = 0; i < RUNS; i++)
        {
            logger.info("this is a %s string with id: %u and double: %f",
                        "sundar",
                        i,
                        static_cast<double>(i + 0.5));
            logger.warn("this is a %s string with id: %u and double: %f",
                        "WARN",
                        2 * i,
                        static_cast<double>(2 * i));
            logger.error("this is a %s string with id: %u and double: %f",
                         "ERROR",
                         4 * i,
                         static_cast<double>(4 * i));
        }
    }
    auto finish = std::chrono::high_resolution_clock::now();
    auto time1 = std::chrono::duration_cast<std::chrono::milliseconds>(finish - start).count();
    file << "RUNS: " << 3 * RUNS << " TIME_MULTITHREADED: " << time1 << " ms\n";

    start = std::chrono::high_resolution_clock::now();
    {
        char time_buf[19];
        for(size_t i = 0; i < RUNS; i++)
        {
            TIME::get_time(time_buf);
            fprintf(stdout,
                    "%s"
                    " [INFO] "
                    "this is a %s string with id: %zu and double: %f\n",
                    time_buf,
                    "atisundar",
                    i,
                    static_cast<double>(i + 0.5));

            TIME::get_time(time_buf);
            fprintf(stdout,
                    "%s"
                    " [WARN] "
                    "this is a %s string with id: %zu and double: %f\n",
                    time_buf,
                    "atisundar",
                    i,
                    static_cast<double>(2 * i));

            TIME::get_time(time_buf);
            fprintf(stdout,
                    "%s"
                    " [ERROR] "
                    "this is a %s string with id: %zu and double: %f\n",
                    time_buf,
                    "atisundar",
                    i,
                    static_cast<double>(4 * i));
        }
    }
    finish = std::chrono::high_resolution_clock::now();
    auto time2 = std::chrono::duration_cast<std::chrono::milliseconds>(finish - start).count();

    file << "RUNS: " << 3 * RUNS << " TIME_PLAIN_LOGGER: " << time2 << " ms\n";
    return 0;
}

Current performance

RUNS: 99999 TIME_MULTITHREADED: 282 ms
RUNS: 99999 TIME_PLAIN_LOGGER: 970 ms
RUNS: 99999 TIME_MULTITHREADED: 203 ms
RUNS: 99999 TIME_PLAIN_LOGGER: 972 ms
RUNS: 99999 TIME_MULTITHREADED: 217 ms
RUNS: 99999 TIME_PLAIN_LOGGER: 970 ms

Known issues

The log function in logger.h isn't thread safe because when multiple threads are trying to log and one of them causes total messages to exceed MESSAGE_PRINT_THRESHOLD, then after the unlock step in log and before notifying the m_consumer_cond_var, one of the other logging threads might take ownership of the mutex and keep writing into the buffer and potentially lead to overwriting the circular buffer. The solution I can see for this is to uncomment the m_producer_cond_var.wait line in log function, but that is causing the code to become slower than plain logger function by almost 1.5x . Can you please suggest what I may be doing wrong here?

\$\endgroup\$

1 Answer 1

Reset to default
4
\$\begingroup\$

Create a separate class for the message queue

Your class my_logger has too many responsibilities and is therefore quite complex. The first thing I would do is to create a separate class for a thread-safe message queue. Your logger class can then use that queue.

msg_count() should not be public

msg_count() should never be called from outside the class. It doesn't take a lock, so it can return incorrect values. Even if it would take a lock, by the time an outside caller would get the result, it might no longer be valid.

log() should do as little as possible

It's clear from your code that you want to optimize the throughput of the log() function. So do as much as possible without holding the lock: you can format the time and build the whole log message first, then take the lock to just push that log message onto the queue.

Even better, don't do that at all inside log(), but defer as much as possible to the logging_thread(): you still have to get the current time in log(), but instead of immediately formatting it, just store the result from now() directly in the queue.

Of course, all this requires some changes to your code, in particular how you store data in the queue.

logging_thread() should not hold the lock for a long time

Consider that you only notify the logging thread when there are at least MESSAGE_PRINT_THRESHOLD messages in the queue. It will then lock the mutex, and print all those messages. During that time, other threads that want to add a log message to the queue are blocked.

Note that you don't need to hold the lock while you are printing, at least if you make sure that the loggers wait if the queue is full.

Log messages can be dropped or printed lated

Since you currently don't block threads from adding log messages if the queue is already full, it can be that messages are being dropped. Is that OK? If not, then do add the wait() call back, and find other ways to improve performance.

However, another issue is that you wait for a threshold to start printing log messages. What if you have a situation where there is just one thread, and it only has one very important log message to print? Unfortunately, the printing thread will not be woken up, and you have to wait for the destructor to be called before it will finally wake up.

Also, it can happen that m_continue_logging is set to false when there are still messages in the buffer, and the printing thread could then exit before it as printed all messages. More about that below.

Avoid using C functions

You are using C functions like strftime(), snprintf(), and so on, when there are much better C++ equivalents for them. In particular, you can use std::format_to_n() to format strings to a buffer. It can also directly format time.

I also see you mixing fprintf(stderr, …) and std::cerr << …. Don't mix C's stdio and C++'s iostreams, it's not guaranteed how those will interact.

Avoid std::chrono::high_resolution_clock()

There is no guarantee what kind of time std::chrono::high_resolution_clock() actually returns. It might give you something that follows wall clock time, or it might follow some other timer that doesn't track the actual time. Either use std::chrono::system_clock() if you need wall clock time (so you can compare timestamps with events outside the local computer), or if you really need high resolution timestamps so you can more accurately see in which order things happen on the local computer, use std::chrono::steady_clock().

Don't mix atomics and mutexes

Because m_continue_logging is not guarded by the same mutex as m_head and m_tail, it can happen that something sets m_continue_logging to false between the check in the while-condition and the subsequent m_consumer_cond_var.wait(). Note that any notifications sent before wait() is called are ignored. So this can cause the printing thread to hang indefinitely.

Make m_continue_logging a regular bool, and check it in the predicate you pass to wait(). And in the destructor, you still need to take a lock when setting it to false.

No need to check for m_printing_thread.joinable()

Since you always start the thread in the constructor, m_printing_thread will always be joinable when you call the destructor. But even better:

Use std::jthread

Instead of manually joining a std::thread, use std::jthread; it takes care of this automatically.

You only need one condition variable

It is extremely unlikely that the printing thread is waiting for the queue to become non-empty, and any other threads waiting for the queue to become non-full at the same time. So there is no need to have two condition variables.

\$\endgroup\$
3
  • \$\begingroup\$ Regarding the log() function you mentioned, how can I avoid the formatting of message inside log()? I can store format, now() and msg_type parameters in a queue but how will I store variable list of args...? I must format them into a char* or std::format to store them in a queue right? \$\endgroup\$ Commented Feb 24, 2024 at 14:15
  • \$\begingroup\$ In logging_thread() why do I not need to hold the lock while printing? Is it because logging_thread() only modifies m_head and log() modifies m_to_print and m_tail? \$\endgroup\$ Commented Feb 24, 2024 at 15:33
  • 1
    \$\begingroup\$ @wwite You could store the arguments in an object, for example by using std::make_format_args(). You can also format the arguments but not format the time. If you do any kind of formatting though, do that outside the lock. And yes, logging_thread() can indeed print without a lock because it's the only thread modifying m_head. \$\endgroup\$ Commented Feb 24, 2024 at 17:30

You must log in to answer this question.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.