Best practice for non-interrupting I/O

Question

I have a small app that I am working with that needs to produce a very verbose log. I have implemented a simple singleton Logger class which looks like this

#ifndef LOGGER_H
#define LOGGER_H

#include <QObject>
#include <QMutex>
#include <QFile>

class Logger : public QObject
{
    Q_OBJECT
public:
    static Logger* sharedInstance()
    {
        static QMutex mutex;

        if (!m_sharedInstance)
        {
            mutex.lock();

            if(!m_sharedInstance)
                m_sharedInstance = new Logger;

            mutex.unlock();
        }

        return m_sharedInstance;
    }

    static void dropInstance()
    {
        static QMutex mutex;
        mutex.lock();
        delete m_sharedInstance;
        m_sharedInstance = 0;
        mutex.unlock();
    }

    void setLogFilePathAndOpen(QString path);
    void logMessage(QString message);
    void logMessageWorker(QString message);
    void closeLog();

private:
    Logger() {}

    Logger(const Logger &);
    Logger& operator=(const Logger &);

    static Logger *m_sharedInstance;

    QFile m_logFile;

signals:

public slots:

};

#endif // LOGGER_H

#include <QDateTime>
#include <QtConcurrentRun>

#include "logger.h"

Logger* Logger::m_sharedInstance = 0;

void Logger::setLogFilePathAndOpen(QString path)
{
    m_logFile.setFileName(path);
    m_logFile.open(QIODevice::Append | QIODevice::Text);
}

void Logger::logMessage(QString message)
{
    //TODO calling QtConcurrent causes about a 22% drop in performance. Look at other ways to do this.
    QtConcurrent::run(this, &Logger::logMessageWorker, message);
}

void Logger::logMessageWorker(QString message)
{
    QTextStream out(&m_logFile);
    out << tr("%1: %2\n").arg(QDateTime::currentDateTime().toString()).arg(message);
}

void Logger::closeLog()
{
    m_logFile.close();
}

Now I am somewhat new to Qt and C++ and perhaps this is all wrong so go easy on me :). Now I get about a 22% performance drop, versus not logging, using this method which is about the best I've been able to manage. I imagine the performance hit comes from creating the QtConcurrent thread.

I guess my question is, would this be the best approach or is there a better way to implement this that will see even closer performance to not logging at all. I am aware that no matter what the application will be slower with logging but I am trying to minimise this as much as possible.

Answer 1

Since you're willing to put up with asynchronous logging, you generally want the logging done in a single thread, and have a thread-safe queue feeding data to it. There are quite a few thread-safe queues around, such as one I posted in a previous answer. You'd (apparently) want to rewrite that using Qt primitives, but I believe that's similar enough that the rewrite will mostly be changing the names you use.

From there, the logging becomes quite a bit simpler. The logging thread just retrieves data from the queue, writes it to the log, and repeats. Since the logging thread is the only one that touches the log directly, it doesn't have to do any locking at all -- it's essentially single-threaded code, and all the locking is handled in the the queue.

Answer 2

There are two ways to deal with this:

1. Reuse an existing logging framework, or at least pilfer its ideas.
2. Stop logging so much (but you should still do 1.)

---

Best practices ?

In general, you should be queuing your logs into a queue that is dequeued by a worker thread. There are many possible implementations (lock-free queues, pool queues, whatever), it does not matter much though, just pick one and already you'll get a very good performance.

Of course, simply reusing an existing framework would be much better. Have you looked into Boost.Log or Pantheios ?

---

The other thing to notice is that you should not be logging so much. Logs are generally rare in an application.

• for debug runs, you can assert liberally to get a full core-dump in case of issue, much more helpful
• for release runs, you can use conditional logging to only log in the presence of exception

The conditional logging trick can be a bit counter-intuitive. The idea is to use the destructor of an object to actually log, and only if std::uncaught_exception() returns true. Of course this means that this logging should be exception-less, so unless you are very confident in your programming skills I would advise pre-formatting the message.

Answer 3

I am using qDebug, qWarning, etc for logging. And then, redirect the event messages to a log file in this way:

...
qInstallMsgHandler(messageHandler);
...

#define LOG_FILE "path/to/file.log"

void messageHandler(QtMsgType type, const char *msg)
{
#define NOW QDateTime::currentDateTime().toString("MM:dd: hh:mm:ss")
  QString out;
  switch (type) {
  case QtDebugMsg:    out = QString("%1: %2\n").arg(NOW).arg(msg); break;
  case QtWarningMsg:  out = QString("%1: warning: %2\n").arg(NOW).arg(msg); break;
  case QtCriticalMsg: out = QString("%1: critical: %2\n").arg(NOW).arg(msg); break;
  case QtFatalMsg:    out = QString("%1: fatal: %2\n").arg(NOW).arg(msg); break;
  default: return;
  }

  QFile file(LOG_FILE);
  if (file.open(QIODevice::WriteOnly | QIODevice::Append))
    QTextStream(&file) << out;
#undef NOW
}

This approach is thread-safe, though it is not the most efficient one, as the file IO is not cached.