Application hangs, spends >99% of CPU in QTimerInfoList::unregisterTimer

[danberindei]

I am running a locally-built version based on 21.2.0.0 + the patch here: #285

perf.zip

[variar]

Could you describe the use case that leads to this? Unfortunately, perf data from local builds is not very helpful because debug symbols are missing.

# Overhead  Command         Shared Object                Symbol                
# ........  ..............  ...........................  ......................
#
    92.84%  klogg           libQt5Core.so.5.15.2         [.] 0x00000000002cd044
     2.32%  klogg           libQt5Core.so.5.15.2         [.] 0x00000000002cd03e
     1.94%  klogg           libQt5Core.so.5.15.2         [.] 0x00000000002cd039
     1.24%  klogg           libQt5Core.so.5.15.2         [.] 0x00000000002cd034
     1.09%  klogg           libQt5Core.so.5.15.2         [.] 0x00000000002cd030
     0.17%  klogg           libQt5Core.so.5.15.2         [.] 0x00000000002cd041
     0.07%  klogg           [unknown]                    [k] 0xffffffff8fc01067
     0.01%  klogg           libQt5Core.so.5.15.2         [.] 0x00000000002a6cd8
     0.01%  klogg           libklogg_tbbmalloc.so        [.] 0x000000000000ab4e
     0.01%  klogg           libstdc++.so.6.0.28          [.] 0x000000000009b064

[danberindei]

Sorry about the missing symbols, I'm not used to debugging native applications. This is the thread stack from pstack:

Thread 1 (Thread 0x7fb34074d940 (LWP 1698177) "klogg"):
#0  0x00007fb343ff5030 in QTimerInfoList::unregisterTimer(int) () from /lib64/libQt5Core.so.5
#1  0x00007fb343fd3ed8 in QObject::killTimer(int) () from /lib64/libQt5Core.so.5
#2  0x00007fb343fdd248 in QSingleShotTimer::timerEvent(QTimerEvent*) () from /lib64/libQt5Core.so.5
#3  0x00007fb343fd1c7f in QObject::event(QEvent*) () from /lib64/libQt5Core.so.5
#4  0x00007fb344bd7ec3 in QApplicationPrivate::notify_helper(QObject*, QEvent*) () from /lib64/libQt5Widgets.so.5
#5  0x00007fb343fa9bd8 in QCoreApplication::notifyInternal2(QObject*, QEvent*) () from /lib64/libQt5Core.so.5
#6  0x00007fb343ff5a03 in QTimerInfoList::activateTimers() () from /lib64/libQt5Core.so.5
#7  0x00007fb343ff6344 in idleTimerSourceDispatch(_GSource*, int (*)(void*), void*) () from /lib64/libQt5Core.so.5
#8  0x00007fb342b24a9f in g_main_context_dispatch () from /lib64/libglib-2.0.so.0
#9  0x00007fb342b76a98 in g_main_context_iterate.constprop () from /lib64/libglib-2.0.so.0
#10 0x00007fb342b21e73 in g_main_context_iteration () from /lib64/libglib-2.0.so.0
#11 0x00007fb343ff66f3 in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /lib64/libQt5Core.so.5
#12 0x00007fb343fa857b in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () from /lib64/libQt5Core.so.5
#13 0x00007fb343fb01b4 in QCoreApplication::exec() () from /lib64/libQt5Core.so.5
#14 0x00000000004c0665 in main ()

It seems to happen pretty consistently if I open the log file in klogg, switch to my Java IDE, run a test that spews about 500k lines of log messages (around 100MB, I like to enable trace logging all the time) in about 30s, and then switch back to klogg.

I no longer see the problem if I disable filesystem change monitoring. Disabling fast modification detection doesn't seem to make any difference.

[variar]

There might be a some problem when file is modified rapidly with big chunks of data. There is a notification throttling mechanism, that combines several notifications from file changes monitor into one. Looks like there is a bug here:

klogg/src/filewatch/src/filewatcher.cpp

Line 368 in 7440d6a

if ( !notificationTimer_->isActive() ) {

Notification timer is checked for activity, but singleshot timer is used to pass events. So condition is always false, and a lot of singleshot times are created.

[variar]

Fix should be in builds >= 21.04.0.890

[danberindei]

Thanks Anton, but I don't think your fix eliminated the problem completely. After rebuilding with current master, I got the application to hang again, and the stack trace looks very similar

Thread 1 (Thread 0x7fb34074d940 (LWP 1698177) "klogg"):
#0  0x00007fb343ff5030 in QTimerInfoList::unregisterTimer(int) () from /lib64/libQt5Core.so.5
#1  0x00007fb343fd3ed8 in QObject::killTimer(int) () from /lib64/libQt5Core.so.5
#2  0x00007fb343fdd248 in QSingleShotTimer::timerEvent(QTimerEvent*) () from /lib64/libQt5Core.so.5
#3  0x00007fb343fd1c7f in QObject::event(QEvent*) () from /lib64/libQt5Core.so.5
#4  0x00007fb344bd7ec3 in QApplicationPrivate::notify_helper(QObject*, QEvent*) () from /lib64/libQt5Widgets.so.5
#5  0x00007fb343fa9bd8 in QCoreApplication::notifyInternal2(QObject*, QEvent*) () from /lib64/libQt5Core.so.5
#6  0x00007fb343ff5a03 in QTimerInfoList::activateTimers() () from /lib64/libQt5Core.so.5
#7  0x00007fb343ff6344 in idleTimerSourceDispatch(_GSource*, int (*)(void*), void*) () from /lib64/libQt5Core.so.5
#8  0x00007fb342b24a9f in g_main_context_dispatch () from /lib64/libglib-2.0.so.0
#9  0x00007fb342b76a98 in g_main_context_iterate.constprop () from /lib64/libglib-2.0.so.0
#10 0x00007fb342b21e73 in g_main_context_iteration () from /lib64/libglib-2.0.so.0
#11 0x00007fb343ff66f3 in QEventDispatcherGlib::processEvents(QFlags<QEventLoop::ProcessEventsFlag>) () from /lib64/libQt5Core.so.5
#12 0x00007fb343fa857b in QEventLoop::exec(QFlags<QEventLoop::ProcessEventsFlag>) () from /lib64/libQt5Core.so.5
#13 0x00007fb343fb01b4 in QCoreApplication::exec() () from /lib64/libQt5Core.so.5
#14 0x00000000004c0665 in main ()

[variar]

I was able to kind-of reproduce this issue with test program that writes to file very fast. Changing to KDAB signal throttler seems to help. Integrated to 21.04.0.908. @danberindei any improvements in your case?

[danberindei]

Sorry for the delay, I had switched to polling and it was good enough for my use case.

I am now back to filesystem change monitoring and it works great. Thanks @variar!