Is >1 second service time normal for /idp/profile/SAML2/POST/SSO and /idp/profile/SAML2/Redirect/SSO ?

[Cameron Kerr]

Hi all,

We've been running our IdP successfully now for at least a year, and are beginning to expand the number of services that use it, with our first big application recently launched, and the client is really happy with how that has gone. So first off, thank you so very much for such a wonderful product to work with, it's been a real pleasure. The implementation and documentation are both excellent examples of how to make a product worth supporting.

Recently I've been developing some further service reporting graphs (based around rrdtool and custom Python scripts). One of the enhancements I have hade was to change the Apache access logging to include the service time. My logging format is quite different, and illustrated below:


(Apache 2.2 on RHEL 6)

# Unfortunately, the name of the module that generated the request is unavailable in RHEL5's Apache "[handler %R]\t"
# Note also that httpd will escape " to \", plus various others... (see the docs)
#
LogFormat "[time %{%FT%T%z}t]\t[addr %h]\t[xff %{X-Forwarded-For}i]\t[user %u]\t[sso %{OAM_REMOTE_USER}i]\t[pid %P]\t[vhost %{Host}i]\t[port %p]\t[prot %H]\t[meth %m]\t[path %U]\t[qs %q]\t[ref %{Referer}i]\t[agent %{User-agent}i]\t[handler %R]\t[resp %>s]\t[redir %{Location}o]\t[serv %D us]\t[bin %I]\t[bout %O]\t[cnx %X]\t" ott

# Let's not log (specifically archive) the noise...
SetEnvIf Remote_Addr ^(load-balancer-health-checker-ip)$ noise
SetEnvIf Request_URI ^/statistics/ noise
SetEnvIf Request_URI ^/idp/profile/Status$ noise
SetEnvIf Request_URI ^/favicon.ico$ noise

CustomLog logs/access_log ott env=!noise
CustomLog logs/access_noise_log common env=noise

# and in the SSL configuration
ErrorLog logs/ssl_error_log
CustomLog logs/ssl_access_log ott env=!noise
CustomLog logs/ssl_access_noise_log common env=noise

'ott' refers to 'over-the-top', meaning something that does more than required... I find it pretty useful though, in this case because it tells me the service time (%D), as documented at http://httpd.apache.org/docs/2.2/mod/mod_log_config.html#formats

%D         The time taken to serve the request, in microseconds.

What I have found potentially concerning is that the service time for some requests seem inordinately longer than I would have expected, though I don't know what is normal for these particular requests, so I'd like to know what others have found.

Taking the logs and processing them lightly, I threw them into a PivotChart to explore possible correlations, and found some things of potential concern. The graph is shown below. Note that the SSO handlers (/idp/profile/SAML2/POST/SSO and /idp/profile/SAML2/Redirect/SSO - but not when a ?SAMLRequest=... is present) have a high standard deviation of response time

I'm not so concerned about the minimum times (well, not for this discussion), as they are likely due to our LDAP infrastructure; and the time for this corresponds well to the time between connection set up and tear-down when communicating with said LDAP server. We use LDAP authentication for UserPassword authentication, and LDAP also back-ends our attribute resolution. We don't operate this IdP in a clustered configuration, and we use uApprove.

What is more of concern are those entries with a high average (and a high standard deviation), such as the GET of /idp/profile/SAML2/Redirect/SSO with no query string, that produces a 200 response.

What would be happening when the IdP is evaluating such a request? My first thought was that entropy might be getting starved, but having looked at that for quite some time, it seems that it is quite buoyant and consistently between 2000 and 3000 bits, so I don't think its blocking on entropy.

I wonder if its MySQL related (used for uApprove as well as storing shared tokens). And there is a bit of an outlier with /idp/uApprove/AttributeRelease. Might enable the slow query log...

Look forward to hearing about other's experiences.

Thanks for reading,
Cameron

[cid:image002.png at 01CF1DB9.BA275990]

--
Cameron Kerr <cameron.kerr at otago.ac.nz>
Systems Engineer. Systems Services Team; Infrastructure & Applications; ITS; University of Otago
Ph. +64 (03) 479 8191. Cell: +6421479527


-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20140129/fd2c8064/attachment-0001.html 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image002.png
Type: image/png
Size: 13458 bytes
Desc: image002.png
Url : http://shibboleth.net/pipermail/users/attachments/20140129/fd2c8064/attachment-0001.png