Bug 185265 - digikam constantly using some CPU in a poll loop due a timeout
Summary: digikam constantly using some CPU in a poll loop due a timeout
Status: RESOLVED FIXED
Alias: None
Product: digikam
Classification: Applications
Component: Preview-Video (show other bugs)
Version: unspecified
Platform: openSUSE Linux
: NOR wishlist
Target Milestone: ---
Assignee: Digikam Developers
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2009-02-22 19:36 UTC by Roman Fietze
Modified: 2018-08-19 14:19 UTC (History)
4 users (show)

See Also:
Latest Commit:
Version Fixed In: 6.0.0


Attachments
complete output when starting showFoto (137.55 KB, application/x-gzip)
2009-02-22 21:08 UTC, Andi Clemens
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Roman Fietze 2009-02-22 19:36:28 UTC
Version:           0.10.0-rc2 (using KDE 4.2.0)
OS:                Linux
Installed from:    SuSE RPMs

Not really a "problem", but on my box digikam constantly uses 3-4% CPU doing the following (not yet knowing where the socket on fd 7 is connected to):

19:30:10.126461 clock_gettime(CLOCK_MONOTONIC, {19813, 484402342}) = 0
19:30:10.126781 read(7, 0x839c12c, 4096) = -1 EAGAIN (Resource temporarily unavailable)
19:30:10.127067 clock_gettime(CLOCK_MONOTONIC, {19813, 484971193}) = 0
19:30:10.127384 clock_gettime(CLOCK_MONOTONIC, {19813, 485290769}) = 0
19:30:10.127671 clock_gettime(CLOCK_MONOTONIC, {19813, 485580140}) = 0
19:30:10.127946 clock_gettime(CLOCK_MONOTONIC, {19813, 485852554}) = 0
19:30:10.128213 read(7, 0x839c12c, 4096) = -1 EAGAIN (Resource temporarily unavailable)
19:30:10.128488 poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=7, events=POLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=13, events=POLLIN}], 6, 195) = 0 (Timeout)
19:30:10.326444 clock_gettime(CLOCK_MONOTONIC, {19813, 684371803}) = 0
19:30:10.326747 read(7, 0x839c12c, 4096) = -1 EAGAIN (Resource temporarily unavailable)
19:30:10.327032 clock_gettime(CLOCK_MONOTONIC, {19813, 684936847}) = 0
19:30:10.327341 clock_gettime(CLOCK_MONOTONIC, {19813, 685250711}) = 0
19:30:10.327630 clock_gettime(CLOCK_MONOTONIC, {19813, 685535629}) = 0
19:30:10.327902 clock_gettime(CLOCK_MONOTONIC, {19813, 685810948}) = 0
19:30:10.328171 read(7, 0x839c12c, 4096) = -1 EAGAIN (Resource temporarily unavailable)
19:30:10.328444 poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=7, events=POLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=13, events=POLLIN}], 6, 195) = 0 (Timeout)

This is a 2x500MHz SMP box. I would assume when using digikam on something small as a netbook, or multiple times on an application server (at home I use this SMP box for up to three desktops), this should or could be reduced.

Therefore I rated this an enhancement, not really a bug.
Comment 1 caulier.gilles 2009-02-22 19:52:03 UTC
Can you identify which process use this cpu ?

digiKam provide also kioslave to play with SQlite database. there are separated process, because SQlite cannot be use with multithreading.

Also, we need to know in which conditions/action in digiKam the cpu is consumed.

Gilles Caulier
Comment 2 Roman Fietze 2009-02-22 20:34:02 UTC
(In reply to comment #1)

> Can you identify which process use this cpu ?

Seems to be a thread of the originally started process. Strace shows e.g the following lines:

15685 <first line in strace output, the original process>
...
15685 20:17:22.664063 clone(child_stack=0xade46474, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT
_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xade46bd8, {entry_number:6, base_addr:0xade46b90, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xade46bd8) = 15695
...
15685 20:25:58.280403 clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
15695 20:25:58.280535 <... futex resumed> ) = 0
15685 20:25:58.280649 <... clock_gettime resumed> {23161, 638303372}) = 0
15695 20:25:58.280870 clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
15685 20:25:58.280994 clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
15695 20:25:58.281125 <... clock_gettime resumed> {23161, 638786876}) = 0
15685 20:25:58.281264 <... clock_gettime resumed> {23161, 638893226}) = 0
15695 20:25:58.281464 clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
15685 20:25:58.281589 clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
15695 20:25:58.281720 <... clock_gettime resumed> {23161, 639382182}) = 0
15685 20:25:58.281857 <... clock_gettime resumed> {23161, 639488045}) = 0
15695 20:25:58.282046 clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
15685 20:25:58.282169 clock_gettime(CLOCK_MONOTONIC,  <unfinished ...>
15695 20:25:58.282299 <... clock_gettime resumed> {23161, 639963573}) = 0
15685 20:25:58.282437 <... clock_gettime resumed> {23161, 640067675}) = 0
15695 20:25:58.282616 gettimeofday( <unfinished ...>
15685 20:25:58.282738 read(7,  <unfinished ...>
15695 20:25:58.282873 <... gettimeofday resumed> {1235330758, 282723}, NULL) = 0
15685 20:25:58.283012 <... read resumed> 0x839c124, 4096) = -1 EAGAIN (Resource temporari
ly unavailable)
15695 20:25:58.283182 clock_gettime(CLOCK_REALTIME,  <unfinished ...>
15685 20:25:58.283337 poll([{fd=3, events=POLLIN}, {fd=8, events=POLLIN}, {fd=7, events=P
OLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=11, events=POLLIN}, {fd=35, ev
ents=POLLIN}, {fd=33, events=POLLIN}, {fd=34, events=POLLIN}, {fd=32, events=POLLIN}, {fd
=39, events=POLLIN}], 11, 191 <unfinished ...>
15695 20:25:58.283692 <... clock_gettime resumed> {1235330758, 283317687}) = 0
...
... <forever>

PID 15685 is the originally started process with the executable digikam. Top also show PID 15685 as the process using the CPU, I do not (yet) know which one of the two threads use that CPU, 15685  or 15695.

> Also, we need to know in which conditions/action in digiKam the cpu is
> consumed.

The system is completely idle, esp. I waited quite some while after I accessed any file, even if it was just to read it (a "sitecopy --update ..."). Digikam is showing a completely empty directory (my "incoming" directory AAA-Temp) while the strace was taken.
Comment 3 Andi Clemens 2009-02-22 21:04:51 UTC
I get million of those messages, too. Even in showFoto... something is polling like crazy. I checked other apps that use dirwatch and such stuff, they all are quiet. But showFoto and digikam constantly are talking to someone, I get 10 messages per second.

read(8, "\1\0F\6\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\30\0\0\0e\n\0\0"..., 4096) = 32
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
clock_gettime(CLOCK_MONOTONIC, {12124, 465636003}) = 0
clock_gettime(CLOCK_MONOTONIC, {12124, 472280283}) = 0
clock_gettime(CLOCK_MONOTONIC, {12124, 478896207}) = 0
clock_gettime(CLOCK_MONOTONIC, {12124, 485614798}) = 0
clock_gettime(CLOCK_MONOTONIC, {12124, 492279960}) = 0
clock_gettime(CLOCK_MONOTONIC, {12124, 498894486}) = 0
clock_gettime(CLOCK_MONOTONIC, {12124, 505616010}) = 0
clock_gettime(CLOCK_MONOTONIC, {12124, 512281661}) = 0
clock_gettime(CLOCK_MONOTONIC, {12124, 518898283}) = 0
clock_gettime(CLOCK_MONOTONIC, {12124, 525616803}) = 0
gettimeofday({1235332748, 285342}, NULL) = 0
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
select(9, [8], [8], NULL, NULL)         = 1 (out [8])
writev(8, [{"\22\0\6\0\30\0@\3\25\1\0\0\4\0\0\0 \0\0\0\0\0\0\0\233\24%\0\243\0@\3\1"..., 5116}, {NULL, 0}, {""..., 0}], 3) = 5116
read(8, "\34yG\6\30\0@\3\25\1\0\0\210\1\271\0\0\264\331\277\352\n\t\10\330\264\331\277\30\0@\3\34"..., 4096) = 64
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
gettimeofday({1235332748, 338660}, NULL) = 0
select(9, [8], [8], NULL, NULL)         = 1 (out [8])
writev(8, [{"+\0\1\0"..., 4}, {NULL, 0}, {""..., 0}], 3) = 4
select(9, [8], [], NULL, NULL)          = 1 (in [8])
read(8, "\1\1j\6\0\0\0\0\1\0\340\1\0\0\0\0\4\0\0\0d\n\0\0\350\n\22\n\0\0\0\0"..., 4096) = 32
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
gettimeofday({1235332748, 405322}, NULL) = 0
select(9, [8], [8], NULL, NULL)         = 1 (out [8])
writev(8, [{"+\0\1\0"..., 4}, {NULL, 0}, {""..., 0}], 3) = 4
select(9, [8], [], NULL, NULL)          = 1 (in [8])
read(8, "\1\1k\6\0\0\0\0\1\0\340\1\0\0\0\0\4\0\0\0d\n\0\0\350\n\22\n\0\0\0\0"..., 4096) = 32
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
gettimeofday({1235332748, 471934}, NULL) = 0
select(9, [8], [8], NULL, NULL)         = 1 (out [8])
writev(8, [{"+\0\1\0"..., 4}, {NULL, 0}, {""..., 0}], 3) = 4
select(9, [8], [], NULL, NULL)          = 1 (in [8])
Comment 4 Andi Clemens 2009-02-22 21:08:22 UTC
Created attachment 31554 [details]
complete output when starting showFoto

This file shows all the output. There are strange messages when showFoto tries to read files like

access("/home/andi/.kde4/share/locale/en_US/LC_SCRIPTS/digikamimageplugin_inserttext/digikamimageplugin_inserttext.js", R_OK) = -1 ENOENT (No such file or directory)

or

access("/home/andi/.kde4/share/locale/en_US/LC_SCRIPTS/digikamimageplugin_oilpaint/digikamimageplugin_oilpaint.js", R_OK) = -1 ENOENT (No such file or directory)

Is this normal? There are thousands of such messages...
Comment 5 Marcel Wiesweg 2009-02-22 21:26:43 UTC
I set a breakpoint on read():

#0  0x00007ffff1977830 in read () from /lib64/libpthread.so.0
#1  0x00007fffea394400 in ?? () from /usr/lib64/libxcb.so.1
#2  0x00007fffea3948b8 in xcb_poll_for_event () from /usr/lib64/libxcb.so.1
#3  0x00007fffefcde8b5 in ?? () from /usr/lib64/libX11.so.6
#4  0x00007fffefcdeff6 in _XEventsQueued () from /usr/lib64/libX11.so.6
#5  0x00007fffefcb0634 in XCheckWindowEvent () from /usr/lib64/libX11.so.6
#6  0x00007fffde15196b in ?? () from /usr/lib64/gstreamer-0.10/libgstximagesink.so
#7  0x00007fffed2a0764 in ?? () from /usr/lib64/libglib-2.0.so.0
#8  0x00007ffff1971070 in start_thread () from /lib64/libpthread.so.0
#9  0x00007ffff0f6a10d in clone () from /lib64/libc.so.6
#10 0x0000000000000000 in ?? ()

which seems to be from phonon/gstreamer.

A breakpoint on poll() is always caught by Qt's/glib's event loop. I believe that is normal.
Comment 6 Andi Clemens 2009-02-22 21:31:08 UTC
So phonon is making that noise? Then amarok should do this output, too... I'll check...
Comment 7 Andi Clemens 2009-02-22 21:33:45 UTC
Amarok behaves the same, but without those error messages from my comment #3:

read(8, 0x98eda18, 4096)                = -1 EAGAIN (Resource temporarily
unavailable)

Question is why? Have we initialized something different?
Comment 8 caulier.gilles 2009-06-03 08:01:36 UTC
If this entry is relevant of Phonon, please move it on right B.K.O component...

Gilles
Comment 9 Roman Fietze 2009-09-03 21:26:27 UTC
This is still true for digikam Version 0.10.0 using KDE 4.3.1 release 163.

Interesting is, that other KDE 4 applications do not use some CPU when they are idle, even applications that could eventually use the sound system, e.g. amarok 2.
Comment 10 Stefan Fleiter 2009-10-16 21:17:55 UTC
Still true for Version 1.0.0-beta5.
Amarok only uses some CPU while not playing audio after it has played audio
once.
This is tracked in phonon bug 204114.
But digikam is causes a lot of wakeups and thereby uses a lot of
cpu and power without playing audio once. So there does seem
to be another bug there.

This shortens battery lifetime for notebooks and netbooks considerably
and thus makes digikam not very well suited for mobile presentations
of photos.

See following powertop output:

PowerTOP 1.11   (C) 2007, 2008 Intel Corporation                                

Collecting data for 15 seconds 


Cn                Avg residency
C0 (cpu running)        ( 1.5%)
polling           0.0ms ( 0.0%)
C1 mwait          0.0ms ( 0.0%)
C2 mwait          0.1ms ( 0.0%)
C4 mwait          6.4ms (98.5%)
P-states (frequencies)         
  2.21 Ghz     0.1%            
  2.21 Ghz     0.0%            
  1.60 Ghz     0.0%            
  1200 Mhz     0.1%            
   800 Mhz    99.8%            
Wakeups-from-idle per second : 153.5    interval: 15.0s
no ACPI power usage estimate available                 
Top causes for wakeups:                                
  46.1% (106.1)           digikam : hrtimer_start_range_ns (hrtimer_wakeup) 
  24.1% ( 55.5)       <interrupt> : extra timer interrupt                   
   8.2% ( 18.8)       <interrupt> : ahci                                    
   5.1% ( 11.8)     <kernel core> : hrtimer_start_range_ns (tick_sched_timer) 
   4.3% (  9.8)       <interrupt> : ata_piix                                  
   3.5% (  8.0)     <kernel core> : usb_hcd_poll_rh_status (rh_timer_func)    
   2.8% (  6.3)      <kernel IPI> : Rescheduling interrupts                   
   1.6% (  3.7)     <kernel core> : hrtimer_start (tick_sched_timer)          
   0.9% (  2.0)       <interrupt> : nvidia                                    
   0.5% (  1.2)    plasma-desktop : hrtimer_start_range_ns (hrtimer_wakeup)   
   0.4% (  1.0)     <kernel core> : add_timer (tg3_timer)                     
   0.4% (  1.0)     <kernel core> : nv_kern_rc_timer (nv_kern_rc_timer)       
   0.2% (  0.5)          kwalletd : hrtimer_start_range_ns (hrtimer_wakeup)   
   0.2% (  0.5)               gpm : hrtimer_start_range_ns (hrtimer_wakeup)   
   0.2% (  0.4)          lancelot : hrtimer_start_range_ns (hrtimer_wakeup)   
   0.2% (  0.4)   hald-addon-stor : hrtimer_start_range_ns (hrtimer_wakeup)   
   0.2% (  0.4)             spamd : hrtimer_start_range_ns (hrtimer_wakeup)   
   0.1% (  0.3)     <kernel core> : neigh_periodic_timer (neigh_periodic_timer) 
   0.1% (  0.3)           konsole : neigh_periodic_timer (neigh_periodic_timer) 
   0.1% (  0.2)           konsole : hrtimer_start_range_ns (hrtimer_wakeup)     
   0.1% (  0.2)           dolphin : hrtimer_start_range_ns (hrtimer_wakeup)     
   0.1% (  0.2)           pdflush : wb_kupdate (wb_timer_fn)                    
   0.1% (  0.1)     <kernel core> : inet_twdr_hangman (inet_twdr_hangman)       
   0.1% (  0.1)   hald-addon-stor : blk_add_timer (blk_rq_timed_out_timer)      
   0.1% (  0.1)           pdflush : add_timer (commit_timeout)                  
   0.1% (  0.1)       ksoftirqd/0 : add_timer (sta_info_cleanup)                
   0.1% (  0.1)           kcryptd : blk_plug_device (blk_unplug_timeout)        
   0.1% (  0.1)             kded4 : hrtimer_start_range_ns (hrtimer_wakeup)     
   0.1% (  0.1)           krunner : hrtimer_start_range_ns (hrtimer_wakeup)     
   0.0% (  0.1)       <interrupt> : PS/2 keyboard/mouse/touchpad                
   0.0% (  0.1)              Xorg : hrtimer_start_range_ns (hrtimer_wakeup)     
   0.0% (  0.1)              bash : start_rt_bandwidth (sched_rt_period_timer)  
   0.0% (  0.1)    btrfs-submit-0 : worker_loop (process_timeout)               
   0.0% (  0.1)          events/0 : queue_delayed_work (delayed_work_timer_fn)  
   0.0% (  0.1)        kjournald2 : blk_add_timer (blk_rq_timed_out_timer)      
   0.0% (  0.1)         ssh-agent : hrtimer_start_range_ns (hrtimer_wakeup)     
   0.0% (  0.1)    NetworkManager : hrtimer_start_range_ns (hrtimer_wakeup)     
   0.0% (  0.1)              Xorg : add_timer (peer_check_expire)
Comment 11 Harald Sitter 2011-01-13 22:21:21 UTC
What backend was this with? And is it still an issue?
Comment 12 Stefan Fleiter 2011-01-14 00:03:16 UTC
This is with Xine backend 0.2.60, KDE 4.5.5 and digikam 1.7.0.
With GStreamer or VLC backend there are less than 7 wakeups per second.
Which backend is recommended nowadays and which is the default?
Comment 13 Harald Sitter 2011-01-14 00:11:00 UTC
That is a duplicated bug then.

We will release Phonon 4.4.4 next week which will have a default priority listing of GStreamer > VLC > Xine.
So I guess, GStreamer can be considered default for that version. Though I do not like talking defaults, because VLC is really as mature as the GStreamer backend, it just happens to miss some of the more advanced features which is going to change within the next couple of versions and is the only reason it is currently ranked lower.

*** This bug has been marked as a duplicate of bug 156215 ***
Comment 14 caulier.gilles 2018-08-19 14:19:29 UTC
Fixed in 6.0.0 since digiKam use QtAV+ffmpeg to play and extract thumbnails from video files