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: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
