Bug 494425 - Audacity consumes lots of CPU time when idle
Summary: Audacity consumes lots of CPU time when idle
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: wxGTK
Version: 11
Hardware: All
OS: Linux
low
medium
Target Milestone: ---
Assignee: Dan Horák
QA Contact: Fedora Extras Quality Assurance
URL: http://sourceforge.net/mailarchive/me...
Whiteboard:
: 528248 (view as bug list)
Depends On:
Blocks: 528248
TreeView+ depends on / blocked
 
Reported: 2009-04-06 19:59 UTC by Tom London
Modified: 2009-10-26 08:30 UTC (History)
7 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2009-10-26 08:30:56 UTC
Type: ---
Embargoed:


Attachments (Terms of Use)

Description Tom London 2009-04-06 19:59:16 UTC
Description of problem:
I noticed a "completely idle" audacity process consuming cpu time.

Here are a few lines from "ps alx":

 8283 ?        Ss     0:00 sendmail: Queue runner@01:00:00 for /var/spool/client
 8967 ?        Sl     0:35 audacity
 9189 ?        Sl     0:00 /usr/sbin/packagekitd

I started the audacity process, minimized it, and just left it idle for a while.

Checking after 10 seconds:

[tbl@tlondon ~]$ ps alx | grep audacity; sleep 10; ps alx | grep audacity
0   500  8967     1  20   0 514024 27000 poll_s Sl   ?          0:48 audacity
0   500  8967     1  20   0 514156 27104 -      Rl   ?          0:50 audacity
0   500  9430  3591  20   0  88692   764 -      R+   pts/1      0:00 grep audacity
[tbl@tlondon ~]$ 

shows 2 seconds more consumed.....

Stracing it yields:


read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
select(6, [5], [5], NULL, NULL)         = 1 (out [5])
writev(5, [{"\2\30\4\0+\4\300\4\0@\0\0f\1\300\4\2\4\4\0\"\4\300\4\0@\0\0f\1\300\4\2"..., 1088}, {NULL, 0}, {""..., 0}], 3) = 1088
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 23) = 0 (Timeout)
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
select(6, [5], [5], NULL, NULL)         = 1 (out [5])
writev(5, [{"\2\30\4\0+\4\300\4\0@\0\0f\1\300\4\2\4\4\0\"\4\300\4\0@\0\0f\1\300\4\2"..., 1088}, {NULL, 0}, {""..., 0}], 3) = 1088
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
select(6, [5], [5], NULL, NULL)         = 1 (out [5])
writev(5, [{"\2\30\4\0+\4\300\4\0@\0\0f\1\300\4\2\4\4\0\"\4\300\4\0@\0\0f\1\300\4\2"..., 1088}, {NULL, 0}, {""..., 0}], 3) = 1088
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 24) = 0 (Timeout)
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
select(6, [5], [5], NULL, NULL)         = 1 (out [5])
writev(5, [{"\2\30\4\0+\4\300\4\0@\0\0f\1\300\4\2\4\4\0\"\4\300\4\0@\0\0f\1\300\4\2"..., 1088}, {NULL, 0}, {""..., 0}], 3) = 1088
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 23) = 0 (Timeout)
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
select(6, [5], [5], NULL, NULL)         = 1 (out [5])
writev(5, [{"\2\30\4\0+\4\300\4\0@\0\0f\1\300\4\2\4\4\0\"\4\300\4\0@\0\0f\1\300\4\2"..., 1088}, {NULL, 0}, {""..., 0}], 3) = 1088
read(5, 0x2ac3eb4, 4096)                = -1 EAGAIN (Resource temporarily unavailable)
poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 23^C <unfinished ...>
Process 7265 detached

Seems "unfriendly".....

Version-Release number of selected component (if applicable):
audacity-1.3.7-0.6.beta.fc11.x86_64

How reproducible:
Every time....

Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:

Comment 1 Michael Schwendt 2009-04-06 21:22:06 UTC
Please report this upstream:
https://lists.sourceforge.net/lists/listinfo/audacity-devel

Comment 2 David Timms 2009-04-06 21:26:30 UTC
Michael, I don't remember whether this includes the pulseaudio patch, so Tom,
what are the following values showing in Edit|Preferences, Audio I/O, 
Playback: device=
Recording: device=

Comment 3 Tom London 2009-04-06 21:45:26 UTC
(In reply to comment #1)
> Please report this upstream:
> https://lists.sourceforge.net/lists/listinfo/audacity-devel  

OK, posted here: http://audacityteam.org/forum/viewtopic.php?f=18&t=9455&start=0&sid=1a40ab0de64fe2a5e0a85183e60dcf2f

Is that in the right place?

Comment 4 Tom London 2009-04-06 21:47:11 UTC
(In reply to comment #2)
> Michael, I don't remember whether this includes the pulseaudio patch, so Tom,
> what are the following values showing in Edit|Preferences, Audio I/O, 
> Playback: device=
> Recording: device=  

Says "ALSA: pulse" in both.  (Also says "using portaudio v19").

Comment 5 Tom London 2009-04-06 21:55:44 UTC
I posted this "strace -ttt" output to the audacity site.

Appears to show a pretty tight polling loop.....

1239054059.906730 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
1239054059.907701 select(6, [5], [5], NULL, NULL) = 1 (out [5])
1239054059.907762 writev(5, [{"\2\0\4\0+\4\300\4\0@\0\0f\1\300\4\2\1\4\0\"\4\300\4\0@\0\0f\1\300\4\2"..., 1088}, {NULL, 0}, {""..., 0}], 3) = 1088
1239054059.907820 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.907858 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 11) = 0 (Timeout)
1239054059.919037 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.919093 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
1239054059.919181 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.919216 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
1239054059.920205 select(6, [5], [5], NULL, NULL) = 1 (out [5])
1239054059.920258 writev(5, [{"\2\0\4\0+\4\300\4\0@\0\0f\1\300\4\2\1\4\0\"\4\300\4\0@\0\0f\1\300\4\2"..., 1088}, {NULL, 0}, {""..., 0}], 3) = 1088
1239054059.920323 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.920361 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 11) = 0 (Timeout)
1239054059.931517 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.931555 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
1239054059.931604 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.931637 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
1239054059.932554 select(6, [5], [5], NULL, NULL) = 1 (out [5])
1239054059.932605 writev(5, [{"\2\0\4\0+\4\300\4\0@\0\0f\1\300\4\2\1\4\0\"\4\300\4\0@\0\0f\1\300\4\2"..., 1088}, {NULL, 0}, {""..., 0}], 3) = 1088
1239054059.932664 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.932702 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 23) = 0 (Timeout)
1239054059.955904 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.955961 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
1239054059.956033 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.956082 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
1239054059.957225 select(6, [5], [5], NULL, NULL) = 1 (out [5])
1239054059.957303 writev(5, [{"\2\0\4\0+\4\300\4\0@\0\0f\1\300\4\2\1\4\0\"\4\300\4\0@\0\0f\1\300\4\2"..., 1088}, {NULL, 0}, {""..., 0}], 3) = 1088
1239054059.957388 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.957442 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 3) = 0 (Timeout)
1239054059.960624 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.960676 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
1239054059.960756 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.960805 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 0) = 0 (Timeout)
1239054059.961844 select(6, [5], [5], NULL, NULL) = 1 (out [5])
1239054059.961916 writev(5, [{"\2\0\4\0+\4\300\4\0@\0\0f\1\300\4\2\1\4\0\"\4\300\4\0@\0\0f\1\300\4\2"..., 1088}, {NULL, 0}, {""..., 0}], 3) = 1088
1239054059.962000 read(5, 0x16260b4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
1239054059.962053 poll([{fd=3, events=POLLIN}, {fd=5, events=POLLIN}], 2, 7^C <unfinished ...>

Comment 6 Tom London 2009-04-07 14:31:32 UTC
A bit more on this.

I ran audacity with gdb and got this after it was running for a while:

(gdb) where
#0  0x0000003daf0d63f3 in *__GI___poll (fds=<value optimized out>, 
    nfds=<value optimized out>, timeout=24)
    at ../sysdeps/unix/sysv/linux/poll.c:87
#1  0x0000003c2bbce034 in wxapp_poll_func (ufds=0x1432e90, nfds=2, timeout=24)
    at src/gtk/app.cpp:259
#2  0x0000003c2703b5c2 in g_main_context_poll (n_fds=<value optimized out>, 
    fds=<value optimized out>, priority=<value optimized out>, 
    timeout=<value optimized out>, context=<value optimized out>)
    at gmain.c:2761
#3  g_main_context_iterate (n_fds=<value optimized out>, 
    fds=<value optimized out>, priority=<value optimized out>, 
    timeout=<value optimized out>, context=<value optimized out>)
    at gmain.c:2443
#4  0x0000003c2703bc65 in IA__g_main_loop_run (loop=0x1432e70) at gmain.c:2656
#5  0x0000003c295297e7 in IA__gtk_main () at gtkmain.c:1205
#6  0x0000003c2bbe6448 in wxEventLoop::Run (this=0x1433370)
    at src/gtk/evtloop.cpp:76
#7  0x0000003c2bc70c7b in wxAppBase::MainLoop (this=0xdda620)
    at src/common/appcmn.cpp:312
#8  0x0000003dba69850c in wxEntry (argc=<value optimized out>, 
    argv=<value optimized out>) at src/common/init.cpp:460
#9  0x00000000004406c2 in main (argc=1, argv=0x2) at AudacityApp.cpp:383
(gdb) 

Repeating a second time (after about 60 seconds) showed a similar backtrace, but the value for timeout in the call to wxapp_poll_func() was 22, and repeating a third time about 30 seconds later had timeout=18:

Program received signal SIGINT, Interrupt.
0x0000003daf0d63f3 in *__GI___poll (fds=<value optimized out>, 
    nfds=<value optimized out>, timeout=22)
    at ../sysdeps/unix/sysv/linux/poll.c:87
87	  int result = INLINE_SYSCALL (poll, 3, CHECK_N (fds, nfds), nfds, timeout);
(gdb) where
#0  0x0000003daf0d63f3 in *__GI___poll (fds=<value optimized out>, 
    nfds=<value optimized out>, timeout=22)
    at ../sysdeps/unix/sysv/linux/poll.c:87
#1  0x0000003c2bbce034 in wxapp_poll_func (ufds=0x1432e90, nfds=2, timeout=22)
    at src/gtk/app.cpp:259
#2  0x0000003c2703b5c2 in g_main_context_poll (n_fds=<value optimized out>, 
    fds=<value optimized out>, priority=<value optimized out>, 
    timeout=<value optimized out>, context=<value optimized out>)
    at gmain.c:2761
#3  g_main_context_iterate (n_fds=<value optimized out>, 
    fds=<value optimized out>, priority=<value optimized out>, 
    timeout=<value optimized out>, context=<value optimized out>)
    at gmain.c:2443
#4  0x0000003c2703bc65 in IA__g_main_loop_run (loop=0x1432e70) at gmain.c:2656
#5  0x0000003c295297e7 in IA__gtk_main () at gtkmain.c:1205
#6  0x0000003c2bbe6448 in wxEventLoop::Run (this=0x1433370)
    at src/gtk/evtloop.cpp:76
#7  0x0000003c2bc70c7b in wxAppBase::MainLoop (this=0xdda620)
    at src/common/appcmn.cpp:312
#8  0x0000003dba69850c in wxEntry (argc=<value optimized out>, 
    argv=<value optimized out>) at src/common/init.cpp:460
#9  0x00000000004406c2 in main (argc=1, argv=0x2) at AudacityApp.cpp:383
(gdb) cont
Continuing.
^C
Program received signal SIGINT, Interrupt.
0x0000003daf0d63f3 in *__GI___poll (fds=<value optimized out>, 
    nfds=<value optimized out>, timeout=18)
    at ../sysdeps/unix/sysv/linux/poll.c:87
87	  int result = INLINE_SYSCALL (poll, 3, CHECK_N (fds, nfds), nfds, timeout);
(gdb) where
#0  0x0000003daf0d63f3 in *__GI___poll (fds=<value optimized out>, 
    nfds=<value optimized out>, timeout=18)
    at ../sysdeps/unix/sysv/linux/poll.c:87
#1  0x0000003c2bbce034 in wxapp_poll_func (ufds=0x1432e90, nfds=2, timeout=18)
    at src/gtk/app.cpp:259
#2  0x0000003c2703b5c2 in g_main_context_poll (n_fds=<value optimized out>, 
    fds=<value optimized out>, priority=<value optimized out>, 
    timeout=<value optimized out>, context=<value optimized out>)
    at gmain.c:2761
#3  g_main_context_iterate (n_fds=<value optimized out>, 
    fds=<value optimized out>, priority=<value optimized out>, 
    timeout=<value optimized out>, context=<value optimized out>)
    at gmain.c:2443
#4  0x0000003c2703bc65 in IA__g_main_loop_run (loop=0x1432e70) at gmain.c:2656
#5  0x0000003c295297e7 in IA__gtk_main () at gtkmain.c:1205
#6  0x0000003c2bbe6448 in wxEventLoop::Run (this=0x1433370)
    at src/gtk/evtloop.cpp:76
#7  0x0000003c2bc70c7b in wxAppBase::MainLoop (this=0xdda620)
    at src/common/appcmn.cpp:312
#8  0x0000003dba69850c in wxEntry (argc=<value optimized out>, 
    argv=<value optimized out>) at src/common/init.cpp:460
#9  0x00000000004406c2 in main (argc=1, argv=0x2) at AudacityApp.cpp:383
(gdb) 


Let me know if this is "not Fedora", and I'll post it upstream......

Comment 7 Michael Schwendt 2009-04-07 14:59:52 UTC
It's nothing that is specific to the Fedora Audacity package. Audacity uses wxWidgets (aka wxGTK) as its GUI toolkit -- in case you want to examine other wxGTK applications.

Comment 8 Tom London 2009-04-07 20:34:18 UTC
Hmmm... I only have "audacity" and "xmlcopyeditor" depending on wxGTK (at least as reported by "yum remove wxGTK").

Starting "xmlcopyeditor", I think I'm seeing the same behavior: starting it, I see 3 seconds of consumed CPU, after minimizing, it continues to consume about 1-2 seconds of CPU per 60 seconds:

[tbl@tlondon ~]$ while :
> do
> ps axgl | grep xmlcopy
> sleep 60
> done
0   500 14167     1  20   0 750404 53232 poll_s S    ?          0:06 xmlcopyeditor

0   500 14167     1  20   0 750404 53232 poll_s S    ?          0:07 xmlcopyeditor

0   500 14167     1  20   0 750404 53232 poll_s S    ?          0:08 xmlcopyeditor

0   500 14167     1  20   0 750404 53232 poll_s S    ?          0:09 xmlcopyeditor

0   500 14167     1  20   0 750404 53232 poll_s S    ?          0:10 xmlcopyeditor


running "gdb" on this process after it consumed about 13 seconds of CPU shows "timeout" set to 98.

Checking again when it consumed 20 seconds of CPU (takes about 35 seconds to consume about 1 second of CPU), "timeout" was 96.....

Comment 9 Tom London 2009-04-07 22:07:13 UTC
I reverted wxGTK to 

wxGTK-debuginfo-2.8.9-4.fc11.x86_64
wxGTK-2.8.9-4.fc11.x86_64
wxGTK-gl-2.8.9-4.fc11.x86_64
wxGTK-devel-2.8.9-4.fc11.x86_64
wxGTK-media-2.8.9-4.fc11.x86_64
wxBase-2.8.9-4.fc11.x86_64
[Had to manually fix the links in /usr/lib64.....]

and I believe the situation improved.

Audacity does continue to consume CPU, but at a greatly reduced rate: about .30  seconds every 60 "real" seconds.

Could this be a problem with wxGTK?

Comment 10 Michael Schwendt 2009-04-08 07:58:45 UTC
You've defined it to be a problem. And yes, it can be that wxGTK's main loop consumes more processor power compared with previous releases.

Comment 11 Bug Zapper 2009-06-09 13:21:57 UTC
This bug appears to have been reported against 'rawhide' during the Fedora 11 development cycle.
Changing version to '11'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping

Comment 12 Jim Radford 2009-10-09 21:30:00 UTC
(In reply to comment #10)
> You've defined it to be a problem.

I define it to be a problem as well.  35% of the CPU while doing nothing with the app is definitely a problem.

Comment 13 Michael Schwendt 2009-10-10 08:54:51 UTC
> 35% of the CPU

First time I hear that. Yes, I would consider 35% as problematic.

Comment 14 Michael Schwendt 2009-10-12 15:56:30 UTC
*** Bug 528248 has been marked as a duplicate of this bug. ***

Comment 15 Michael Schwendt 2009-10-12 15:58:38 UTC
More details:  http://trac.wxwidgets.org/ticket/11315

Comment 16 Dan Horák 2009-10-13 08:49:33 UTC
I have built an updated F-11 wxGTK package at http://koji.fedoraproject.org/koji/taskinfo?taskID=1743074 (scratch build). Please let me know if it fixes the CPU usage issues and I will prepare a regular update.

Comment 17 Michael Schwendt 2009-10-13 09:50:48 UTC
It fixes the problem for Audacity and AMule.

Comment 18 Tom London 2009-10-13 13:25:48 UTC
Worth trying these (f11) packages load/work/test in my f12/rawhide system?

Comment 19 Dan Horák 2009-10-13 13:39:13 UTC
(In reply to comment #18)
> Worth trying these (f11) packages load/work/test in my f12/rawhide system?  

Rather wait for https://koji.fedoraproject.org/koji/taskinfo?taskID=1744110 to finish.

Comment 20 Tom London 2009-10-16 13:50:20 UTC
(In reply to comment #19)
> (In reply to comment #18)
> > Worth trying these (f11) packages load/work/test in my f12/rawhide system?  
> 
> Rather wait for https://koji.fedoraproject.org/koji/taskinfo?taskID=1744110 to
> finish.  

That seems locked to me, but I see wxGTK-2.8.10-5.fc12.x86_64.rpm in koji.

Will install that.

Thanks for the fix!

Comment 21 Dave Allan 2009-10-23 17:34:49 UTC
Upgrading to wxGTK-2.8.10-3.fc10.i386 fixed the problem for me.


Note You need to log in before you can comment on or make changes to this bug.