Deadlock: Indexing lines...(99%)

[dwrobel]

version: glogg-1.0.2-1.fc21 (http://koji.fedoraproject.org/koji/buildinfo?buildID=604412)

While loading log file (not so long 262499051bytes) glogg got stuck displaying "Indexing lines...(99%)".

(gdb) thread 1
[Switching to thread 1 (Thread 0x7f911da72880 (LWP 21747))]
#6  WatchTower<INotifyWatchTowerDriver>::addFile(std::string const&, std::function<void ()>) (this=0x2519448, file_name="/home/D.Wrobel/tmp/logs/com-5555.txt", notification=...) at src/watchtower.h:112
(gdb) bt
#0  __lll_lock_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/lowlevellock.S:135
#1  0x000000384a00a11b in _L_lock_812 () from /lib64/libpthread.so.0
#2  0x000000384a009fe8 in __GI___pthread_mutex_lock (mutex=0x2519508) at ../nptl/pthread_mutex_lock.c:79
#3  0x00000000004817cd in __gthread_mutex_lock (__mutex=0x2519508) at /usr/include/c++/4.8.3/x86_64-redhat-linux/bits/gthr-default.h:748
#4  lock (this=0x2519508) at /usr/include/c++/4.8.3/mutex:134
#5  lock_guard (__m=..., this=<synthetic pointer>) at /usr/include/c++/4.8.3/mutex:414
#6  WatchTower<INotifyWatchTowerDriver>::addFile(std::string const&, std::function<void ()>) (this=0x2519448, file_name="/home/D.Wrobel/tmp/logs/com-5555.txt", notification=...) at src/watchtower.h:112
#7  0x000000000047b2f3 in PlatformFileWatcher::addFile (this=this@entry=0x2613838, fileName=...) at src/platformfilewatcher.cpp:45
#8  0x000000000042c5de in LogData::indexingFinished (this=0x2592528, status=Successful) at src/data/logdata.cpp:267
#9  0x0000000000487733 in LogData::qt_static_metacall (_o=<optimized out>, _c=<optimized out>, _id=<optimized out>, _a=<optimized out>) at .moc/release-shared/moc_logdata.cpp:95
#10 0x00000036c3abe956 in QObject::event (this=0x2592528, e=<optimized out>) at kernel/qobject.cpp:1245
#11 0x00000036c2b5b50c in QApplicationPrivate::notify_helper (this=this@entry=0x221d190, receiver=receiver@entry=0x2592528, e=e@entry=0x7f90e00028d0) at kernel/qapplication.cpp:3722
#12 0x00000036c2b60870 in QApplication::notify (this=0x7fffb362d940, receiver=0x2592528, e=0x7f90e00028d0) at kernel/qapplication.cpp:3505
#13 0x00000036c3a8cc35 in QCoreApplication::notifyInternal (this=0x7fffb362d940, receiver=0x2592528, event=event@entry=0x7f90e00028d0) at kernel/qcoreapplication.cpp:932
#14 0x00000036c3a8ec27 in sendEvent (event=0x7f90e00028d0, receiver=<optimized out>) at kernel/qcoreapplication.h:228
#15 QCoreApplicationPrivate::sendPostedEvents (receiver=receiver@entry=0x0, event_type=event_type@entry=0, data=0x221d300) at kernel/qcoreapplication.cpp:1536
#16 0x00000036c3a8f238 in QCoreApplication::sendPostedEvents (receiver=receiver@entry=0x0, event_type=event_type@entry=0) at kernel/qcoreapplication.cpp:1394
#17 0x00000036c3ae77b3 in postEventSourceDispatch (s=s@entry=0x225b650) at kernel/qeventdispatcher_glib.cpp:271
#18 0x000000384c4492a6 in g_main_dispatch (context=0x7f9110001740) at gmain.c:3066
#19 g_main_context_dispatch (context=context@entry=0x7f9110001740) at gmain.c:3642
#20 0x000000384c449628 in g_main_context_iterate (context=context@entry=0x7f9110001740, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at gmain.c:3713
#21 0x000000384c4496dc in g_main_context_iteration (context=0x7f9110001740, may_block=1) at gmain.c:3774
#22 0x00000036c3ae6bdc in QEventDispatcherGlib::processEvents (this=0x224c280, flags=...) at kernel/qeventdispatcher_glib.cpp:418
#23 0x00000036c3a8aa9b in QEventLoop::exec (this=this@entry=0x7fffb362d6d0, flags=..., flags@entry=...) at kernel/qeventloop.cpp:204
#24 0x00000036c3a92496 in QCoreApplication::exec () at kernel/qcoreapplication.cpp:1185
#25 0x00000036c32e33cc in QGuiApplication::exec () at kernel/qguiapplication.cpp:1532
#26 0x00000036c2b57a75 in QApplication::exec () at kernel/qapplication.cpp:2956
#27 0x000000000041e5b9 in main (argc=1, argv=<optimized out>) at src/main.cpp:250
(gdb) frame 6
#6  WatchTower<INotifyWatchTowerDriver>::addFile(std::string const&, std::function<void ()>) (this=0x2519448, file_name="/home/D.Wrobel/tmp/logs/com-5555.txt", notification=...) at src/watchtower.h:112
(gdb) p observers_mutex_
$4 = {<std::__mutex_base> = {_M_mutex = {__data = {__lock = 2, __count = 0, __owner = 22824, __nusers = 1, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = "\002\000\000\000\000\000\000\000(Y\000\000\001", '\000' <repeats 26 times>, __align = 2}}, <No data fields>}
(gdb) thread 10
[Switching to thread 10 (Thread 0x7f910ffff700 (LWP 22824))]
#0  0x000000384a00e7fd in read () at ../sysdeps/unix/syscall-template.S:81
(gdb) frame 3
#3  0x000000000047f655 in WatchTower<INotifyWatchTowerDriver>::run (this=0x2519448) at src/watchtower.h:225
(gdb) p observers_mutex_
$7 = {<std::__mutex_base> = {_M_mutex = {__data = {__lock = 2, __count = 0, __owner = 22824, __nusers = 1, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = "\002\000\000\000\000\000\000\000(Y\000\000\001", '\000' <repeats 26 times>, __align = 2}}, <No data fields>}
(gdb) 

So it looks like the following:

thread 10
  WatchTower
    lock(observers_mutex_)
       read()

thread 1
   LogData::indexingFinished()
     PlatformFileWatcher::addFile()
       WatchTower<INotifyWatchTowerDriver>::addFile()
         lock(observers_mutex_)

Ofcourse, if I manually executed the following command (to let the read() to finish):
echo "please wakeup" >> /home/D.Wrobel/tmp/logs/com-5555.txt
it started to work.

[nickbnf]

Thanks Damian, is the problem reproducible often?

I reviewed the code in inotifywatchtowerdriver.cpp and we should never block on the read() since we do a poll() before, well unless I missed something of course.

If it is easily reproducible in your setup, I can give you a patch for making the inotify fd non-blocking, though I must admit I don't understand why it is necessary. Alternatively we could leave the mutex unlocked whilst we are doing the read since we don't really need it, but again it should not be a problem.

If you still have the stack trace, could you check which read() we are blocked on, is it the one at line 120 or the one at line 141?

[dwrobel]

I haven't tried to reproduce it, it just happened. I'll try to reproduce it.

Callstacks are available here:
bt: https://dwrobel.fedorapeople.org/tmp/glogg/glogg-bt.txt
bt full: https://dwrobel.fedorapeople.org/tmp/glogg/glogg-bt-full.txt