Multithreaded logger

Question

I made a multithreaded logger years ago when I was still a total newbie. It "worked" (when it didn't deadlock). Now that I'm slightly less newbie I'd like to get some criticism on this new version.

The logger spawns an internal thread on its own method writer(), whose purpose is writing (to console and to file) the logging information.

There are two queues, one from which the writer writes data (queue_write), the other where the rest of the program can push data (queue_log). Upon pushing, the writer is awakened, it takes control of a mutex to make sure no other thread is accessing the queue_log queue, and it swaps the content with queue_write; then releases the lock. That way, threads using the logger would at worst have to wait for a simple pointer swap between two queues, which should be efficient.

After the swap, the writer thread empties his new queue on the output streams, until it's empty, then proceeds to check if the logger is still running (false when destructed or explicitly closed), takes the lock again, and if the queue_log is empty it goes asleep releasing the lock.

A couple of notes:

• The "utils" namespace is a namespace of utilities I made for myself and willingly reflects the STL implementation. The choice of having the class start in lower case is made on purpose.
• The logger is made with one thread producing and the inner thread consuming; it's not made for multiple consumers. It can have multiple producers but it's not optimized with that in mind.
• The Message class I use in the usage example is stripped down of all the non-relevant content (I've another portion of utils taking care of colouring output to console).

logger.h

#pragma once
#include <fstream>
#include <iostream>
#include <queue>
#include <thread>
#include <mutex>
namespace utils
 {
 //TODO
 // With C++20 replace the time_points with actual readable time https://stackoverflow.com/questions/62954221/c-print-chronotime-pointchronohigh-resolution-clock-to-be-readable
 template <typename Message_type>
 class logger
 {
 private:
 std::ofstream file;
 std::queue<Message_type> queue_log;
 std::queue<Message_type> queue_write;
 std::thread thread;
 std::atomic_bool running = true;
 std::mutex queue_free;
 std::condition_variable work_available;
 void writer()
 {
 while (running)
 {
 if (true)
 {
 std::unique_lock lock{queue_free};
 if (queue_log.empty()) { work_available.wait(lock); }
 queue_write.swap(queue_log);
 }
 write_all();
 }
 }
 void write_all()
 {
 while (!queue_write.empty())
 {
 Message_type& message = queue_write.front();
 std::cout << message << std::endl;
 file << message << std::endl;
 queue_write.pop();
 }
 }
 public:
 logger(const std::string& file_name = "log.txt")
 : thread(&logger::writer, this) { file.open(file_name); }
 logger(const logger& copy) = delete; // don't copy threads please, thank you
 logger& operator=(const logger& copy) = delete; // don't copy threads please, thank you
 logger(logger&& move) noexcept = default; //could make those (running is already a flag for the instance being alive or not) but I'm lazy
 logger& operator=(logger&& move) = default; //could make those (running is already a flag for the instance being alive or not) but I'm lazy
 ~logger() { if (running) { close(); } }
 //Push messages begin
 void operator<<(const Message_type& message) { push(message); }
 void operator()(const Message_type& message) { push(message); }
 template <typename ...Args>
 void emplace(Args&&... args)
 {
 Message_type message{args...};
 push(message);
 }
 void push(const Message_type& message)
 {
 if (true)
 {
 std::lock_guard lock(queue_free);
 queue_log.push(message);
 }
 work_available.notify_one();
 }
 //Push messages end
 void close()
 {
 running = false;
 work_available.notify_one();
 thread.join();
 queue_write.swap(queue_log);
 write_all();
 file.close();
 }
 };
 }

---

Usage example

Message.h

#pragma once
#include <chrono>
#include <iomanip>
#include <string>
#include <string_view>
class Message
 {
 private:
 static std::string filter_last_newline(const std::string& string)
 {
 if (string.length() > 0 && string[string.length() - 1] == '\n') { return string.substr(0, string.length() - 1); }
 else { return string; }
 }
 public:
 enum class Type { log, dgn, inf, wrn, err };
 Message(Type type, const std::string& string, std::chrono::time_point<std::chrono::system_clock> time) noexcept
 : type(type), string(string), time(time)
 {}
 Message(Type type, const std::string& string) noexcept
 : type(type), string(string), time(std::chrono::system_clock::now())
 {}
 Message(const std::string& string) noexcept
 : type(Type::log), string(string), time(std::chrono::system_clock::now())
 {}
 Type type = Type::log;
 std::string string = "";
 std::chrono::time_point<std::chrono::system_clock> time;
 const char* out_type() const noexcept
 {
 switch (type)
 {
 case Message::Type::log: return "[LOG]"; // [LOG]
 case Message::Type::dgn: return "[DGN]"; // [DIAGNOSTIC]
 case Message::Type::inf: return "[INF]"; // [INFO]
 case Message::Type::wrn: return "[WRN]"; // [WARNING]
 case Message::Type::err: return "[ERR]"; // [ERROR]
 }
 }
 static Message log(const std::string& string) { return {Type::log, filter_last_newline(string), std::chrono::system_clock::now()}; }
 static Message dgn(const std::string& string) { return {Type::dgn, filter_last_newline(string), std::chrono::system_clock::now()}; }
 static Message inf(const std::string& string) { return {Type::inf, filter_last_newline(string), std::chrono::system_clock::now()}; }
 static Message wrn(const std::string& string) { return {Type::wrn, filter_last_newline(string), std::chrono::system_clock::now()}; }
 static Message err(const std::string& string) { return {Type::err, filter_last_newline(string), std::chrono::system_clock::now()}; }
 friend std::ostream& operator<<(std::ostream& os, const Message& m)
 {
 size_t beg = 0;
 size_t end = m.string.find_first_of('\n', beg);
 if (end == std::string::npos) { end = m.string.length(); }
 //First line
 os << std::setw(18) << m.time.time_since_epoch().count() << ' ';
 os << m.out_type();
 os << ' ' << std::string_view(m.string).substr(beg, end - beg) << '\n';
 //Other lines
 while (true)
 {
 if (end == m.string.length()) { break; }
 else
 {
 beg = end + 1;
 end = m.string.find_first_of('\n', beg);
 if (end == std::string::npos) { end = m.string.length(); }
 }
 os << std::setw(24) << '|';
 os << ' ' << std::string_view(m.string).substr(beg, end - beg) << '\n';
 }
 return os;
 }
 };

Main.cpp

#include "utils/logger.h"
#include "Message.h"
int main()
 {
 utils::logger<Message> logger;
 logger.push(Message(Message::Type::err, "This is a verbose way to write an error."));
 logger.emplace(Message::Type::err, "This is a still quite verbose to write an error.");
 logger.push(Message::err("This is a less verbose way to write an error."));
 logger << Message::err("This is the slightly shorter way to write an error.");
 logger(Message::err("This is the shortest I could think of, although far from the \"standard\" way of doing things."));
 logger(Message::wrn("Multi\nline\nwarning\njust\nto\nmake\nsure\nit\nworks."));
 return 0;
 }

• Toby Speight: One question - why are the messages written to std::cout rather than to std::clog?
• Barnack: @TobySpeight they're not necessarily errors, and clog outputs to the error channel. There's arguments for either of them, I just didn't want to make its usage more clunky than it already is by asking the user what stream he wants to output on too.
• Emily L.: Can you clarify why you need a multi threaded logger instead of a thread safe logger?
• Barnack: @EmilyL. any instance where the thread outputting log messages needs to spend as little time logging as possible. Then you have the second thread bothering with slow i/o operation while the rest of the program can keep doing what it's doing as fast as it can. An example could be a game engine, this way you can log multiple things every frame without it inhibiting the fps too much.

Answer 1

While formatting is a matter of preference, you shouldn't stray too far away from common ground. Consider moving your opening and closing brackets back, so:

int main()
{
 return 0;
}

instead of

int main()
 {
 return 0;
 }

---

Message_type

Make a stand, either CamelCase or snake_case, not some weird offspring.

---

 while (running)
 {
 if (true)

if (true) is redundant here, you can use { .. } only.

---

if (queue_log.empty()) { work_available.wait(lock); }

instead go:

work_available.wait(lock, [&]() { return !running || !queue_log.empty(); });

std::condition_variable::wait() might awake spuriously (without reason), in which case your queue_log will be empty and you called write_all for nothing. wait call with predicate takes care of this.

---

Message_type& message = queue_write.front();

use auto:

auto& message = queue_write.front();

this will make refactoring the code easier.

---

 while (!queue_write.empty())
 {
 Message_type& message = queue_write.front();
 std::cout << message << std::endl;
 file << message << std::endl;
 queue_write.pop();
 }

Use std::vector instead of std::queue - you don't need to pop from queue_write, you can just iterate over it and destroy it all together. So:

for(auto &message : queue_write) {
 std::cout << message << std::endl;
 file << message << std::endl;
}

and:

 std::vector<Message_type> queue_log;
 std::vector<Message_type> queue_write;

instead of:

 std::queue<Message_type> queue_log;
 std::queue<Message_type> queue_write;

---

Pass queue_write by an argument. Don't keep it as member field. Passing it as an argument shows the value is "private" to a caller and callee. When you put it as a member field, every member function can access it so anyone else will have to scan more source code to see, that it's being accessed in two functions only. So:

 void write_all(const std::vector<Message_type> &queue_write) {
 for(auto &message: queue_write) {
 std::cout << message << std::endl;
 file << message << std::endl;
 }
 }

and

 void writer() {
 while (running) {
 std::vector<Message_type> queue_write;
 {
 std::unique_lock lock{queue_free};
 if (queue_log.empty()) { work_available.wait(lock); }
 queue_write.swap(queue_write);
 }
 write_all(queue_write);
 }
 }

---

 logger(const std::string& file_name = "log.txt")
 : thread(&logger::writer, this) { file.open(file_name); }

this is undefined behaviour (race condition) and major error. You create a thread, which uses file variable and also uses this variable in a constructor, which is on different thread. Instead write it like this:

 logger(const std::string& file_name = "log.txt")
 : file(file_name), thread(&logger::writer, this) {}

file variable is before thread variable, which means it will be initialized first. Thus you will certainly create thread after opening your file for writing.

---

 void operator<<(const Message_type& message) { push(message); }
 void operator()(const Message_type& message) { push(message); }

instead write:

 void operator<<(Message_type message) { push(std::move(message)); }
 void operator()(Message_type message) { push(std::move(message)); }

This might prevent copying message.

---

void push(const Message_type& message)
 

instead use:

 void push(Message_type message)
 {
 if (true)
 {
 std::lock_guard lock(queue_free);
 queue_log.push(std::move(message));
 }
 work_available.notify_one();
 }

If you're worried about Message_type being not movable, then provide both const Message_type & and Message_type && overloads.

---

 static std::string filter_last_newline(const std::string& string)
 {
 if (string.length() > 0 && string[string.length() - 1] == '\n') { return string.substr(0, string.length() - 1); }
 else { return string; }
 }

instead write:

 static std::string filter_last_newline(std::string str) {
 if (!str.empty() && str.back() == '\n')
 str.pop_back();
 // c++17 rules about copy ellision are convoluted,
 // i'm not sure, if compiler will be forced to do std::move here
 // when returning value passed in as an argument, so just in case
 // we std::move explicitly
 return std::move(str);
 }

This might prevent unnecesary coping a string.

---

 Message(Type type, const std::string& string, std::chrono::time_point<std::chrono::system_clock> time) noexcept
 : type(type), string(string), time(time)
 {}

as a rule of thumb, take arguments in constructors by value, not by const reference, so:

 Message(Type type, std::string string, std::chrono::time_point<std::chrono::system_clock> time) noexcept
 : type(type), string(std::move(string)), time(time)
 {}

once again this might prevent copying the string.

---

std::string string = "";

std::string already has a default constructor, so = "" is redundant.

---

 switch (type)
 {
 case Message::Type::log: return "[LOG]"; // [LOG]
 case Message::Type::dgn: return "[DGN]"; // [DIAGNOSTIC]
 case Message::Type::inf: return "[INF]"; // [INFO]
 case Message::Type::wrn: return "[WRN]"; // [WARNING]
 case Message::Type::err: return "[ERR]"; // [ERROR]
 }

in such case always add an assert at the end of the function to make sure noone will get there. This oneliner can save you a lot of debugging.

---

 while (true)
 {
 if (end == m.string.length()) { break; }

instead use while condition:

 while (end < m.string.length()) {

• Casey: Generally logging should appear in the order received. By using a properly thread-safe queue (by wrapping a std::queue interface with std::scoped_lock) this is handled automatically and is easy to understand. Using a std::vector is not intuitive and potentially confusing.
• Barnack: "Make a stand, either CamelCase or snake_case, not some weird offspring." camelCase and snake_case are more about what separates the first word from the second. The first letter being capital or not is usually used to split instances from classes.CamelCase and Snake_case would be classes, camelCase and snake_case would be instances. Unless you go the prefix way "class_xxx", "obj_xxx" etcc. Similar thing for the braces positioning, I use whitesmiths indentation, which is admittedly not much popular. en.wikipedia.org/wiki/Indentation_style
• Barnack: What I mostly care about here is having the interface be as much stl-like as I can. Ty for the straightforwards filter_last_newline implementation, I didn't even know there was a pop method for strings. I'll surely look closer at all the copy-avoiding optimizations you've pointed out, thanks!
• Radosław Cybulski: @Casey this depends on the environment. I'm senior with around 15 years of experience and my peers would actually find std::deque confusing. First question would be what do you need deque for, when vector is enough (he only push_bac's onto it and iterates over whole content).
• Radosław Cybulski: @Barnack "Make a stand..." comment was intended as piece of humour within many comments. My point is - once you start working with others, you need to "get with a program". We're creatures of habbits and having a habbit of using non-standard (unheard of) convention of names / indentation will only bring you pain. It's extremely unlikeable you will be able to convince anyone to follow it, as it would be "whole team must switch" - unlikely anyone else uses even similar convention. Thus they will force you to change and it will take time and some work. Why not start now?

Answer 2

IMO, I think that the logger is being too busy. Every push into queue_log is being moved into queue_write instantly (with some caveats, see addendum), which sort of negates the advantage of having a separate write queue for I/O. A potential optimization would be to wait for N log entries before performing the write. A high N will be more efficient, but will have higher latency, and higher risk in case of a crash because you can potentially lose the last N log entries; so choose wisely.

For example:

while (queue_log.size() < 10)
 work_available.wait(lock);

Now your queue_write will be populated when you have 10 log entries.

Also in your write_all function you use std::endl for every Message, which can be replaced with newlines in the loop and a flush at the end. Flushing is an expensive operation which should be done sparingly. Obviously, the same caveats apply, this is more risky; a crash and you will lose some log entries.

while (!queue_write.empty())
{
 ...
 std::cout << message << '\n';
 file << message << '\n';
 ...
}
file << std::flush;
std::cout << std::flush;

---

Addendum:

The other issue (other than the spurious wakeup case, which Radoslaw mentioned) with the use of condition variables in your code is that you did not take the case of missed notifications into account. A condition variable needs to be in a wait state, for a notify_one/all() to work.

The effects of notify_one()/notify_all() and each of the three atomic parts of wait()/wait_for()/wait_until() (unlock+wait, wakeup, and lock) take place in a single total order that can be viewed as modification order of an atomic variable: the order is specific to this individual condition_variable. This makes it impossible for notify_one() to, for example, be delayed and unblock a thread that started waiting just after the call to notify_one() was made.

From cppreference : std::condition_variable::wait(); emphasis mine.

A possible modification would be

while (queue_log.empty()) {
 using namespace std::chrono_literals;
 work_available.wait_for(lock, 2s); // or whatever interval you choose
}

Now the thread will wakeup every 2s and check if the condition (queue_log.empty()) is still true, and go back to sleep if it is. I doubt this is much of an issue in a logging scenario, but rather general advice about using condition variables.