[horde] High load with enabled activesync - Horde 5.1.2

Tue Sep 10 09:02:34 UTC 2013

  Hi,

I've got trouble with high load apache processes on my server when horde
activesync is enabled. I'm using horde/webmail in release 5.1.2 on a Debian
6 system installed via pear. I'm accessing the horde system with an ios
device (iphone 5).

I've enabled activesync within the conf.php this way:
$conf['activesync']['enabled'] = true;
$conf['activesync']['emailsync'] = true;
$conf['activesync']['logging']['path'] = '/var/log/horde';
$conf['activesync']['logging']['type'] = 'custom';

Everything works fine; getting emails, contacts and calendar entries...

But looking at the serverload is shows me this information:
PID USER      PR  NI  VIRT  RES  SHR S  %CPU %MEM    TIME+ 
COMMAND                                                                                                                                   
25403 www-data  20   0  465m  42m 6412 R  84.4  0.5   0:53.00
apache2

Looking at the apache server-status:
Srv PID Acc M CPU SS Req Conn Child Slot Client VHost Request
0-0 25373 0/59/59 _ 16.51 62 386 0.0 0.02 0.02 212.6.65.181 home.multi.box
NULL
1-0 25374 0/34/34 _ 97.85 62 275 0.0 0.01 0.01 212.6.65.181 home.multi.box
NULL
2-0 25375 0/18/18 W 3.38 10 0 0.0 0.01 0.01 212.6.65.181 home.multi.box
POST /Microsoft-Server-ActiveSync?User=sascha&DeviceId=ApplC39J
3-0 25376 1/30/30 K 54.37 4 140 0.1 0.01 0.01 212.6.65.181 home.multi.box
POST /horde/services/ajax.php/imp/poll HTTP/1.1
4-0 25377 0/22/22 _ 5.97 39 0 0.0 0.02 0.02 192.168.2.71 home.multi.box
NULL
5-0 25403 0/17/17 _ 56.01 4 60354 0.0 0.04 0.04 80.187.106.147
home.multi.box POST
/Microsoft-Server-ActiveSync?User=sascha&DeviceId=ApplC39J
6-0 25445 0/18/18 _ 54.47 10 59455 0.0 0.00 0.00 80.187.106.147
home.multi.box POST
/Microsoft-Server-ActiveSync?User=sascha&DeviceId=ApplC39J
7-0 25854 0/28/28 W 9.11 0 0 0.0 0.02 0.02 192.168.2.71 home.multi.box GET
/server-status HTTP/1.1
8-0 27254 0/83/83 _ 4.97 36 663 0.0 0.04 0.04 80.187.106.147 home.multi.box
POST /Microsoft-Server-ActiveSync?User=sascha&DeviceId=ApplC39J

Looking at the activesync-log I'm getting flooded with repeats of the
following actions:
2013-09-10T10:56:27+02:00 NOTICE: [25375] Skipping ed3eed25 because it is
not PINGable.
2013-09-10T10:56:27+02:00 INFO: [25375] Sleeping for  seconds.
2013-09-10T10:56:27+02:00 INFO: [25375] SyncCache collections refreshed.
2013-09-10T10:56:27+02:00 INFO: [25375] Refreshing 0b0824ac from the cache.
2013-09-10T10:56:27+02:00 INFO: [25375] Refreshing @Calendar@ from the
cache.
2013-09-10T10:56:27+02:00 INFO: [25375] Refreshing @Contacts@ from the
cache.
2013-09-10T10:56:27+02:00 INFO: [25375] Refreshing @Tasks@ from the cache.
2013-09-10T10:56:27+02:00 INFO: [25375] Refreshing ed3eed25 from the cache.
2013-09-10T10:56:27+02:00 INFO: [25375] Initializing state for collection:
INBOX, synckey: {522ed7f8-f094-402b-b191-6321c0a80204}7
2013-09-10T10:56:27+02:00 INFO: [25375] Loading state for synckey
{522ed7f8-f094-402b-b191-6321c0a80204}7
2013-09-10T10:56:27+02:00 INFO: [25375] Initializing message diff engine
for 0b0824ac (INBOX)
2013-09-10T10:56:27+02:00 INFO: [25375] Using MODSEQ 1378803387 for
0b0824ac.
2013-09-10T10:56:27+02:00 INFO: [25375]
Horde_Core_ActiveSync_Driver::getServerChanges(INBOX, 1378803055,
1378803387, 0, 1)
2013-09-10T10:56:27+02:00 INFO: [25375] MODSEQ: 1253
2013-09-10T10:56:27+02:00 INFO: [25375] Found 0 message changes in
0b0824ac.
2013-09-10T10:56:27+02:00 INFO: [25375] Initializing state for collection:
@Calendar@, synckey: {522edb97-d8a4-4933-b119-6a76c0a80204}4
2013-09-10T10:56:27+02:00 INFO: [25375] Loading state for synckey
{522edb97-d8a4-4933-b119-6a76c0a80204}4
2013-09-10T10:56:27+02:00 INFO: [25375] Initializing message diff engine
for @Calendar@ (@Calendar@)
2013-09-10T10:56:27+02:00 INFO: [25375] Using MODSEQ 779 for @Calendar at .
2013-09-10T10:56:27+02:00 INFO: [25375]
Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 779, 779, 0, 1)
2013-09-10T10:56:27+02:00 INFO: [25375] Fetching changes for calendar using
MODSEQ.
2013-09-10T10:56:27+02:00 INFO: [25375] Found 0 message changes in
@Calendar at .
2013-09-10T10:56:27+02:00 INFO: [25375] Initializing state for collection:
@Contacts@, synckey: {522edb0b-8e40-440e-9982-64fec0a80204}4
2013-09-10T10:56:27+02:00 INFO: [25375] Loading state for synckey
{522edb0b-8e40-440e-9982-64fec0a80204}4
2013-09-10T10:56:27+02:00 INFO: [25375] Initializing message diff engine
for @Contacts@ (@Contacts@)
2013-09-10T10:56:27+02:00 INFO: [25375] Using MODSEQ 587 for @Contacts at .
2013-09-10T10:56:27+02:00 INFO: [25375]
Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 587, 587, 0, 1)
2013-09-10T10:56:27+02:00 INFO: [25375] Fetching changes for contacts using
MODSEQ.
2013-09-10T10:56:27+02:00 INFO: [25375] Found 0 message changes in
@Contacts at .
2013-09-10T10:56:27+02:00 INFO: [25375] Initializing state for collection:
@Tasks@, synckey: {522edb9a-0e00-448d-b28d-6a76c0a80204}2
2013-09-10T10:56:27+02:00 INFO: [25375] Loading state for synckey
{522edb9a-0e00-448d-b28d-6a76c0a80204}2
2013-09-10T10:56:27+02:00 INFO: [25375] Initializing message diff engine
for @Tasks@ (@Tasks@)
2013-09-10T10:56:27+02:00 INFO: [25375] Using MODSEQ 592 for @Tasks at .
2013-09-10T10:56:27+02:00 INFO: [25375]
Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 592, 592, 0, 1)
2013-09-10T10:56:27+02:00 INFO: [25375] Fetching changes for tasks using
MODSEQ.
2013-09-10T10:56:27+02:00 INFO: [25375] Found 0 message changes in @Tasks at .
2013-09-10T10:56:27+02:00 INFO: [25375] Initializing state for collection:
INBOX.0-SPAM.Spamverdacht, synckey: {522ed81a-162c-4c60-b400-64fec0a80204}8
2013-09-10T10:56:27+02:00 INFO: [25375] Loading state for synckey
{522ed81a-162c-4c60-b400-64fec0a80204}8
2013-09-10T10:56:27+02:00 NOTICE: [25375] Skipping ed3eed25 because it is
not PINGable.
2013-09-10T10:56:27+02:00 INFO: [25375] Sleeping for  seconds.
2013-09-10T10:56:27+02:00 INFO: [25375] SyncCache collections refreshed.
2013-09-10T10:56:27+02:00 INFO: [25375] Refreshing 0b0824ac from the cache.
2013-09-10T10:56:27+02:00 INFO: [25375] Refreshing @Calendar@ from the
cache.
2013-09-10T10:56:27+02:00 INFO: [25375] Refreshing @Contacts@ from the
cache.
[...]

After deleting the account on the iphone it takes up to 2 minutes until the
flood within the log stops and the serverload drops back to a normal value.

I hope someone can give me a hint whats going on here and if there's
something I can do to prevent such a high continuous serverload.

Thanks in advance
Sascha