hc-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Oleg Kalnichevski <ol...@apache.org>
Subject Re: High server load due to SessionOutputBufferImpl.flush()
Date Fri, 19 Sep 2014 11:51:41 GMT
On Fri, 2014-09-19 at 11:31 +0200, Tobias Bieniek wrote:
> Hi Oleg,
> we've finally managed to freeze the log file after the spinning was
> first detected and this is the output of the spinning session:
> https://gist.github.com/Turbo87/db7365bac349c7e56690
> Tobias

Thanks Good Lord it happens over a plain connection as TLS/SSL
encryption layer makes everything more complex by an order of magnitude.

There appears to be multiple coinciding issues that lead to the spin.

Firstly, something must have gone sideways while reading incoming data
on a persistent connection.
consumeInput : http-incoming-33955: Consume input
submitResponse : http-incoming-33955: HTTP/1.1 500 Internal Server Error
The handler attempts to send back a 500 status back to the client. Given
that mo data appears to have been received in the first place, this
might actually be be a bug.

The problem is I cannot see the exception logged, which is likely a
problem with your application code. It would help a lot to find out what
exactly caused the 500 status.

Secondly, the protocol handler writes out the message to the session
buffer but leaves the underlying channel open until the buffer is fully

produceOutput : http-incoming-33955: Produce output
close : http-incoming-33955: Close connection

For some reason nothing gets ever flushed and no I/O exception is
thrown. The session spins. I do not understand two things here: (1) why
connection #close keeps on getting called? It does not seem to match the
4.3.2 source code. (2) why there is no I/O exception if the underlying
channel can no longer accept output?

I'll need to digest all this. In the meantime can I ask you the
following? Is there a chance you could find out what kind of exception
(with the full stack trace) caused the initial 500 status and triggered
the whole sequence of events. Could you please confirm that you are
_really_ using version 4.3.2? Could you also consider upgrading to the
latest snapshot of the 4.3.x branch?   


And of course, a reproducer that I could run locally would be awesome.


> 2014-09-16 13:36 GMT+02:00 Oleg Kalnichevski <olegk@apache.org>:
> > On Tue, 2014-09-16 at 13:08 +0200, Tobias Bieniek wrote:
> >> > If you do not want me to make wild guesses, please make available a
> >> > _complete_ context / header log of the session.
> >>
> >> I'll see what I can do. The problem is that with our production
> >> traffic on the server the log files are rotating very fast and it is
> >> hard to catch a log of one entire request session, but without the
> >> production traffic the problem doesn't seem to be reproducible.
> >>
> >> Since yesterday more of the I/O workers have started spinning again
> >> and are cluttering the log files now.
> >>
> >> I know it is wild guessing, but could the problem be related to
> >> streaming file downloads over SSL that are cancelled on the client
> >> side? It appears as if the SSL session might be staying in the CLOSING
> >> state forever with some data in the buffer but unable to flush it out.
> >>
> >> Tobias
> >>
> >
> > Tobias
> >
> > This is quite likely to be related to abnormal SSL connection
> > termination causing the I/O session to spin while trying to complete SSL
> > session handshake. But I need to see the session log to be 100% sure.
> >
> > Oleg
> >
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: dev-unsubscribe@hc.apache.org
> > For additional commands, e-mail: dev-help@hc.apache.org
> >
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@hc.apache.org
> For additional commands, e-mail: dev-help@hc.apache.org

To unsubscribe, e-mail: dev-unsubscribe@hc.apache.org
For additional commands, e-mail: dev-help@hc.apache.org

View raw message