[horde] Slow response times
Simon Wilson
simon at simonandkate.net
Fri Apr 18 13:21:48 UTC 2014
I have been running Horde for quite a few years now, but have never
had this issue before. I would appreciate some help if anyone can...
I've moved my Horde web server (that has been running Horde 5 for a
year or more) from being reverse proxied behind another box to now
being 'direct', so I have made a couple of Apache config changes. That
was a week ago, and it has been running fast and fine. Today Horde has
slowed to a crawl, from multiple PCs and browsers.
The server is running fully up to date Horde 5.1.6 on a CentOS 6.5 KVM
virtual machine with 8GB RAM (the host has 32GB), as it has been for
ages. PHP is 5.3.28. Horde VM average load is under 5%. The host's
average load is under 10%.
Horde apps and pages are taking between 15 and 30 seconds to load.
Logout is instantaneous. Test.php is instantaneous. GET login.php is
instantaneous. POST login takes 30 seconds, but loading the CSS and JS
is quick. Basic mode is as slow as dynamic. If I log into Smart phone
mobile mode it is fast (under 3 seconds even for 'heavy' pages).
ActiveSync is still flying, with logged response times under 0.5 sec.
ActiveSync refreshes fast on the phones. Connectivity within Horde
apps remains fast and responsive, so if I load Imp (which takes 15
seconds) emails appear almost instantly once Imp loads, and can be
read, refreshed, deleted, etc., all as per normal speed.
The Apache server on the VM serves other web sites, and they respond
in under a second, including a Wordpress blog that runs on PHP and
that is plenty quick enough. PHPLdapAdmin runs internally on the same
server, and responds (including with a https login to the separate
LDAP server that Horde auths users to) in under 0.5 seconds).
For troubleshooting I am connecting inside the LAN with just http
instead of https and with no port forwarding via my router. I have
disabled / re-enabled caching (currently xcache). I have restarted
apache, checked its config, and rebooted the server. I have trimmed
down php loaded modules. Still, horde load times are between 12
seconds and 30 seconds.
Horde logs show nothing abnormal at INFO level, and at DEBUG level so
much is logged it is hard to follow anything for the 30 or 40 seconds
I have it at DEBUG.
If anyone has any ideas where I can look next please let me know! :)
Log detail below.
Thanks
Simon
Times from logs:
The following is an example from the Apache log files for a page
loaded in dynamic mode:
192.168.1.1 - - [18/Apr/2014:21:25:00 +1000] "GET /admin/config/
HTTP/1.1" 200 79066 "http://emp06.simonandkate.lan/admin/config/"
"Mozilla/5.0 (Windows NT 6.1; WOW64; rv:28.0) Gecko/20100101
Firefox/28.0" 21/21872686
The last two numbers are the time taken to serve the page (seconds,
millseconds). So it took 21 seconds to deliver that page.
GETting and POSTing login.php from my tablet is quick:
192.168.1.40 - - [18/Apr/2014:21:38:12 +1000] "GET /login.php
HTTP/1.1" 200 2818 "-" "Mozilla/5.0 (Linux; Android 4.3; SM-P605
Build/JSS15J) AppleWebKit/537.36 (KHTML, like Gecko)
Chrome/33.0.1750.166 Safari/537.36 OPR/20.0.1396.73172" 0/123154
192.168.1.40 - - [18/Apr/2014:21:39:20 +1000] "POST /login.php
HTTP/1.1" 302 26 "http://emp06.simonandkate.lan/login.php"
"Mozilla/5.0 (Linux; Android 4.3; SM-P605 Build/JSS15J)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/33.0.1750.166
Safari/537.36 OPR/20.0.1396.73172" 0/117334
But then actual logging in:
192.168.1.40 - - [18/Apr/2014:21:39:20 +1000] "GET
/services/portal/index.php HTTP/1.1" 200 162477
"http://emp06.simonandkate.lan/login.php" "Mozilla/5.0 (Linux; Android
4.3; SM-P605 Build/JSS15J) AppleWebKit/537.36 (KHTML, like Gecko)
Chrome/33.0.1750.166 Safari/537.36 OPR/20.0.1396.73172" 43/43865598
192.168.1.40 - - [18/Apr/2014:21:40:04 +1000] "GET
/static/5d693ca9ba76d21690a82d404fbb6219.css HTTP/1.1" 200 100050
"http://emp06.simonandkate.lan/services/portal/index.php" "Mozilla/5.0
(Linux; Android 4.3; SM-P605 Build/JSS15J) AppleWebKit/537.36 (KHTML,
like Gecko) Chrome/33.0.1750.166 Safari/537.36 OPR/20.0.1396.73172"
0/76524
192.168.1.40 - - [18/Apr/2014:21:40:04 +1000] "GET
/trean/favicon.php?bookmark_id=6 HTTP/1.1" 200 623
"http://emp06.simonandkate.lan/services/portal/index.php" "Mozilla/5.0
(Linux; Android 4.3; SM-P605 Build/JSS15J) AppleWebKit/537.36 (KHTML,
like Gecko) Chrome/33.0.1750.166 Safari/537.36 OPR/20.0.1396.73172"
0/52231
192.168.1.40 - - [18/Apr/2014:21:40:05 +1000] "GET
/static/cd4a555b4f0c87ddcf5aeb32a14c437f884d563b.js HTTP/1.1" 200
99489 "http://emp06.simonandkate.lan/services/portal/index.php"
"Mozilla/5.0 (Linux; Android 4.3; SM-P605 Build/JSS15J)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/33.0.1750.166
Safari/537.36 OPR/20.0.1396.73172" 0/77364
192.168.1.40 - - [18/Apr/2014:21:40:05 +1000] "GET
/static/8e2549e0c6a7c081f04dc8b881b92232000aa227.js HTTP/1.1" 200
139785 "http://emp06.simonandkate.lan/services/portal/index.php"
"Mozilla/5.0 (Linux; Android 4.3; SM-P605 Build/JSS15J)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/33.0.1750.166
Safari/537.36 OPR/20.0.1396.73172" 0/123634
Takes 43 seconds for index.php. The css and js serve fast.
Another example (loading Imp):
192.168.1.1 - - [18/Apr/2014:22:43:44 +1000] "GET /imp/index.php
HTTP/1.1" 302 26
"http://emp06.simonandkate.lan/services/portal/index.php" "Mozilla/5.0
(Windows NT 6.1; WOW64; rv:28.0) Gecko/20100101 Firefox/28.0" 0/70514
192.168.1.1 - - [18/Apr/2014:22:43:44 +1000] "GET
/imp/dynamic.php?page=mailbox HTTP/1.1" 200 34670
"http://emp06.simonandkate.lan/services/portal/index.php" "Mozilla/5.0
(Windows NT 6.1; WOW64; rv:28.0) Gecko/20100101 Firefox/28.0"
15/15184821
192.168.1.1 - - [18/Apr/2014:22:43:59 +1000] "POST
/services/ajax.php/imp/dynamicInit HTTP/1.1" 200 4166
"http://emp06.simonandkate.lan/imp/dynamic.php?page=mailbox"
"Mozilla/5.0 (Windows NT 6.1; WOW64; rv:28.0) Gecko/20100101
Firefox/28.0" 0/590395
This is a fairly typical rewrite level 4 log event with a 30 second wait time:
192.168.1.1 - - [18/Apr/2014:23:05:00 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(3) [perdir /var/www/horde/] strip per-dir prefix:
/var/www/horde/admin/config/config.php -> admin/config/config.php
192.168.1.1 - - [18/Apr/2014:23:05:00 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(3) [perdir /var/www/horde/] applying pattern '.*' to uri
'admin/config/config.php'
192.168.1.1 - - [18/Apr/2014:23:05:00 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(3) [perdir /var/www/horde/] strip per-dir prefix:
/var/www/horde/admin/config/config.php -> admin/config/config.php
192.168.1.1 - - [18/Apr/2014:23:05:00 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(3) [perdir /var/www/horde/] applying pattern '^(.*)$' to uri
'admin/config/config.php'
192.168.1.1 - - [18/Apr/2014:23:05:00 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(4) [perdir /var/www/horde/] RewriteCond:
input='/var/www/horde/admin/config/config.php' pattern='!-d' => matched
192.168.1.1 - - [18/Apr/2014:23:05:00 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(4) [perdir /var/www/horde/] RewriteCond:
input='/var/www/horde/admin/config/config.php' pattern='!-f' =>
not-matched
192.168.1.1 - - [18/Apr/2014:23:05:00 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(1) [perdir /var/www/horde/] pass through
/var/www/horde/admin/config/config.php
192.168.1.1 - - [18/Apr/2014:23:05:30 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(3) [perdir /var/www/horde/] strip per-dir prefix:
/var/www/horde/admin/config/index.php -> admin/config/index.php
192.168.1.1 - - [18/Apr/2014:23:05:30 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(3) [perdir /var/www/horde/] applying pattern '.*' to uri
'admin/config/index.php'
192.168.1.1 - - [18/Apr/2014:23:05:30 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(3) [perdir /var/www/horde/] strip per-dir prefix:
/var/www/horde/admin/config/index.php -> admin/config/index.php
192.168.1.1 - - [18/Apr/2014:23:05:30 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(3) [perdir /var/www/horde/] applying pattern '^(.*)$' to uri
'admin/config/index.php'
192.168.1.1 - - [18/Apr/2014:23:05:30 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(4) [perdir /var/www/horde/] RewriteCond:
input='/var/www/horde/admin/config/index.php' pattern='!-d' => matched
192.168.1.1 - - [18/Apr/2014:23:05:30 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(4) [perdir /var/www/horde/] RewriteCond:
input='/var/www/horde/admin/config/index.php' pattern='!-f' =>
not-matched
192.168.1.1 - - [18/Apr/2014:23:05:30 +1000]
[emp06.simonandkate.lan/sid#7f8e2a0891b8][rid#7f8e2a4ee088/initial]
(1) [perdir /var/www/horde/] pass through
/var/www/horde/admin/config/index.php
Only things installed in recent weeks:
Apr 15 15:39:37 emp06 yum[25505]: Installed:
php53u-gd-5.3.28-2.ius.centos6.x86_64. I have unloaded it from PHP, no
difference.
--
Simon Wilson
M: 0400 12 11 16
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-keys
Size: 1339 bytes
Desc: PGP Public Key
URL: <http://lists.horde.org/archives/horde/attachments/20140418/ca6b1cb8/attachment.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 198 bytes
Desc: PGP Digital Signature
URL: <http://lists.horde.org/archives/horde/attachments/20140418/ca6b1cb8/attachment-0001.bin>
More information about the horde
mailing list