Apps and services use large amount of CPU after unity8 resets

[Andrew Hayzen]

I noticed that media-hub-service can get into a state where it uses a large amount of CPU.

Steps to reproduce
1) Start music-app
2) Play music
3) Pause music
4) Close the music-app
5) $ pkill unity8 (to emulate unity crashing a resetting)

Notice that media-hub-service is now using a large amount of CPU, note this [0] is the media-hub.log at the time.

The device has to be reset to get the CPU usage back to normal.

0 - http://pastebin.ubuntu.com/8553411/

[Leo Arias (elopio)]

I tried to reproduce this and I got media-hub on the top of $ top for a few seconds, but it didn't stay consuming a lot of CPU.

[Andrew Hayzen (ahayzen)]

Note this was on utopic-proposed and just reproduced this first time.

$ system-image-cli -i
current build number: 283
device name: mako
channel: ubuntu-touch/devel-proposed
alias: ubuntu-touch/utopic-proposed
last update: 2014-10-14 14:01:00
version version: 283
version ubuntu: 20141014.2
version device: 20140929.1
version custom: mako-0.8

[Bill Filler (bfiller)]

Unity8 crashed for me and I did a top and media-hub-service was using 96% cpu
I attached to it with gdb and this is what it's doing:

(gdb) bt
#0 0xb6a08712 in epoll_wait () from /lib/arm-linux-gnueabihf/libc.so.6
#1 0xb6ecf422 in ?? () from /usr/lib/arm-linux-gnueabihf/libdbus-cpp.so.4
#2 0xb6ed12be in ?? () from /usr/lib/arm-linux-gnueabihf/libdbus-cpp.so.4
#3 0xb6ed168e in ?? () from /usr/lib/arm-linux-gnueabihf/libdbus-cpp.so.4
#4 0xb6eba92c in core::dbus::Bus::run() () from /usr/lib/arm-linux-gnueabihf/libdbus-cpp.so.4
#5 0x000d8f16 in main ()
(gdb) t a a bt

Thread 7 (Thread 0xb52683e0 (LWP 2490)):
#-1 0xb66bf840 in ?? ()
Backtrace stopped: Cannot access memory at address 0x78696e6c

Thread 6 (Thread 0xb48ff3e0 (LWP 2493)):
#0 0xb66bf840 in ?? ()
#1 0xb66d329c in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 5 (Thread 0xb3eff3e0 (LWP 2499)):
#0 0xb6a70554 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
#1 0xb6a6e1e4 in __lll_lock_wait () from /lib/arm-linux-gnueabihf/libpthread.so.0
#2 0xb6a6a840 in pthread_mutex_lock () from /lib/arm-linux-gnueabihf/libpthread.so.0
#3 0x000de3a8 in std::mutex::lock() ()
#4 0x000e39de in core::Signal<void>::~Signal() ()
#5 0x0012f704 in gstreamer::Engine::Private::~Private() ()
#6 0x0012ae92 in gstreamer::Engine::~Engine() ()
#7 0x000d9692 in std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release() ()
#8 0x00121604 in std::_Sp_counted_ptr_inplace<core::ubuntu::media::PlayerImplementation::Private, std::allocator<core::ubuntu::media::PlayerImplementation::Private>, (__gnu_cxx::_Lock_policy)2>::_M_dispose() ()
#9 0x000d9692 in std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release() ()
#10 0x0011f3ec in core::ubuntu::media::PlayerImplementation::~PlayerImplementation() ()
#11 0x000d9692 in std::_Sp_counted_base<(__gnu_cxx::_Lock_policy)2>::_M_release() ()
#12 0x000d9ae4 in core::ubuntu::media::ServiceSkeleton::remove_player_for_key(unsigned int const&)
    ()
#13 0x00118be0 in ?? ()
#14 0xb6ed13b0 in ?? () from /usr/lib/arm-linux-gnueabihf/libdbus-cpp.so.4
#15 0xb6ed168e in ?? () from /usr/lib/arm-linux-gnueabihf/libdbus-cpp.so.4
#16 0xb6eba92c in core::dbus::Bus::run() () from /usr/lib/arm-linux-gnueabihf/libdbus-cpp.so.4
#17 0xb6b38360 in ?? () from /usr/lib/arm-linux-gnueabihf/libstdc++.so.6
#18 0xb6a68f98 in start_thread () from /lib/arm-linux-gnueabihf/libpthread.so.0
---Type <return> to continue, or q <return> to quit---
#19 0xb6a0822c in ?? () from /lib/arm-linux-gnueabihf/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 4 (Thread 0xb31943e0 (LWP 4713)):
#0 0xb6a70556 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
#1 0xb6a6e1e4 in __lll_lock_wait () from /lib/arm-linux-gnueabihf/libpthread.so.0
#2 0xb6a6a840 in pthread_mutex_lock () from /lib/arm-linux-gnueabihf/libpthread.so.0
#3 0x000de3a8 in std::mutex::lock() ()
#4 0x0011f064 in ?? ()
#5 0x000e390c in core::Signal<void>::operator()() ()
#6 0x000e390c in core::Signal<void>::operator()() ()
#7 0xb673a15e in ?? ()
Backtrace stopped: previous frame identical to this frame (corrup...

[Pat McGowan (pat-mcgowan)]

I have seen this with a number of other apps and services, seems whatever is active when the shell crashed grabs all the cpu.
One theory is that when a dbus client terminates the service side spins consuming cpu.

[Pat McGowan (pat-mcgowan)]

Made the bug more generic, and added dbus-cpp as its a commonly used element that could possibly be related

[Bill Filler (bfiller)]

Just got another unity8 crash and this time system-settings maxing the cpu. Here is the thread dump. It appears it's in a tight loop spawing and exiting threads:

(gdb) bt
#0 0xb623baa2 in poll () from /lib/arm-linux-gnueabihf/libc.so.6
#1 0xb5e5c0c0 in ?? () from /lib/arm-linux-gnueabihf/libglib-2.0.so.0
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) t a a bt

Thread 15 (Thread 0xb2297450 (LWP 4318)):
Cannot access memory at address 0x0
#0 0xb442c840 in ?? ()
Cannot access memory at address 0x0
#1 0xb444029c in ?? ()
Cannot access memory at address 0x0
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 14 (Thread 0xb2507b40 (LWP 4319)):
#0 0xb5e11b76 in ?? () from /lib/arm-linux-gnueabihf/librt.so.1
#1 0xb5e11be2 in ?? () from /lib/arm-linux-gnueabihf/librt.so.1
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 13 (Thread 0xb18ff450 (LWP 4320)):
#0 0xb6199554 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
#1 0xb6195192 in pthread_cond_wait@@GLIBC_2.4 () from /lib/arm-linux-gnueabihf/libpthread.so.0
Cannot access memory at address 0x3000000
#2 0xb235e0a8 in ?? ()
Cannot access memory at address 0x3000000
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 12 (Thread 0xb10ff450 (LWP 4321)):
#0 0xb6199554 in __libc_do_syscall () from /lib/arm-linux-gnueabihf/libpthread.so.0
#1 0xb6195192 in pthread_cond_wait@@GLIBC_2.4 () from /lib/arm-linux-gnueabihf/libpthread.so.0
Cannot access memory at address 0x3000000
#2 0xb235e0a8 in ?? ()
Cannot access memory at address 0x3000000
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 11 (Thread 0xb08ff450 (LWP 4322)):
#0 0xb623baa2 in poll () from /lib/arm-linux-gnueabihf/libc.so.6
#1 0xb5e5c0c0 in ?? () from /lib/arm-linux-gnueabihf/libglib-2.0.so.0
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 10 (Thread 0xae9bb450 (LWP 4328)):
#0 0xb6242712 in epoll_wait () from /lib/arm-linux-gnueabihf/libc.so.6
#1 0xb3d20422 in ?? () from /usr/lib/arm-linux-gnueabihf/libdbus-cpp.so.4
#2 0xb3d222be in ?? () from /usr/lib/arm-linux-gnueabihf/libdbus-cpp.so.4
#3 0xb3d2268e in ?? () from /usr/lib/arm-linux-gnueabihf/libdbus-cpp.so.4
---Type <return> to continue, or q <return> to quit---
#4 0xb3d0b92c in core::dbus::Bus::run() () from /usr/lib/arm-linux-gnueabihf/libdbus-cpp.so.4
#5 0xb634f360 in ?? () from /usr/lib/arm-linux-gnueabihf/libstdc++.so.6
#6 0xb6191f98 in start_thread () from /lib/arm-linux-gnueabihf/libpthread.so.0
#7 0xb624222c in ?? () from /lib/arm-linux-gnueabihf/libc.so.6
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 9 (Thread 0xadf2e450 (LWP 4332)):
#0 0xb623baa2 in poll () from /lib/arm-linux-gnueabihf/libc.so.6
#1 0xb5e5c0c0 in ?? () from /lib/arm-linux-gnueabihf/libglib-2.0.so.0
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

Thread 8 (Thread 0xad433450 (LWP 4335)):
#0 0xb623baa2 in poll () from /lib/arm-linux-gnueabihf/libc.so.6
#1 0xb5e5c0c0 in ?? () from /lib/arm-linux-gnueabihf/libglib-2.0....

[Thomas Voß (thomas-voss)]

I will try to come up with a distilled down test case illustrating that libdbus-cpp is not the cause but a symptom of the issue. Point being that it certainly shows up in the stack traces, but it sits waiting in all of them (specifically for the system settings crash).

[Thomas Voß (thomas-voss)]

We should assign this bug to an overarching component/project as multiple independent services (media-hub, location-service, dbus-daemon) are affected.

However, one idea that came to my mind: It might be that a spurious posix signal is causing these issues, probably a SIGHUP somewhere, arising on a thread that the respective signal is not blocked on. I will keep on investigating into that direction.

[Michał Sawicz (saviq)]

I wonder if we should make it so the whole session is restarted (or even the phone rebooted) if unity8 respawned...

[Alexandros Frantzis (afrantzis)]

I am getting similar symptoms (media-hub-server high cpu) , although I didn't see unity8 restarting (perhaps it did and I didn't notice?).

I have attached a tarball of strace (clipped because it was just the same after a point), gdb backtrace and a core file generated from inside gdb for media-hub-server.

[Alexandros Frantzis (afrantzis)]

The spinning futex wait we get in the strace:

2391 futex(0x1072a70, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)

Comes from:

25 Thread 0xb528f3e0 (LWP 2391) "Binder_1" __libc_do_syscall ()
    at ../ports/sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:44

#0 __libc_do_syscall () at ../ports/sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:44
#1 0xb6a951e4 in __lll_lock_wait (futex=0xfffffff5, futex@entry=0x1072a70, private=<optimized out>)
    at ../ports/sysdeps/unix/sysv/linux/arm/nptl/lowlevellock.c:46
#2 0xb6a91840 in __GI___pthread_mutex_lock (mutex=0x1072a70) at pthread_mutex_lock.c:79
#3 0x000de3a8 in std::mutex::lock() ()
#4 0x0011f064 in ?? ()
#5 0x000e390c in core::Signal<void>::operator()() ()
#6 0x000e390c in core::Signal<void>::operator()() ()
#7 0xb676115e in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

[Alexandros Frantzis (afrantzis)]

An easy way to reproduce this (works for me at least):

Install "stallboard" app from the store, run it, play a couple of sounds and then close it (swipe up/down in the window list) => media-hub-server starts spinning. This doesn't involve a unity8 crash, so not 100% sure it's the same problem described in this bug, but it sure seems related.

[Ricardo Mendoza (ricmm)]

Do you guys have any way to reproduce the dbus-daemon or location-service spinning issues? Due to a fix of mine + tvoss's other branch I can no longer see the media-hub problem.

[Launchpad Janitor (janitor)]

This bug was fixed in the package media-hub - 2.0.0+15.04.20141105.1-0ubuntu1

---------------
media-hub (2.0.0+15.04.20141105.1-0ubuntu1) vivid; urgency=low

  [ Ricardo Mendoza ]
  * Use new hybris interface to correctly register for client deaths.
    (LP: #1380848)
 -- Ubuntu daily release <email address hidden> Wed, 05 Nov 2014 20:41:14 +0000

[Launchpad Janitor (janitor)]

This bug was fixed in the package media-hub - 2.0.0+15.04.20141105.1~rtm-0ubuntu1

---------------
media-hub (2.0.0+15.04.20141105.1~rtm-0ubuntu1) 14.09; urgency=low

  [ Ricardo Mendoza ]
  * Use new hybris interface to correctly register for client deaths.
    (LP: #1380848)
 -- Ubuntu daily release <email address hidden> Wed, 05 Nov 2014 20:41:14 +0000