Bug 36259

Summary: Logger eating all my precious CPU
Product: Telepathy Reporter: Guillaume Desmottes <guillaume.desmottes>
Component: loggerAssignee: Telepathy bugs list <telepathy-bugs>
Status: RESOLVED NOTOURBUG QA Contact: Telepathy bugs list <telepathy-bugs>
Severity: major    
Priority: medium CC: bigon, nicolas
Version: unspecified   
Hardware: Other   
OS: All   
Whiteboard:
i915 platform: i915 features:
Bug Depends on: 36627    
Bug Blocks:    
Attachments: logger log
backtrace

Description Guillaume Desmottes 2011-04-15 06:53:51 UTC
Created attachment 45668 [details]
logger log

I was doing some empathy hacking and so was creating/destroying text channels pretty often. At some point I noticed that the logger was eating all the CPU.

This is the logger from Ubuntu natty: 0.2.6 with this patch : http://patches.ubuntu.com/t/telepathy-logger/telepathy-logger_0.2.6-1ubuntu1.patch
Comment 1 Nicolas Dufresne 2011-04-15 09:53:07 UTC
This was fixed and released in 0.2.7, but latest stable is 0.2.8. I recommend updating to latest.

*** This bug has been marked as a duplicate of bug 35793 ***
Comment 2 Guillaume Desmottes 2011-04-18 00:25:13 UTC
Could you please point out the commits which fixed this bug so I can ask Ubuntu to backport those?
Comment 3 Nicolas Dufresne 2011-04-18 06:36:24 UTC
(In reply to comment #2)
> Could you please point out the commits which fixed this bug so I can ask Ubuntu
> to backport those?

That's a waste of time imho, but's it's your time. So change is 884c52dad5d5fb30a450b013b83aed306ed49164. And you should consider adding a3c5b572ce3e46102d2833b284c21eecd031ec85 (the only change in 0.2.8, Fix wrong shared object version) and everything in 0.2.7 that is not related to Call is something you most likely want. Especially the search regex that fix a long term bug in log viewer search capability.
Comment 4 Guillaume Desmottes 2011-04-18 06:46:08 UTC
884c52dad5d5fb30a450b013b83aed306ed49164 is in the package, see the patch URL I linked, so that's another issue.
Comment 5 Nicolas Dufresne 2011-04-18 06:58:31 UTC
(In reply to comment #4)
> 884c52dad5d5fb30a450b013b83aed306ed49164 is in the package, see the patch URL I
> linked, so that's another issue.

Well, give instructions to reproduce please, or investigate (e.g. a bt when it's looking, debug logs), as I can't on 0.2.8.
Comment 6 Laurent Bigonville 2011-04-29 05:59:25 UTC
Hi,

Just had telepathy-logger eating 100% of one CPU

Here the backtrace:


#0  g_str_hash (v=<value optimised out>) at /build/buildd/glib2.0-2.28.6/./glib/gstring.c:146
#1  0x00007fd383f4af6d in g_hash_table_lookup_node (hash_table=0x20e7cf0, key=0x7fd3852210a1) at /build/buildd/glib2.0-2.28.6/./glib/ghash.c:313
#2  g_hash_table_lookup (hash_table=0x20e7cf0, key=0x7fd3852210a1) at /build/buildd/glib2.0-2.28.6/./glib/ghash.c:902
#3  0x00007fd383239cbb in tp_asv_get_uint32 (asv=<value optimised out>, key=<value optimised out>, valid=0x0) at dbus.c:1211
#4  0x00007fd385219ae4 in pendingproc_store_pending_messages (ctx=0x20c7320, user_data=<value optimised out>) at text-channel.c:593
#5  0x00007fd385209311 in _tpl_action_chain_continue (self=0x20c7320) at action-chain.c:118
#6  0x00007fd3852192fe in pendingproc_get_remote_contact (ctx=0x20c7320, user_data=<value optimised out>) at text-channel.c:259
#7  0x00007fd385209311 in _tpl_action_chain_continue (self=0x20c7320) at action-chain.c:118
#8  0x00007fd383227c72 in contacts_context_continue (c=0x2064060) at contact.c:1783
#9  0x00007fd38322a5fc in contacts_got_attributes (connection=0x20d75f0, attributes=0x20ef230, error=<value optimised out>, user_data=0x2064060, weak_object=<value optimised out>) at contact.c:3731
#10 0x00007fd3831fede8 in _tp_cli_connection_interface_contacts_invoke_callback_get_contact_attributes (self=0x20d75f0, error=0x0, args=0x20ee0a0, generic_callback=0x7fd38322a1c0 <contacts_got_attributes>, 
    user_data=<value optimised out>, weak_object=<value optimised out>) at _gen/tp-cli-connection-body.h:12181
#11 0x00007fd38326dbd0 in tp_proxy_pending_call_idle_invoke (p=0x20e68c0) at proxy-methods.c:153
#12 0x00007fd383f5bbcd in g_main_dispatch (context=0x2062540) at /build/buildd/glib2.0-2.28.6/./glib/gmain.c:2440
#13 g_main_context_dispatch (context=0x2062540) at /build/buildd/glib2.0-2.28.6/./glib/gmain.c:3013
#14 0x00007fd383f5c3a8 in g_main_context_iterate (context=0x2062540, block=<value optimised out>, dispatch=1, self=<value optimised out>) at /build/buildd/glib2.0-2.28.6/./glib/gmain.c:3091
#15 0x00007fd383f5c9f2 in g_main_loop_run (loop=0x20c62a0) at /build/buildd/glib2.0-2.28.6/./glib/gmain.c:3299
#16 0x00000000004018e3 in main (argc=<value optimised out>, argv=<value optimised out>) at telepathy-logger.c:189
Comment 7 Laurent Bigonville 2011-04-29 06:00:41 UTC
Created attachment 46153 [details]
backtrace

More readable backtrace
Comment 8 Nicolas Dufresne 2011-04-29 07:23:29 UTC
(In reply to comment #7)
> Created an attachment (id=46153) [details]
> backtrace
> 
> More readable backtrace

The line number in the backtrace does not match the source code I have, can you provide the source you are using (text-channel.c).
Comment 9 Nicolas Dufresne 2011-04-29 07:33:40 UTC
(In reply to comment #8)
> (In reply to comment #7)
> > Created an attachment (id=46153) [details] [details]
> > backtrace
> > 
> > More readable backtrace
> 
> The line number in the backtrace does not match the source code I have, can you
> provide the source you are using (text-channel.c).

Also, I would need value of pending_id, pending_ts, cached->id and cached->timestamp.
Comment 10 Nicolas Dufresne 2011-04-29 07:34:39 UTC
(In reply to comment #9)
> (In reply to comment #8)
> > (In reply to comment #7)
> > > Created an attachment (id=46153) [details] [details] [details]
> > > backtrace
> > > 
> > > More readable backtrace
> > 
> > The line number in the backtrace does not match the source code I have, can you
> > provide the source you are using (text-channel.c).
> 
> Also, I would need value of pending_id, pending_ts, cached->id and
> cached->timestamp.

That's on frame 4 btw.
Comment 11 Nicolas Dufresne 2011-05-16 09:32:06 UTC
Did I understood well that the patch was not applied as expected in Ubuntu ?
Comment 12 Brian Curtis 2011-05-19 09:57:43 UTC
https://bugs.launchpad.net/ubuntu/+source/telepathy-logger/+bug/745803

got the patch (from gnome git) into natty-proposed, here:
https://code.launchpad.net/~bcurtiswx/ubuntu/natty/telepathy-logger/lp_745803_fix
so it was available for testing

BUT,
I just got this bug report with the new version that includes the patch
https://bugs.launchpad.net/ubuntu/+source/telepathy-logger/+bug/785178

Trying to look into it more...
Comment 13 Nicolas Dufresne 2011-05-19 10:46:28 UTC
(In reply to comment #12)
> https://bugs.launchpad.net/ubuntu/+source/telepathy-logger/+bug/745803
> 
> got the patch (from gnome git) into natty-proposed, here:
> https://code.launchpad.net/~bcurtiswx/ubuntu/natty/telepathy-logger/lp_745803_fix
> so it was available for testing

618 	else if (cached->id < pending_id)
619 	{

Followed this linked, clicked on "browse the code" and saw that it's not showing patched code.
Comment 14 Nicolas Dufresne 2011-06-07 06:33:51 UTC
As it's marked fixed in the Ubuntu bug.

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.