Bug 304986 - Dolphin (and kio_file) eat up CPU when basically doing nothing
Summary: Dolphin (and kio_file) eat up CPU when basically doing nothing
Status: RESOLVED FIXED
Alias: None
Product: dolphin
Classification: Applications
Component: general (show other bugs)
Version: 16.12.2
Platform: unspecified Linux
: NOR normal
Target Milestone: ---
Assignee: Dolphin Bug Assignee
URL:
Keywords: investigated
Depends on:
Blocks:
 
Reported: 2012-08-11 17:17 UTC by Kai Uwe Broulik
Modified: 2014-03-21 12:16 UTC (History)
7 users (show)

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


Attachments
Backtrace (63.45 KB, text/plain)
2012-10-05 10:55 UTC, Sandro Mani
Details
kio_thumbnail backtrace (113.47 KB, text/plain)
2012-10-05 12:55 UTC, Sandro Mani
Details
Add some debug output (4.95 KB, patch)
2012-10-08 04:07 UTC, Frank Reininghaus
Details
Log of Dolphin after rename opened in Gwenview image (8.04 KB, text/x-log)
2012-10-08 19:35 UTC, Alexey Shildyakov
Details
Some GDB output of looping in Dolphin (9.34 KB, application/octet-stream)
2012-10-08 19:55 UTC, Alexey Shildyakov
Details
Loop-output (26.12 KB, text/plain)
2012-10-09 09:11 UTC, Sandro Mani
Details
Callgrinded Dolpin with renaming opened in Gwenview image file (60 bytes, text/plain)
2012-10-09 09:32 UTC, Alexey Shildyakov
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Kai Uwe Broulik 2012-08-11 17:17:48 UTC
Now, finally, I think, virtuoso-t has stopped eating up my CPU, now with KDE 4.9 Dolphin does its job.
I have two folder in split view open with a lot of PNG files in it (and frequently receiving new ones via Skype), and when doing nothing basically, Dolphin shows up with 13% CPU consumption and kio_file with 14% (four core CPU)
I cannot reliably reproduce this but it definitly was not in 4.8

Reproducible: Sometimes
Comment 1 Hrvoje Senjan 2012-08-15 16:20:05 UTC
I have noticed the same thing (altough, i can say that dolphin drains the CPU, not sure about kio_file).
Temporary workaround - refresh dolphin. Also, in my case i had previews turned off in currently watched directories. It's hard to put more details, cause this can happen all of the sudden and without any apparent reason, and since you are usually in the middle of something else, you can't remember exactly how-to-reproduce-part (if there is any).
It usually happens after doing something (copying, browsing, openning files, etc).
Comment 2 Frank Reininghaus 2012-08-15 17:03:07 UTC
Thanks for the bug report! Some more details about how to reproduce this would indeed be helpful, but I know  that it's often not easy to tell what might have triggered the problem.

Do you have Nepomuk enabled? If yes, does disabling it help?
Comment 3 Kai Uwe Broulik 2012-08-15 17:05:22 UTC
Nepomuk is completely disabled on this machine, ie. not only file indexer but the entire "Nepomuk semantic service" AND the nepomukfilewatcher service (edited nepomukserverrc to disasble autostart for this service as well as pointed out on a recent blogpost on planetkde)
Comment 4 Hrvoje Senjan 2012-08-15 17:18:15 UTC
I have it enabled, but this happens both in monitored and not monitored folders. 
2 things i have noticed (i cannot guarantee accuracy of this, it might be i didn't remembered correctly):
a) It is easier to trigger this with split view, although this issue is not exclusive to split view
b) It also usually happens when i leave dolphin view (ie minimize, focus on some other window)
I have a CPU monitor widget in top panel, so i can immediately see when it happens, and, as said, refreshing fixes it.
Comment 5 Frank Reininghaus 2012-08-15 18:12:25 UTC
Thanks for the quick replies! I still don't know what the cause might be, but the fact that refreshing the view works as a temporary workaround might help.
Comment 6 Hrvoje Senjan 2012-08-23 19:14:38 UTC
Just happened:
Opened dolphin -> turned on hidden files -> go to $KDEHOME/apps/desktoptheme/ , installed a theme, go back to home folder (it was in the background for some time like this), disabled hidden files --> CPU got destroyed :)
I have previews for my home folder turned on; refresh again solved this; attached strace output  of dolphin (if this means anything at all).

http://dl.dropbox.com/u/88430917/dolphin.txt
http://dl.dropbox.com/u/88430917/doplhin.txt
Files are too large to be uploaded somewhere else
Comment 7 Jeroen van Meeuwen (Kolab Systems) 2012-08-24 16:19:43 UTC
Resetting assignee to default as per bug #305719
Comment 8 Sandro Mani 2012-10-05 10:55:30 UTC
Created attachment 74353 [details]
Backtrace

I guess I'm experiencing the same problem: occasionally, dolphin takes 50% cpu (dualcore machine), while it should theoretically be idle. When I refresh the folder, CPU usage returns to normal.

I've collected a backtrace when dolphin is endless-looping, see attachment.
Comment 9 Frank Reininghaus 2012-10-05 11:06:07 UTC
Thanks for the backtrace! Looks like it's somehow related to the generation of previews (see below). I don't understand though why this keeps the CPU busy. Normally, the PreviewJobs should not do anything when the generation of previews in the current folder is finished.

#0  0x00007ffce8aa8881 in _int_malloc () from /lib64/libc.so.6
#1  0x00007ffce8aaaef3 in malloc () from /lib64/libc.so.6
#2  0x00007ffcea7e5b29 in QString::realloc (this=this@entry=0x7fffe8523610, alloc=16) at tools/qstring.cpp:1346
#3  0x00007ffcea7e66ee in QString::resize (this=this@entry=0x7fffe8523610, size=<optimized out>, size@entry=15) at tools/qstring.cpp:1282
#4  0x00007ffcea7e6862 in operator>> (in=..., str=...) at tools/qstring.cpp:7605
#5  0x00007ffceafc9e1a in operator>><QString, QVariant> (in=..., map=...) at /usr/include/QtCore/qdatastream.h:410
#6  0x00007ffceafe4094 in KServicePrivate::load (this=this@entry=0x249a1a0, s=...) at /usr/src/debug/kdelibs-4.9.2/kdecore/services/kservice.cpp:333
#7  0x00007ffceafe42a3 in KServicePrivate (_offset=1015000, _str=..., this=0x249a1a0) at /usr/src/debug/kdelibs-4.9.2/kdecore/services/kservice_p.h:41
#8  KService::KService (this=0x24b2280, _str=..., _offset=1015000) at /usr/src/debug/kdelibs-4.9.2/kdecore/services/kservice.cpp:405
#9  0x00007ffceafe612d in KServiceFactory::createEntry (this=<optimized out>, offset=1015000) at /usr/src/debug/kdelibs-4.9.2/kdecore/services/kservicefactory.cpp:181
#10 0x00007ffceafe6e2c in KServiceFactory::serviceOffers (this=0x2092b10, serviceTypeOffset=15103, serviceOffersOffset=<optimized out>)
    at /usr/src/debug/kdelibs-4.9.2/kdecore/services/kservicefactory.cpp:266
#11 0x00007ffceaff399f in KServiceTypeTrader::defaultOffers (this=this@entry=0x1ea1ef0, serviceType=..., constraint=...)
    at /usr/src/debug/kdelibs-4.9.2/kdecore/services/kservicetypetrader.cpp:125
#12 0x00007ffceaff3d61 in KServiceTypeTrader::query (this=0x1ea1ef0, serviceType=..., constraint=...) at /usr/src/debug/kdelibs-4.9.2/kdecore/services/kservicetypetrader.cpp:141
#13 0x00007ffcd9c7502f in KIO::PreviewJobPrivate::startPreview (this=0x241f000) at /usr/src/debug/kdelibs-4.9.2/kio/kio/previewjob.cpp:272
#14 0x00007ffcea8aa63e in QObject::event (this=0x24b7a20, e=<optimized out>) at kernel/qobject.cpp:1195
#15 0x00007ffce9a2b4cc in QApplicationPrivate::notify_helper (this=this@entry=0x192e3e0, receiver=receiver@entry=0x24b7a20, e=e@entry=0x241f670) at kernel/qapplication.cpp:4557
#16 0x00007ffce9a2f94a in QApplication::notify (this=0x7fffe8524660, receiver=0x24b7a20, e=0x241f670) at kernel/qapplication.cpp:4418
#17 0x00007ffceb8bb7b6 in KApplication::notify (this=0x7fffe8524660, receiver=0x24b7a20, event=0x241f670) at /usr/src/debug/kdelibs-4.9.2/kdeui/kernel/kapplication.cpp:311
#18 0x00007ffcea895d3e in QCoreApplication::notifyInternal (this=0x7fffe8524660, receiver=receiver@entry=0x24b7a20, event=event@entry=0x241f670)
    at kernel/qcoreapplication.cpp:915
Comment 10 Sandro Mani 2012-10-05 12:55:04 UTC
Created attachment 74355 [details]
kio_thumbnail backtrace

There is a bug in kio_thumbnail, which causes it to hang similarly. Maybe it is the same issue, just that kio_thumbnail runns within dolphin? See attached backtrace of kio_thumbnail.
Comment 11 Christoph Feck 2012-10-05 13:39:47 UTC
Is there any filesystem activity in other programs, e.g. background compile, torrents, etc.?

As far as I know, there is a bug in either KDirWatch, kio, or Dolphin, that makes it wake up even when a different process (which requested different watch directories) modifies files.
Comment 12 Kai Uwe Broulik 2012-10-05 14:11:31 UTC
On my machine this usually happens when I am doing webdesign, that is I have that folder opened in split view (the other column shows various other folders such as style or documents), and of course I am regularly saving the files in that folder I have opened in Kate.
Comment 13 Frank Reininghaus 2012-10-05 15:28:28 UTC
Hm, it looks like KFileItemModelRolesUpdater continuously starts preview jobs, even though this is not necessary when all previews are generated already. I don't think that it's related to KDirWatch - KFileItemModelRolesUpdater only uses it to determine the number of items in subfolders. Maybe there is some bug in the logic of KFileItemModelRolesUpdater. Unfortunately, I haven't been able to reproduce the problem yet. I have to leave now, but I might be able to provide a patch with some debug output that could answer the question if there is a bug in that class or not.

By the way, I think that kio_thumbnail might only keep the CPU busy because Dolphin keeps requesting previews, so this might have the same root cause.
Comment 14 Alexey Shildyakov 2012-10-06 12:29:34 UTC
  PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+  COMMAND                                                                                                                        
11149 ashl1     20   0  232m  51m 7204 R  97.9  0.6  19:39.93 kio_file                                                                                                                       
 6048 ashl1     20   0  604m  28m 9.8m S  16.7  0.4   6:47.08 dolphin

Think has the same problem. Steps to reproduce:
1. Open folder with images in Details view mode with showing preview (my size is 32 pixels but this doesn't affect I think)
2. Open image in Gwenview
3. Rotate image in Gwenview, don't save
4. Go to next image in Gwenview (without closing)
5. Repeat steps 3-4 several times
6. Save images
7. kio_file and dolphin now uses a lot of CPU

Workaround as sad before:
1. Close Gwenview
2. Refresh the view in Dolphin
Comment 15 Frank Reininghaus 2012-10-08 04:07:14 UTC
Created attachment 74401 [details]
Add some debug output

Thanks, but I still can't reproduce.

The attached patch (can be applied to both 4.9 and master) adds some debug output to KFileItemModelRolesUpdater. In particular, it prints information about the sets m_pendingVisibleItems and m_pendingInvisibleItems, which contain the files that previews are still needed for, and information about started, succeeded, and failed preview jobs.

When this patch is applied and the bug is reproduced, it could be that a lot of debug output containing "KFileItemModelRolesUpdater" is generated, which repeats itself over and over again. It might be helpful if someone could attach a few iterations of this endless debug output here. Thanks for your help!
Comment 16 Alexey Shildyakov 2012-10-08 08:51:06 UTC
It's not always reproducable.
I applied your patch and see that debug information. Will wait to reproduce the situation.
Comment 17 Sandro Mani 2012-10-08 13:14:25 UTC
It should suffice to run dolphin from the terminal and check at the output right? Cause I've just noticed both kio_thumbnail and kio_file endless-looping, but dolphin stayed silent. As usual, refreshing the folder killed the two kio.

For completeness, the respective backtraces:
kio_thumbnail:
####
#0  0x00007ffcea510660 in __write_nocancel () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007ffce732d914 in qt_safe_write (len=92, data=0x2691cf8, fd=8) at ../../src/corelib/kernel/qcore_unix_p.h:262
#2  QNativeSocketEnginePrivate::nativeWrite (this=0x1a48a30, data=0x2691cf8 "    52_66_", len=92)
    at socket/qnativesocketengine_unix.cpp:1014
#3  0x00007ffce7322df2 in QAbstractSocketPrivate::flush (this=this@entry=0x1a48660) at socket/qabstractsocket.cpp:758
#4  0x00007ffce73232ac in QAbstractSocketPrivate::canWriteNotification (this=this@entry=0x1a48660)
    at socket/qabstractsocket.cpp:695
#5  0x00007ffce7325927 in QAbstractSocket::waitForBytesWritten (this=0x1a798e0, msecs=-1) at socket/qabstractsocket.cpp:1962
#6  0x00007ffcd9bc7fb2 in KIO::SocketConnectionBackend::sendCommand (this=0x1a422d0, task=...)
    at /usr/src/debug/kdelibs-4.9.2/kio/kio/connection.cpp:298
#7  0x00007ffcd9bc92e9 in sendnow (data=..., _cmd=102, this=0x1a482f8) at /usr/src/debug/kdelibs-4.9.2/kio/kio/connection.cpp:509
#8  KIO::Connection::sendnow (this=0x1a482f8, _cmd=102, data=...) at /usr/src/debug/kdelibs-4.9.2/kio/kio/connection.cpp:497
#9  0x00007ffcd9bc9d2d in KIO::Connection::send (this=0x1a482f8, cmd=102, data=...)
    at /usr/src/debug/kdelibs-4.9.2/kio/kio/connection.cpp:493
#10 0x00007ffcd9c8b7b8 in KIO::SlaveBase::send (this=this@entry=0x7fffe8524610, cmd=cmd@entry=102, arr=...)
    at /usr/src/debug/kdelibs-4.9.2/kio/kio/slavebase.cpp:1309
#11 0x00007ffcd9c8e3ec in KIO::SlaveBase::error (this=0x7fffe8524610, _errid=104, _text=...)
    at /usr/src/debug/kdelibs-4.9.2/kio/kio/slavebase.cpp:441
#12 0x00007ffccd806adb in ThumbnailProtocol::get (this=0x7fffe8524610, url=...)
    at /usr/src/debug/kde-runtime-4.9.2/kioslave/thumbnail/thumbnail.cpp:269
#13 0x00007ffcd9c90a3c in KIO::SlaveBase::dispatch (this=0x7fffe8524610, command=67, data=...)
    at /usr/src/debug/kdelibs-4.9.2/kio/kio/slavebase.cpp:1046
#14 0x00007ffcd9c8b746 in KIO::SlaveBase::dispatchLoop (this=0x7fffe8524610)
    at /usr/src/debug/kdelibs-4.9.2/kio/kio/slavebase.cpp:295
#15 0x00007ffccd8033c8 in kdemain (argc=4, argv=0x1913c10)
    at /usr/src/debug/kde-runtime-4.9.2/kioslave/thumbnail/thumbnail.cpp:136
#16 0x0000000000408226 in launch (argc=argc@entry=4, _name=_name@entry=0x18fab58 "kio_thumbnail", args=0x18fabdc "", args@entry=
    0x18fab66 "thumbnail", cwd=cwd@entry=0x0, envc=envc@entry=0, envs=<optimized out>, envs@entry=0x18fabe4 "", reset_env=false, 
    tty=tty@entry=0x0, avoid_loops=false, startup_id_str=startup_id_str@entry=0x40aa8e "0")
    at /usr/src/debug/kdelibs-4.9.2/kinit/kinit.cpp:726
#17 0x00000000004090ab in handle_launcher_request (sock=8, who=<optimized out>)
    at /usr/src/debug/kdelibs-4.9.2/kinit/kinit.cpp:1218
#18 0x00000000004096f0 in handle_requests (waitForPid=waitForPid@entry=0) at /usr/src/debug/kdelibs-4.9.2/kinit/kinit.cpp:1411
#19 0x0000000000405307 in main (argc=4, argv=<optimized out>, envp=0x7fffe8525450)
    at /usr/src/debug/kdelibs-4.9.2/kinit/kinit.cpp:1899
###

kio_file:
###
#0  0x00007ffcea899649 in QCoreApplicationPrivate::sendPostedEvents (receiver=0x0, event_type=52, data=0x18622d0)
    at kernel/qcoreapplication.cpp:1495
#1  0x00007ffcd9c8b528 in KIO::SlaveBase::dispatchLoop (this=0x7fffe8524650)
    at /usr/src/debug/kdelibs-4.9.2/kio/kio/slavebase.cpp:320
#2  0x00007ffccd7ffb6e in kdemain (argc=4, argv=0x1912a70) at /usr/src/debug/kdelibs-4.9.2/kioslave/file/file.cpp:117
#3  0x0000000000408226 in launch (argc=argc@entry=4, _name=_name@entry=0x18e6c08 "kio_file", args=0x18e6c82 "", args@entry=
    0x18e6c11 "file", cwd=cwd@entry=0x0, envc=envc@entry=0, envs=<optimized out>, envs@entry=0x18e6c8a "", reset_env=false, 
    tty=tty@entry=0x0, avoid_loops=false, startup_id_str=startup_id_str@entry=0x40aa8e "0")
    at /usr/src/debug/kdelibs-4.9.2/kinit/kinit.cpp:726
#4  0x00000000004090ab in handle_launcher_request (sock=8, who=<optimized out>)
    at /usr/src/debug/kdelibs-4.9.2/kinit/kinit.cpp:1218
#5  0x00000000004096f0 in handle_requests (waitForPid=waitForPid@entry=0) at /usr/src/debug/kdelibs-4.9.2/kinit/kinit.cpp:1411
#6  0x0000000000405307 in main (argc=4, argv=<optimized out>, envp=0x7fffe8525450)
    at /usr/src/debug/kdelibs-4.9.2/kinit/kinit.cpp:1899
###
Comment 18 Frank Reininghaus 2012-10-08 13:16:27 UTC
Yes, checking Dolphin's output should be sufficient. You have to run 'kdebugdialog' and enable debug output though, sorry for forgetting to mention this.
Comment 19 Sandro Mani 2012-10-08 19:23:12 UTC
Hang-output:

dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::jobFinished: KIO::StatJob(0x21c20d0) KIO::Slave(0x22928f0)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::doJob: KIO::SimpleJob(0x2501a60)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::jobFinished: KIO::StatJob(0x2501a60) KIO::Slave(0x22928f0)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::doJob: KIO::SimpleJob(0x230e580)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::jobFinished: KIO::StatJob(0x230e580) KIO::Slave(0x22928f0)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::doJob: KIO::SimpleJob(0x229e060)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::jobFinished: KIO::StatJob(0x229e060) KIO::Slave(0x22928f0)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::doJob: KIO::SimpleJob(0x21fcce0)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::jobFinished: KIO::StatJob(0x21fcce0) KIO::Slave(0x22928f0)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::doJob: KIO::SimpleJob(0x21c20d0)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::jobFinished: KIO::StatJob(0x21c20d0) KIO::Slave(0x22928f0)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::doJob: KIO::SimpleJob(0x1c50130)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::jobFinished: KIO::StatJob(0x1c50130) KIO::Slave(0x22928f0)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::doJob: KIO::SimpleJob(0x226ce50)
dolphin(20290)/kio (KDirListerCache) KDirListerCache::stopListingUrl: KFileItemModelDirLister(0x1dc8670)  url= KUrl("file:///home/sandro/Desktop")
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::cancelJob: KIO::StatJob(0x226ce50) KIO::Slave(0x22928f0)
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::cancelJob: Scheduler: killing slave  20298
dolphin(20290)/kio (Slave) KIO::Slave::kill: killing slave pid 20298 ( "file://" )
dolphin(20290)/kio (Scheduler) KIO::SchedulerPrivate::jobFinished: KIO::StatJob(0x226ce50) KIO::Slave(0x22928f0)
dolphin(20290)/kio (KDirListerCache) KDirListerCache::forgetDirs: KFileItemModelDirLister(0x1dc8670) item moved into cache: KUrl("file:///home/sandro/Desktop")
dolphin(20290)/kio (KDirListerCache) KDirListerCache::listDir: Reloading directory: KUrl("file:///home/sandro/Desktop")


Reproducer:
- Make screenshot, save in currently open folder
- Open saved image in gewnview
- While image is open, rename the image
- Dolphin starts eating the CPU
Comment 20 Alexey Shildyakov 2012-10-08 19:35:04 UTC
Created attachment 74426 [details]
Log of Dolphin after rename opened in Gwenview image

Don't reallyt think this is helpfull. Because kio_file and dolphin still using more CPU, but with no logging. The behavior described above works wor me.
Comment 21 Alexey Shildyakov 2012-10-08 19:55:58 UTC
Created attachment 74427 [details]
Some GDB output of looping in Dolphin
Comment 22 Frank Reininghaus 2012-10-09 09:01:01 UTC
Thanks for the logs! If there is no output from KFileItemModelRolesUpdater while the high CPU usage occurs, my assumption that something is going wrong in that class is wrong :-(

The backtrace from comment 8 showed that new preview jobs get started all the time, and I thought that KFileItemModelRolesUpdater was responsible for it. Sandro, you got that backtrace, but your log from comment 19 did not show any indication of this. Could you verify that you do get some debug output containing KFileItemModelRolesUpdater when starting Dolphin with my patch applied? Just to make sure that the debug output is configured correctly.
Comment 23 Sandro Mani 2012-10-09 09:11:15 UTC
Created attachment 74440 [details]
Loop-output

Whoops, my mistake. New output log attached (obtained using the reproducer I mentioned in comment 19)
Comment 24 Sandro Mani 2012-10-09 09:14:39 UTC
Just to point out: /home/sandro/Desktop/snapshot.png is the new name of the file.
Comment 25 Alexey Shildyakov 2012-10-09 09:32:21 UTC
Created attachment 74442 [details]
Callgrinded Dolpin with renaming opened in Gwenview image file

Seems that while using valgrind and callgrind the problem is gone. But anyway attach the info cause it may help you.
Comment 26 Frank Reininghaus 2012-10-09 09:45:04 UTC
Thanks Sandro!

dolphin(26285) KFileItemModelRolesUpdater::slotGotPreview: [KFileItem for KUrl("file:///home/sandro/Desktop/snapshot.png") ]
dolphin(26285) KFileItemModelRolesUpdater::slotGotPreview: m_pendingVisibleItems contains 1 items: ([KFileItem forKUrl("file:///home/sandro/Desktop/snapshot.png") ] )

This output is generated by the following code:

    kDebug() << item;
    m_pendingVisibleItems.remove(item);
    m_pendingInvisibleItems.remove(item);

    DEBUG_PENDING_ITEMS;

Looks like removing the item from m_pendingVisibleItems fails. I'm not sure yet why it happens, but knowing where it happens is a *big* step forward. I'll have a close look at the code when I find some time.
Comment 27 Frank Reininghaus 2012-10-09 10:59:54 UTC
I think the reason why the KFileItem that the preview has been received for is not removed from the set m_pendingVisibleItems is that KFileItems are only considered equal if their "d" pointers are the same, see

http://api.kde.org/4.x-api/kdelibs-apidocs/kio/html/kfileitem_8cpp_source.html#l01247

and note the "is this enough?" comment. If the KFileItems in the PreviewJob and in the sets m_pending*Items are the same or not probably depends quite sensitively on the timing of the "PreviewJob started", "file modified", and "PreviewJob finished" events, which explains why the issue is not always reproducible for everyone and why Alexey does not see the problem when running in Valgrind.

But this still doesn't fully explain why we receive previews for KFileItems which don't match those in m_pending*Items in an endless loop, and not only once. The preview jobs are always started for KFileItems which are taken directly from these sets. Maybe some sort of caching is done inside the preview job which changes the KFileItems behind the scenes.
Comment 28 Frank Reininghaus 2012-10-09 16:10:49 UTC
I think I've got it. The "rename" part of comment 19, which I only noticed now, was a good hint, and finally made me able to reproduce this.

The real problem is the following:

1. When renaming the item inside the view, DolphinView::slotRoleEditingFinished() changes the item's name using KFileItemModel::setData(), which changes the URL of the KFileItem inside the model, and, unfortunately, detaches it from all other KFileItems which have the same 'd' pointer.

2. At the same time, the KFileItem in KFileItemModel's set m_pendingVisibleItems apparently has its URL changed behind the scenes by KIO's magic.

The problem is that both KFileItems now share the URL and everything else, but are considered different because their 'd' pointer is different.

Aaaargh!

We could fix this inside KFileItemModelRolesUpdater, but I'm wondering if it makes more sense to change the way KFileItems are compared to prevent that other people have to go through such a debugging mess in the future.
Comment 29 Alexey Shildyakov 2012-10-09 16:22:24 UTC
Yeap. I also tried to understand that situation with GDB and documentation. I suspect of detach() cause KFileItem use implicit sharing but as I don't know inner KDE structure it's problematic to find the location of problem.
To solve in KFileItem term you need to change the type of shared d pointer to QExplicitlySharedDataPointer. See http://qt-project.org/doc/qt-4.8/qshareddatapointer.html#implicit-vs-explicit-sharing But it'll produce more time due to synchronization, you know, so I'm in doubt is that really need to change the type? Who are response for KIO?
I'm wondering the KIO magic synchronizing the objects while renaming :)
Comment 30 Frank Reininghaus 2012-10-09 16:36:49 UTC
(In reply to comment #29)
> Yeap. I also tried to understand that situation with GDB and documentation.
> I suspect of detach() cause KFileItem use implicit sharing but as I don't
> know inner KDE structure it's problematic to find the location of problem.

Yes, it is. You don't see the detaching of the KFileItem at all in the source, that confused me for a while. It's all done behind the scenes by QExplicitlySharedDataPointer.

> To solve in KFileItem term you need to change the type of shared d pointer
> to QExplicitlySharedDataPointer. See
> http://qt-project.org/doc/qt-4.8/qshareddatapointer.html#implicit-vs-
> explicit-sharing But it'll produce more time due to synchronization, you
> know, so I'm in doubt is that really need to change the type? Who are
> response for KIO?
> I'm wondering the KIO magic synchronizing the objects while renaming :)

David Faure is responsible for most parts of KIO, I'll get in touch with him.

Just one thing I forgot in my earlier comment: the key part in the chain of events that leads to the endless loop is the function KFileItemModelRolesUpdater::slotPreviewJobFinished(). To determine which previews it will request next, it takes the set m_pendingVisibleItems (which contains the 'old' KFileItem, which has its URL changed by KIO, and is not 'equal' to the one inside the KFileItemModel), but sorts it using KFileItemModelRolesUpdater::sortedItems(). Now this function returns a list which contains the corresponding KFileItem from the KFileItemModel. 

This item also goes to the PreviewJob and finally ends up in KFileItemModelRolesUpdater::slotGotPreview(const KFileItem& item, ..), where removing it from the set m_pendingVisibleItems fails because 'item' is the one from the KFileItemModel, which is 'different' from the one in m_pendingVisibleItems.

There is still some time to go until 4.9.3 is tagged, so I can think about the best solution for this issue and possibly discuss it with David Faure and others.

I would like to thank everyone who provided feedback about this bug. I would have never found out the cause of this bug alone!
Comment 31 Alexey Shildyakov 2012-10-09 16:59:21 UTC
(In reply to comment #30)
> It's all done behind the scenes by QExplicitlySharedDataPointer.
Of course. I mean I don't find the location when KFileItem was changed because I think it's done earlier and doesn't correspond to update preview. Now KFileItem uses QSharedDataPointer for d pointer instead of QExplicitlySharedDataPointer I sad about.

> I would like to thank everyone who provided feedback about this bug. I would
> have never found out the cause of this bug alone!
And great thanks to you who involves into our doings, believing in users and quick finding the problem!
All we really deserve a cake! :)
Comment 32 Sandro Mani 2012-10-09 17:20:00 UTC
This is when open source rocks :)
Comment 33 Frank Reininghaus 2012-10-19 14:27:22 UTC
There is a discussion about the KFileItem comparison issue on the kde-core-devel list:

http://lists.kde.org/?t=135056131400003&r=1&w=2

If you still have the debug output patch applied, please revert it because it can cause crashes in some situations when closing the view (bug 308656). Sorry for the trouble!
Comment 34 Frank Reininghaus 2012-10-26 08:12:51 UTC
The KFileItem change in kdelibs will only be in KDE 4.10 - this looks safer because this behaviour change could potentially cause unexpected regressions in existing code which relies on the old behaviour.

I'll try to commit a workaround for this issue in Dolphin for KDE 4.9.3 because the bug can be really annoying, and a lot of people (including those who haven't actually upgrade to KDE 4.9 yet) will benefit from a fix. That's not quite as easy as the change in kdelibs, but should be doable with not too much effort.
Comment 35 Frank Reininghaus 2012-10-26 08:13:44 UTC
Git commit b8f64ca3f4b6311519c21046031d66d9d0a570c6 by Frank Reininghaus.
Committed on 26/10/2012 at 10:05.
Pushed by freininghaus into branch 'KDE/4.10'.

Consider two KFileItems 'equal' if they share the same URL

Up to now, KFileItem::operator==(const KFileItem&) only returned true if
both items shared the same d pointer. However, the implicitly shared
d pointer is an implementation detail of the class, and making the
comparison depend on it might not be expected by the developer using the
class. Fixes a problem in Dolphin, where the unexpected outcome of the
comparison caused permanent high CPU usage.

M  +2    -3    kio/kio/kfileitem.cpp
M  +11   -3    kio/kio/kfileitem.h
M  +8    -2    kio/tests/kfileitemtest.cpp

http://commits.kde.org/kdelibs/b8f64ca3f4b6311519c21046031d66d9d0a570c6
Comment 36 Sandro Mani 2012-10-26 08:19:02 UTC
Many thanks!
Comment 37 Frank Reininghaus 2012-10-27 07:52:58 UTC
Git commit ea6a7c09a0067aaf62ef2de69b5a2c4967676768 by Frank Reininghaus.
Committed on 27/10/2012 at 09:48.
Pushed by freininghaus into branch 'KDE/4.9'.

Workaround for failed comparison of items in KFileItemModelRolesUpdater

The real fix is in the KDE/4.10 branch of kdelibs
(commit b8f64ca3f4b6311519c21046031d66d9d0a570c6). We work around the
problem that the KFileItem that a preview has been requested for is
different from the KFileItems in the sets m_pendingVisibleItems and
m_pendingInvisibleItems by refreshing those sets when we detect that
the bug has been triggered.
FIXED-IN: 4.9.3

M  +26   -0    dolphin/src/kitemviews/kfileitemmodelrolesupdater.cpp

http://commits.kde.org/kde-baseapps/ea6a7c09a0067aaf62ef2de69b5a2c4967676768