You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Neil Aggarwal <ne...@JAMMConsulting.com> on 2003/10/11 00:32:14 UTC
Performance problem?
Hello:
We have noticed that in our app, on occasion, a request takes an
inordinately long time to execute even though it is performing a
simple task.
I added some tracing to the org.apache.jasper.servlet.JspServletWrapper
class and get this output immediately before calling service
on the servlet created from my jsp file:
10/10/2003 8:52:08.635 AM [Thread-188] Calling service on
org.apache.jsp.index_jsp
My code is in the call to the service() method of the servlet after
checking
that Tomcat is not running a SingleThreadModel:
if (theServlet instanceof SingleThreadModel) {
// sync on the wrapper so that the freshness
// of the page is determined right before servicing
synchronized (this) {
theServlet.service(request, response);
}
} else {
com.slsideas.pagegen.servlets.BaseControllerServlet.addNote(request,
"Calling service on "+theServlet.getClass().getName() );
theServlet.service(request, response);
}
My next line of output from the same thread is in my jsp file at the
very top. It
gave me:
10/10/2003 8:53:49.193 AM [Thread-188] At top of index.jsp
So, you can see that it took over a minute and a half to get from the
invocation of the
service method on my jsp servlet to the actual execution of it.
This seems strange to me, since this is just a method invocation.
I don't believe this is caused by compilation of the jsp file since I
have development
set to false in tomcat's config file and this code is past that point in
the JspServlet
class.
I don't believe this is garbage collection related since I have the
verbose garbage
collection flags turned on and I see that the GC for 100 seconds before
and after
this event look like this:
6467.31: [Full GC 285948K->236784K(460072K), 1.7318340 secs]
6497.1: [GC 287631K->259103K(460072K), 0.0225250 secs]
[My output occurred here]
6497.84: [GC 287775K->259175K(460072K), 0.0198420 secs]
6529.71: [Full GC 382024K->259185K(460072K), 0.7856030 secs]
The garbage collector is not taking very long to run.
Does anyone have any insights to why this is taking so long?
Thanks,
Neil.
--
Neil Aggarwal, JAMM Consulting, (972)612-6056, www.JAMMConsulting.com
FREE! Valuable info on how your business can reduce operating costs by
17% or more in 6 months or less! => http://newsletter.JAMMConsulting.com
---------------------------------------------------------------------
To unsubscribe, e-mail: tomcat-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tomcat-user-help@jakarta.apache.org
Re: Performance problem?
Posted by Oreste Luci <or...@axer.cl>.
Neil Aggarwal wrote:
>Oreste:
>
>I have been profiling the garbase collector in our app
>and it does not seem to be taking a long time to run.
>
>Do you think that could still be the problem?
>
>Thanks,
> Neil
>
>
I think you should try changing the GC and give it a try, may be it will
solve your problem. The thing is that some GC stop the world while they
do the cleaning and for some applications this can be very bad.
Oreste
---------------------------------------------------------------------
To unsubscribe, e-mail: tomcat-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tomcat-user-help@jakarta.apache.org
RE: Performance problem?
Posted by Neil Aggarwal <ne...@JAMMConsulting.com>.
Oreste:
I have been profiling the garbase collector in our app
and it does not seem to be taking a long time to run.
Do you think that could still be the problem?
Thanks,
Neil
--
Neil Aggarwal, JAMM Consulting, (972)612-6056, www.JAMMConsulting.com
FREE! Valuable info on how your business can reduce operating costs by
17% or more in 6 months or less! => http://newsletter.JAMMConsulting.com
> -----Original Message-----
> From: Oreste Luci [mailto:oreste.luci@axer.cl]
> Sent: Monday, October 13, 2003 1:02 PM
> To: Tomcat Users List
> Subject: Re: Performance problem?
>
>
> Neil Aggarwal wrote:
>
> >Hello:
> >
> >We have noticed that in our app, on occasion, a request takes an
> >inordinately long time to execute even though it is performing a
> >simple task.
> >
> >I added some tracing to the
> org.apache.jasper.servlet.JspServletWrapper
> >class and get this output immediately before calling service
> >on the servlet created from my jsp file:
> >
> >10/10/2003 8:52:08.635 AM [Thread-188] Calling service on
> >org.apache.jsp.index_jsp
> >
> >
> I had a very similar problem, and it was the GC. I'm using
> JRockit, and
> changed from -Xgc:parallel to -Xgc:gencon and that fixed it.
>
> Oreste
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: tomcat-user-unsubscribe@jakarta.apache.org
> For additional commands, e-mail: tomcat-user-help@jakarta.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: tomcat-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tomcat-user-help@jakarta.apache.org
Re: Performance problem?
Posted by Oreste Luci <or...@axer.cl>.
Neil Aggarwal wrote:
>Hello:
>
>We have noticed that in our app, on occasion, a request takes an
>inordinately long time to execute even though it is performing a
>simple task.
>
>I added some tracing to the org.apache.jasper.servlet.JspServletWrapper
>class and get this output immediately before calling service
>on the servlet created from my jsp file:
>
>10/10/2003 8:52:08.635 AM [Thread-188] Calling service on
>org.apache.jsp.index_jsp
>
>
I had a very similar problem, and it was the GC. I'm using JRockit, and
changed from -Xgc:parallel to -Xgc:gencon and that fixed it.
Oreste
---------------------------------------------------------------------
To unsubscribe, e-mail: tomcat-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tomcat-user-help@jakarta.apache.org
RE: Performance problem?
Posted by Neil Aggarwal <ne...@JAMMConsulting.com>.
Hello All:
While profiling my app, I also see another baffling output from my code:
10/10/2003 7:00:56.391 PM [Thread-96] Before synchronized block
10/10/2003 7:00:56.391 PM [Thread-96] Getting server context
10/10/2003 7:04:07.762 PM [Thread-96] Setting server context attribute
This corresponds to this code in my class:
ServerContext serverContext = null;
addNote(req,"Before synchronized block" );
synchronized (serverContextManager) {
// Record the time when we entered the synchronized block
Calendar synchronizedStart = new GregorianCalendar();
addNote(req,"Getting server context" );
serverContext =
(ServerContext)serverContextManager.get(httpHost);
//
// If doing a reset.
//
if (req.getParameter(_RESET_PARAM) != null && serverContext !=
null) {
addNote(req,"Destrying server context" );
serverContext.destroy();
serverContext = null;
}
//
// If serverContext null then create it.
//
if (serverContext == null) {
addNote(req,"Creating server context" );
System.out.println("Config: " + systemRoot + "/config/" +
httpHost);
serverContext = new ServerContext(this,
systemRoot +
"/config/"+httpHost,req);
serverContextManager.put(httpHost, serverContext);
}
addNote(req,"Setting server context attribute" );
req.setAttribute(SERVER_CONTEXT, serverContext);
As you can see, the delay occurred while getting the server context from
serverContextManager (which is a java.util.Hashtable) and doing some
simple
if statement checks (which never get executed).
Looking at the GC logs to ensure that this is not a GC delay, I see the
next GC statement after this output is:
9422.37: [GC 178147K->160010K(298744K), 0.0233400 secs]
Grepping the log for GC statements, I get these around this event:
9102.61: [GC 295917K->278423K(298744K), 0.0055240 secs]
9102.67: [GC 296443K->278451K(298744K), 0.0055600 secs]
9102.74: [GC 296984K->278479K(298744K), 0.0051700 secs]
9102.81: [GC 296607K->278507K(298744K), 0.0053320 secs]
9102.88: [GC 296961K->278535K(298744K), 0.0052320 secs]
9102.94: [GC 296304K->278559K(298744K), 0.0052560 secs]
9103.01: [GC 296738K->278585K(298744K), 0.0054490 secs]
9103.07: [GC 295993K->278609K(298744K), 0.0052450 secs]
9103.13: [GC 296458K->278713K(298744K), 0.0055630 secs]
9103.2: [GC 296852K->278737K(298744K), 0.0056190 secs]
9103.27: [GC 297221K->278761K(298744K), 0.0054230 secs]
9103.33: [GC 296333K->278784K(298744K), 0.0054540 secs]
9103.39: [GC 296679K->278805K(298744K), 0.0053570 secs]
9103.46: [GC 297002K->278828K(298744K), 0.0054750 secs]
9110.38: [GC 297375K->280719K(300056K), 0.0164410 secs]
9110.4: [Full GC 280719K->151025K(300056K), 0.2755410 secs]
9115.45: [GC 169584K->151883K(298744K), 0.0064940 secs]
9116.49: [GC 170439K->152421K(298744K), 0.0068510 secs]
9117.41: [GC 170978K->152646K(298744K), 0.0075410 secs]
9123.96: [GC 171202K->152704K(298744K), 0.0071470 secs]
9126: [GC 171264K->152757K(298744K), 0.0063730 secs]
9130.04: [GC 171302K->153194K(298744K), 0.0068320 secs]
9133.61: [GC 171726K->153551K(298744K), 0.0077230 secs]
9136.89: [GC 172096K->153762K(298744K), 0.0074560 secs]
9140.67: [GC 172322K->154029K(298744K), 0.0077430 secs]
9140.77: [GC 172722K->154313K(298744K), 0.0067860 secs]
9147.56: [GC 173003K->154481K(298744K), 0.0125330 secs]
9158.27: [GC 173011K->154929K(298744K), 0.0127420 secs]
9158.75: [GC 173468K->155000K(298744K), 0.0076740 secs]
9167.62: [GC 173551K->155512K(298744K), 0.0081280 secs]
9169.75: [Full GC 170487K->155074K(298744K), 0.2686600 secs]
9170.11: [GC 173634K->155720K(298744K), 0.0056310 secs]
9174.28: [GC 174280K->156023K(298744K), 0.0054010 secs]
9181.61: [GC 174577K->156404K(298744K), 0.0073980 secs]
9186.08: [GC 174964K->156546K(298744K), 0.0078340 secs]
9187.57: [GC 175104K->156833K(298744K), 0.0072990 secs]
9193.42: [GC 175387K->157125K(298744K), 0.0076240 secs]
9212.22: [GC 175685K->157160K(298744K), 0.0077510 secs]
9213.55: [Full GC 158189K->154977K(298744K), 0.2687580 secs]
9218.27: [GC 173593K->155527K(298744K), 0.0048250 secs]
9224.63: [GC 174039K->156180K(298744K), 0.0069800 secs]
9226.92: [GC 174717K->156202K(298744K), 0.0066730 secs]
9284.39: [GC 174762K->156688K(298744K), 0.0113370 secs]
9413.07: [GC 175248K->159587K(298744K), 0.0239160 secs]
9422.37: [GC 178147K->160010K(298744K), 0.0233400 secs]
9422.52: [GC 178570K->160892K(298744K), 0.0201960 secs]
9422.66: [GC 179452K->161365K(298744K), 0.0130190 secs]
9422.79: [GC 179925K->162077K(298744K), 0.0210060 secs]
9422.96: [GC 180637K->163041K(298744K), 0.0185410 secs]
9423.11: [GC 181594K->163586K(298744K), 0.0169170 secs]
9423.22: [GC 182146K->164363K(298744K), 0.0081180 secs]
9423.3: [GC 183055K->165082K(298744K), 0.0153120 secs]
9423.37: [GC 183681K->165560K(298744K), 0.0078910 secs]
9428.96: [GC 184120K->165820K(298744K), 0.0067790 secs]
9429.67: [GC 184380K->165819K(298744K), 0.0047730 secs]
9430.38: [GC 184379K->165819K(298744K), 0.0046940 secs]
9431.09: [GC 184378K->165819K(298744K), 0.0049550 secs]
9431.86: [GC 184379K->165820K(298744K), 0.0050470 secs]
9432.87: [GC 184380K->165819K(298744K), 0.0048000 secs]
9433.58: [GC 184379K->165820K(298744K), 0.0048570 secs]
9434.3: [GC 184380K->165820K(298744K), 0.0049900 secs]
9441.61: [GC 184380K->165820K(298744K), 0.0052050 secs]
9443.14: [GC 184380K->165823K(298744K), 0.0059740 secs]
As you can see, there are no long GC events around that time, so I do
not
believe the delay is GC related.
We are running:
Redhat 9
j2sdk1.4.1_02 from Sun
Tomcat 4.1.24
Any ideas why our app would just suddenly slow down?
Thanks,
Neil
--
Neil Aggarwal, JAMM Consulting, (972)612-6056, www.JAMMConsulting.com
FREE! Valuable info on how your business can reduce operating costs by
17% or more in 6 months or less! => http://newsletter.JAMMConsulting.com
---------------------------------------------------------------------
To unsubscribe, e-mail: tomcat-user-unsubscribe@jakarta.apache.org
For additional commands, e-mail: tomcat-user-help@jakarta.apache.org