You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by Kevin Seguin <se...@motive.com> on 2002/02/18 03:51:13 UTC

RE: DO NOT REPLY [Bug 5735] - HTTP connector running out of processors under heavy load

> 
> ------- Additional Comments From glenn@apache.org  2002-02-18 
> 00:30 -------
> Based on the apache logs it looks like when the 
> Ajp13Processor's become
> unavailable for reuse they have successfully handled a request.  I can
> tell this due to entries existing in the apache access_log 
> for image files,
> etc. related to a request forwarded to Tomcat via mod_jk 
> being requested.
> 
> So the problem which is causing the Ajp13Processor's to hang 
> must be in
> Ajp13Proccessor code after a request has been handled and 
> before it calls
> connector.recycle(this) to make itself available to process 
> another Ajp request.
> 

that would be somewhere in Ajp13Processor.process()...

if you can reproduce this consistently, can you turn up the logging for the ajp13 connector, then send me (seguin at apache.org) the all of the pertinent log files and the captured stdout/stderr - unfortunately, some of the ajp stuff "logs" to stdout :( - from a run where this problem occurs?

thanks.

--
To unsubscribe, e-mail:   <ma...@jakarta.apache.org>
For additional commands, e-mail: <ma...@jakarta.apache.org>


Re: DO NOT REPLY [Bug 5735] - HTTP connector running out of processors under heavy load

Posted by Glenn Nielsen <gl...@voyager.apg.more.net>.
I have a failure.  There is about 90MB worth of debug data.

I can make the logs available for download for anyone who is
interested in debugging this. Let me know and I will send you the URL.

It is hard to correlate the Ajp13 debug output in catalina.out
because there are no datestamps. 

One thing I noticed right away is that there is a gap of 2 minutes
between log entries in the catalina_log when the problem starts.

Here is the snippet from the logs, notice the 2 minute 7 second gap
between logs entries below starting at 09:39:36.  And it is immediately 
after that gap where the Ajp13Connector starts creating new Ajp13Processors 
one after another until it runs out.

2002-02-18 09:39:34 Ajp13Processor[8009][6] finished handling request.
2002-02-18 09:39:34 Ajp13Processor[8009][17] invoking...
2002-02-18 09:39:34 Ajp13Processor[8009][16] done invoking, finishing request/response....
2002-02-18 09:39:34 Ajp13Processor[8009][16] finished handling request.
2002-02-18 09:39:34 Ajp13Processor[8009][17] done invoking, finishing request/response....
2002-02-18 09:39:34 Ajp13Processor[8009][17] finished handling request.
2002-02-18 09:39:34 Ajp13Processor[8009][22] finished handling request.
2002-02-18 09:39:34 Ajp13Processor[8009][13] done invoking, finishing request/response....
2002-02-18 09:39:34 Ajp13Processor[8009][13] finished handling request.
2002-02-18 09:39:34 Ajp13Processor[8009][13] invoking...
2002-02-18 09:39:34 Ajp13Processor[8009][15] done invoking, finishing request/response....
2002-02-18 09:39:34 Ajp13Processor[8009][15] finished handling request.
2002-02-18 09:39:34 Ajp13Processor[8009][9] invoking...
2002-02-18 09:39:34 Ajp13Processor[8009][21] invoking...
2002-02-18 09:39:35 Ajp13Processor[8009][11] invoking...
2002-02-18 09:39:35 Ajp13Processor[8009][11] done invoking, finishing request/response....
2002-02-18 09:39:35 Ajp13Processor[8009][11] finished handling request.
2002-02-18 09:39:35 Ajp13Processor[8009][6] process:  done
2002-02-18 09:39:35 Ajp13Processor[8009][26] invoking...
2002-02-18 09:39:35 Ajp13Processor[8009][10] done invoking, finishing request/response....
2002-02-18 09:39:35 Ajp13Processor[8009][10] finished handling request.
2002-02-18 09:39:35 Ajp13Processor[8009][22] invoking...
2002-02-18 09:39:35 Ajp13Processor[8009][13] done invoking, finishing request/response....
2002-02-18 09:39:35 Ajp13Processor[8009][13] finished handling request.
2002-02-18 09:39:35 Ajp13Processor[8009][2] invoking...
2002-02-18 09:39:35 Ajp13Processor[8009][23] done invoking, finishing request/response....
2002-02-18 09:39:35 Ajp13Processor[8009][23] finished handling request.
2002-02-18 09:39:35 Ajp13Processor[8009][5] invoking...
2002-02-18 09:39:35 Ajp13Processor[8009][16] invoking...
2002-02-18 09:39:35 Ajp13Processor[8009][13] invoking...
2002-02-18 09:39:36 Ajp13Processor[8009][15] invoking...
2002-02-18 09:39:36 Ajp13Processor[8009][19] invoking...
2002-02-18 09:39:36 Ajp13Processor[8009][15] done invoking, finishing request/response....
2002-02-18 09:39:36 Ajp13Processor[8009][15] finished handling request.
2002-02-18 09:41:43 Ajp13Processor[8009][17] process:  done
2002-02-18 09:41:43 Ajp13Processor[8009][8] invoking...
2002-02-18 09:41:44 Ajp13Processor[8009][23] invoking...
2002-02-18 09:41:43 Ajp13Processor[8009][6]  An incoming request is being assigned
2002-02-18 09:41:44 Ajp13Processor[8009][17]  An incoming request is being assigned
2002-02-18 09:41:44 Ajp13Processor[8009][15] invoking...
2002-02-18 09:41:44 Ajp13Processor[8009][13] done invoking, finishing request/response....
2002-02-18 09:41:44 Ajp13Processor[8009][13] finished handling request.
2002-02-18 09:41:44 Ajp13Processor[8009][10] invoking...
2002-02-18 09:41:44 Ajp13Processor[8009][17]   The incoming request has been awaited
2002-02-18 09:41:44 Ajp13Processor[8009][11] invoking...
2002-02-18 09:41:44 Ajp13Processor[8009][12] invoking...
2002-02-18 09:41:44 Ajp13Processor[8009][6]   The incoming request has been awaited
2002-02-18 09:41:44 Ajp13Processor[8009][13] process:  done
2002-02-18 09:41:45 Ajp13Processor[8009][27] Starting background thread
2002-02-18 09:41:45 Ajp13Processor[8009][14] done invoking, finishing request/response....
2002-02-18 09:41:45 Ajp13Processor[8009][6] invoking...
2002-02-18 09:41:45 Ajp13Processor[8009][17] invoking...
2002-02-18 09:41:45 Ajp13Processor[8009][20] done invoking, finishing request/response....
2002-02-18 09:41:45 Ajp13Processor[8009][20] finished handling request.

Regards,

Glenn

Glenn Nielsen wrote:
> 
> I have setup a test environment to try and reproduce the problem.
> 
> It is using the same Tomcat server but a different Apache server.
> I have debug turned on in Tomcat for the AJP connector and debug
> turned on for mod_jk in Apache.
> 
> One problem I am encountering when trying to test with debug is
> that debug logging adds alot of overhead.
> 
> The load testing has generated enough request's to cause 26
> Ajp13Processors to be created at this point.  But the server
> load is a problem.  Load on the Tomcat server is 4.5 (Sun 250
> with 1 CPU) and the load on the Apache server is 1.8 (Sun Netra T1
> with 1 CPU).
> 
> Now it is just a matter of waiting and see if it fails 2-3 hours
> into the test.
> 
> Regards,
> 
> Glenn
> 
> Glenn Nielsen wrote:
> >
> > Kevin Seguin wrote:
> > >
> > > >
> > > > ------- Additional Comments From glenn@apache.org  2002-02-18
> > > > 00:30 -------
> > > > Based on the apache logs it looks like when the
> > > > Ajp13Processor's become
> > > > unavailable for reuse they have successfully handled a request.  I can
> > > > tell this due to entries existing in the apache access_log
> > > > for image files,
> > > > etc. related to a request forwarded to Tomcat via mod_jk
> > > > being requested.
> > > >
> > > > So the problem which is causing the Ajp13Processor's to hang
> > > > must be in
> > > > Ajp13Proccessor code after a request has been handled and
> > > > before it calls
> > > > connector.recycle(this) to make itself available to process
> > > > another Ajp request.
> > > >
> > >
> > > that would be somewhere in Ajp13Processor.process()...
> > >
> > > if you can reproduce this consistently, can you turn up the logging for the ajp13 connector, then send me (seguin at apache.org) the all of the pertinent log files and the captured stdout/stderr - unfortunately, some of the ajp stuff "logs" to stdout :( - from a run where this problem occurs?
> > >
> >
> > I ran across this AJP problem when trying to put a new site into production.
> > And it did happen consistently, about 2 - 2 1/2 hours after Tomcat was started.
> > But I didn't have time during the window for replacing the old site with the
> > new to do a run with debug on.  I will have to see if I can setup a test
> > environment that can duplicate the problem.
> >
> > I'll see what I can do.
> >
> > Glenn
> >
> > ----------------------------------------------------------------------
> > Glenn Nielsen             glenn@more.net | /* Spelin donut madder    |
> > MOREnet System Programming               |  * if iz ina coment.      |
> > Missouri Research and Education Network  |  */                       |
> > ----------------------------------------------------------------------
> >
> > --
> > To unsubscribe, e-mail:   <ma...@jakarta.apache.org>
> > For additional commands, e-mail: <ma...@jakarta.apache.org>
> 
> --
> ----------------------------------------------------------------------
> Glenn Nielsen             glenn@more.net | /* Spelin donut madder    |
> MOREnet System Programming               |  * if iz ina coment.      |
> Missouri Research and Education Network  |  */                       |
> ----------------------------------------------------------------------
> 
> --
> To unsubscribe, e-mail:   <ma...@jakarta.apache.org>
> For additional commands, e-mail: <ma...@jakarta.apache.org>

-- 
----------------------------------------------------------------------
Glenn Nielsen             glenn@more.net | /* Spelin donut madder    |
MOREnet System Programming               |  * if iz ina coment.      |
Missouri Research and Education Network  |  */                       |
----------------------------------------------------------------------

--
To unsubscribe, e-mail:   <ma...@jakarta.apache.org>
For additional commands, e-mail: <ma...@jakarta.apache.org>


Re: DO NOT REPLY [Bug 5735] - HTTP connector running out of processors under heavy load

Posted by Glenn Nielsen <gl...@voyager.apg.more.net>.
I have setup a test environment to try and reproduce the problem.

It is using the same Tomcat server but a different Apache server.
I have debug turned on in Tomcat for the AJP connector and debug
turned on for mod_jk in Apache.

One problem I am encountering when trying to test with debug is
that debug logging adds alot of overhead.

The load testing has generated enough request's to cause 26 
Ajp13Processors to be created at this point.  But the server
load is a problem.  Load on the Tomcat server is 4.5 (Sun 250
with 1 CPU) and the load on the Apache server is 1.8 (Sun Netra T1
with 1 CPU).

Now it is just a matter of waiting and see if it fails 2-3 hours
into the test.

Regards,

Glenn

Glenn Nielsen wrote:
> 
> Kevin Seguin wrote:
> >
> > >
> > > ------- Additional Comments From glenn@apache.org  2002-02-18
> > > 00:30 -------
> > > Based on the apache logs it looks like when the
> > > Ajp13Processor's become
> > > unavailable for reuse they have successfully handled a request.  I can
> > > tell this due to entries existing in the apache access_log
> > > for image files,
> > > etc. related to a request forwarded to Tomcat via mod_jk
> > > being requested.
> > >
> > > So the problem which is causing the Ajp13Processor's to hang
> > > must be in
> > > Ajp13Proccessor code after a request has been handled and
> > > before it calls
> > > connector.recycle(this) to make itself available to process
> > > another Ajp request.
> > >
> >
> > that would be somewhere in Ajp13Processor.process()...
> >
> > if you can reproduce this consistently, can you turn up the logging for the ajp13 connector, then send me (seguin at apache.org) the all of the pertinent log files and the captured stdout/stderr - unfortunately, some of the ajp stuff "logs" to stdout :( - from a run where this problem occurs?
> >
> 
> I ran across this AJP problem when trying to put a new site into production.
> And it did happen consistently, about 2 - 2 1/2 hours after Tomcat was started.
> But I didn't have time during the window for replacing the old site with the
> new to do a run with debug on.  I will have to see if I can setup a test
> environment that can duplicate the problem.
> 
> I'll see what I can do.
> 
> Glenn
> 
> ----------------------------------------------------------------------
> Glenn Nielsen             glenn@more.net | /* Spelin donut madder    |
> MOREnet System Programming               |  * if iz ina coment.      |
> Missouri Research and Education Network  |  */                       |
> ----------------------------------------------------------------------
> 
> --
> To unsubscribe, e-mail:   <ma...@jakarta.apache.org>
> For additional commands, e-mail: <ma...@jakarta.apache.org>

-- 
----------------------------------------------------------------------
Glenn Nielsen             glenn@more.net | /* Spelin donut madder    |
MOREnet System Programming               |  * if iz ina coment.      |
Missouri Research and Education Network  |  */                       |
----------------------------------------------------------------------

--
To unsubscribe, e-mail:   <ma...@jakarta.apache.org>
For additional commands, e-mail: <ma...@jakarta.apache.org>


Re: DO NOT REPLY [Bug 5735] - HTTP connector running out of processors under heavy load

Posted by Glenn Nielsen <gl...@voyager.apg.more.net>.
Kevin Seguin wrote:
> 
> >
> > ------- Additional Comments From glenn@apache.org  2002-02-18
> > 00:30 -------
> > Based on the apache logs it looks like when the
> > Ajp13Processor's become
> > unavailable for reuse they have successfully handled a request.  I can
> > tell this due to entries existing in the apache access_log
> > for image files,
> > etc. related to a request forwarded to Tomcat via mod_jk
> > being requested.
> >
> > So the problem which is causing the Ajp13Processor's to hang
> > must be in
> > Ajp13Proccessor code after a request has been handled and
> > before it calls
> > connector.recycle(this) to make itself available to process
> > another Ajp request.
> >
> 
> that would be somewhere in Ajp13Processor.process()...
> 
> if you can reproduce this consistently, can you turn up the logging for the ajp13 connector, then send me (seguin at apache.org) the all of the pertinent log files and the captured stdout/stderr - unfortunately, some of the ajp stuff "logs" to stdout :( - from a run where this problem occurs?
> 

I ran across this AJP problem when trying to put a new site into production.
And it did happen consistently, about 2 - 2 1/2 hours after Tomcat was started.
But I didn't have time during the window for replacing the old site with the
new to do a run with debug on.  I will have to see if I can setup a test
environment that can duplicate the problem.

I'll see what I can do.

Glenn

----------------------------------------------------------------------
Glenn Nielsen             glenn@more.net | /* Spelin donut madder    |
MOREnet System Programming               |  * if iz ina coment.      |
Missouri Research and Education Network  |  */                       |
----------------------------------------------------------------------

--
To unsubscribe, e-mail:   <ma...@jakarta.apache.org>
For additional commands, e-mail: <ma...@jakarta.apache.org>