Bug 383843 - Spawning insane amounts of DBus messages while copying files
Summary: Spawning insane amounts of DBus messages while copying files
Status: RESOLVED FIXED
Alias: None
Product: frameworks-kio
Classification: Frameworks and Libraries
Component: general (show other bugs)
Version: unspecified
Platform: Other Linux
: NOR normal
Target Milestone: ---
Assignee: David Faure
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2017-08-22 11:40 UTC by Kevin Funk
Modified: 2017-08-22 14:44 UTC (History)
2 users (show)

See Also:
Latest Commit:
Version Fixed In: 5.38
Sentry Crash Report:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Kevin Funk 2017-08-22 11:40:20 UTC
Observed via dbus-monitor while copying a file via the FISH kio slave:

```
...
method call time=1503401586.132715 sender=:1.3660 -> destination=:1.3659 serial=17575 path=/DataEngine/applicationjobs/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218009599
   string "bytes"
method call time=1503401586.133399 sender=:1.3662 -> destination=org.kde.JobViewServer serial=17658 path=/JobViewServer/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218025983
   string "bytes"
method call time=1503401586.133556 sender=:1.3660 -> destination=:1.3659 serial=17576 path=/DataEngine/applicationjobs/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218025983
   string "bytes"
method call time=1503401586.135317 sender=:1.3662 -> destination=org.kde.JobViewServer serial=17659 path=/JobViewServer/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218042367
   string "bytes"
method call time=1503401586.135448 sender=:1.3662 -> destination=org.kde.JobViewServer serial=17660 path=/JobViewServer/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218046462
   string "bytes"
method call time=1503401586.135558 sender=:1.3660 -> destination=:1.3659 serial=17577 path=/DataEngine/applicationjobs/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218042367
   string "bytes"
method call time=1503401586.135569 sender=:1.3660 -> destination=:1.3659 serial=17578 path=/DataEngine/applicationjobs/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218046462
   string "bytes"
method call time=1503401586.149265 sender=:1.3662 -> destination=org.kde.JobViewServer serial=17661 path=/JobViewServer/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218058751
   string "bytes"
method call time=1503401586.149698 sender=:1.3660 -> destination=:1.3659 serial=17579 path=/DataEngine/applicationjobs/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218058751
   string "bytes"
method call time=1503401586.150065 sender=:1.3662 -> destination=org.kde.JobViewServer serial=17662 path=/JobViewServer/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218062846
   string "bytes"
method call time=1503401586.150196 sender=:1.3660 -> destination=:1.3659 serial=17580 path=/DataEngine/applicationjobs/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218062846
   string "bytes"
method call time=1503401586.150800 sender=:1.3662 -> destination=org.kde.JobViewServer serial=17663 path=/JobViewServer/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218075131
   string "bytes"
method call time=1503401586.150944 sender=:1.3660 -> destination=:1.3659 serial=17581 path=/DataEngine/applicationjobs/JobView_2; interface=org.kde.JobViewV2; member=setProcessedAmount
   uint64 218075131
   string "bytes"
...
```

The sender (:1.3660) is the kuiserver executable in this case.


This is part of the reason why the Plasma Desktop tends to become *really* sluggish when copying large files (observed in a number of other bug reports, such as https://bugs.kde.org/show_bug.cgi?id=356479).

When copying files via Dolphin, I usually get the following CPU usages:
- plasmashell: 120% CPU
- Xorg: 60% CPU
- kwin_x11: 7% CPU
- fish.so OR sftp.so: ~5% CPU


Note: This is unrelated to the fish kio slave, it also happens with the sftp kio slave. I didn't test others. I'm not sure how/when the 'processedAmount' updates are triggered; but right now the happen *far* too often. The desktop cannot cope with this.
Comment 1 Kevin Funk 2017-08-22 11:58:16 UTC
This looks really bad...:

 528│ void SlaveBase::processedSize(KIO::filesize_t _bytes)
 529│ {
 530├>    bool emitSignal = false;
 531│
 532│     QDateTime now = QDateTime::currentDateTime();
 533│ 
 534│     if (_bytes == d->totalSize) {
 535│         emitSignal = true;
 536│     } else {
 537│         if (d->lastTimeout.isValid()) {
 538│             emitSignal = d->lastTimeout.msecsTo(now);    // emit size 10 times a second
 539│         } else {
 540│             emitSignal = true;
 541│         }
 542│     }


 538│             emitSignal = d->lastTimeout.msecsTo(now);    // emit size 10 times a second

^ This expression is totally wrong, isn't it? It doesn't do what the comment says. It will evaluate to true if there's just a millisecond time difference => signal will be emitted every ms?
Comment 2 Kevin Funk 2017-08-22 12:04:56 UTC
Introduced by this commit:

commit dca3d5cfd19375f61dd7d8232586227af3f4b34b
Author: David Gil <davidgiloliva@gmail.com>
Date:   Fri Jun 7 22:06:15 2013 +0200

    Port time_t to QDateTime in SlaveBase (KIO)


... with the following interesting hunks of the diff:

-void SlaveBase::processedSize( KIO::filesize_t _bytes )
+void SlaveBase::processedSize(KIO::filesize_t _bytes)
 {
-    bool           emitSignal=false;
-    struct timeval tv;
-    int            gettimeofday_res=gettimeofday( &tv, 0L );
+    bool emitSignal = false;
+
+    QDateTime now = QDateTime::currentDateTime();
 
-    if( _bytes == d->totalSize )
+    if (_bytes == d->totalSize)
         emitSignal=true;
-    else if ( gettimeofday_res == 0 ) {
-        time_t msecdiff = 2000;
-        if (d->last_tv.tv_sec) {
-            // Compute difference, in ms
-            msecdiff = 1000 * ( tv.tv_sec - d->last_tv.tv_sec );
-            time_t usecdiff = tv.tv_usec - d->last_tv.tv_usec;
-            if ( usecdiff < 0 ) {
-                msecdiff--;
-                msecdiff += 1000;
-            }
-            msecdiff += usecdiff / 1000;
-        }
-        emitSignal=msecdiff >= 100; // emit size 10 times a second
+    else {
+        if (d->lastTimeout.isValid())
+            emitSignal = d->lastTimeout.msecsTo(now); // emit size 10 times a second
+        else
+            emitSignal = true;
     }
 
-    if( emitSignal ) {
+    if (emitSignal) {
         KIO_DATA << KIO_FILESIZE_T(_bytes);
-        send( INF_PROCESSED_SIZE, data );
-        if ( gettimeofday_res == 0 ) {
-            d->last_tv.tv_sec = tv.tv_sec;
-            d->last_tv.tv_usec = tv.tv_usec;
-        }
+        send(INF_PROCESSED_SIZE, data);
+        d->lastTimeout = now;
     }
-//    d->processed_size = _bytes;
+
+    //    d->processed_size = _bytes;
 }
Comment 3 Kevin Funk 2017-08-22 14:44:36 UTC
Git commit 801f58e7e76acd4bcb23d6e8092825cdda203a81 by Kevin Funk.
Committed on 22/08/2017 at 14:43.
Pushed by kfunk into branch 'master'.

Really rate-limit INF_PROCESSED_SIZE messages

Summary:
Fixing an ancient porting bug which popped up when porting from Qt4 to
Qt5.

FIXED-IN: 5.38

Reviewers: dfaure

Reviewed By: dfaure

Subscribers: dfaure, #frameworks

Tags: #frameworks

Differential Revision: https://phabricator.kde.org/D7463

M  +1    -1    src/core/slavebase.cpp

https://commits.kde.org/kio/801f58e7e76acd4bcb23d6e8092825cdda203a81