Topic: Apache 2.4.10/Linux giving 60 sec response time randomly

[neerajtati]

Hello Everyone,
I am facing an intermittent slow response issue in our apache web server. The slow response time is always 60.x seconds which suggest that something is timing out after 60 seconds and then serving the request. But not sure exactly what.The slow response is not specific to any transaction. It is randomly coming by accessing any URL.

Behaviour of the problem:
The slow response request doesn't turn into any error. It is served exactly after 60.x seconds.

I have done all the checks and don't find any configuration mismatch.

I am looking for an advise from experts on this forum as to what else can be checked to find out the cause of slow response.


Apache Info: Apache/2.4.10; 64 bit, worker mode
Web server OS info: RHEL 6.6 (64 bit)

Setup:
In backend, weblogic server is used as app server. We have checked response time of weblogic, it is normal. The entire 60 seconds are spent at apache level.

Investigation:
1. 60 second response time is coming for non-ssl and ssl requests both.

Apache configurations:

1. worker mode:

<IfModule mpm_worker_module>
    ServerLimit             40
    StartServers            20
    MaxClients             800
    MinSpareThreads         75
    MaxSpareThreads        125
    ThreadsPerChild         20
    MaxConnectionsPerChild   0

</IfModule>

2. Cipher Suite:
SSLCipherSuite EECDH+AESGCM:EDH+AESGCM:AES256+EECDH:AES256+EDH:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-RSA-AES128-GCM-SHA256:DHE-RSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-SHA384:ECDHE-RSA-AES128-SHA256:ECDHE-RSA-AES256-SHA:ECDHE-RSA-AES128-SHA:DHE-RSA-AES256-SHA256:DHE-RSA-AES128-SHA256:DHE-RSA-AES256-SHA:DHE-RSA-AES128-SHA:ECDHE-RSA-DES-CBC3-SHA:EDH-RSA-DES-CBC3-SHA:AES256-GCM-SHA384:AES128-GCM-SHA256:AES256-SHA256:AES128-SHA256:AES256-SHA:AES128-SHA:DES-CBC3-SHA:HIGH:!aNULL:!eNULL:!EXPORT:!DES:!MD5:!PSK:!RC4
SSLProtocol All -SSLv2 -SSLv3

3. KeepAliveTimeout is 15seconds
4. MaxkeepAliveRequest 1000
5. Timeout in httpd-default.conf is set to 30 seconds.

Logs:
Apache access logs:
 
203.127.23.73 - - [11/Aug/2015:11:56:16 +0800] [0.249 (secs)] "HEAD / HTTP/1.0" 302 - "-" "-"
203.127.23.73 - - [11/Aug/2015:11:55:16 +0800] [60.60519305 (secs)] "GET /issoselfservicebrt/redrewards.action?portalTy=4&success_callback_url=https://rewards.singtel.com:8443/rewards/my-account/account-summary.aspx&failure_callback_url= HTTP/1.1" 200 842 "https://sso.singtel.com/issoselfservicebrt/signIn.action?portalTy=4&success_callback_url=https://rewards.singtel.com:8443/rewards/my-account/account-summary.aspx" "Mozilla/5.0 (Windows NT 6.1; Trident/7.0; rv:11.0) like Gecko"
 
Apache debug logs:
[Tue 11 Aug 11:55:15.063597 2015] [reqtimeout:info] [pid 18257:tid 139653184771840] [client 203.127.23.73:32965] AH01382: Request header read timeout
[Tue 11 Aug 11:55:15.063714 2015] [ssl:info] [pid 18257:tid 139653184771840] (70007)The timeout specified has expired: [client 203.127.23.73:32965] AH01991: SSL input filter read failed.
[Tue 11 Aug 11:55:15.063794 2015] [ssl:debug] [pid 18257:tid 139653184771840] ssl_engine_io.c(1003): [client 203.127.23.73:32965] AH02001: Connection closed to child 65 with standard shutdown (server sso.singtel.com:443)
[Tue 11 Aug 11:55:16.255576 2015] [weblogic:debug] [pid 18257:tid 139653184771840] ap_proxy.cpp(776): BEFORE acquire_lock
[Tue 11 Aug 11:55:16.255620 2015] [weblogic:debug] [pid 18257:tid 139653184771840] ap_proxy.cpp(786): AFTER acquire_lock
[Tue 11 Aug 11:55:16.255627 2015] [weblogic:debug] [pid 18257:tid 139653184771840] ap_proxy.cpp(789): List size is 1
[Tue 11 Aug 11:55:16.255631 2015] [weblogic:debug] [pid 18257:tid 139653184771840] ap_proxy.cpp(796): Cleaning up the list node '10.44.46.185:17005,10.44.46.107:17005'list Length '2''
[Tue 11 Aug 11:55:16.255637 2015] [weblogic:debug] [pid 18257:tid 139653184771840] ap_proxy.cpp(816): stale connections: KA = 20, delta = 801'
[Tue 11 Aug 11:55:16.255641 2015] [weblogic:debug] [pid 18257:tid 139653184771840] ap_proxy.cpp(826): Cleaning up stale connections at host '10.44.46.185/17005/0''
[Tue 11 Aug 11:55:16.255663 2015] [weblogic:debug] [pid 18257:tid 139653184771840] ap_proxy.cpp(816): stale connections: KA = 20, delta = 6'
[Tue 11 Aug 11:55:16.264082 2015] [ssl:info] [pid 18260:tid 139653174281984] [client 203.127.23.73:32966] AH01964: Connection to child 130 established (server sso.singtel.com:443)
[Tue 11 Aug 11:55:16.264381 2015] [socache_shmcb:debug] [pid 18260:tid 139653174281984] mod_socache_shmcb.c(527): AH00835: socache_shmcb_retrieve (0xe6 -> subcache 6)
[Tue 11 Aug 11:55:16.264410 2015] [socache_shmcb:debug] [pid 18260:tid 139653174281984] mod_socache_shmcb.c(850): AH00849: match at idx=0, data=0
[Tue 11 Aug 11:55:16.264421 2015] [socache_shmcb:debug] [pid 18260:tid 139653174281984] mod_socache_shmcb.c(537): AH00836: leaving socache_shmcb_retrieve successfully
[Tue 11 Aug 11:55:16.264475 2015] [ssl:debug] [pid 18260:tid 139653174281984] ssl_engine_kernel.c(1908): [client 203.127.23.73:32966] AH02043: SSL virtual host for servername sso.singtel.com found
[Tue 11 Aug 11:55:16.268409 2015] [ssl:debug] [pid 18260:tid 139653174281984] ssl_engine_kernel.c(1841): [client 203.127.23.73:32966] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES256-SHA (256/256 bits)
[Tue 11 Aug 11:55:16.272145 2015] [ssl:debug] [pid 18260:tid 139653174281984] ssl_engine_kernel.c(243): [client 203.127.23.73:32966] AH02034: Initial (No.1) HTTPS request received for child 130 (server sso.singtel.com:443), referer: https://sso.singtel.com/issoselfservicebrt/signIn.action?portalTy=4&success_callback_url=https://rewards.singtel.com:8443/rewards/my-account/account-summary.aspx
[Tue 11 Aug 11:55:16.295162 2015] [ssl:debug] [pid 18260:tid 139653174281984] ssl_engine_kernel.c(243): [client 203.127.23.73:32966] AH02034: Subsequent (No.2) HTTPS request received for child 130 (server sso.singtel.com:443), referer: https://sso.singtel.com/issoselfservicebrt/signIn.action?portalTy=4&success_callback_url=https://rewards.singtel.com:8443/rewards/my-account/account-summary.aspx
 
[Tue 11 Aug 11:56:16.371945 2015] [authz_core:debug] [pid 18260:tid 139653174281984] mod_authz_core.c(802): [client 203.127.23.73:32966] AH01626: authorization result of Require all granted:
granted, referer: https://sso.singtel.com/issoselfservicebrt/signIn.action?portalTy=4&success_callback_url=https://rewards.singtel.com:8443/rewards/my-account/account-summary.aspx
 
[Tue 11 Aug 11:56:16.371998 2015] [authz_core:debug] [pid 18260:tid 139653174281984] mod_authz_core.c(802): [client 203.127.23.73:32966] AH01626: authorization result of <RequireAny>: granted,
referer: https://sso.singtel.com/issoselfservicebrt/signIn.action?portalTy=4&success_callback_url=https://rewards.singtel.com:8443/rewards/my-account/account-summary.aspx
[Tue 11 Aug 11:56:16.372077 2015] [weblogic:debug] [pid 18260:tid 139653174281984] ApacheProxy.cpp(766): [client 203.127.23.73:32966] <1822514350302411> Matched ELSE clause, calling

Regards,
Neeraj

[James Blond]

Can you please post your ssl vhost?

[AntG]

Hi, Did this issue resolve? I recently upgraded my server 2 days back to apache 2.4.16 and started seeing similar errors in apache logs.