Bug 27801

Summary:	Logger causes dbus-daemon to use 100% cpu when starting chat
Product:	Telepathy	Reporter:	Thomas Rydzynski <qsorix>
Component:	logger	Assignee:	Telepathy bugs list <telepathy-bugs>
Status:	RESOLVED WORKSFORME	QA Contact:	Telepathy bugs list <telepathy-bugs>
Severity:	normal
Priority:	medium	CC:	nicolas
Version:	unspecified
Hardware:	x86-64 (AMD64)
OS:	Linux (All)
Whiteboard:
i915 platform:		i915 features:

Description Thomas Rydzynski 2010-04-22 17:18:57 UTC

When I open new chat window in empathy, dbus-deamon starts to utilize 100% of CPU for about a minute and the chat window opens with 15 seconds delay.

Steps to reproduce:
1. (optional) Start dbus-deamon in debug mode and export new DBUS_SESSION_BUS_ADDRES.
2. Start empathy.
3. At this point telepathy-gabble, telepathy-logger and mission-control-5 are running.
4. Open roster, double click on any contact.

Result:
CPU utilization by dbus-deamon goes to 100%, chat window opens but after about 15 seconds delay. After some time CPU goes down to normal. During this period dbus works (i.e. all communication proceeds without interruptions)

Expected result:
Chat window opens instantly. Dbus-deamon is not affected

I've noticed that if I kill telepathy-logger and let it start by itself (I don't know how it is started), then this bug still happens but this time without cpu burning -- just the delay before opening chat window. If i kill telepathy-logger again and run it myself from terminal, it is the same again (delay and 100% cpu).

If I kill telepathy-logger and prevent it from starting (e.g. mv binary) everything works as expected. I don't have to restart dbus or empathy or anything.

dbus-monitor shows no intensive communication during that period.

I tried to get some logs from telepathy-logger or dbus but failed. dbus running in debug mode doesn't output anything at the time I double click a contact. I don't know how to make telepathy-logger print some debug info. I've emerged it with USE=debug but it still doesn't print a thing.

I've run it like this: LOGGER_PERSIST=1 LOGGER_DEBUG=all /usr/bin/telepathy-logger

Give me some tips, please, I'll attach logs then.

I'm using:

telepathy-gabble 0.8.8
telepathy-logger 0.1.1
telepathy-mission-control 5.2.5
telepathy-salut 0.3.10
empathy 2.30.0.1

dbus 1.2.24
dbus-glib 0.86
telepathy-glib 0.10.1
glib 2.24.0

kernel 2.6.31-gentoo-r6

gcc (Gentoo 4.3.2-r3 p1.6, pie-10.1.5) 4.3.2

Everything was emerged from gentoo's ebuilds using
CFLAGS="-march=k8-sse3 -mmmx -m3dnow -O2 -pipe"

Comment 1 Cosimo Alfarano 2010-04-23 02:57:45 UTC

It happened to me once, but after restarting the X session it stareted to behave as expected. I couldn't reproduce the problem anymore since then and I concluded it was some dbus/session problem.

Can you check if, after restarting your X session, you have the same behaviour.

We should have a new release in a short time, which fixes several problems, it might fix it too.

Comment 2 Thomas Rydzynski 2010-04-23 03:46:25 UTC

I've used this set of software for several days and I've restarted X and also rebooted whole system many times. It happened every single time.

I'll check this again after the release you've mentioned and let you know.

Comment 3 Cosimo Alfarano 2010-10-25 06:51:14 UTC

Thomas, does this still happen with the last version of TPL?

Comment 4 Thomas Rydzynski 2010-10-25 11:20:22 UTC

I'm trying to compile newest sources and check but I'm having troubles. Perhaps you could help me. Where can you get glib-compile-schemas binary? Configure script complains about it and I can't google it anywhere.

Thanks

Comment 5 Emilio Pozuelo Monfort 2010-12-06 06:32:13 UTC

I can't reproduce this either.

You can get glib-compile-schemas from glib >= 2.26 IIRC

Comment 6 Nicolas Dufresne 2011-02-24 09:10:36 UTC

Works for me too. If your still having issues with 0.2 version let us knwo we'll reopen this bug.

Comment 7 Thomas Rydzynski 2011-02-26 09:28:48 UTC

I'm not able to reproduce this anymore. Thanks.

Comment 8 Patryk Zawadzki 2011-09-02 03:42:49 UTC

I am experiencing this right now. Not sure how to debug. Packages:

empathy-3.1.90.1-1.x86_64
telepathy-butterfly-0.5.15-1.x86_64
telepathy-farsight-0.0.19-1.x86_64
telepathy-farstream-0.1.1-1.x86_64
telepathy-gabble-0.13.5-1.x86_64
telepathy-glib-0.15.5-1.x86_64
telepathy-idle-0.1.5-2.x86_64
telepathy-logger-0.2.10-1.x86_64
telepathy-mission-control-5.9.1-1.x86_64
telepathy-salut-0.4.0-1.x86_64
telepathy-sofiasip-0.5.18-1.x86_64
telepathy-sunshine-0.2.0-1.x86_64

telepathy-logger causes mission-control-5 and the dbus-daemon to eat all available processing power.

Will try to reproduce, attach with gdb and get the output of "thread apply all bt full".

Comment 9 Patryk Zawadzki 2011-09-02 03:47:08 UTC

Thread 3 (Thread 0x7fa7dc820700 (LWP 25703)):
#0  0x00007fa7de1b1993 in poll () from /lib64/libc.so.6
No symbol table info available.
#1  0x00007fa7de949af8 in g_main_context_poll (context=0x423e60, 
    block=<value optimized out>, dispatch=1, self=<value optimized out>)
    at gmain.c:3402
        poll_func = 0x7fa7de957f40 <g_poll>
#2  g_main_context_iterate (context=0x423e60, block=<value optimized out>, 
    dispatch=1, self=<value optimized out>) at gmain.c:3084
        max_priority = 2147483647
        timeout = 120000
        some_ready = <value optimized out>
        nfds = 1
        allocated_nfds = <value optimized out>
        fds = 0x7fa7d4001170
#3  0x00007fa7de94a322 in g_main_loop_run (loop=0x7fa7d4001150) at gmain.c:3297
        __PRETTY_FUNCTION__ =           "g_main_loop_run"
#4  0x00007fa7dca62b6b in ?? () from /usr/lib64/gio/modules/libdconfsettings.so
No symbol table info available.
#5  0x00007fa7de96f106 in g_thread_create_proxy (data=0x423de0)
    at gthread.c:1962
        thread = 0x423de0
        __PRETTY_FUNCTION__ =           "g_thread_create_proxy"
#6  0x00007fa7dd76fed5 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#7  0x00007fa7de1bab5d in clone () from /lib64/libc.so.6
No symbol table info available.
#8  0x0000000000000000 in ?? ()
No symbol table info available.

Thread 2 (Thread 0x7fa7db1b1700 (LWP 25705)):
#0  0x00007fa7de1b1993 in poll () from /lib64/libc.so.6
No symbol table info available.
#1  0x00007fa7de949af8 in g_main_context_poll (context=0x7fa7d400dde0, 
    block=<value optimized out>, dispatch=1, self=<value optimized out>)
    at gmain.c:3402
        poll_func = 0x7fa7de957f40 <g_poll>
#2  g_main_context_iterate (context=0x7fa7d400dde0, 
    block=<value optimized out>, dispatch=1, self=<value optimized out>)
    at gmain.c:3084
        max_priority = 2147483647
        timeout = -1
        some_ready = <value optimized out>
        nfds = 3
        allocated_nfds = <value optimized out>
        fds = 0x7fa7d0001150
#3  0x00007fa7de94a322 in g_main_loop_run (loop=0x7fa7d400dd90) at gmain.c:3297
        __PRETTY_FUNCTION__ =           "g_main_loop_run"
#4  0x00007fa7dda43ca6 in gdbus_shared_thread_func (
    user_data=<value optimized out>) at gdbusprivate.c:276
        data = 0x7fa7d400ddb0
#5  0x00007fa7de96f106 in g_thread_create_proxy (data=0x7fa7d400ded0)
    at gthread.c:1962
        thread = 0x7fa7d400ded0
        __PRETTY_FUNCTION__ =           "g_thread_create_proxy"
#6  0x00007fa7dd76fed5 in start_thread () from /lib64/libpthread.so.0
No symbol table info available.
#7  0x00007fa7de1bab5d in clone () from /lib64/libc.so.6
No symbol table info available.
#8  0x0000000000000000 in ?? ()
No symbol table info available.

Thread 1 (Thread 0x7fa7de8af700 (LWP 25702)):
#0  0x00007fa7de1b1993 in poll () from /lib64/libc.so.6
No symbol table info available.
#1  0x00007fa7de949af8 in g_main_context_poll (context=0x418c80, 
    block=<value optimized out>, dispatch=1, self=<value optimized out>)
    at gmain.c:3402
        poll_func = 0x7fa7de957f40 <g_poll>
#2  g_main_context_iterate (context=0x418c80, block=<value optimized out>, 
    dispatch=1, self=<value optimized out>) at gmain.c:3084
        max_priority = 2147483647
        timeout = -1
        some_ready = <value optimized out>
        nfds = 3
        allocated_nfds = <value optimized out>
        fds = 0x447a30
#3  0x00007fa7de94a322 in g_main_loop_run (loop=0x447a50) at gmain.c:3297
        __PRETTY_FUNCTION__ =           "g_main_loop_run"
#4  0x00000000004019fc in main (argc=<value optimized out>, 
    argv=<value optimized out>) at telepathy-logger.c:204
        dbus_srv = <value optimized out>
        observer = 0x420000
        error = 0x0
        __PRETTY_FUNCTION__ =           "main"

Comment 10 Simon McVittie 2011-09-02 04:00:01 UTC

If you look in /proc/12345/fd where 12345 is the dbus-daemon's pid, how many fds are there? Tens or low hundreds are be OK, but if it's more than 500 it's likely to be Bug #23194.

If you run dbus-monitor, do you see ridiculously many messages? (Sustained multiple-messages-per-second when you're not doing anything in the UI probably counts as ridiculous.)

Comment 11 Nicolas Dufresne 2011-09-02 06:20:04 UTC

Small note, to get debug output from Telepathy Logger, use TPL_DEBUG= and TPL_PERSIST=1.

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.