Qt EventLoop Duty Cycle (Blocking vs Spinning)

[bob2oneil]

There has been a general discussion about the efficiency of the Qt event loop, and whether or not the application or thread event loops block or spin burning CPU cycles. I desire to write an application that is patterned more after an RTOS type of construct wherein secondary threads pend until they actually have data to process or exit. Intuitively, it would seem that any Qt application or thread that implements event handling, must have the event loop running. This subject has been discussed on these forums, that is the necessity to have an event loop running for a thread to receive and process emitted signals.

In my current design, I anticipate using a Qt console based application (running exec()) running the Qt state machine framework (running exec()) with several secondary threads which will NOT run event loops. Per previous dialog, the general rule was a thread can emit signals without an event loop, but the receiver must be running an event loop to propertly detect the event.

When I think of characterizing the efficiency of a thread, it really comes down to a duty cycle calculation, that is, how often is the thread running burning CPU cycles relative to the time it spends blocking. Certainly this duty cycle will change as a function of activity, but I want to characterize the behavior for a more nominal condition where the application/thread running exec() is not being actively tickled by signals or events.

To that end, I am trying to come up with a methodology to characterize the efficiency of the QCoreApplication::exec() call as well as the QThread::exec() call. By inspection of the Qt source code, exec() will eventually call QEventLoop:rocessEvents, and
the QAbstractEventDispatcher calls a Windows or Linux specific implementation.

QtCored4.dll!QEventDispatcherWin32::processEvents(QFlags<enum QEventLoop::ProcessEventsFlag> flags={...})  Line 834	C++
QtGuid4.dll!QGuiEventDispatcherWin32::processEvents(QFlags<enum QEventLoop::ProcessEventsFlag> flags={...})  Line 1170 + 0x15 bytes	C++
QtCored4.dll!QEventLoop::processEvents(QFlags<enum QEventLoop::ProcessEventsFlag> flags={...})  Line 150	C++
QtCored4.dll!QEventLoop::exec(QFlags<enum QEventLoop::ProcessEventsFlag> flags={...})  Line 201 + 0x2d bytes	C+

QtCored4.dll!QEventDispatcherWin32::processEvents(QFlags<enum QEventLoop::ProcessEventsFlag> flags={...})  Line 834	C++
QtGuid4.dll!QGuiEventDispatcherWin32::processEvents(QFlags<enum QEventLoop::ProcessEventsFlag> flags={...})  Line 1170 + 0x15 bytes	C++
QtCored4.dll!QEventLoop::processEvents(QFlags<enum QEventLoop::ProcessEventsFlag> flags={...})  Line 150	C++
QtCored4.dll!QEventLoop::exec(QFlags<enum QEventLoop::ProcessEventsFlag> flags={...})  Line 201 + 0x2d bytes	C+

To copy to clipboard, switch view to plain text mode 

Under Windows, (file C:\Qt\4.7.3\src\corelib\kernel\qeventdispatcher_wi n.cpp), QEventDispatcherWin32:rocessEvents() is called. Within the method, there are conditions wherre MsgWaitForMultipleObjectsEx() is called blocking the thread. The aboutToBlock() signal is emited prior to the thread blocking, and conversely, the awake() signal is emitted when the thread unblocks.

Under Linux (file C:\Qt\4.7.3\src\corelib\kernel\qeventdispatcher_un ix.cpp), the doSelect() API is called to pend the thread, and the aboutToBlock() and awake() signals are emitted to frame the blocking session.

My original idea on characterizing the duty cycle was to implement handlers for these two signals and record the time at each point so a duty cycle calculation of thread "blocking" time could be determined relative to thread active time burning CPU cycles.

However, the eventloop for the main application is implemented within QCoreApplication::exec() as a local stack based variable QEventLoop. I am unable to override the implementation of QCoreApplication::exec() without access to the
private members of the base class.

Perhaps I am approaching this incorrectly, and there some profiling tool available to characterize the exec() event loop to get a metric on its efficiency (or lack thereof).

Anybody have any thoughts on this or have already characterized exec()'s behavior?

[Santosh Reddy]

Even if you able to get into private sections of Qt code and plant dome profiling hooks, I don't think you will get any extra information than what you get from "Task Manager".

Blocking exec() or scheduing (running / spinning) exec() is completly in OS resposibility. Qt exec() may block by itself, if it requires some resource from OS. Also, even in cases where exec() is ready and want to run, OS may still block it for many scheduing reasons, which Qt / programmer may not have control on, things like thread affinity, process proprity, process resource limitation, system load, etc.

I think if Qt event loop is the only thread (in the only process) running on the the CPU, it would never stop, and use 100% processor.

[bob2oneil]

Thanks for your input, I agree with your assessment. Still, I would like to metric the nominal duty cycle since there seems to be some attempt at blocking within the Qt code base event loop code to determine just how "bad" a particular thread can be in terms of yielding CPU time to other threads so I can determine if and where it is worth replacing the Qt exec() loop with one that actually pends/blocking until useful work can be performed.

[bob2oneil]

I did some further experimenting by intercepting the two signals mentioned in my thread. The following source code was used in a console application where I derived a class from QCoreApplication as App.

The results were logged to a file. Under Windows, since the ability to read time with high accuracy is a known issue, I am using the GetSystemTimeAsFileTime() API, which is accurate to only 15 ms. Time information is written to the log time in format similar to the Linux timespec (as sec.microseconds).

Regardless of the inaccuracy of time, the Windows XP task manager indicates CPU consumption of the running console as 00, and what is interesting in the logging is that the triad pattern of awake(), awake(), and then aboutToBlock() suggests that the thread is indeed blocking for most of the time.

The seems to suggest to me that perhaps the Qt event loop is not as inefficient as I perhaps thought it might be. If the thread is spending most of its time in a blocked state, then it is not constantly spinning for new events.

Now I could be misunderstanding the results, and perhaps I need to test it out in a different manner.

Looking for suggestions or perhaps a Qt kernel expert who can shed some light on this behavior.

I will repeat this under Linux (much better time accuracy) and convey those results to the community.

Test results are as follows:


1311112841.765625 INFO: Entering Event Loop
1311112842.0 INFO: awake()
1311112842.15625 INFO: awake()
1311112842.15625 INFO: aboutToBlock()
1311112909.125000 INFO: awake()
1311112910.375000 INFO: awake()
1311112910.375000 INFO: aboutToBlock()
1311112971.296875 INFO: awake()
1311112971.312500 INFO: awake()
1311112971.312500 INFO: aboutToBlock()
1311113022.46875 INFO: awake()
1311113022.78125 INFO: awake()
1311113022.78125 INFO: aboutToBlock()
1311113023.125000 INFO: awake()
1311113023.156250 INFO: awake()
1311113023.156250 INFO: aboutToBlock()

Source code is as follows:

int main(int argc, char *argv[])
{
    App app (argc, argv);
 
    QString logFile = QCoreApplication::arguments().at(0) + ".txt";
    QFile::remove(logFile);
    FILELog::ReportingLevel() = logDEBUG2;    
    FILE* pFile = fopen(qPrintable(logFile), "a");
    Output2FILE::Stream() = pFile;
 
    QAbstractEventDispatcher *eventDispatcher = QAbstractEventDispatcher::instance();
    if (eventDispatcher)
    {
        QObject::connect(eventDispatcher, SIGNAL(aboutToBlock()), &app, SLOT(aboutToBlock()));
        QObject::connect(eventDispatcher, SIGNAL(awake()), &app, SLOT(awake()));
    }
 
    FILE_LOG(logINFO) << "Entering Event Loop";
    int returnCode = app.exec();
    FILE_LOG(logINFO) << "Exiting Event Loop";    
 
    if (eventDispatcher)
    {
        QObject::disconnect(eventDispatcher, SIGNAL(aboutToBlock()), &app, SLOT(aboutToBlock()));
        QObject::disconnect(eventDispatcher, SIGNAL(awake()), &app, SLOT(awake()));
    }
 
    return returnCode;
}

int main(int argc, char *argv[])
{
    App app (argc, argv);

    QString logFile = QCoreApplication::arguments().at(0) + ".txt";
    QFile::remove(logFile);
    FILELog::ReportingLevel() = logDEBUG2;    
    FILE* pFile = fopen(qPrintable(logFile), "a");
    Output2FILE::Stream() = pFile;
    
    QAbstractEventDispatcher *eventDispatcher = QAbstractEventDispatcher::instance();
    if (eventDispatcher)
    {
        QObject::connect(eventDispatcher, SIGNAL(aboutToBlock()), &app, SLOT(aboutToBlock()));
        QObject::connect(eventDispatcher, SIGNAL(awake()), &app, SLOT(awake()));
    }
    
    FILE_LOG(logINFO) << "Entering Event Loop";
    int returnCode = app.exec();
    FILE_LOG(logINFO) << "Exiting Event Loop";    
    
    if (eventDispatcher)
    {
        QObject::disconnect(eventDispatcher, SIGNAL(aboutToBlock()), &app, SLOT(aboutToBlock()));
        QObject::disconnect(eventDispatcher, SIGNAL(awake()), &app, SLOT(awake()));
    }
    
    return returnCode;
}

To copy to clipboard, switch view to plain text mode 

In the App class, the two slots are defined as:

void App::aboutToBlock()
{
    FILE_LOG(logINFO) << "aboutToBlock()";
}
 
void App::awake()
{
    FILE_LOG(logINFO) << "awake()";
}

void App::aboutToBlock()
{
    FILE_LOG(logINFO) << "aboutToBlock()";
}

void App::awake()
{
    FILE_LOG(logINFO) << "awake()";
}

To copy to clipboard, switch view to plain text mode 

[Santosh Reddy]

also try adding a QTimer of 0 ms, connect a slot to it, have a log in slot, and see how results vary

[bob2oneil]

Not sure what the intention was with your suggestion, but here are the results.

According to the documentation, a QTimer with a timeout interval of 0 will time out as soon as all the events in the window system's event queue have been processed.

This keeps the event loop constantly busy and will not enter the blocking state.

1311193072.781250 INFO: awake()
1311193072.781250 INFO: awake()
1311193072.781250 INFO: awake()
1311193072.781250 INFO: awake()
1311193072.796875 INFO: awake()
1311193072.796875 INFO: awake()
1311193072.796875 INFO: awake()
1311193072.796875 INFO: awake()
1311193072.796875 INFO: awake()
1311193072.796875 INFO: awake()
1311193072.796875 INFO: awake()
1311193072.796875 INFO: awake()
1311193072.796875 INFO: awake()
1311193072.796875 INFO: awake()
1311193072.812500 INFO: awake()
1311193072.812500 INFO: awake()
1311193072.812500 INFO: awake()
1311193072.812500 INFO: awake()
1311193072.812500 INFO: awake()
1311193072.812500 INFO: awake()
1311193072.812500 INFO: awake()
1311193072.828125 INFO: awake()
1311193072.828125 INFO: awake()
1311193072.828125 INFO: awake()
1311193072.828125 INFO: awake()
1311193072.828125 INFO: awake()
1311193072.828125 INFO: awake()
1311193072.828125 INFO: awake()
1311193072.828125 INFO: awake()
1311193072.843750 INFO: awake()
1311193072.843750 INFO: awake()
1311193072.843750 INFO: awake()
1311193072.843750 INFO: awake()
1311193072.843750 INFO: awake()
1311193072.843750 INFO: awake()
1311193072.843750 INFO: awake()
1311193072.843750 INFO: awake()
1311193072.843750 INFO: awake()
1311193072.843750 INFO: awake()
1311193072.843750 INFO: awake()
1311193072.859375 INFO: awake()
1311193072.859375 INFO: awake()
1311193072.859375 INFO: awake()
1311193072.859375 INFO: awake()
1311193072.859375 INFO: awake()
1311193072.859375 INFO: awake()
1311193072.859375 INFO: awake()
1311193072.859375 INFO: awake()
1311193072.875000 INFO: awake()
1311193072.875000 INFO: awake()
1311193072.875000 INFO: awake()
1311193072.875000 INFO: awake()
1311193072.875000 INFO: awake()
1311193072.875000 INFO: awake()
1311193072.890625 INFO: awake()
1311193072.890625 INFO: awake()
1311193072.890625 INFO: awake()
1311193072.890625 INFO: awake()
1311193072.890625 INFO: awake()

---

Added after 41 minutes:

Here are the Linux results, both with and without the QTimer(0). This test is performed on a faster machine than the original results.

Interested in your interpretation of the results. I am pleased to see some blocking calls under Linux for QTimer(0). Looking at the results, under Linux with QTimer(0), the duty cycle of blocking is approximately 50% based on the timing information.

Linux without timer running

1311195116.648288 INFO: Entering Event Loop
1311195116.648568 INFO: aboutToBlock()
1311195116.648708 INFO: awake()
1311195116.648757 INFO: aboutToBlock()

With QTimer(0)

1311194967.250633 INFO: Entering Event Loop
1311194967.250723 INFO: Starting timer
1311194967.250763 INFO: aboutToBlock()
1311194967.250813 INFO: awake()
1311194967.250825 INFO: aboutToBlock()
1311194967.250840 INFO: awake()
1311194967.250850 INFO: aboutToBlock()
1311194967.250864 INFO: awake()
1311194967.250924 INFO: aboutToBlock()
1311194967.250938 INFO: awake()
1311194967.250950 INFO: aboutToBlock()
1311194967.250965 INFO: awake()
1311194967.250977 INFO: aboutToBlock()
1311194967.250991 INFO: awake()
1311194967.251002 INFO: aboutToBlock()
1311194967.251016 INFO: awake()
1311194967.251030 INFO: aboutToBlock()
1311194967.251046 INFO: awake()
1311194967.251060 INFO: aboutToBlock()
1311194967.251075 INFO: awake()
1311194967.251088 INFO: aboutToBlock()
1311194967.251103 INFO: awake()
1311194967.251116 INFO: aboutToBlock()
1311194967.251129 INFO: awake()
1311194967.251140 INFO: aboutToBlock()