D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

jtamate added a comment.


  Qt 5.11.0 and frameworks 5.46.0 over xcb.
  I'm sorry, I'll have to wait until the next lock, I didn't find the lock file 
neither the blocked kdeinit5.
  Is the complete name of the lock file be logged with qCDebug() ?.
  Just after killing dolphin yesterday afternoon (I've read your comments this 
morning), clementine appeared suddenly playing a song.

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[David Faure]

dfaure added a comment.


  In D14302#298099 , @thiago wrote:
  
  > In D14302#297515 , @dfaure wrote:
  >
  > > The idea of the old code was: if I can't get the lock, then someone else 
is already in the process of starting kdeinit, so I'll just wait for that to 
happen, by locking again, i.e. blocking on purpose, and then checking that the 
DBus name is up, i.e. the other process did manage to do it successfully.
  >
  >
  > It's Kind of silly to tryLock() then lock(). Why not just lock()? Was it 
the optimisation to avoid the D-Bus call? If so, a comment would be warranted.
  
  
  Yes: it would be kind of silly to check the dbus servicename, get the lock 
(because nobody else is doing this), and then check the dbus service name 
again, what chance did that have to suddenly pass?
  
  I think the new set of comments explains quite clearly the logic, now.
  
  > Anyway, one theory for why the lock file is still present: it's stale from 
a previous boot, but the PID is taken by some process in the current boot. This 
is fixed in Qt 5.11 by saving the boot ID (commit 
772863355a0cf57a49e93608790dfd17c8fd82da). So question to @jtamate , what Qt 
version is this? Can you paste here the contents of the lock file itself, as 
well as what process (if any) the PID in that file points to.
  
  Good point.

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Thiago Macieira]

thiago added a comment.


  In D14302#297515 , @dfaure wrote:
  
  > The idea of the old code was: if I can't get the lock, then someone else is 
already in the process of starting kdeinit, so I'll just wait for that to 
happen, by locking again, i.e. blocking on purpose, and then checking that the 
DBus name is up, i.e. the other process did manage to do it successfully.
  
  
  It's Kind of silly to tryLock() then lock(). Why not just lock()? Was it the 
optimisation to avoid the D-Bus call? If so, a comment would be warranted.
  
  > I said from the start that it wasn't tryLock() that was blocking but 
lock(), good to see that this is now confirmed, however we're back to square 
one: why is lock never returning? Surely the other process which is executing 
this method is releasing the lock after the QProcess::execute, right?
  
  Yeah, I trusted the patch too. The frame for lock() is missing because it's a 
tail-call jump.
  
  Anyway, one theory for why the lock file is still present: it's stale from a 
previous boot, but the PID is taken by some process in the current boot. This 
is fixed in Qt 5.11 by saving the boot ID (commit 
772863355a0cf57a49e93608790dfd17c8fd82da). So question to @jtamate , what Qt 
version is this? Can you paste here the contents of the lock file itself, as 
well as what process (if any) the PID in that file points to.

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

This revision was automatically updated to reflect the committed changes.
Closed by commit R271:8097e1aa0d21: Dont block forever in 
ensureKdeinitRunning (authored by jtamate).

REPOSITORY
  R271 KDBusAddons

CHANGES SINCE LAST UPDATE
  https://phabricator.kde.org/D14302?vs=38403=38448

REVISION DETAIL
  https://phabricator.kde.org/D14302

AFFECTED FILES
  src/kdeinitinterface.cpp

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[David Faure]

dfaure accepted this revision.
dfaure added a comment.
This revision is now accepted and ready to land.


  That's reasonable. Still when you see this warning in the future, it would be 
useful to find out what kdeinit+klauncher are actually doing, if klauncher 
doesn't manage to register with DBus after 30 seconds...

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

jtamate updated this revision to Diff 38403.
jtamate edited the summary of this revision.
jtamate added a comment.


  Don't wait forever, if the lock is blocked for more than 30 seconds, write a 
warning and don't try to start kdeinit5 again.

REPOSITORY
  R271 KDBusAddons

CHANGES SINCE LAST UPDATE
  https://phabricator.kde.org/D14302?vs=38387=38403

REVISION DETAIL
  https://phabricator.kde.org/D14302

AFFECTED FILES
  src/kdeinitinterface.cpp

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[David Faure]

dfaure requested changes to this revision.
dfaure added a comment.
This revision now requires changes to proceed.


  The comments look good. The actual change, not so much ;)

INLINE COMMENTS

> kdeinitinterface.cpp:72
> +QProcess proc;
> +// started asynchronously, so even if kdeinit5 takes forever to start, 
> the lock will be released
> +proc.start(srv, args);

But that means the other processes coming into this method, will either succeed 
in  tryLock() and will run yet another kdeinit instance (your system is slow 
and you're bombarding it with kdeinit processes trying to start at the same 
time?),
or worse, tryLock() fails and lock() succeeds (because the first process 
released the lock too early here), and then isServiceRegistered fails (because 
we're trying too early), and again we start yet another kdeinit process that 
will fight it with the currently starting one.

If the bug is that kdeinit takes forever to start (not just a long time) and 
QProcess::execute never returns, then that's the actual bug. This proposed 
change is just a workaround which potentially makes things worse (10 kdeinit 
processes attempting to start at the same time).

BTW ~QProcess would kill kdeinit, what you meant was startDetached. But all of 
the above is the reasoning against startDetached, actually ;)

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

jtamate updated this revision to Diff 38387.
jtamate edited the summary of this revision.
jtamate added a comment.


  > I said from the start that it wasn't tryLock() that was blocking but 
lock(), good to see that this is now confirmed.
  
  I trusted blindly in gdb stacktrace, and also I didn't understood, again, the 
code.
  
  Added your description as comments.

REPOSITORY
  R271 KDBusAddons

CHANGES SINCE LAST UPDATE
  https://phabricator.kde.org/D14302?vs=38372=38387

REVISION DETAIL
  https://phabricator.kde.org/D14302

AFFECTED FILES
  src/kdeinitinterface.cpp

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[David Faure]

dfaure added a comment.


  The idea of the old code was: if I can't get the lock, then someone else is 
already in the process of starting kdeinit, so I'll just wait for that to 
happen, by locking again, i.e. blocking on purpose, and then checking that the 
DBus name is up, i.e. the other process did manage to do it successfully.
  
  I can't wrap my head around whatever the new code is trying to do instead.
  
  I said from the start that it wasn't tryLock() that was blocking but lock(), 
good to see that this is now confirmed, however we're back to square one: why 
is lock never returning? Surely the other process which is executing this 
method is releasing the lock after the QProcess::execute, right?

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

jtamate updated this revision to Diff 38372.
jtamate edited the summary of this revision.
jtamate edited the test plan for this revision.
jtamate added a comment.


  It is my first time of a backtrace that doesn't reflect the true state of a 
program. But I've learned the lesson, in case of counter intuitive backtrace, 
take a look at the dissasembler.
  Thanks everybody, specially to @thiago.

REPOSITORY
  R271 KDBusAddons

CHANGES SINCE LAST UPDATE
  https://phabricator.kde.org/D14302?vs=38264=38372

REVISION DETAIL
  https://phabricator.kde.org/D14302

AFFECTED FILES
  src/kdeinitinterface.cpp

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Thiago Macieira]

thiago added inline comments.

INLINE COMMENTS

> kdeinitinterface.cpp:46
>  QLockFile lock(QDir::tempPath() + QLatin1Char('/') + 
> QLatin1String("startkdeinitlock"));
> -if (!lock.tryLock()) {
> +if (!lock.tryLock(timeout)) {
>  lock.lock();

This line doesn't need changing. You're getting a tryLock() failure because the 
lock file already exists. Adding a 5 second timeout is not going to change that.

> kdeinitinterface.cpp:47
> +if (!lock.tryLock(timeout)) {
>  lock.lock();
>  if 
> (dbusDaemon->isServiceRegistered(QStringLiteral("org.kde.klauncher5"))) {

The problem is here. So we failed to lock, then we try again to lock, forever. 
Why is this code doing that?

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Thiago Macieira]

thiago added a comment.


  In D14302#297159 , @jtamate wrote:
  
  >   (gdb) disass
  >   Dump of assembler code for function _ZN9QLockFile7tryLockEi:
  >  0x7f54be8bc752 <+2>: mov$0x,%eax
  >   ...
  >  0x7f54be8bc76d <+29>:test   %esi,%esi
  >   ...
  >  0x7f54be8bc772 <+34>:cmovs  %eax,%esi
  >   ...
  >  0x7f54be8bc78c <+60>:movslq %esi,%rsi
  >  0x7f54be8bc78f <+63>:callq  0x7f54be962150 

  >
  
  
  This is entirely correct: in +29 it checks  parameter (in %esi) and in +34 if 
it has the sign bit set (read: is negative), moves -1 to it. Then it does a 
sign extension from 32- to 64-bit in +60, before placing the call.
  
  qMax is working properly.
  
  >   Dump of assembler code for function 
_ZN16KDEInitInterface20ensureKdeinitRunningEv:
  >   ...
  >  0x7f54c0a23ae1 <+497>:   xor%esi,%esi
  >  0x7f54c0a23ae3 <+499>:   mov%r12,%rdi
  >  0x7f54c0a23ae6 <+502>:   callq  0x7f54c0a1e960 
<_ZN9QLockFile7tryLockEi@plt>
  
  Also correct: this passed a zero as the parameter to tryLock().
  
  Now here's the interesting thing:
  
  >  0x7f54c0a23aeb <+507>:   test   %al,%al
  >  0x7f54c0a23aed <+509>:   jne0x7f54c0a23b8d 
<_ZN16KDEInitInterface20ensureKdeinitRunningEv+669>
  >  0x7f54c0a23af3 <+515>:   mov%r12,%rdi
  >  0x7f54c0a23af6 <+518>:   callq  0x7f54c0a1e9c0 
<_ZN9QLockFile4lockEv@plt>
  >   => 0x7f54c0a23afb <+523>:   mov%rbx,%rdi
  
  Note where the => is pointing to. It's not to the return from tryLock(), but 
to the return to lock(). We've been looking at the wrong line.
  
  That also means the patch doesn't make sense, because it's changing the line 
that is already working.

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Thiago Macieira]

thiago added a comment.


  Quickly checking on openSUSE Tumbleweed
  
  In D14302#297185 , @lvsouza wrote:
  
  > I think I know what is happening. This line
  >
  > QDeadlineTimer timer(qMax(timeout, -1));// QDT only takes -1 as 
"forever"
  >
  > passes the result of qMax() to QDeadlineTimer's constructor. That 
constructor receives a quint64. Since qMax() is a template:
  
  
  The constructor takes a qint64, not a quint64.
  
  > inline const T (const T , const T ) { return (a < b) ? b : a; }
  > 
  > it will use the type of the assigned variable (quint64 in this case) as T 
and casting -1 to INT64_MAX. Changing the line to:
  
  Again, incorrect. It will use the type T, which must be the same for both 
arguments. The timeout parameter is int and the -1 literal is int. So the 
comparison is performed in int, which should return 0.

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Lamarque Souza]

lvsouza added a comment.


  I think I know what is happening. This line
  
  QDeadlineTimer timer(qMax(timeout, -1));// QDT only takes -1 as "forever"
  
  passes the result of qMax() to QDeadlineTimer's constructor. That constructor 
receives a quint64. Since qMax() is a template:
  
  inline const T (const T , const T ) { return (a < b) ? b : a; }
  
  it will use the type of the assigned variable (quint64 in this case) as T and 
casting -1 to INT64_MAX. Changing the line to:
  
  QDeadlineTimer timer(qMax(timeout, qint64(-1)));
  
  should solve the problem. If it does not then this should work:
  
  qint64 maxTimeout = qMax(timeout, -1);
  QDeadlineTimer timer(maxTimeout);

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: lvsouza, kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

jtamate added a comment.


(gdb) disass
Dump of assembler code for function _ZN9QLockFile7tryLockEi:
   0x7f54be8bc750 <+0>: push   %r15
   0x7f54be8bc752 <+2>: mov$0x,%eax
   0x7f54be8bc757 <+7>: mov$0x1,%edx
   0x7f54be8bc75c <+12>:push   %r14
   0x7f54be8bc75e <+14>:push   %r13
   0x7f54be8bc760 <+16>:push   %r12
   0x7f54be8bc762 <+18>:push   %rbp
   0x7f54be8bc763 <+19>:push   %rbx
   0x7f54be8bc764 <+20>:mov$0x64,%ebx
   0x7f54be8bc769 <+25>:sub$0x58,%rsp
   0x7f54be8bc76d <+29>:test   %esi,%esi
   0x7f54be8bc76f <+31>:mov(%rdi),%rbp
   0x7f54be8bc772 <+34>:cmovs  %eax,%esi
   0x7f54be8bc775 <+37>:lea0x20(%rsp),%r12
   0x7f54be8bc77a <+42>:lea0x30(%rsp),%r14
   0x7f54be8bc77f <+47>:lea0x10(%rsp),%r15
   0x7f54be8bc784 <+52>:lea0x18(%rsp),%r13
   0x7f54be8bc789 <+57>:mov%r12,%rdi
   0x7f54be8bc78c <+60>:movslq %esi,%rsi
   0x7f54be8bc78f <+63>:callq  0x7f54be962150 

   0x7f54be8bc794 <+68>:mov%rbp,%rdi
   0x7f54be8bc797 <+71>:callq  0x7f54be910d00 
<_ZN16QLockFilePrivate11tryLock_sysEv>
   0x7f54be8bc79c <+76>:mov%eax,0x10(%rbp)
   0x7f54be8bc79f <+79>:cmp$0x1,%eax
   0x7f54be8bc7a2 <+82>:je 0x7f54be8bc7d0 
<_ZN9QLockFile7tryLockEi+128>
   0x7f54be8bc7a4 <+84>:test   %eax,%eax
   0x7f54be8bc7a6 <+86>:je 0x7f54be8bc9a0 
<_ZN9QLockFile7tryLockEi+592>
   0x7f54be8bc7ac <+92>:cmp$0x3,%eax
   0x7f54be8bc7af <+95>:ja 0x7f54be8bc968 
<_ZN9QLockFile7tryLockEi+536>
   0x7f54be8bc7b5 <+101>:   add$0x58,%rsp
   0x7f54be8bc7b9 <+105>:   xor%eax,%eax
   0x7f54be8bc7bb <+107>:   pop%rbx
   0x7f54be8bc7bc <+108>:   pop%rbp
   0x7f54be8bc7bd <+109>:   pop%r12
   0x7f54be8bc7bf <+111>:   pop%r13
   0x7f54be8bc7c1 <+113>:   pop%r14
   0x7f54be8bc7c3 <+115>:   pop%r15
   0x7f54be8bc7c5 <+117>:   retq   
   0x7f54be8bc7c6 <+118>:   nopw   %cs:0x0(%rax,%rax,1)
   0x7f54be8bc7d0 <+128>:   cmpb   $0x0,0x14(%rbp)
   0x7f54be8bc7d4 <+132>:   jne0x7f54be8bc968 
<_ZN9QLockFile7tryLockEi+536>
   0x7f54be8bc7da <+138>:   mov%rbp,%rdi
   0x7f54be8bc7dd <+141>:   callq  0x7f54be8bc3a0 
<_ZNK16QLockFilePrivate17isApparentlyStaleEv>
   0x7f54be8bc7e2 <+146>:   test   %al,%al
   0x7f54be8bc7e4 <+148>:   je 0x7f54be8bc968 
<_ZN9QLockFile7tryLockEi+536>
   0x7f54be8bc7ea <+154>:   mov%r14,%rdi
   0x7f54be8bc7ed <+157>:   callq  0x7f54be807360 

   0x7f54be8bc7f2 <+162>:   mov%rbp,%rsi
   0x7f54be8bc7f5 <+165>:   mov%r15,%rdi
   0x7f54be8bc7f8 <+168>:   callq  0x7f54be8b2640 
<_ZN9QFileInfoC2ERK7QString>
   0x7f54be8bc7fd <+173>:   mov%r15,%rsi
   0x7f54be8bc800 <+176>:   mov%r13,%rdi
   0x7f54be8bc803 <+179>:   callq  0x7f54be8b4160 

   0x7f54be8bc808 <+184>:   mov%r13,%rsi
   0x7f54be8bc80b <+187>:   mov%r14,%rdi
   0x7f54be8bc80e <+190>:   callq  0x7f54be806e90 

   0x7f54be8bc813 <+195>:   mov%r13,%rdi
   0x7f54be8bc816 <+198>:   mov%al,0x8(%rsp)
   0x7f54be8bc81a <+202>:   callq  0x7f54be804a00 

   0x7f54be8bc81f <+207>:   mov%r15,%rdi
   0x7f54be8bc822 <+210>:   callq  0x7f54be8b43a0 

   0x7f54be8bc827 <+215>:   mov%r14,%rdi
   0x7f54be8bc82a <+218>:   callq  0x7f54be804a00 

   0x7f54be8bc82f <+223>:   movzbl 0x8(%rsp),%eax
   0x7f54be8bc834 <+228>:   test   %al,%al
   0x7f54be8bc836 <+230>:   je 0x7f54be8bc8c0 
<_ZN9QLockFile7tryLockEi+368>
   0x7f54be8bc83c <+236>:   lea0x1564dd(%rip),%rax# 
0x7f54bea12d20
   0x7f54be8bc843 <+243>:   pxor   %xmm0,%xmm0
   0x7f54be8bc847 <+247>:   movq   $0x2,0x30(%rsp)
   0x7f54be8bc850 <+256>:   mov%rax,0x48(%rsp)
   0x7f54be8bc855 <+261>:   mov0x0(%rbp),%rax
   0x7f54be8bc859 <+265>:   movups %xmm0,0x38(%rsp)
   0x7f54be8bc85e <+270>:   mov%rax,0x18(%rsp)
   0x7f54be8bc863 <+275>:   mov(%rax),%edx
   0x7f54be8bc865 <+277>:   add$0x1,%edx
   0x7f54be8bc868 <+280>:   cmp$0x1,%edx
   0x7f54be8bc86b <+283>:   ja 0x7f54be8bc9f1 
<_ZN9QLockFile7tryLockEi+673>
   0x7f54be8bc871 <+289>:   mov%r13,%rdi
   0x7f54be8bc874 <+292>:   callq  0x7f54be83d530 
   0x7f54be8bc879 <+297>:   mov%rax,%rdx
   0x7f54be8bc87c <+300>:   lea0x20a715(%rip),%rsi# 
0x7f54beac6f98
   0x7f54be8bc883 <+307>:   mov%r14,%rdi
  

D14302: Don't block forever in ensureKdeinitRunning

[Thiago Macieira]

thiago added a comment.


  > timer = {t1 = 9223372036854775807, t2 = 0, type = 1}
  
  This is indeed Forever. How did it get there?
  
  I showed in my debug session that the QDeadlineTimer is passed zero, and then 
it does initialise properly. So I'm now beginning to question the compiler. 
Specifically, this line:
  
QDeadlineTimer timer(qMax(timeout, -1));// QDT only takes -1 as 
"forever"
  
  Is it possible that the compiler miscompiled qMax and caused a value of -1 to 
be passed?
  
  Alternatively, could timeout be -1? The call site is (before your patch):
  
if (!lock.tryLock()) {
  
  Which should get the default value of 0. Could it be getting -1 somehow? 
Maybe your distribution patched Qt?
  
  Can you provide the disassembly of those two functions? Just run "disass" in 
gdb from those two frames and paste here.
  
  > In D14302#297119 , @thiago wrote:
  > 
  >> No, because your statement is incorrect. setPreciseRemainingTime **does** 
assign to t1:
  >>
  >>   t1 += secs + toSecsAndNSecs(nsecs).first;
  >>   
  > 
  > 
  > Yes, but this is assuming t1 = 0, I mean, it is not t1 = secs (not with 
+=).
  
  Wrong line. It does assign here:
  
*this = current(timerType);
  
  And even if it didn't, the value in the timer  is very specific (t1 == 
INT64_MAX and t2 == 0). The chance of getting that from uninitialised data is 
too small to be considered.

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

jtamate added a comment.


  In D14302#297120 , @thiago wrote:
  
  > Can you print the contents of the timer object inside tryLock()?
  
  
  
  
(gdb) info frame
Stack level 2, frame at 0x7ffdda9967c0:
 rip = 0x7f54be8bc985 in QLockFile::tryLock (io/qlockfile.cpp:274); saved 
rip = 0x7f54c0a23afb
 called by frame at 0x7ffdda996860, caller of frame at 0x7ffdda996730
 source language c++.
 Arglist at 0x7ffdda996728, args: this=, timeout=
 Locals at 0x7ffdda996728, Previous frame's sp is 0x7ffdda9967c0
 Saved registers:
  rbx at 0x7ffdda996788, rbp at 0x7ffdda996790, r12 at 0x7ffdda996798, r13 
at 0x7ffdda9967a0, r14 at 0x7ffdda9967a8, r15 at 0x7ffdda9967b0, rip at 
0x7ffdda9967b8
(gdb) info locals
remainingTime = 
d = 0x557a916a98f0
timer = {t1 = 9223372036854775807, t2 = 0, type = 1}
sleepTime = 6400
(gdb) up
#3  0x7f54c0a23afb in KDEInitInterface::ensureKdeinitRunning() () from 
/usr/lib64/libKF5DBusAddons.so.5
(gdb) info locals
No symbol table info available.
(gdb) info frame
Stack level 3, frame at 0x7ffdda996860:
 rip = 0x7f54c0a23afb in KDEInitInterface::ensureKdeinitRunning(); saved 
rip = 0x7f54c2d16ffb
 called by frame at 0x7ffdda9968a0, caller of frame at 0x7ffdda9967c0
 Arglist at 0x7ffdda9967b8, args: 
 Locals at 0x7ffdda9967b8, Previous frame's sp is 0x7ffdda996860
 Saved registers:
  rbx at 0x7ffdda996828, rbp at 0x7ffdda996830, r12 at 0x7ffdda996838, r13 
at 0x7ffdda996840, r14 at 0x7ffdda996848, r15 at 0x7ffdda996850, rip at 
0x7ffdda996858
  
  
  
  In D14302#297119 , @thiago wrote:
  
  > No, because your statement is incorrect. setPreciseRemainingTime **does** 
assign to t1:
  >
  >   t1 += secs + toSecsAndNSecs(nsecs).first;
  >   
  
  
  Yes, but this is assuming t1 = 0, I mean, it is not t1 = secs (not with 
+=).

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Thiago Macieira]

thiago added a comment.


  Can you print the contents of the timer object inside tryLock()?

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Thiago Macieira]

thiago added a comment.


  In D14302#296671 , @jtamate wrote:
  
  > Another hypothesis:
  >
  >   QDeadlineTimer::QDeadlineTimer(qint64 msecs, Qt::TimerType type) 
Q_DECL_NOTHROW
  >   : t2(0)
  >   {
  >   setRemainingTime(msecs, type);
  >   }
  >  
  >
  >
  > As t1 is not initialized and QDeadlineTimer::setPreciseRemainingTime only 
add to t1, it could be any value instead of 0?.
  >
  > Should I open a Qt bug?
  
  
  No, because your statement is incorrect. setPreciseRemainignTime *does* 
assign to t1:
  
*this = current(timerType);
if (QDeadlineTimerNanosecondsInT2) {
t1 += secs + toSecsAndNSecs(nsecs).first;
t2 += toSecsAndNSecs(nsecs).second;

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

jtamate added a comment.


  Another hypothesis:
  
QDeadlineTimer::QDeadlineTimer(qint64 msecs, Qt::TimerType type) 
Q_DECL_NOTHROW
: t2(0)
{
setRemainingTime(msecs, type);
}
  
  As t1 is not initialized and QDeadlineTimer::setPreciseRemainingTime only add 
to t1, it could be any value instead of 0?.
  
  Should I open a Qt bug?

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Thiago Macieira]

thiago added a comment.


  Quick testing via gdb:
  
Breakpoint 1, QLockFile::tryLock (this=0x7fffc6d8, timeout=0) at 
/home/tjmaciei/src/qt/qt5/qtbase/src/corelib/io/qlockfile.cpp:241
241 Q_D(QLockFile);
(gdb) n
242 QDeadlineTimer timer(qMax(timeout, -1));// QDT only takes 
-1 as "forever"
(gdb) 
243 int sleepTime = 100;
(gdb) 
245 d->lockError = d->tryLock_sys();
(gdb) 
246 switch (d->lockError) {
(gdb) 
254 if (!d->isLocked && d->isApparentlyStale()) {
(gdb) 
265 break;
(gdb) 
268 int remainingTime = timer.remainingTime();
(gdb) p timer
$4 = {t1 = 39043, t2 = 76902106, type = 1}
(gdb) s
QDeadlineTimer::remainingTime (this=0x7fffc590) at 
/home/tjmaciei/src/qt/qt5/qtbase/src/corelib/kernel/qdeadlinetimer.cpp:426
426 qint64 ns = remainingTimeNSecs();
(gdb) s
QDeadlineTimer::remainingTimeNSecs (this=0x7fffc590) at 
/home/tjmaciei/src/qt/qt5/qtbase/src/corelib/kernel/qdeadlinetimer.cpp:440
440 if (isForever())
(gdb) n
442 qint64 raw = rawRemainingTimeNSecs();
(gdb) n
443 return raw < 0 ? 0 : raw;
(gdb) p raw
$5 = -24344165069
(gdb) fin
Run till exit from #0  QDeadlineTimer::remainingTimeNSecs 
(this=0x7fffc590)
at 
/home/tjmaciei/src/qt/qt5/qtbase/src/corelib/kernel/qdeadlinetimer.cpp:443
0x77a1d014 in QDeadlineTimer::remainingTime (this=0x7fffc590)
at 
/home/tjmaciei/src/qt/qt5/qtbase/src/corelib/kernel/qdeadlinetimer.cpp:426
426 qint64 ns = remainingTimeNSecs();
Value returned is $6 = 0
(gdb) 
Run till exit from #0  0x77a1d014 in QDeadlineTimer::remainingTime 
(this=0x7fffc590)
at 
/home/tjmaciei/src/qt/qt5/qtbase/src/corelib/kernel/qdeadlinetimer.cpp:426
QLockFile::tryLock (this=0x7fffc6d8, timeout=0) at 
/home/tjmaciei/src/qt/qt5/qtbase/src/corelib/io/qlockfile.cpp:268
268 int remainingTime = timer.remainingTime();
Value returned is $7 = 0

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Thiago Macieira]

thiago added a comment.


  In D14302#296479 , @dfaure wrote:
  
  > I agree about tryLock(0) should return immediately, tryLock(-1) should 
block forever -- I wrote that code and that docu ;-)
  >
  > Thiago wrote QDeadLineTimer later on though, and ported QLockFile to it. 
Thiago, any input?
  
  
  QDT has no escape path for 0. The constructor calls setRemainngTime(0), which 
calls setPreciseRemainingTime(0, 0), which will get the current time, add zero, 
and store it.
  
  After all of that, the QDT should return that the remaining time is zero, 
since it's expired.
  
  remainingTime() calls remainingTimeNSecs(), which calls 
rawRemainingTimeNSecs(), which should return a negative value. 
remainingTimeNSecs() should detect the negative and return 0; remainingTime 
detects the zero and returns it.
  
(gdb) print timer.remainingTime()
$11 = -1
  
  That's not supposed to happen.

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

jtamate added a comment.


  In D14302#296469 , @jtamate wrote:
  
  > I guess this is a Qt bug.
  >
  >   qint64 QDeadlineTimer::remainingTime() const Q_DECL_NOTHROW
  >   {
  >   qint64 ns = remainingTimeNSecs();
  >   return ns <= 0 ? ns : (ns + 99) / (1000 * 1000);
  >   }
  >
  >
  > Shouldn't it be:
  >
  >   return ns <= 0 ? **0** : (ns + 99) / (1000 * 1000);
  >
  
  
  I answer myself. It is ok. If remainingTimeNSecs() return -1 it also returns 
-1 (never expire), and in inremainingTimeNSecs() it can only be -1 or 0 or >0
  
return raw < 0 ? 0 : raw;
  
  But
  (gdb) print timer.remainingTime()
  $11 = -1
  (gdb) print sleepTime
  $13 = 6400
  
  Therefore isForever() is returning true. Why?

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[David Faure]

dfaure added a comment.


  I agree about tryLock(0) should return immediately, tryLock(-1) should block 
forever -- I wrote that code and that docu ;-)
  
  Thiago wrote QDeadLineTimer later on though, and ported QLockFile to it. 
Thiago, any input?

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[David Faure]

dfaure added a reviewer: thiago.

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks, thiago
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

jtamate added a comment.


  I guess this is a Qt bug.
  
qint64 QDeadlineTimer::remainingTime() const Q_DECL_NOTHROW
{
qint64 ns = remainingTimeNSecs();
return ns <= 0 ? ns : (ns + 99) / (1000 * 1000);
}
  
  Shouldn't it be:
  
return ns <= 0 ? **0** : (ns + 99) / (1000 * 1000);

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

jtamate added a comment.


  I kept dolphin blocked, just in case.
  
  The backtrace:
  
#0  0x7f54c47c4c90 in __GI___nanosleep 
(requested_time=requested_time@entry=0x7ffdda996710, 
remaining=remaining@entry=0x7ffdda996710)
at ../sysdeps/unix/sysv/linux/nanosleep.c:28
#1  0x7f54be9b236d in qt_nanosleep(timespec) (amount=...) at 
kernel/qelapsedtimer_unix.cpp:195
#2  0x7f54be8bc985 in QLockFile::tryLock(int) (this=, 
timeout=) at io/qlockfile.cpp:274
#3  0x7f54c0a23afb in KDEInitInterface::ensureKdeinitRunning() () at 
/usr/lib64/libKF5DBusAddons.so.5
#4  0x7f54c2d16ffb in  () at /usr/lib64/libKF5KIOCore.so.5
#5  0x7f54c2d17e7a in KIO::Slave::createSlave(QString const&, QUrl 
const&, int&, QString&) () at /usr/lib64/libKF5KIOCore.so.5
#6  0x7f54c2d4c715 in  () at /usr/lib64/libKF5KIOCore.so.5
#7  0x7f54c2d52fbc in  () at /usr/lib64/libKF5KIOCore.so.5
#8  0x7f54be98ba53 in QMetaObject::activate(QObject*, int, int, void**) 
(sender=0x557a8ecc2948, signalOffset=, local_signal_index=0, 
argv=0x7ffdda996b80) at kernel/qobject.cpp:3771
#9  0x7f54be98c087 in QMetaObject::activate(QObject*, QMetaObject 
const*, int, void**) (sender=, m=m@entry=0x7f54bede4d80 
, local_signal_index=local_signal_index@entry=0, 
argv=argv@entry=0x7ffdda996b80) at kernel/qobject.cpp:3633
#10 0x7f54be996fd7 in QTimer::timeout(QTimer::QPrivateSignal) 
(this=, _t1=...) at .moc/moc_qtimer.cpp:200
#11 0x7f54be98c27b in QObject::event(QEvent*) (this=0x557a8ecc2948, 
e=) at kernel/qobject.cpp:1232
#12 0x7f54bf96eb01 in QApplicationPrivate::notify_helper(QObject*, 
QEvent*) (this=this@entry=0x557a8e694980, 
receiver=receiver@entry=0x557a8ecc2948, e=e@entry=0x7ffdda996e30) at 
kernel/qapplication.cpp:3714
#13 0x7f54bf975cea in QApplication::notify(QObject*, QEvent*) 
(this=0x7ffdda9970b0, receiver=0x557a8ecc2948, e=0x7ffdda996e30) at 
kernel/qapplication.cpp:3473
#14 0x7f54be963be9 in QCoreApplication::notifyInternal2(QObject*, 
QEvent*) (receiver=0x557a8ecc2948, event=0x7ffdda996e30)
at ../../include/QtCore/../../src/corelib/kernel/qobject.h:142
#15 0x7f54be9b1e28 in QCoreApplication::sendEvent(QObject*, QEvent*) 
(event=0x7ffdda996e30, receiver=)
at ../../include/QtCore/../../src/corelib/kernel/qcoreapplication.h:234
#16 0x7f54be9b1e28 in QTimerInfoList::activateTimers() 
(this=0x557a8e760f60) at kernel/qtimerinfo_unix.cpp:643
#17 0x7f54be9b00ac in 
QEventDispatcherUNIX::processEvents(QFlags) 
(this=, flags=...)
at kernel/qeventdispatcher_unix.cpp:514
#18 0x7f54b0c0f78d in 
QUnixEventDispatcherQPA::processEvents(QFlags) 
(this=, flags=...)
at qunixeventdispatcher.cpp:68
#19 0x7f54be9629fb in 
QEventLoop::exec(QFlags) (this=0x7ffdda996fc0, 
flags=...)
at ../../include/QtCore/../../src/corelib/global/qflags.h:140
#20 0x7f54be96a78e in QCoreApplication::exec() () at 
../../include/QtCore/../../src/corelib/global/qflags.h:120
#21 0x7f54c4b03c59 in kdemain(int, char**) (argc=, 
argv=) at 
/usr/src/debug/dolphin-18.04.2-1.1.x86_64/src/main.cpp:150
#22 0x7f54c472011b in __libc_start_main (main=
0x557a8d3057c0 , argc=3, argv=0x7ffdda997238, init=, fini=, rtld_fini=, stack_end=0x7ffdda997228)
at ../csu/libc-start.c:308
#23 0x557a8d3057fa in _start () at ../sysdeps/x86_64/start.S:120
  
  0 timeout should exit immediately, a negative number is locked forever (the 
documentation tells).

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[David Faure]

dfaure requested changes to this revision.
dfaure added a comment.
This revision now requires changes to proceed.


  Strange, I never had that bug.
  
  Note that you can use gdb to get a backtrace for a deadlock, no need for 
hotspot for that particular task. In fact, hotspot even misled you. tryLock() 
can't be the problem, it returns immediately ;)  (default timeout 0)
  
  I guess lock() -- which is the actual blocking method in this code -- is 
where everything got stuck. Unfortunately you didn't get a backtrace so we 
can't verify this until it happens again? :(
  
  Maybe a stale lock file, but not detected as one by QLockFile, could lead to 
lock() blocking forever... A recursive call to that method would do that too, 
but I don't see how that could happen.
  
  If you want to introduce some safety against locking forever, it's lock() 
that should be replaced with tryLock(long timeout). I would make it much more 
than 5s though, kdeinit startup can take much more than that (imagine a slow 
system, swapping already, kdeinit starts a number of other processes, and 
triggers config file migration with kconf_update, etc.).

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever in ensureKdeinitRunning

[Jaime Torres Amate]

jtamate retitled this revision from "Don't block forever to 
ensureKdeinitRunning" to "Don't block forever in ensureKdeinitRunning".
jtamate edited the summary of this revision.

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

To: jtamate, dfaure, #frameworks
Cc: kde-frameworks-devel, michaelh, ngraham, bruns

D14302: Don't block forever to ensureKdeinitRunning

[Jaime Torres Amate]

jtamate created this revision.
jtamate added reviewers: dfaure, Frameworks.
Restricted Application added a project: Frameworks.
Restricted Application added a subscriber: kde-frameworks-devel.
jtamate requested review of this revision.

REVISION SUMMARY
  My wife has been suffering this block for several months while I was not 
there, and it never happened to me.
  Finally, It just has happened to me: plasmashell, ktorrent, akregator and 
dolphin where totally blocked.
  With the help of hotspot, the common method between all of them is: 
ensureKdeinitRunning()
  
  Instead of blocking forever, wait a finite amount of time.

REPOSITORY
  R271 KDBusAddons

REVISION DETAIL
  https://phabricator.kde.org/D14302

AFFECTED FILES
  src/kdeinitinterface.cpp

To: jtamate, dfaure, #frameworks
Cc: kde-frameworks-devel, michaelh, ngraham, bruns