Comment 18 for bug 672206

Revision history for this message
Eugene Kirpichov (ekirpichov) wrote :

I observed this behavior while I had an unread message notification in Psi messenger. indicator-application was using 100% cpu (according to "top"), but it immediately stopped doing so as soon as I read the notification.

This happened at least two times; then I decided to debug things.

The top entry looks like this:
  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
  745 kirpicho 20 0 538m 136m 3888 R 99.8 0.4 3603:49 indicator-appli

Here's some strace data while it's consuming 100% CPU:
poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}], 2, 0) = 1 ([{fd=3, revents=POLLIN}])
read(3, "\3\0\0\0\0\0\0\0", 16) = 8
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
futex(0x7f764400c1c0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f764400bd50, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x12af0b0, FUTEX_WAKE_PRIVATE, 1) = 1
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
futex(0x7f764400c1c0, FUTEX_WAKE_PRIVATE, 1) = 1
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
futex(0x7f764400c1c0, FUTEX_WAKE_PRIVATE, 1) = 1
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
futex(0x7f764400c1c0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f764400bd50, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x12af0b0, FUTEX_WAKE_PRIVATE, 1) = 1
poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}], 2, 0) = 1 ([{fd=3, revents=POLLIN}])
read(3, "\3\0\0\0\0\0\0\0", 16) = 8
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
futex(0x7f76516c1720, FUTEX_WAKE_PRIVATE, 1) = 0
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
futex(0x12af0b0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7f76440024a0, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x7f76440024a0, FUTEX_WAKE_PRIVATE, 1) = 0
poll([{fd=3, events=POLLIN}, {fd=7, events=POLLIN}], 2, 0) = 1 ([{fd=3, revents=POLLIN}])
read(3, "\1\0\0\0\0\0\0\0", 16) = 8
write(5, "\1\0\0\0\0\0\0\0", 8) = 8
futex(0x7f764400c1c0, FUTEX_WAKE_PRIVATE, 1) = 1

A stack trace from gdb looks like this:
(gdb) bt
#0 0x00007f7651929f20 in g_list_length () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#1 0x00000000004035e4 in ?? ()
#2 0x000000000040464e in ?? ()
#3 0x00007f7651e960c7 in g_simple_async_result_complete () from /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#4 0x00007f7651eee56d in ?? () from /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#5 0x00007f7651e960c7 in g_simple_async_result_complete () from /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#6 0x00007f7651ee494a in ?? () from /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#7 0x00007f7651e960c7 in g_simple_async_result_complete () from /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#8 0x00007f7651e961c9 in ?? () from /usr/lib/x86_64-linux-gnu/libgio-2.0.so.0
#9 0x00007f765192cd13 in g_main_context_dispatch () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#10 0x00007f765192d060 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#11 0x00007f765192d45a in g_main_loop_run () from /lib/x86_64-linux-gnu/libglib-2.0.so.0
#12 0x0000000000402e59 in ?? ()
#13 0x00007f765132976d in __libc_start_main (main=0x402de0, argc=1, ubp_av=0x7ffff6e9ad78, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffff6e9ad68)
    at libc-start.c:226
#14 0x0000000000402ed5 in ?? ()
#15 0x00007ffff6e9ad68 in ?? ()
#16 0x000000000000001c in ?? ()
#17 0x0000000000000001 in ?? ()
#18 0x00007ffff6e9b7aa in ?? ()
#19 0x0000000000000000 in ?? ()

I wanted to capture one more stack trace but the process crashed after I ran "c" and then "Ctrl+C" in gdb.
The restarted process did not exhibit this behavior - after I got one more notification, there was no 100% cpu usage.

A top entry for the restarted process looks like this:
  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 1376 kirpicho 20 0 407m 5052 3932 S 2 0.0 0:01.63 indicator-appli

so, apparently, RES is now only 5k instead of 136m.

Hope this helps the developers debug this issue.