XMPP daemon high CPU usage

XMPP daemon high CPU usage

Submitted by mathaba on Wed, 06/22/2011 - 15:23
Issue ID:3232
Issue Category:bug
Component:plugin
Priority:major
Status:fixed
Assigned:Unassigned
Version:1.0

Cannot keep bot running due to very high CPU usage. Please verify or suggest work-around or further info required?

Updates

#1

Submitted by crosser on Wed, 07/20/2011 - 08:52.

When imdaemon tries to connect to the xmpp server, it busyloops spewing this to the log:


Jul 20 16:34:58 cahost statusnet: [www.average.org:imdaemon.php:22730] [2] stream_select(): No stream arrays were passed (/var/www/htdocs/status-git/plugins/Xmpp/extlib/XMPPHP/XMLStream.php:397)
Jul 20 16:34:58 cahost statusnet: [www.average.org:imdaemon.php:22730] [2] fclose() expects parameter 1 to be resource, null given (/var/www/htdocs/status-git/plugins/Xmpp/extlib/XMPPHP/XMLStream.php:403)
Jul 20 16:34:58 cahost statusnet: [www.average.org:imdaemon.php:22730] [2] stream_select(): supplied argument is not a valid stream resource (/var/www/htdocs/status-git/plugins/Xmpp/extlib/XMPPHP/XMLStream.php:397)

This is the config:


$config['xmpp']['enabled'] = true;
$config['xmpp']['server'] = 'average.org';
$config['xmpp']['host'] = 'localhost';
$config['xmpp']['port'] = 5222;
$config['xmpp']['user'] = 'update';
$config['xmpp']['encryption'] = true;
$config['xmpp']['resource'] = 'statusnet10';
$config['xmpp']['password'] = '********';
$config['xmpp']['debug'] = false;

I *think* this is probably the same problem as mathaba reported.

#2

Submitted by mathaba on Wed, 07/20/2011 - 13:14.

yes, we have the exact same issue.

Very high cpu usage because of a connection loop.

had to disable XMPP bot to be able to run statusnet

Thank you,
hope this get fixed soon, XMPP is so crucial for us.

#3

Submitted by mathaba on Wed, 07/20/2011 - 12:52.

Im running alpha5, maybe beta1 fixed?
I will try on beta1 to see how it goes.

#4

Submitted by mcepl on Tue, 07/26/2011 - 18:51.
Version:1.0» 0.9

Unfortunately I have to add me too (running statusnet-0.9.7fix1-0.el6.noarch and prosody-0.8.2-1.el6.i686 on RHEL-6). This is my XMPP configuration:

[root@luther ~]# grep xmpp /usr/share/statusnet/config.php
$config['xmpp']['enabled'] = true;
$config['xmpp']['user'] = 'social';
$config['xmpp']['server'] = 'ceplovi.cz';
$config['xmpp']['host'] = 'luther.ceplovi.cz';
$config['xmpp']['password'] = 'somethingelse';
$config['xmpp']['resource'] = 'statusnet';
$config['xmpp']['encryption'] = false;
[root@luther ~]#

(luther.ceplovi.cz is actually just another name for localhost, should I put there localhost?)

#5

Submitted by crosser on Wed, 07/27/2011 - 00:26.
Version:0.9» 1.0

I think mcepl may have a different problem that is probably better to report as a separate issue. For me (and presumably for the original reporter) this is version 1.x (alpha, beta, git-current) specific. 0.9.7 and earlier version did not have this problem.

#6

Submitted by mcepl on Wed, 07/27/2011 - 02:47.

I am not a PHP programmer, but it seems to me that this is not actually a bug in the Status.net but in the XMPP libraries it uses. Which may be same for both of us.

#7

Submitted by crosser on Wed, 07/27/2011 - 05:55.

I (temporarily) replaced extlib/XMPPHP in the 0.9.7 installation with the copy from plugins/Xmpp/extlib/ from 1.0.x and daemon worked, and did _not_ loop. So the problem is unlikely in the XMPPHP library.

#8

Submitted by crosser on Tue, 08/30/2011 - 05:58.

I did some investigation. Problem #1 - incoming messages with empty body are "ignored" but not dequeued, so the daemon busyloops trying to handle them. These are e.g. status change messages (like what you see as "such and such is typing"). This seems to be the "right" fix (diff attached).

AttachmentSize
0001-Dequeue-xmpp-items-with-empty-body.patch_.txt 832 bytes

#9

Submitted by crosser on Tue, 08/30/2011 - 06:06.

Problem #2 that became apparent after fixing the "empty body" case is that the daemon starts to talk to itself:

| 61119 | a:4:{s:4:"type";s:4:"chat";s:4:"from";s:26:"feed@average.org/statusnet";s:4:"body";s:113:"[Average Feed] Unknown user; go to https://www.average.org/status/settings/im to add your address to your account";s:3:"xml";O:13:"XMPPHP_XMLObj":5:{s:4:"name";s:7:"message";s:2:"ns";s:13:"jabber:client";s:5:"attrs";a:4:{s:5:"xmlns";s:13:"jabber:client";s:4:"type";s:4:"chat";s:2:"to";s:26:"feed@average.org/statusnet";s:4:"from";s:26:"feed@average.org/statusnet";}s:4:"subs";a:1:{i:0;O:13:"XMPPHP_XMLObj":5:{s:4:"name";s:4:"body";s:2:"ns";s:13:"jabber:client";s:5:"attrs";a:0:{}s:4:"subs";a:0:{}s:4:"data";s:113:"[Average Feed] Unknown user; go to https://www.average.org/status/settings/im to add your address to your account";}}s:4:"data";s:0:"";}} | xmpp-in | 2011-07-05 13:25:04 | 2011-07-05 13:25:07 |

You can see that "to" and "from" here are the same jid (the one specified as the statusnet's jid in config.php). The log shows that the daemon is indeed sending and receiving this message continuously. I am trying to figure what causes this but maybe someone with more knowledge will be able to fix it faster.

#10

Submitted by crosser on Tue, 08/30/2011 - 07:44.

Possibly my patch from comment #8 is not right - maybe handleIncoming() should not be called. Is "take 2" more "correct" maybe? It seems to work for me.

I am stuck because in various places in the code, parameters are apparently taken either from the second parameter of addPlugin() or from $config['xmpp'] array - and if you skip any of them things don't work.

AttachmentSize
0001-Dequeue-xmpp-items-with-empty-body-take-2.patch_.txt 1.06 KB

#11

Submitted by mathaba on Fri, 10/07/2011 - 03:59.

Still happening on version 1.0.1
imqueue.php CPU usage goes very high and posting by bot does not work.
statusnet.log file becomes very huge quickly over 1 GB in a few minutes.

this is the log example:


2011-10-07 07:57:33 LOG_INFO: [mathaba.info:imdaemon.php:21482] DBQueueManager (im): Got Array for transport xmpp-in
2011-10-07 07:57:33 LOG_WARNING: [mathaba.info:imdaemon.php:21482] XmppPlugin: Ignoring message with empty body from fred@mathaba.info: Offline Storage
2011-10-07 07:57:33 LOG_INFO: [mathaba.info:imdaemon.php:21482] DBQueueManager (im): [xmpp-in:Array] Failed to handle item
2011-10-07 07:57:33 LOG_DEBUG: [mathaba.info:imdaemon.php:21482] Waiting up to 0 seconds for socket data...

#12

Submitted by Somsak Sriprayoon... on Wed, 10/12/2011 - 00:27.

Attach patch should fix the problem.

I installed status.net 3 days ago and found the same problem. I dig down the code and found that it compose of 2 reasons

  • implugin does not dequeue the invalid message as mentioned above. I fixed it by forcing return true in XmppPlugin.php for every occasions.
  • For each notice, XMPP will try to build the 'Activity' information and padded it to the end of *each* message. Consequently it will try to create Atom Feed URL for the dent and eventually call ProfileNoticeStream to get the last stream of the user. However the ProfileNoticeStream seems to be wrongly constructed here so it ends up searching for all notices in notice table for each dent send through XMPP. For my case, I have around 100K notices already in database and about 10+ active user, this means for *each* dent sent through XMPP, it will query for 100K x 10 == 1M notice, thus cause extremely high CPU usage in PHP and MySQL. Caching is no good since the data is so large that it won't fit in cache and get purged every time. I fixed it by passing $profile as second parameter in Profile.php so it finished the search once it found latest dent from the user.

The other codes in the patch fix the problem with GTalk (which seems to hate from= parameter). I don't sure whether this will affect Jabber. Feel free to discard those codes if you like.

NOTE: Why doesn't attach file section accept .diff or .patch?

AttachmentSize
statusnet-1.0.1-inox.txt 6.38 KB

#13

Submitted by mathaba on Fri, 10/28/2011 - 02:13.

Somsak Sriprayoon, thanks for you patch.
With your patch XMPP bot works, I am able to send messages with BOT.
but I still have high CPU with imdaemon.php

at first CPU is low and normal, but within a few seconds, maybe 20 seconds. CPU goes up high again.

This is from my statusnet.log file:

2011-10-28 05:53:47 LOG_DEBUG: [mathaba.info:imdaemon.php:47004] Waiting up to 0 seconds for socket data...
2011-10-28 05:53:47 LOG_DEBUG: [mathaba.info:imdaemon.php:47004] Servicing the XMPP queue.
2011-10-28 05:53:47 LOG_DEBUG: [mathaba.info:imdaemon.php:47004] DBQueueManager (im): Checking for notices...
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] claiming queue item id = 67554 for transport xmpp-in
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] claim succeeded.
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] DBQueueManager (im): Got Array for transport xmpp-in
2011-10-28 05:53:47 LOG_WARNING: [mathaba.info:imdaemon.php:47004] Message from unknown user bot@mathaba.info
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] DBQueueManager (im): [xmpp-in:Array] Successfully handled item
2011-10-28 05:53:47 LOG_DEBUG: [mathaba.info:imdaemon.php:47004] Waiting up to 0 seconds for socket data...
2011-10-28 05:53:47 LOG_DEBUG: [mathaba.info:imdaemon.php:47004] DBQueueManager (im): Checking for notices...
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] claiming queue item id = 67555 for transport xmpp-out
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] claim succeeded.
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] DBQueueManager (im): Got string ' $config['xmpp']['debug'] = true;

those messages loop forever.

1319781395 [VERBOSE]: Successfully sent 169 bytes.
1319781395 [VERBOSE]: RECV: [mathaba.info] Unknown user; go to https://mathaba.info/settings/im to add your address to your account
1319781395 [DEBUG]: Calling message_handler
1319781395 [DEBUG]: Message: [mathaba.info] Unknown user; go to https://mathaba.info/settings/im to add your address to your account
1319781395 [DEBUG]: EVENT: message
1319781395 [VERBOSE]: Socket is ready; send it.
1319781395 [VERBOSE]: SENT: [mathaba.info] Unknown user; go to https://mathaba.info/settings/im to add your address to your account

Any ideas on this issue?
Highly appreciated.

#14

Submitted by mathaba on Fri, 10/28/2011 - 02:16.

Somsak Sriprayoon, thanks for you patch.
With your patch XMPP bot works, I am able to send messages with BOT.
but I still have high CPU with imdaemon.php

at first CPU is low and normal, but within a few seconds, maybe 20 seconds. CPU goes up high again.

This is from my statusnet.log file:

2011-10-28 05:53:47 LOG_DEBUG: [mathaba.info:imdaemon.php:47004] Waiting up to 0 seconds for socket data...
2011-10-28 05:53:47 LOG_DEBUG: [mathaba.info:imdaemon.php:47004] Servicing the XMPP queue.
2011-10-28 05:53:47 LOG_DEBUG: [mathaba.info:imdaemon.php:47004] DBQueueManager (im): Checking for notices...
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] claiming queue item id = 67554 for transport xmpp-in
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] claim succeeded.
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] DBQueueManager (im): Got Array for transport xmpp-in
2011-10-28 05:53:47 LOG_WARNING: [mathaba.info:imdaemon.php:47004] Message from unknown user bot@mathaba.info
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] DBQueueManager (im): [xmpp-in:Array] Successfully handled item
2011-10-28 05:53:47 LOG_DEBUG: [mathaba.info:imdaemon.php:47004] Waiting up to 0 seconds for socket data...
2011-10-28 05:53:47 LOG_DEBUG: [mathaba.info:imdaemon.php:47004] DBQueueManager (im): Checking for notices...
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] claiming queue item id = 67555 for transport xmpp-out
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] claim succeeded.
2011-10-28 05:53:47 LOG_INFO: [mathaba.info:imdaemon.php:47004] DBQueueManager (im): Got string '[mathaba.info] Unknown user; go to https://mathaba.info/settings/im to add your address to your account
1319781395 [DEBUG]: Calling message_handler
1319781395 [DEBUG]: Message: [mathaba.info] Unknown user; go to https://mathaba.info/settings/im to add your address to your account
1319781395 [DEBUG]: EVENT: message
1319781395 [VERBOSE]: Socket is ready; send it.
1319781395 [VERBOSE]: SENT: [mathaba.info] Unknown user; go to https://mathaba.info/settings/im to add your address to your account

Any ideas on this issue?
Highly appreciated.

#15

Submitted by Somsak Sriprayoon... on Sun, 10/30/2011 - 10:33.

Tried clear all rows in queue_items table (truncate table queue_items) and try again.

Also, i am using activemq as queue manager. I found that it is slightly faster than dbqueue. Anyway for me both didn't cause high cpu usage.

#16

Submitted by mathaba on Sun, 10/30/2011 - 13:27.

hi,
thank you for your reply.
I cleared the table queue_item as you suggested and still having high cpu issue.
at first it stays 1-2% then slow increases to 5-10, then after few minutes it slowly increases to 50% .

I still see those messages in the logs and debug output:

1319994999 [DEBUG]: EVENT: message
1319994999 [VERBOSE]: Socket is ready; send it.
1319994999 [VERBOSE]: SENT: [mathaba.info] Unknown user; go to https://mathaba.info/settings/im to add your address to your account
1319994999 [VERBOSE]: Successfully sent 169 bytes.
1319994999 [VERBOSE]: RECV: [mathaba.info] Unknown user; go to https://mathaba.info/settings/im to add your address to your account
1319994999 [DEBUG]: Calling message_handler
1319994999 [DEBUG]: Message: [mathaba.info] Unknown user; go to https://mathaba.info/settings/im to add your address to your accountk

2011-10-30 17:17:03 LOG_DEBUG: [mathaba.info:imdaemon.php:45761] Waiting up to 0 seconds for socket data...
2011-10-30 17:17:03 LOG_DEBUG: [mathaba.info:imdaemon.php:45761] Servicing the XMPP queue.
2011-10-30 17:17:03 LOG_DEBUG: [mathaba.info:imdaemon.php:45761] DBQueueManager (im): Checking for notices...
2011-10-30 17:17:03 LOG_INFO: [mathaba.info:imdaemon.php:45761] claiming queue item id = 1917 for transport xmpp-in
2011-10-30 17:17:03 LOG_INFO: [mathaba.info:imdaemon.php:45761] claim succeeded.
2011-10-30 17:17:03 LOG_INFO: [mathaba.info:imdaemon.php:45761] DBQueueManager (im): Got Array for transport xmpp-in
2011-10-30 17:17:03 LOG_WARNING: [mathaba.info:imdaemon.php:45761] Message from unknown user bot@mathaba.info
2011-10-30 17:17:03 LOG_INFO: [mathaba.info:imdaemon.php:45761] DBQueueManager (im): [xmpp-in:Array] Successfully handled item
2011-10-30

Any help from statusnet Team?

Best regards.

#17

Submitted by Thomas Mangin on Sat, 05/19/2012 - 12:38.

The patch provided fixes the issue on my local installation. Please consider reviewing it for inclusion in 1.1.0

#18

Submitted by Thomas Mangin on Sat, 05/19/2012 - 12:41.
Component:core» plugin

The patch provided in this issue fixes the bug on my local installation. Could someone please review it and consider it for inclusion before the release of 1.1.0.

#19

Submitted by Jeremy Pope on Tue, 07/10/2012 - 14:31.
Status:active» fixed

A number of us have applied the fix in post #10 quite successfully. Evan has merged it into mainline: https://gitorious.org/statusnet/mainline/merge_requests/196

Login or Register to modify this issue, or to receive updates by email.

You can also subscribe to the RSS feed for updates to this issue.