Visualizing threads in QDebug output

written on Sunday, March 5, 2017

Here is a handy tip I figured out recently to track in which thread things happens inside a Qt application. First install Synesthesia. This command line tool let's you highlight the output of your program based on regular expressions. The beauty of Synesthesia is that it automatically picks the color of the highlight, and it does so based on the matched string, not the matched expression (this distinction is important).

Here is an example. Let's create a file with the following content:

Hello world
Some other line
Goodbye world

If we pipe this through synesthesia '.*world' we get this:

$ synesthesia '.*world' < example.txt
Hello world
Some other line
Goodbye world

As you can see, it picked different colors for the "hello world" and "goodbye world" sentences because even if they match the same regular expression, the matched string is different.

How can we use this to inspect thread activity in our program? Here is a simple Qt multithreaded program. It prints numbers from 0 to 9 in two threads, with a random wait between each number.

#include <QCoreApplication>
#include <QDebug>
#include <QThread>
class CounterThread : public QThread
{
protected:
    void run() {
        // Hackish way to set a different random seed per thread
        qsrand(reinterpret_cast<qint64>(this));
        for (int x = 0; x < 10; ++x) {
            qDebug() << x;
            int delay = qrand() % 500;
            QThread::msleep(delay);
        }
        qDebug() << "done";
    }
};
int main(int, char**)
{
    CounterThread thread1;
    CounterThread thread2;
    thread1.start();
    thread2.start();
    qDebug() << "wait";
    thread1.wait();
    qDebug() << "thread1 finished";
    thread2.wait();
    qDebug() << "thread2 finished";
    return 0;
}

Let's run this example:

$ ./threadedapp wait
0
0
1
2
1
2
3
4
3
5
4
5
6
6
7
8
7
9
8
9
done
done
thread1 finished
thread2 finished

Now, let's take advantage of the customizability of QDebug to print the thread id (and the message type while we are at it). We can do so by setting the QT_MESSAGE_PATTERN environment variable:

$ QT_MESSAGE_PATTERN='%{threadid} %{type} %{message}' ./threadedapp
24914 debug wait
24916 debug 0
24915 debug 0
24916 debug 1
24915 debug 1
24916 debug 2
24915 debug 2
24916 debug 3
24916 debug 4
24915 debug 3
24916 debug 5
24915 debug 4
24915 debug 5
24915 debug 6
24916 debug 6
24916 debug 7
24916 debug 8
24915 debug 7
24916 debug 9
24915 debug 8
24915 debug 9
24916 debug done
24915 debug done
24914 debug thread1 finished
24914 debug thread2 finished

That's already interesting: we can see which thread prints what. But let's pipe the output to Synesthesia with a regular expression matching the thread ids of our program:

$ QT_MESSAGE_PATTERN='%{threadid} %{type} %{message}' ./threadedapp 2>&1 | synesthesia '^[0-9]+'
24429 debug 0
24428 debug 0
24426 debug wait
24428 debug 1
24429 debug 1
24429 debug 2
24429 debug 3
24428 debug 2
24429 debug 4
24428 debug 3
24428 debug 4
24429 debug 5
24429 debug 6
24428 debug 5
24428 debug 6
24428 debug 7
24428 debug 8
24428 debug 9
24429 debug 7
24428 debug done
24426 debug thread1 finished
24429 debug 8
24429 debug 9
24429 debug done
24426 debug thread2 finished

The color makes it much easier to figure out what's going on, and thanks to QDebug runtime customizability, we didn't even had to modify our code!

That's it for this article, give Synesthesia a try, it's a really handy tool!