IdP 2.2.1 (with ECP) and long transactions

[Derek Yuen]

Hi,
   (Environment: Two [identical] Shibboleth IdP 2.2.1 with ECP on RHEL 5 / Apache 2.2.3 / Tomcat 6 / Java JDK 1.6.0_24 / local MySQL 5 persistentId store).


For unknown reasons our production IdPs have transactions that take a long time to complete and resulting in most cases the IdP becoming unresponsive.
We see this in the apache request logs where we also log transaction times, 
we observe (at problem periods) there are transactions taking > 30 seconds to complete.

The majority of these long transactions appear to be in ECP (per  "POST /idp/profile/SAML2/SOAP/ECP HTTP/1.1" from the apache request log).
There are also proportionately as many long transactions for non-ECP transactions. 
  (Proportionately because there are significantly more ECP transactions than non-ECP transactions thanks to the Live at edu SP!)

Around the time of the problems,
we also see in the catalina logs:
> SEVERE: All threads (250) are currently busy, waiting. Increase maxThreads (250) or check the servlet status
> Jul 12, 2012 3:31:14 AM org.apache.jk.common.ChannelSocket processConnection
> WARNING: processCallbacks status 2
> Jul 11, 2012 3:14:02 PM org.apache.jk.core.MsgContext action
> WARNING: Unable to send headers
> java.net.SocketException: Broken pipe 
(If you're interested, the stack trace is at the bottom of the message).

At the same time, In the apache error logs, we see:
> [error] (70007)The timeout specified has expired: ajp_ilink_receive() can't receive header

So I've raised the maxThreads in server.xml for Tomcat (from 200 to 500) and slightly increased the MaxChildren (from 255 to 350) in httpd.
This has mostly eliminated the java.net.SocketException: Broken pipe errors but did not fix long transaction times.

The apache server-status page indicates during the problem periods that most, if not all of the apache processes stuck in "W" or "Sending Reply" state.

> Srv	PID	Acc	M	CPU	SS	Req	Conn	Child	Slot	Client	VHost	Request
> 0-3	24903	0/40/18678	W	0.50	3	0	0.0	0.16	74.17	1.2.3.4	hostname	POST /idp/profile/SAML2/SOAP/ECP HTTP/1.1

We thought it might be the attribute stores but there's no evidence from the idp-process log files of any ldap or MySQL latency.
  (We're fortunate to have debug logging on our production IdPs!)

I've tried to strace the httpd processes while grasping for straws but strace can't see what's happening within the java process.

Recently, a major service has changed to use Shibboleth for authentication and have begun forcing students to migrate to our Live at edu service.
I presume that the increase in authentication request has pushed the IdPs beyond what they're currently configured for. 
Admittedly we haven't had many problems and so we haven't spent any time studying how to improve performance. 

We're following all of the recommendations from:
https://wiki.shibboleth.net/confluence/display/SHIB2/IdPApacheTomcatPrepare
https://wiki.shibboleth.net/confluence/display/SHIB2/IdPProdJVMTuning


My guess is that there might be a timeout parameter somewhere in the chain (perhaps in Tomcat?) that isn't set right.
  (I'm hesitant to make major changes to Tomcat as I don't really have a firm understanding of the application.)
Or that there's a delay in response somewhere in the chain which is holding up the Apache-Tomcat connection/process/thread.
If this is the case, how might I go about tracing the chain to see where the problem is?
Or maybe i'm completely wrong?


Has anyone experienced this and/or have any advice to offer?
If your environment is similar to ours, would you be willing to share notes on Apache/Tomcat/IdP configuration for scaling up as more services adopt Shibboleth for authentication? 


I sincerely appreciate your time and help in this matter.

I'd be happy to summarize as we make progress.



Thanks in advance,
Derek
--
Derek Yuen
Technical Project Manager - Live at edu Implementation
University of Toronto



Stack trace from catalina.log:
java.net.SocketException: Broken pipe
	at java.net.SocketOutputStream.socketWrite0(Native Method)
	at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
	at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
	at org.apache.jk.common.ChannelSocket.send(ChannelSocket.java:539)
	at org.apache.jk.common.JkInputStream.appendHead(JkInputStream.java:326)
	at org.apache.jk.core.MsgContext.action(MsgContext.java:266)
	at org.apache.coyote.Response.action(Response.java:183)
	at org.apache.coyote.Response.sendHeaders(Response.java:379)
	at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:305)
	at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:288)
	at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:98)
	at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:278)
	at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:122)
	at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:212)
	at edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler.completeAuthenticationRequest(ECPProfileHandler.java:265)
	at edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler.processRequest(ECPProfileHandler.java:193)
	at edu.internet2.middleware.shibboleth.idp.ext.ecp.profile.ECPProfileHandler.processRequest(ECPProfileHandler.java:110)
	at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:83)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:49)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:77)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:51)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:298)
	at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190)
	at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:291)
	at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:776)
	at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:705)
	at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:898)
	at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690)
	at java.lang.Thread.run(Thread.java:662)