Bug 185642 - Odd disk activity during file copy operations if progress panel is shown
Summary: Odd disk activity during file copy operations if progress panel is shown
Status: RESOLVED FIXED
Alias: None
Product: plasma4
Classification: Unmaintained
Component: general (other bugs)
Version First Reported In: unspecified
Platform: Debian testing Linux
: NOR normal
Target Milestone: ---
Assignee: Plasma Bugs List
URL:
Keywords:
: 183557 185883 (view as bug list)
Depends on:
Blocks:
 
Reported: 2009-02-26 20:35 UTC by Janne Pikkarainen
Modified: 2009-05-13 18:40 UTC (History)
7 users (show)

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


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Janne Pikkarainen 2009-02-26 20:35:36 UTC
Version:            (using KDE 4.2.0)
OS:                Linux
Installed from:    Debian testing/unstable Packages

Please don't laugh at me, of course some kind of disk activity is expected if one is copying files around. :-) But what I just encountered is something completely different.

I just started to backup my files from my laptop (Dell Latitude D830 with 2 GB RAM and NVidia Quadro 140NVS) to my NAS. Just for kicks I used Dolphin for that this time. Dolphin puts an information applet to systray and clicking that shows the current copy progress.

I was performing this backup while sitting in a quiet room. Then I suddenly discovered this odd bug or whatever: if I click the systray info applet to see the current copy progress, my laptops hard drive starts to make a clicking sound (like seeking activity) about three times per second. When I hide the progress bar, the clicking sound goes away. 

xorg, kwin and plasma CPU usage jumps from couple of percents to 15-25% while the progress bar is kept visible. Everything seems to be still working smoothly, though.

I tried to capture a video clip about this with my mobile phone. Unfortunately the clip quality is not very good, but I hope you can hear the HD sound nevertheless.

Anyway, I started "btrace /dev/sda" to see what's going on. When the progress bar is hidden, btrace remains silent. Right after I make the progress bar visible, btrace starts to spew stuff like this:

---
 8,0    0        8     1.367404495  5642  A  WS 11070430 + 64 <- (8,3) 10508155
  8,0    0        9     1.367407009  5642  Q  WS 11070430 + 64 [plasma]         
  8,0    0       10     1.367416228  5642  G  WS 11070430 + 64 [plasma]         
  8,0    0       11     1.367422095  5642  P   N [plasma]                       
  8,0    0       12     1.367426844  5642  I   W 11070430 + 64 [plasma]         
  8,0    0       13     1.367477130  5642  D   W 11070430 + 64 [plasma]         
  8,0    0       14     1.369016713  5642  C   W 11070430 + 64 [0]              
  8,0    1        1     1.639800682  5642  A  WS 11070494 + 64 <- (8,3) 10508219
  8,0    1        2     1.639802638  5642  Q  WS 11070494 + 64 [plasma]         
  8,0    1        3     1.639809063  5642  G  WS 11070494 + 64 [plasma]         
  8,0    1        4     1.639813254  5642  P   N [plasma]                       
  8,0    1        5     1.639816327  5642  I   W 11070494 + 64 [plasma]         
  8,0    1        6     1.639845940  5642  D   W 11070494 + 64 [plasma]         
  8,0    1        7     1.641447541  5642  C   W 11070494 + 64 [0]              
  8,0    1        8     1.689142725  5642  A  WS 11070558 + 64 <- (8,3) 10508283
  8,0    1        9     1.689186865  5642  Q  WS 11070558 + 64 [plasma]         
  8,0    1       10     1.689193290  5642  G  WS 11070558 + 64 [plasma]         
  8,0    1       11     1.689197481  5642  P   N [plasma]                       
  8,0    1       12     1.689200554  5642  I   W 11070558 + 64 [plasma]         
  8,0    1       13     1.689230446  5642  D   W 11070558 + 64 [plasma]         
  8,0    0       15     1.689807335     0  C   W 11070558 + 64 [0]              
  8,0    1       14     2.076124750  5642  A  WS 11070622 + 64 <- (8,3) 10508347
  8,0    1       15     2.076127544  5642  Q  WS 11070622 + 64 [plasma]         
  8,0    1       16     2.076137321  5642  G  WS 11070622 + 64 [plasma]         
  8,0    1       17     2.076152407  5642  P   N [plasma]                       
  8,0    1       18     2.076156598  5642  I   W 11070622 + 64 [plasma]         
  8,0    1       19     2.076197944  5642  D   W 11070622 + 64 [plasma]         
---

So it seems that plasma is doing some extra work.
Comment 1 Peter Penz 2009-02-26 20:40:38 UTC
Thanks for the report, I've forwarded this issue to the plasma team and stay on CC. @plasma team: Please let me know if you think this is not in your responsibility.
Comment 2 Janne Pikkarainen 2009-02-26 20:43:33 UTC
Thanks for the extremely fast response! It seems I can't upload attachments to this 'zilla, so here's the video clip I mentioned in my bug report:

http://jaba.mbnet.fi/odd-disk-activity-dolphin-while-copying-files
Comment 3 Janne Pikkarainen 2009-02-26 21:11:55 UTC
I also straced the process with "strace -p `pidof plasma`". What in the world plasma is doing with some theme index + lock files?

---
open("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock.aM5642", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) = 18                                                                 
fchmod(18, 0644)                        = 0                                                                                                                                        
uname({sys="Linux", node="lappy", ...}) = 0                                                                                                                    
write(18, "5642\n"..., 5)               = 5                                                                                                                                        
write(18, "plasma\n"..., 7)             = 7                                                                                                                                        
write(18, "lappy\n"..., 26) = 26                                                                                                                               
link("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock.aM5642", "/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock") = 0                                                  
lstat64("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock.aM5642", {st_mode=S_IFREG|0644, st_size=38, ...}) = 0                                                               
lstat64("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock", {st_mode=S_IFREG|0644, st_size=38, ...}) = 0                                                                      
_llseek(18, 0, [0], SEEK_SET)           = 0                                                                                                                                        
close(18)                               = 0                                                                                                                                        
unlink("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock.aM5642") = 0                                                                                                         
stat64("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.index", {st_mode=S_IFREG|0644, st_size=33656832, ...}) = 0                                                                
stat64("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.index", {st_mode=S_IFREG|0644, st_size=33656832, ...}) = 0                                                                
stat64("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.index", {st_mode=S_IFREG|0644, st_size=33656832, ...}) = 0                                                                
stat64("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.index", {st_mode=S_IFREG|0644, st_size=33656832, ...}) = 0                                                                
stat64("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.index", {st_mode=S_IFREG|0644, st_size=33656832, ...}) = 0                                                                
unlink("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock") = 0                                                                                                                
clock_gettime(CLOCK_MONOTONIC, {10302, 746697381}) = 0                                                                                                                             
clock_gettime(CLOCK_MONOTONIC, {10302, 746730067}) = 0                                                                                                                             
lstat64("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock", 0xbfb85e18) = -1 ENOENT (No such file or directory)                                                               
stat64("/tmp/kde-jaba/", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0                                                                                                            
stat64("/var/tmp/kdecache-jaba/kpc", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0                                                                                                
open("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock.TA5642", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE, 0600) = 18                                                                 
fchmod(18, 0644)                        = 0                                                                                                                                        
uname({sys="Linux", node="lappy", ...}) = 0                                                                                                                    
write(18, "5642\n"..., 5)               = 5                                                                                                                                        
write(18, "plasma\n"..., 7)             = 7                                                                                                                                        
write(18, "lappy\n"..., 26) = 26                                                                                                                               
link("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock.TA5642", "/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock") = 0                                                  
lstat64("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock.TA5642", {st_mode=S_IFREG|0644, st_size=38, ...}) = 0                                                               
lstat64("/var/tmp/kdecache-jaba/kpc/plasma_theme_Oxyglass.lock", {st_mode=S_IFREG|0644, st_size=38, ...}) = 0                                                                      
_llseek(18, 0, [0], SEEK_SET)           = 0                                                                                                                                        
close(18)                               = 0
Comment 4 Janne Pikkarainen 2009-02-26 21:15:43 UTC
Just a wild guess (I've never actually read KDE 4.x source code): maybe plasma is creating a new lock file and then removing it every time the progress bar needs to be updated? That can't be right. 

A temporary work-around (for me) would be to move my /var/tmp/kdecache-jaba to /dev/shm, but that would not be right, either. :-)
Comment 5 Janne Pikkarainen 2009-02-26 21:40:01 UTC
I took a quick peek to KDE's code via websvn.kde.org. For me it seems that KDE attempts to cache theme related pixmaps, but for some reason in this case it fails to do so, discarding the whole cache for that plasma info popup, and thus creating the disk activity. Was that right? :-)

So my guess is that ThemePrivate::discardCache() gets called from some unexpected place.

http://websvn.kde.org/trunk/KDE/kdelibs/plasma/theme.cpp?view=markup

Oh well. Gotta go to sleep, I'll try to investigate this further to help you more.
Comment 6 Peter Penz 2009-02-27 10:43:32 UTC
*** Bug 183557 has been marked as a duplicate of this bug. ***
Comment 7 Peter Penz 2009-03-01 19:16:10 UTC
*** Bug 185883 has been marked as a duplicate of this bug. ***
Comment 8 Janne Pikkarainen 2009-03-06 19:20:25 UTC
Out of curiosity, I just copied my /var/tmp/kdecache-jaba to /dev/shm/kdecache-jaba, symlinked /var/tmp/kdecachejaba to /dev/shm/kdecache-jaba and logged in to KDE. Or in Unix-speak:

---
mkdir /dev/shm/kdecache-jaba
cp -pr /var/tmp/kdecache-jaba/* /dev/shm/kdecache-jaba
chown -R jaba /dev/shm/kdecache-jaba
mv /var/tmp/kdecache-jaba /var/tmp/kdecache-jaba.bak
ln -s /var/tmp/kdecache-jaba /dev/shm/kdecache-jaba
---

Overall feeling is a bit snappier, for example clicking on taskbar clock (to open the calendar) doesn't cause any disk activity and calendar pops up instantly.
Comment 9 Aaron J. Seigo 2009-05-13 06:22:30 UTC
yes, according to those straces it's evident that an svg is being repeatedly cached and destroyed. my guess is that it's the progress bar... it's painting using an svg which is automatically caching behind the scenes .... only it's changing it's size quite often which results in re-caching over and over. in the case of something moving like the progress meter, it's really counter productive to do caching at all. i'll whip up a patch to allow svg's to bypass caching under such circumstances.
Comment 10 Aaron J. Seigo 2009-05-13 18:40:53 UTC
SVN commit 967637 by aseigo:

turn off caching when we are rending the bar
BUG:185642


 M  +7 -1      meter.cpp  


WebSVN link: http://websvn.kde.org/?view=rev&revision=967637