Bug #233734 (elisa-1174) “100% cpu usage on some systems” : Bugs : Moovida

Revision history for this message

Fabian-elisa (fabian-elisa) wrote on 2008-03-20:

#1

elisa log file Edit (37.3 KiB, text/plain)

elisa log file

Revision history for this message

Florian Boucault (fboucault) wrote on 2008-07-17:

#2

Fabian, is that issue still relevant in Elisa 0.5.1. Can you please try it out? Thanks.

Florian Boucault (fboucault) on 2008-10-03

Changed in elisa:
status:	New → Incomplete

Florian Boucault (fboucault) on 2008-10-07

Changed in elisa:
importance:	Undecided → High

Revision history for this message

luzik (luzik) wrote on 2008-11-15:

#3

this is still issue on elisa 0.5.17 100% of cpu when elisa is idle

Revision history for this message

Olivier Tilloy (osomon) wrote on 2009-01-14:

#4

From the support forums (https://elisa.fluendo.com/forums/viewtopic.php?id=903):

100 % cpu on one core when idling

    my specs:
    elisa 5.22
    opensuse 11.1
    cv : nvidia 8800 gtx - proprio driver -xinerama on (1440x900 x 2 monitors)
    ram 3 go - non dual channel
    proc amd 5600+ 2x core

Edit : update to 5.23 elisa version and 180.11.02 opengl3 beta nvidia driver - always the same

Changed in elisa:
milestone:	none → 0.5.x
status:	Incomplete → Confirmed

Philippe Normand (philn) on 2009-04-30

tags:

added: pigment

Revision history for this message

ch4204 (ch4204) wrote on 2009-05-09:

#5

cpu at 100 % with elisa 5.37 on ubuntu jaunty => critical
when using new web plugins (games, movies or grooveshark...)

Note:
reading movie .avi or dvd = CPU's behaviour OK

other problems:
*bad integration of new gnome notifications (jaunty)
*triptic "minimize/resize/close" is sometimes present on primary menu (and more times not)
*Backspace do not close elisa but resize it and the top of the window is hide by the taskbar...

comments:
*Good idea the menu "slideshow" on the right top... but why not a such a selection in the primary menu to configure the "slideshow view" for all choices (videos, music...)
*Bad integration of weather plugin - unusefull there where it is (and how configure it ?)
*There is no link to the to reading track when moving inside elisa menu (music video ..)
*Why not a button "Exit"?

By the way.... congratulations for this mediacenter... I understand why ubuntu team support it!
thks.

Revision history for this message

Olivier Tilloy (osomon) wrote on 2009-05-13:

#6

@ch4204: thanks for your feedback.
If you want to discuss ideas for improvements, the mailing list (http://lists.fluendo.com/mailman/listinfo/elisa) or our IRC channel (irc://freenode/#elisa) is better suited than a bug report.
For all mentioned problems, could you please file new bug reports?

Revision history for this message

Olivier Tilloy (osomon) wrote on 2009-05-27:

#7

Anyone still experiencing similar issues with Moovida 1.0 and the latest pigment?

Changed in elisa:
milestone:	0.5.x → none
status:	Confirmed → Incomplete

Revision history for this message

Christian Schulze (lynx-quantentunnel) wrote on 2009-05-31:

#8

I still have this 100% load issue running pigment 0.3.11 and moovida 1.0.1.
It is the case for nvidia and intel graphics.

Olivier Tilloy (osomon) on 2009-06-02

Changed in elisa:
status:	Incomplete → Confirmed

Revision history for this message

Krzysztof Adamski (kadamski) wrote on 2009-06-28:

#9

Download full text (6.5 KiB)

I have similar issue with latest Moovida (from bzr) and latest pigment (from svn). I did some research about that, however, and I'm not sure if it's accually Moovida/Pigment BUG. My setup is:
- Fedora 11
- Moovida 1.0.3 (from git)
- Pigment ?.?.? (from svn)
- Mesa
- Xorg
- intel-driver
- Twisted
- GTK

First of all, I've checked if it's a Pigment bug by running python-pigment examples. They run fine so it's not. Second thing i have done was checking what is Moovida actually doing with strace and I found out that this (running again and again):

15519 poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN}, {fd=8, events=POLLIN}, {fd=14, events=POLLIN}, {fd=22, events=POLLIN}, {fd=23, events=POLLIN}, {fd=24, events=POLLIN}, {fd=32, events=POLLIN}, {fd=25, events=POLLIN}, {fd=29, events=POLLIN}, {fd=34, events=POLLIN}, {fd=36, events=POLLIN}, {fd=12, events=POLLIN}, {fd=3, events=POLLIN}, {fd=38, events=POLLIN}], 16, 25) = 1 ([{fd=8, revents=POLLIN}])
15519 gettimeofday({1246013664, 941148}, NULL) = 0
15519 read(11, 0x9606d98, 4096) = -1 EAGAIN (Resource temporarily unavailable)
15519 gettimeofday({1246013664, 941223}, NULL) = 0

15519 poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN}, {fd=8, events=POLLIN}, {fd=14, events=POLLIN}, {fd=22, events=POLLIN}, {fd=23, events=POLLIN}, {fd=24, events=POLLIN}, {fd=32, events=POLLIN}, {fd=25, events=POLLIN}, {fd=29, events=POLLIN}, {fd=34, events=POLLIN}, {fd=36, events=POLLIN}, {fd=12, events=POLLIN}, {fd=3, events=POLLIN}, {fd=38, events=POLLIN}], 16, 25) = 1 ([{fd=8, revents=POLLIN}])
15519 gettimeofday({1246013664, 941401}, NULL) = 0
15519 read(11, 0x9606d98, 4096) = -1 EAGAIN (Resource temporarily unavailable)
15519 gettimeofday({1246013664, 941569}, NULL) = 0

Note couple things:
- it looks like it's a poll loop running all the time consuming 100% CPU
- poll is returning 1 FD ready (fd=8)
- this fd is NEVER READ (?!)
- after this, fd=11 is read and there is next poll immediately (check out gettimeofday values)
- next poll returns immediately with fd=8 since it wasn't read before.. this continues forever and uses all the CPU

So I've done some more research to find what douse FD's are:
$ ls -l /proc/15519/fd/8 /proc/15519/fd/11
razem 0
lrwx------. 1 k k 64 06-26 13:02 11 -> socket:[244343]
lr-x------. 1 k k 64 06-26 13:02 8 -> pipe:[244347]

and from trace file:

15519 execve("/usr/bin/python", ["python", "moovida/elisa-core/bin/moovida", "-c", "moovida.conf"], [/* 50 vars */]) = 0
[...]
15519 socket(PF_FILE, SOCK_STREAM, 0) = 11
15519 connect(11, {sa_family=AF_FILE, path=@"/tmp/.X11-unix/X0"...}, 20) = 0
15519 getpeername(11, {sa_family=AF_FILE, path=@"/tmp/.X11-unix/X0"...}, [20]) = 0
[...]
15519 fcntl64(11, F_GETFL) = 0x2 (flags O_RDWR)
15519 fcntl64(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0
15519 fcntl64(11, F_SETFD, FD_CLOEXEC) = 0
[...]
15519 rt_sigaction(SIGCHLD, {0x2c51a90, [], 0}, {SIG_DFL, [], 0}, 8) = 0
[...]
15519 pipe([8, 9]) = 0
[...]
15519 pipe([16, 17]) = 0
15519 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb8004728) = 15523
1551...

I have similar issue with latest Moovida (from bzr) and latest pigment (from svn). I did some research about that, however, and I'm not sure if it's accually Moovida/Pigment BUG. My setup is:
- Fedora 11
- Moovida 1.0.3 (from git)
- Pigment ?.?.? (from svn)
- Mesa
- Xorg
- intel-driver
- Twisted
- GTK

First of all, I've checked if it's a Pigment bug by running python-pigment examples. They run fine so it's not. Second thing i have done was checking what is Moovida actually doing with strace and I found out that this (running again and again):

15519 poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN}, {fd=8, events=POLLIN}, {fd=14, events=POLLIN}, {fd=22, events=POLLIN}, {fd=23, events=POLLIN}, {fd=24, events=POLLIN}, {fd=32, events=POLLIN}, {fd=25, events=POLLIN}, {fd=29, events=POLLIN}, {fd=34, events=POLLIN}, {fd=36, events=POLLIN}, {fd=12, events=POLLIN}, {fd=3, events=POLLIN}, {fd=38, events=POLLIN}], 16, 25) = 1 ([{fd=8, revents=POLLIN}])
15519 gettimeofday({1246013664, 941148}, NULL) = 0
15519 read(11, 0x9606d98, 4096)         = -1 EAGAIN (Resource temporarily unavailable)
15519 gettimeofday({1246013664, 941223}, NULL) = 0

15519 poll([{fd=5, events=POLLIN}, {fd=7, events=POLLIN}, {fd=11, events=POLLIN}, {fd=8, events=POLLIN}, {fd=14, events=POLLIN}, {fd=22, events=POLLIN}, {fd=23, events=POLLIN}, {fd=24, events=POLLIN}, {fd=32, events=POLLIN}, {fd=25, events=POLLIN}, {fd=29, events=POLLIN}, {fd=34, events=POLLIN}, {fd=36, events=POLLIN}, {fd=12, events=POLLIN}, {fd=3, events=POLLIN}, {fd=38, events=POLLIN}], 16, 25) = 1 ([{fd=8, revents=POLLIN}])
15519 gettimeofday({1246013664, 941401}, NULL) = 0
15519 read(11, 0x9606d98, 4096)         = -1 EAGAIN (Resource temporarily unavailable)
15519 gettimeofday({1246013664, 941569}, NULL) = 0

Note couple things:
- it looks like it's a poll loop running all the time consuming 100% CPU
- poll is returning 1 FD ready (fd=8)
- this fd is NEVER READ (?!)
- after this, fd=11 is read and there is next poll immediately (check out gettimeofday values)
- next poll returns immediately with fd=8 since it wasn't read before.. this continues forever and uses all the CPU

So I've done some more research to find what douse FD's are:
$ ls -l /proc/15519/fd/8 /proc/15519/fd/11
razem 0
lrwx------. 1 k k 64 06-26 13:02 11 -> socket:[244343]
lr-x------. 1 k k 64 06-26 13:02 8 -> pipe:[244347]

and from trace file:

15519 execve("/usr/bin/python", ["python", "moovida/elisa-core/bin/moovida", "-c", "moovida.conf"], [/* 50 vars */]) = 0
[...]
15519 socket(PF_FILE, SOCK_STREAM, 0)   = 11
15519 connect(11, {sa_family=AF_FILE, path=@"/tmp/.X11-unix/X0"...}, 20) = 0
15519 getpeername(11, {sa_family=AF_FILE, path=@"/tmp/.X11-unix/X0"...}, [20]) = 0
[...]
15519 fcntl64(11, F_GETFL)              = 0x2 (flags O_RDWR)
15519 fcntl64(11, F_SETFL, O_RDWR|O_NONBLOCK) = 0
15519 fcntl64(11, F_SETFD, FD_CLOEXEC)  = 0
[...]
15519 rt_sigaction(SIGCHLD, {0x2c51a90, [], 0}, {SIG_DFL, [], 0}, 8) = 0
[...]
15519 pipe([8, 9])                      = 0
[...]
15519 pipe([16, 17])                    = 0
15519 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0xb8004728) = 15523
15519 close(17)                         = 0
15523 close(16 <unfinished ...>
15519 read(16,  <unfinished ...>
(15523 is a short running process making a lot of stats on gstreamer plugin files)
[...]
15523 write(17, "\1\0\0\0"..., 4)       = 4
15523 close(17)                         = 0
15523 exit_group(0)                     = ?
15519 <... read resumed> "\1\0\0\0"..., 4) = 4
15519 --- SIGCHLD (Child exited) @ 0 (0) ---
15519 write(9, "\0"..., 1)              = 1
15519 sigreturn()                       = ? (mask now [])
15519 close(16)                         = 0
15519 waitpid(15523, NULL, 0)           = 15523
(no more writes to 9)
(no READS from 8!)

Here's what you can find out there:
- FD=11 is X11 socket file, which is set to NOBLOCK, this is why it is read (with -1) after each poll (note it shouldn't be done since FD=11 is in poll so we know when to read it.. but it doesn't do much harm actually)
- Next, we can see that SIGCHLD handler is registered
- fd=8 is one of pipes end (fd=9 is the 2nd one)
- there is a clone syscall, creating new process which reads gstreamer plugins (such a process is created when "import gst" is called)
- when the process is finished, SIGCHLD is send (of course) and and we can see that before sigreturn (which ends signal handler) there is a write to FD=9 (2nd end of the pipe which is returned by our polls)
- fd=8 is NEVER read to the and of the program and this is why our poll is returning immediately wasting all the CPU

Ok, so we know WHY this is happening but I wanted to know WHERE is the bug accually. I have spend quite a lot of time to find out two facts:
- the poll syscall came from Twisted reactor
- the same is true for the signal handler

So it looked like a Twisted bug.. But is it? I tried to find that out too, so first I disabled the SIGCHLD handler in twisted code:
   from /usr/lib/python2.6/site-packages/twisted/internet/base.py:
     if platformType == 'posix':
         signal.signal(signal.SIGCHLD, self._handleSigchld)

when this 2 lines where disabled, CPU was idle.. So it fixes the bug.. ALMOST.. It's more a workaround than a fix so I was searching deeper. I was very surprised by the results:
- I found out that Twisted handler is not called when "import gst" process is terminating.. where is this "write" coming from then? i have no idea:/
- Since i couldn't find where is "write" coming from I started looking for where is "pipe()" creating fd=8 and fd=9 coming from.. and I found out
  it is coming from GTK.. It happens somewhere at the beginning of gobject.MainLoop().run() called from run() method of Gtk2Reactor class in Twisted
- GTK2Reactor is generating further poll() calls which consumes 100% CPU

CONCLUSION:
1. Source of the BUG seams to be somewhere between 3 components:
  - Moovida
  - Twisted
  - GTK2
2. Python-pigment "timing" example runs fine, without any problems and it's very similar in architecture to how Moovida is doing.
3. The bug happens only on SOME (not all) systems.

Since I'm not sure where this BUG is coming from and I have no experience with Twisted which seams to be involved a lot in this bug, I'm hoping you will be able to give me some clues what is wrong. Is Moovida using Twisted in some strace way or is this bug completely outside of Moovida?

I'll continue my research tomorrow and update you if I get any results. Thanks in advance for any suggestions. I can provide trace file if anyone is interested but it is huge (57MB) so I won't attach it here.

Revision history for this message

Krzysztof Adamski (kadamski) wrote on 2009-06-28:

#10

Sorry I forgot to write my software versions. So I'm running on Fedora 11 (i386) with:
- Moovida 1.0.3 (from git)
- Pigment ?.?.? (from svn)
- Mesa 7.5
- Xorg server 1.6.1
- intel-driver 2.7.0
- Twisted 8.2.0
- GTK 2.16.2
- pygtk 2.14

Revision history for this message

Michał Sawicz (saviq) wrote on 2009-06-29:

#11

I'm experiencing the same thing with openSUSE 11.1 (x86_64) + GNOME 2.26:
- Mesa 7.2
- Xorg server 1.5.2
- nvidia driver 180.51
- Twisted 8.1.0
- GTK 2.16.1
- pygtk 2.12.1

summary:

- 100% cpu usage with nvidia-drivers
+ 100% cpu usage on some systems

Revision history for this message

Olivier Tilloy (osomon) wrote on 2009-06-29:

#12

Thanks for your very thorough investigations Krzysztof.
I cannot tell where exactly the problem is, but I know that some time ago people at Fluendo suggested that using the GTK2 reactor is useless and that we could save memory usage by getting rid of it. Maybe time to evaluate this solution? Could potentially fix the problem, or at least simplify it by removing one of its components.

Revision history for this message

Krzysztof Adamski (kadamski) wrote on 2009-06-29:

#13

I've got some new informations - looks like It's related to the PySignal_SetWakeupFd function from CPython:
http://docs.python.org/dev/c-api/exceptions.html#PySignal_SetWakeupFd. From my understanding, it seams that the bug only exists with Python 2.6 (i didn't test it, however). It is quite clear for me now that this is not Moovida bug and I think the problem is in pygobject/pygtk:
http://bugzilla.gnome.org/show_bug.cgi?id=481569

I'm using:
Python 2.6.9
pygobject 2.16.1
pygtk 2.14.1

I'm going to try never versions of pygtk/pygobject to see if anything changes.

Revision history for this message

Krzysztof Adamski (kadamski) wrote on 2009-06-29:

#14

Here's related Twisted bug report:
http://twistedmatrix.com/trac/ticket/3096

Revision history for this message

Krzysztof Adamski (kadamski) wrote on 2009-06-29:

#15

Conclusion is that this is pygtk bug. They have a patch in their bug trucking system but since it is not included in the mainstream (it has one corner case). Twisted does not want to create any workaround so it seams there are 2 possibilities:
- get rid of using gtk2reactor, as Olivier said
- fix mainstream pygtk

Note that this issue will be more and more common for all users as they switch to python 2.6.

Revision history for this message

Olivier Tilloy (osomon) wrote on 2009-06-29:

#16

According to Guillaume, the glib2 reactor (which is the one we use, sorry for the confusion) _is_ needed, so getting rid of it is not an option. That leaves us with fixing pygtk.

Revision history for this message

Philippe Normand (philn) wrote on 2009-06-29:

#17

Hmm some precisions to add. pygtk & pygobject are both broken but in the case of Moovida it is pygobject that needs fixing. The glib2reactor uses a pygobject main loop, AFAIK. And Moovida uses pygtk only for the splash screen, which is unrelated with this bug.

Florian Boucault (fboucault) on 2009-11-16

tags:

added: performance

Revision history for this message

dino99 (9d9) wrote on 2013-07-11:

#18

The latest free moovida 1.09 does not get any maintenance since a while. Now moovidadb.com is supporting Linux and support can be found at : http://www.fluendo.com/faq/

Changed in moovida:
status:	Confirmed → Invalid

Moovida

100% cpu usage on some systems

Bug Description

Other bug subscribers

Bug attachments

Remote bug watches