Is creating a separate thread for a logger ok?

Question

I'm writing a multithreaded application in Qt (several threads with their own event loops). When logging I want the logger to include a thread id (they have meaningful names) into the log. Qt default logger seems incapable of doing this. So I have three options:

1. every thread does logging by itself (this involves mutexes, so is probably the worst approach, but I'm not sure)
2. There's a dedicated logger thread and other threads directly post events into it (probably faster, than 3.)
3. Same as 2. but the message is dispatched through the signal/slot system (in fact, this will result in posting an event as well).

Which one is better and what are best practices doing it in general?

---

Some things to clarify after questions in comments:

• QThread has a standard method postEvent(), that is thread-safe.

So the question becomes, does the logger thread need to do enough work per event to justify the cost of marshaling the event's data across some sort of queue

• That is the essence of the question. I know that the best answer is "Measure!", but currently the app is in an early development stage, there's not much what to measure. Also it's always good to choose the right design from the beginning.
• In my case threads are probably a good idea: it's a media player, so there's GUI thread, playback thread, DB/Media library thread, network thread pool... The whole Zoo of threads in other words.

Answer 1

These are general remarks since I have no experience with Qt. With respect to the cost of queuing, in general: I/O usually lets other run time costs pale, so it should not matter.

Properties of a dedicated logging thread:

• Good: Minimal impact on runtime behavior of the program.
• Good: Guaranteed single log messages (not intermixed output from several threads).
• Bad: Significant implementation effort.
• Bad: The time of initiating and actually performing the logging are decoupled (that is the whole point!). You may see logging output not where you expect it.
• Bad: a terminating program may swallow the last and most important log messages (Andreas' point), so you may want to add a synchronous log function (this is an extreme of the point above).

The (dis)advantages of logging from each thread directly are the inverse of the above. No two threads can log at the same time (either because functions like printf() implicitly lock a FILE, or because you synchronize the log function explicitly); this makes all threads which want to log block until the current thread is done. If logging is done for debugging purposes one may want to log unbuffered (so that the data is not lost in the event of a subsequent crash), which exacerbates the run time impact.

How bad that is depends on the nature of the application as well as the logging mechanism and amount of data.

Answer 2

I have implemented logging mechanisms for Qt applications in a nice clean way using the Qt Event mechanism.

In a Qt application there is a single instance of QApplication representing the application.

You can create your own events by inheriting from QEvent, and post them and handle them using the QApplication object for the application.

So for example you might have your log event class

MyLogEvent : public QEvent
{
public:
   MyLogEvent(QString threadId, QString logMessage) : QEvent(QEvent::User)
       { /* Store the ThreadID and log message, with accessor functions */};
}

And you can post events from any Qt thread using

MyLogEvent *event = new MyLogEvent(QString("Thread 1"), QString("Something Happened"));
QApplication::postEvent(mainWindow, event);

The handler could be a main window object (if you want to log to a window), or a dedicated object if you want to e.g. log to a file.

In the object handling the events, override QObject::event to handle the log messages

bool MainWindow::event(QEvent *e)
{
   if(e->type()==QEvent::User)
   {
        // This is a log event
        MyLogEvent *logEvent = static_cast<MyLogEvent *>(e);
        ui.textEdit->appendPlainText(logEvent->logMessage())
        return true;
   }
   return QMainWindow::event(e);
}

Answer 3

I don't quite understand why every thread doing logging by itself would need to use an explicit mutex.

If you're logging to a disk file, then every thread can be logging to its own file. You can name the files with a common prefix:

QFile * logFile(QObject * parent = nullptr) {
  auto baseName = QStringLiteral("MyApplication-");
  auto threadName = QThread::currentThread()->objectName();
  if (threadName.isEmpty())
    return new QTemporaryFile(baseName);
  else
    return new QFile(baseName + threadName);
}

The operating system is serializing access via its filesystem mutex(es).

If you're logging to a database that supports concurrent access, such as sqlite with proper concurrency options selected, the database driver will take care of serializing access.

If you're logging to a common thread, then the event queue has a mutex that you automatically serialize with when you postEvent.

You're right that using the signal-slot mechanism doesn't buy you much over using events directly. In fact, it's guaranteed to perform more memory allocations, so you should prefer posting an event yourself, ideally an event that uses a QVarLengthArray<char> of a size that fits "most" of the log messages. Then, allocating such an event is done with a single malloc call:

// logger.h

struct MyLogEvent : QEvent {
  constexpr static QEvent::Type theType() { return (QEvent::Type)(QEvent::User + 1); }
  QVarLengthArray<char, 128> message;
  MyLogEvent(const char * msg) : QEvent(theType()) {
    message.append(msg, strlen(msg));
  }
};

class Logger : public QObject {
  ...
public:
  static void log(const char * msg) {
    QCoreApplication::postEvent(instance(), new MyLogEvent(msg));
  }
  static Logger * instance(); // singleton, must be a thread safe method
};

// logger.cpp
...
Q_GLOBAL_STATIC(Logger, loggerInstance);

Logger * Logger::instance() {
  // Thread-safe since QGlobalStatic is.
  return loggerInstance;
}

Had you used a QByteArray or a QString, the expression new MyLogEvent would have performed at least two allocations.