[horde] High load with enabled activesync - Horde 5.1.2
Arjen de Korte
arjen+horde at de-korte.org
Tue Sep 10 09:56:16 UTC 2013
Citeren Sascha Schmidt <sascha at schmidt.ps>:
> 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.
What is the value of $conf[activesync][ping][waitinterval]? Looking at
the above log, it looks like it is not set. This could be the reason
why it is now continuously looking for changes. That's definitly not
what you want. Try setting it to something like 60 seconds or so.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 308 bytes
Desc: PGP digitale ondertekening
URL: <http://lists.horde.org/archives/horde/attachments/20130910/5a788ce0/attachment.bin>
More information about the horde
mailing list