subject:"Re\: very slow class loading on initial JSP\/servlet request after restart"


Caldarale, Charles R wrote:


The key lines have a 3+ second response time:

2498  15:24:35 stat64("/net/ims/jcms/Object.class", 0x7b6b9c20) = -1 ENOENT (No such 
file or directory) <3.020996>

Most of the calls return in much less than a millisecond, but there are a few 
ENOENT (not all) responses that hit this 3-second delay.  All of the slow ones 
are looking at the /net/ims/jcms directory; what is that?  Why is it in this 
webapp's classpath?  (It might be in the jar's META-INF entries.)


Wow, good eye, Chuck, and those add up to at least 35 seconds of the delay - 
the bulk of it.  I have absolutely no idea
why it's looking there.  I certainly didn't put /net/ims/jcms in the classpath, 
and the jar file that contains
net.ims.jcms just has a stub MANIFEST.MF entry, nothing else, in META-INF.  I 
don't have a META-INF directory under the
web app ROOT.  The only place classes are stored under /net/ims/jcms is within 
WEB-INF/lib/jcms.jar.  But this is
clearly where the bulk of the time is spent, and one can see how this could 
scale up really poorly, since Tomcat is
looking for random core classes like Object.class and Throwable.class under 
/net/ims/jcms.

For comparison, here is the strace output from a test JSP that imports all of 
the net.ims.jcms classes explicitly (no
wildcird import), and responds in three seconds:

http://ims.net/media/strace-test-explicit.txt

You can see the read/GET near the top and the write HTTP 200 response near the 
bottom.  There is only ONE attempt to
find a file under /net/ims/jcms, and that only takes .025 sec.

It looks like we've boiled the problem, at least in this test JSP case, down to 
the classloader wasting 3 seconds per
try on stat-ing core Java classes in an imaginary location, /net/ims/jcms, on 
the server's filesystem, which actually
corresponds to a path WITHIN a jar file that I wrote, and which doesn't contain 
any core Java classes.  This sure seems
like a bug to me, but why it is manifested only on this one server, and primarily 
when I use a <%@ page
import="net.ims.jcms.*" %> call, remains a mystery.  I can see how these 
3-second errant lookups can really bog down the
server when it starts up, though, when a ton of classes are being loaded for 
page requests on several virtual hosts.


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


André Warnier wrote:

What in this directory path is (are) a symlink(s) ?
/home/sites/ims/jcms/webapps/ROOT/WEB-INF/classes/org/apache/jsp/test6_jsp.class 


There are no symlinks in that path.


And how is this different from the other 2 systems that work fine ?


It differs in no known way, other than being different hardware.

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


NEW DISCOVERY - using a wildcard package import results in a much longer 
response delay!

I've taken Mark's suggestion that I import individual classes rather than importing all with a wildcard to see if a 
particular class is slowing down classloading.  It turns out that it's the WILDCARD itself that is causing most of the 
delay!


If I request the following "wildcard import" JSP:

<%@ page import="java.util.Date" %>
<%@ page import="net.ims.jcms.*" %> 


<%
java.util.Date endDate = new java.util.Date();
out.println(endDate.toString());
%>

it responds in 49 seconds, consistently, over several different tries (renaming the file each time to incur the delay). 
 That includes on-the-fly compilation.


If I request a JSP that imports EVERY class in net.ims.jcms explicitly (it's a 
lot of lines, so truncated below):

<%@ page import="java.util.Date" %>
<%@ page import="net.ims.jcms.AccessRole" %> 

<%@ page import="net.ims.jcms.AccessRoleException" %> 

<%@ page import="net.ims.jcms.AccessUser" %> 

<%@ page import="net.ims.jcms.AccessUserException" %> 


... a bunch more here ...
<%@ page import="net.ims.jcms.UtilityLink" %>
<%@ page import="net.ims.jcms.ValidationException" %>
<%
java.util.Date endDate = new java.util.Date();
out.println(endDate.toString());
%>

it responds in 3 seconds, consistently (with renaming), which isn't as fast as it should be, but it's way faster than 49 
seconds.


I have no idea why a wildcard package import differs from importing explicit classes (from the same JAR), so I don't 
know what this is telling us, but it sure seems to be significant!  I have not been able to get lsof to display any 
files related to these requests, I expect they open and close too quickly for me to catch it.


I have run strace during a request of a wildcard import JSP (test7.jsp) on a standalone Tomcat instance so that I don't 
have lines from other requests.  The request is made at 15:24:09, and the response came at 15:24:58.  I've included the 
strace lines from that time range here:


http://ims.net/media/strace-test-wildcard.txt

You can see the read call on the HTTP GET request on the sixth line.  The HTTP 200 response is in a write call near the 
bottom.  Presumably everything that happened during the 49 seconds is recorded here.  You can see that the .java file 
has been opened within a second,


2498  15:24:09 open("/usr/local/tomcat-2/work/Catalina/test.ims.net/_/org/apache/jsp/test7_jsp.java", 
O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 62 <0.65>


and the compiled class is opened at 15:24:58,

2498  15:24:58 open("/usr/local/tomcat-2/work/Catalina/test.ims.net/_/org/apache/jsp/test7_jsp.class", 
O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, 0666) = 62 <0.64>


I have no idea how to interpret all the wheel-spinning that goes on in between.

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

André Warnier wrote:
Sam, because there is quite a bit of traffic on this issue, and because
the exact description seems to change a bit over time (e.g.
compilation-only or not), could you remake a summary of what you are
sure of so far ?

1. Initial requests to ANY JSP page on a site, precompiled or not, or a compiled servlet, take an inordinate amount of
time to generate a response, often several minutes, as long as 20 minutes or so after the server is restarted.

2. After a response is finally generated from a given JSP, that JSP always
responds quickly to subsequent requests.

3. The four virtual hosts start serving pages at the same time, after a Tomcat restart, as long as 20 minutes after
Tomcat started up.

4. jstack showed that the delay during a small JSP request was during a call to java.io.File.exists(). It is still not
known what the particular file was.

5. strace reveals that thousands and thousands of stat64, access and lstat64 calls are made to JAR files and classes
during the initial "stall phase." I've posted a couple short examples from my test6.jar requests.

Without totally excluding it for instance, I would surmise that it is
unlikely to be a disk-related problem, because copying the complete
webapp somewhere else does not change the issue.

Yes, and I have done so several times.

About the File.exists() issue and what it is checking, isn't a tool like
"lsof" a possible way to find out ? It can show all I/O like resources
used by a given process, be they sockets or files.

I'm looking at lsof now. Haven't seen anything remarkable so far, but I'll
keep at it a bit.

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


Pieter Temmerman wrote:

Try this strace command:

strace -f -etrace=\!futex,gettimeofday,clock_gettime -p
PID_OF_TOMCAT_JAVA

where PID_OF_TOMCAT_JAVA is the PID of your Tomcat, duh! :)


Thanks! That certainly did the trick.  The first time I ran strace against the Tomcat process, it brought Tomcat to a 
halt.  I had to restart it.


After the restart, it took an absolute eternity for the sites to respond to requests, as usual.  One thing that I 
haven't mentioned, by the way, is that all four sites begin to respond at the SAME TIME.  There appears to be something 
going on server-wide that finally resolves.  (There are currently four Host entries in server.xml, each of which having 
several Context entries, by the way.  Three hosts are on the same IP address, one has its own.)


During the startup stall phase, I requested my simple test JSP page.  strace revealed, as it did for all the other pages 
being requested on the server, repeated calls to stat64 and lstat64 of the SAME class files.  Here are the lines from 
strace while test6.jsp (precompiled into test6_jsp.class) was stalled:


http://www.ims.net/media/strace-test6-stall.txt

After I shut off strace (being convinced that it was hindering the server from getting done with its post-startup 
shenanigans), and the rest of the sites were finally responding to requests, I fired up strace again and requested 
test6.jsp, and got this:


http://www.ims.net/media/strace-test6-ok.txt

along with a successful HTTP response.  So: stat64; access; lstat64; stat64; read; read; read.  The class probably was 
already loaded from the previous stalled request.


During the Tomcat stall phase there are thousands and thousands of stat64, access, lstat64 calls to the same class files 
(and directories above those files) across pages on all four sites.


My next step is to set up a new instance on another port so I (hopefully) stop beating on the production sites with 
these diagnostics, and then do Mark's suggestion to import, one by one, the classes in my Java package to see if there 
is a particular one that is causing the delay.  I've tried that to some extent in the past and felt that the delay just 
increased linearly as I added more classes, but I can do it more methodically.


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


Tim Funk wrote:

While I am late to this ... Is this an accurate summary?

- Slow re-load on a server
- Server is a production server
- Other servers are OK so it can only be reproduced on production server
- Initial looks at network seem to be no network activity
- There seems to be a hint at File.exists() causing an issue
- The wisdom of the crowds is pointing to disk issue


Yes, Tim, that's pretty accurate.

Would it be possible to copy the tomcat installation and webapp to 
another disk (or new directory) on the same machine and then run the 
copy on an alternate port? If it "fails" like it does on the lower port 
- you have a better sandbox for debugging. If not ... you have a new 
interesting data point in the debug process.


That's a good suggestion, I'll do so.  I've been a bit concerned about running a second Tomcat instance on this 
production server since I've been having so much trouble with it, but if a second instance is a problem, I'll just turn 
it off.  It's probably better to leave the production instance alone, actually.  I have changed JVM versions, Tomcat 
versions, etc. over the course of this issue, by the way.


Last oddball question - even though this is a Linux server, is there any 
virus scanning software running?


Nope.

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-25 Thread André Warnier


Mark Thomas wrote:

Sam Hokin wrote:

Mark Thomas wrote:

Sam Hokin wrote:

[...]



My thinking is if we can reduce the scope of the problem to importing a
single class, we can then separate out that class and reduce the code in
it bit by bit until we have the bare minimum that causes the problem.
Hopefully, there will be little enough code left that it will be obvious.

Which is basically what I suggested a few posts back, after trying to 
summarise the problem again.  My posts are not always about reindeers or 
chocolate.
Sam, because there is quite a bit of traffic on this issue, and because 
the exact description seems to change a bit over time (e.g. 
compilation-only or not), could you remake a summary of what you are 
sure of so far ?
Without totally excluding it for instance, I would surmise that it is 
unlikely to be a disk-related problem, because copying the complete 
webapp somewhere else does not change the issue.
About the File.exists() issue and what it is checking, isn't a tool like 
"lsof" a possible way to find out ? It can show all I/O like resources 
used by a given process, be they sockets or files.
lsof has more options than a human can easily digest, but I think it is 
a simple matter to just ask for the full list, for a given process-id.
You'll be surprised at how many I/O thinks a process uses, but maybe 
something in the list will catch your eye, since you among all of us 
knows best what it /should/ be using.


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-25 Thread Tim Funk


While I am late to this ... Is this an accurate summary?

- Slow re-load on a server
- Server is a production server
- Other servers are OK so it can only be reproduced on production server
- Initial looks at network seem to be no network activity
- There seems to be a hint at File.exists() causing an issue
- The wisdom of the crowds is pointing to disk issue

Would it be possible to copy the tomcat installation and webapp to 
another disk (or new directory) on the same machine and then run the 
copy on an alternate port? If it "fails" like it does on the lower port 
- you have a better sandbox for debugging. If not ... you have a new 
interesting data point in the debug process.


Last oddball question - even though this is a Linux server, is there any 
virus scanning software running?


-Tim

Mark Thomas wrote:

Sam Hokin wrote:

Mark Thomas wrote:

Sam Hokin wrote:

Thanks, Chris.  I ran e2fsck with the -c option, which runs badblocks,
when I tested it earlier.  And I just ran badblocks again - 0 bad blocks
found.  I wish I could fix this by simply as swapping out a bad disk
(notwithstanding Andre's desire for intellectual pursuits), but I really
think it's software, either in some service mucking up the JVM or the
JVM itself.  But it only manifests itself under Tomcat, and then only
when this particular package is imported.

Do you see the same issue if you pre-compile that JSP?

Surprisingly, yes.  So it's not only a compilation issue.


Ok. To summarise when you include net.ims.jcms.* in your imports the
page compiles quickly but takes ages to respond to the first request.

I wonder if this is related to loading a specific class in your library.
Can you use a test JSP try and isolate which class(es) are causing the
slow down?

My thinking is if we can reduce the scope of the problem to importing a
single class, we can then separate out that class and reduce the code in
it bit by bit until we have the bare minimum that causes the problem.
Hopefully, there will be little enough code left that it will be obvious.
 



-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-25 Thread Pieter Temmerman


> Thanks, Juha.  Actually Pieter suggested it a little while ago, and I've been 
> trying to get some information out of 
> strace.  The best I can do is to put strace in front of the java command 
> that's inside catalina.sh.  That's the command 
> that shows with ps -ef when Tomcat is running.  BUT, I get nothing out of 
> strace when I make page requests on a site, it 
> just shows output during Tomcat startup.  So, I've not figured out how to get 
> strace to say what the JVM is during the 
> delay.  

Try this strace command:

strace -f -etrace=\!futex,gettimeofday,clock_gettime -p
PID_OF_TOMCAT_JAVA

where PID_OF_TOMCAT_JAVA is the PID of your Tomcat, duh! :)



-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-25 Thread Mark Thomas

Sam Hokin wrote:
> Mark Thomas wrote:
>> Sam Hokin wrote:
>>> Thanks, Chris.  I ran e2fsck with the -c option, which runs badblocks,
>>> when I tested it earlier.  And I just ran badblocks again - 0 bad blocks
>>> found.  I wish I could fix this by simply as swapping out a bad disk
>>> (notwithstanding Andre's desire for intellectual pursuits), but I really
>>> think it's software, either in some service mucking up the JVM or the
>>> JVM itself.  But it only manifests itself under Tomcat, and then only
>>> when this particular package is imported.
>>
>> Do you see the same issue if you pre-compile that JSP?
> 
> Surprisingly, yes.  So it's not only a compilation issue.

Ok. To summarise when you include net.ims.jcms.* in your imports the
page compiles quickly but takes ages to respond to the first request.

I wonder if this is related to loading a specific class in your library.
Can you use a test JSP try and isolate which class(es) are causing the
slow down?

My thinking is if we can reduce the scope of the problem to importing a
single class, we can then separate out that class and reduce the code in
it bit by bit until we have the bare minimum that causes the problem.
Hopefully, there will be little enough code left that it will be obvious.

Mark

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-24 Thread Christopher Schultz

-BEGIN PGP SIGNED MESSAGE-
Hash: SHA1

Sam,

On 2/24/2009 1:54 PM, Sam Hokin wrote:
> Mark Thomas wrote:
>> Sam Hokin wrote:
>>> Thanks, Chris.  I ran e2fsck with the -c option, which runs badblocks,
>>> when I tested it earlier.  And I just ran badblocks again - 0 bad blocks
>>> found.  I wish I could fix this by simply as swapping out a bad disk
>>> (notwithstanding Andre's desire for intellectual pursuits), but I really
>>> think it's software, either in some service mucking up the JVM or the
>>> JVM itself.  But it only manifests itself under Tomcat, and then only
>>> when this particular package is imported.
>>
>> Do you see the same issue if you pre-compile that JSP?
> 
> Surprisingly, yes.  So it's not only a compilation issue.  After some
> individual tests, I compiled the JSPs from the four sites I have running
> on this server and restarted Tomcat, and the LONG delay before Tomcat
> begins serving page requests continues.

... and what is happening when you take a thread dump. Is it
File.exists() taking forever again? If that's the case, the class
loading is what's taking forever. I have no idea what could be causing
that other than a disk read error (or network latency, but you mentioned
you weren't using NFS or anything like that).

Someone mentioned running strace which sounds like a good idea to me.
You'll just have to sift through a ton of information to find what
you're looking for since the JVM performs a /lot/ of system calls during
its operation.

- -chris
-BEGIN PGP SIGNATURE-
Version: GnuPG v1.4.9 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iEYEARECAAYFAkmkbIoACgkQ9CaO5/Lv0PAHFQCeKMwKXF3xU655W54unmGGeJx7
66wAn3hwEPghxTzMWv3Be7W4NIfQSr2o
=53TD
-END PGP SIGNATURE-

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-24 Thread Sam Hokin


János Löbb wrote:


How about just using tcpdump during the long delay and see what the 
machine is doing network wise ?


I have, and network timeout was suggested earlier on this thread.  There is no TCP activity of particular interest 
during the delay.  I've hunted for, and not seen, anything to do with the network during the stall.  And IPv6 is turned 
off, by the way.  I can't rule out a network cause, but I've seen nothing with tcpdump or netstat associated with the 
delay to date.  And I can't muck with the network much since it's at a remote data center.  I can drive out there late 
at night to take it offline, for example, but I'd need a quick test plan for that to minimize the downtime.  (I have 
gone out there to test memory and disk, both tested fine.)


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-24 Thread János Löbb



On Feb 24, 2009, at 4:16 PM, Sam Hokin wrote:


Juha Laiho wrote:
One tool that I haven't yet seen suggested is 'strace', the Linux  
system
call tracer. This will show all the calls your application makes to  
the
operating system. As you say the application is mostly idle during  
the

delay, it is, in one way or another, waiting for some OS service to
complete. 'strace' should provide you with timestamped information on
what OS services were called, with which arguments, and how long did
it take for them to return with results. 'strace' will leave you with
a huge file (or a set of huge files, depending on the options you  
use),

and going through them will take some time - but you'll most likely
also find what causes the delay.


Thanks, Juha.  Actually Pieter suggested it a little while ago, and  
I've been trying to get some information out of strace.  The best I  
can do is to put strace in front of the java command that's inside  
catalina.sh.  That's the command that shows with ps -ef when Tomcat  
is running.  BUT, I get nothing out of strace when I make page  
requests on a site, it just shows output during Tomcat startup.  So,  
I've not figured out how to get strace to say what the JVM is during  
the delay.  jstack has led us to a stalled File.exists() in one  
case, but we don't know what file it's looking for.  And I'm not  
convinced that File.exists() is the only method that's stalling.


Since this problem exists only on a production server, a server on  
which I must still serve at least two customer sites (due to DNS  
issues) in addition to our own and any others I put on there, I'm a  
bit restricted in terms of how much I can muck with it (not that I  
haven't brought those live sites down for awkward periods of time  
with the diagnosis I've attempted so far).  I wish I had a test  
environment on another server that replicates this issue, but my  
other two servers run Tomcat perfectly fast, and since I don't  
understand what's causing the problem, I cannot make one of my other  
servers reproduce it.


Another diagnostic problem is that undeploying a context with the  
Tomcat /manager app, and then starting it again, does NOT reset this  
problem - the response to a JSP request is immediate (provided it  
had been requested since the last Tomcat startup).  This problem is  
only reset on a given JSP if I restart Tomcat entirely; I can  
reproduce it by creating fresh JSPs with new names and requesting  
them.


But, clearly, the key diagnostic issue is finding out WHAT is going  
on during the delay that a JSP incurs when it is first requested of  
a given Tomcat instance.  I've not been able to find out from  
strace.  I'll give truss -f and truss -ff a try.




How about just using tcpdump during the long delay and see what the  
machine is doing network wise ?


man tcpdump

János
-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-24 Thread János Löbb



On Feb 24, 2009, at 3:57 PM, Juha Laiho wrote:


So, looks like I'm late to the party, but will crash in nonetheless.


Sam Hokin wrote:

Christopher Schultz wrote:

On 2/19/2009 6:23 PM, Sam Hokin wrote:
The problem, which spontaneously appeared a few days before  
Christmas on
this one server, is that the initial request of a JSP or servlet  
takes

AGES to respond, usually exceeding several minutes.


Well, I have used a number of diagnostics, like jconsole, jstat and
jhat, but haven't been able to glean anything informative from them
about my issue.  I've run the -Xloggc JVM option, and watched it  
garbage
collect, again not informing me of anything.  Yes, if I could  
figure out

what the JVM is actually DOING doing the long wait, I'd hopefully be
able to deal with it, but I honestly haven't been able to figure  
out how

to do that.  What do you suggest?

I'll cast my hat into the ring: I suspect you're loading a  
resource that
wants to looking an external resource (like an XML file with a  
remote
DTD/Schema and validation is on in the parser) and the DNS is  
tripping

you up.


No, there are no external references in my Java package.  It's all  
just

local class files.


Still it sounds like a network (DNS) issue, but it does not pay to  
just

argue, more information is needed.

One tool that I haven't yet seen suggested is 'strace', the Linux  
system
call tracer. This will show all the calls your application makes to  
the

operating system. As you say the application is mostly idle during the
delay, it is, in one way or another, waiting for some OS service to
complete. 'strace' should provide you with timestamped information on
what OS services were called, with which arguments, and how long did
it take for them to return with results. 'strace' will leave you with
a huge file (or a set of huge files, depending on the options you  
use),

and going through them will take some time - but you'll most likely
also find what causes the delay.

If you decide to go this way, trim down your application to the  
minimum

where you can still see the delay; with this you hopefully can get
at least some reduction to the amount of log data written. Even  
though it

is possible to temporarily attach strace to a running process (like
the Tomcat at the moment when it is hung), I'd recommend starting the
tomcat under truss (with -f or -ff to make it also trace new processes
created), because this way it is easier to trace back the file  
descriptor

numbers accessed.
--
..Juha



It could be other network issue, like having IP6 enabled on the  
machine connected to an IP4 network, or an inefficient routing of  
network traffic for that particular machine.  Sounds like it is timing  
out on some network task.


János
-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-24 Thread Sam Hokin

Juha Laiho wrote:

One tool that I haven't yet seen suggested is 'strace', the Linux system
call tracer. This will show all the calls your application makes to the
operating system. As you say the application is mostly idle during the
delay, it is, in one way or another, waiting for some OS service to
complete. 'strace' should provide you with timestamped information on
what OS services were called, with which arguments, and how long did
it take for them to return with results. 'strace' will leave you with
a huge file (or a set of huge files, depending on the options you use),
and going through them will take some time - but you'll most likely
also find what causes the delay.

Thanks, Juha. Actually Pieter suggested it a little while ago, and I've been trying to get some information out of
strace. The best I can do is to put strace in front of the java command that's inside catalina.sh. That's the command
that shows with ps -ef when Tomcat is running. BUT, I get nothing out of strace when I make page requests on a site, it
just shows output during Tomcat startup. So, I've not figured out how to get strace to say what the JVM is during the
delay. jstack has led us to a stalled File.exists() in one case, but we don't know what file it's looking for. And I'm
not convinced that File.exists() is the only method that's stalling.

Since this problem exists only on a production server, a server on which I must still serve at least two customer sites
(due to DNS issues) in addition to our own and any others I put on there, I'm a bit restricted in terms of how much I
can muck with it (not that I haven't brought those live sites down for awkward periods of time with the diagnosis I've
attempted so far). I wish I had a test environment on another server that replicates this issue, but my other two
servers run Tomcat perfectly fast, and since I don't understand what's causing the problem, I cannot make one of my
other servers reproduce it.

Another diagnostic problem is that undeploying a context with the Tomcat /manager app, and then starting it again, does
NOT reset this problem - the response to a JSP request is immediate (provided it had been requested since the last
Tomcat startup). This problem is only reset on a given JSP if I restart Tomcat entirely; I can reproduce it by creating
fresh JSPs with new names and requesting them.

But, clearly, the key diagnostic issue is finding out WHAT is going on during the delay that a JSP incurs when it is
first requested of a given Tomcat instance. I've not been able to find out from strace. I'll give truss -f and truss
-ff a try.

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-24 Thread Juha Laiho

So, looks like I'm late to the party, but will crash in nonetheless.

Sam Hokin wrote:
> Christopher Schultz wrote:
>> On 2/19/2009 6:23 PM, Sam Hokin wrote:
>>> The problem, which spontaneously appeared a few days before Christmas on
>>> this one server, is that the initial request of a JSP or servlet takes
>>> AGES to respond, usually exceeding several minutes.
> 
> Well, I have used a number of diagnostics, like jconsole, jstat and
> jhat, but haven't been able to glean anything informative from them
> about my issue.  I've run the -Xloggc JVM option, and watched it garbage
> collect, again not informing me of anything.  Yes, if I could figure out
> what the JVM is actually DOING doing the long wait, I'd hopefully be
> able to deal with it, but I honestly haven't been able to figure out how
> to do that.  What do you suggest?
> 
>> I'll cast my hat into the ring: I suspect you're loading a resource that
>> wants to looking an external resource (like an XML file with a remote
>> DTD/Schema and validation is on in the parser) and the DNS is tripping
>> you up.
> 
> No, there are no external references in my Java package.  It's all just
> local class files.

Still it sounds like a network (DNS) issue, but it does not pay to just
argue, more information is needed.

One tool that I haven't yet seen suggested is 'strace', the Linux system
call tracer. This will show all the calls your application makes to the
operating system. As you say the application is mostly idle during the
delay, it is, in one way or another, waiting for some OS service to
complete. 'strace' should provide you with timestamped information on
what OS services were called, with which arguments, and how long did
it take for them to return with results. 'strace' will leave you with
a huge file (or a set of huge files, depending on the options you use),
and going through them will take some time - but you'll most likely
also find what causes the delay.

If you decide to go this way, trim down your application to the minimum
where you can still see the delay; with this you hopefully can get
at least some reduction to the amount of log data written. Even though it
is possible to temporarily attach strace to a running process (like
the Tomcat at the moment when it is hung), I'd recommend starting the
tomcat under truss (with -f or -ff to make it also trace new processes
created), because this way it is easier to trace back the file descriptor
numbers accessed.
-- 
..Juha

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-24 Thread Sam Hokin


Mark Thomas wrote:

Sam Hokin wrote:

Thanks, Chris.  I ran e2fsck with the -c option, which runs badblocks,
when I tested it earlier.  And I just ran badblocks again - 0 bad blocks
found.  I wish I could fix this by simply as swapping out a bad disk
(notwithstanding Andre's desire for intellectual pursuits), but I really
think it's software, either in some service mucking up the JVM or the
JVM itself.  But it only manifests itself under Tomcat, and then only
when this particular package is imported.


Do you see the same issue if you pre-compile that JSP?


Surprisingly, yes.  So it's not only a compilation issue.  After some individual tests, I compiled the JSPs from the 
four sites I have running on this server and restarted Tomcat, and the LONG delay before Tomcat begins serving page 
requests continues.  I looked at my individual test JSP, now precompiled, and, sure enough, it takes a long time to 
respond to the first request after a Tomcat restart.  In fact, it wasn't any better than when Tomcat compiles them on 
the fly.  So I'm back to thinking the classloader is involved in this delay as well.


I did check, just to be sure, and Tomcat did not write any class files under Catalina/work.  And if I deleted a compiled 
class file on a site, a request throws an error logged in catalina.out.  So, Tomcat is definitely using the compiled 
classes.


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-23 Thread Sam Hokin


Christopher Schultz wrote:

Sam,

On 2/20/2009 6:44 PM, Sam Hokin wrote:

Thanks, Chris.  I ran e2fsck with the -c option, which runs badblocks,
when I tested it earlier.  And I just ran badblocks again - 0 bad blocks
found.


Did you run badblocks on the array, or on an individual disk?

I would expect the disk-level check to be more useful.


On the array.  I'm not even sure I can get at a single disk from the OS with this hardware RAID configuration.  The OS 
had no idea that it's a RAID array as far as I know.


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-22 Thread Christopher Schultz

-BEGIN PGP SIGNED MESSAGE-
Hash: SHA1

Sam,

On 2/20/2009 6:44 PM, Sam Hokin wrote:
> Thanks, Chris.  I ran e2fsck with the -c option, which runs badblocks,
> when I tested it earlier.  And I just ran badblocks again - 0 bad blocks
> found.

Did you run badblocks on the array, or on an individual disk?

I would expect the disk-level check to be more useful.

- -chris
-BEGIN PGP SIGNATURE-
Version: GnuPG v1.4.9 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iEYEARECAAYFAkmhaVYACgkQ9CaO5/Lv0PD0tACghW7VAUa5yZPZ8B4mxOTFFLCV
8zEAnj4lqIXCfdsbPRBpJrFFCmpk8ftN
=f1uv
-END PGP SIGNATURE-

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-21 Thread André Warnier


A summary so far :
- the problem is : on one certain machine, when deploying any JSP which 
imports a certain self-made library of classes, that JSP takes an 
inordinate amount of time (one minute or more) to compile for a 5-line JSP
- after compilation, the JSP in question responds totally normally to 
requests
- there are no errors in the Tomcat logs.  The logs show only the 
inordinate amount of time needed to load the application, when the 
offending library is included.
- the issue appears only on that particular machine, which is a modern 
and fast machine, dual quad-core Intel Xeon E5310 CPUs, with a 4-disk 
Raid array.  The same JSP and library on any other of 3 machines using 
the same JVM and Tomcat, does not exhibit the same problem
- the disk array was checked for problems using various means, and does 
not exhibit any.  The RAM was similarly checked.
- the issue persists if the JSP is copied under another name on the same 
machine
- the issue persists if the whole webapp containing that JSP is copied 
to a new webapp name on the same machine (and thus occupying a different 
disk and memory area)
- the issue disappears if said self-made library is no longer imported 
in the JSP; it reappears if the library is imported again
- the issue persists if the imported library is moved from 
webapp/WEB-INF/lib to the Tomcat common lib location and vice-versa

- the issue persists despite changing the JVM version and/or Tomcat version
- the issue does not appear when importing the same self-made library in 
a separate stand-alone Java program and compiling/running that program 
on the same machine (?) (was that the whole library, or just a 
File.exists() test ?)
- during the compilation of the bewitched JSP, the machine on which the 
inordinate delay occurs does not exhibit any remarkably high CPU, memory 
 or disk usage
- the bewitching library of which it is question does not make evident 
references to external network resources whose unavailability or slow 
access could explain the compilation delay
- the affected system is not near any known source of Alpha particles, 
nor near a reindeer farm, nor in the proximity of any significant 
quantity of chocolate or other dark matter
- other applications on the striken machine work fine and do not exhibit 
the above symptoms
- the machine in question does not activate Java's security manager (nor 
do the other non-affected machines)



Suggestions of the day :

1.
under the assumption that the library in question does not contain 
hundreds of classes, and that the problem occurs during compilation, so 
that an error during execution of the JSP would not matter..


Start removing (commenting out) the content of each class one by one and 
test, until the specific class causing the issue is found.


2.
turn off 1,2,3,4,5,6,7 of the machine cores and see if it changes the 
symptoms


3.
I have a currently unused machine standing here, which in a spirit of 
camaraderie and assistance I would offer to exchange for the affected 
machine.  It's not a quad-core or anything like that, but to my 
knowledge when it was last powered on a couple of years ago, it did not 
exhibit that kind of problem.



-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

RE: very slow class loading on initial JSP/servlet request after restart

2009-02-20 Thread Martin Gainty

agreed
the jspc task from ANT will compile your jsps for you

(although you'll need jasper.jar and jasper-runtime.jar)
Documentation avaialable at
http://ant.apache.org/manual/OptionalTasks/jspc.html

ping me offline if you needs those jars..

Martin 
__ 
Disclaimer and confidentiality note 
Everything in this e-mail and any attachments relates to the official business 
of Sender. This transmission is of a confidential nature and Sender does not 
endorse distribution to any party other than intended recipient. Sender does 
not necessarily endorse content contained within this transmission. 

> Date: Fri, 20 Feb 2009 23:50:21 +
> From: ma...@apache.org
> To: users@tomcat.apache.org
> Subject: Re: very slow class loading on initial JSP/servlet request after 
> restart
> 
> Sam Hokin wrote:
> > Thanks, Chris.  I ran e2fsck with the -c option, which runs badblocks,
> > when I tested it earlier.  And I just ran badblocks again - 0 bad blocks
> > found.  I wish I could fix this by simply as swapping out a bad disk
> > (notwithstanding Andre's desire for intellectual pursuits), but I really
> > think it's software, either in some service mucking up the JVM or the
> > JVM itself.  But it only manifests itself under Tomcat, and then only
> > when this particular package is imported.
> 
> Do you see the same issue if you pre-compile that JSP?
> 
> Mark
> 
> 
> 
> -
> To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
> For additional commands, e-mail: users-h...@tomcat.apache.org
> 

_
Windows Live™: E-mail. Chat. Share. Get more ways to connect. 
http://windowslive.com/online/hotmail?ocid=TXT_TAGLM_WL_HM_AE_Faster_022009

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-20 Thread Mark Thomas

Sam Hokin wrote:
> Thanks, Chris.  I ran e2fsck with the -c option, which runs badblocks,
> when I tested it earlier.  And I just ran badblocks again - 0 bad blocks
> found.  I wish I could fix this by simply as swapping out a bad disk
> (notwithstanding Andre's desire for intellectual pursuits), but I really
> think it's software, either in some service mucking up the JVM or the
> JVM itself.  But it only manifests itself under Tomcat, and then only
> when this particular package is imported.

Do you see the same issue if you pre-compile that JSP?

Mark



-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


André Warnier wrote:

Sam Hokin wrote:
I'd like to correct an error I made in my earlier report of this 
problem.  It turns out that the response delay in my simple test JSP 
IS during compilation!  I ran stat on the files in question, as well 
as looked at the time shown on the response page (which is all the 
test JSP does).  (I think I got confused by the output of the 
-verbose:class JVM option earlier.)



Restarting from the point above..
Leaving the current test jsp page in place, but taking a copy of it 
under another name, does the symptom then also show up on the copy ?


Yes, always.  That's how I reproduce it without having to restart the server. I just copy from test1.jsp to test2.jsp, 
and then test2.jsp takes a long time to compile.  It's a very robust problem, with no specific source or compiled files 
involved.  It just requires a JSP that hasn't yet been compiled.



The same with the whole webapp, copied under another name.


Any web app.  There are four running now, I used to have about 8 running on this server, and I've put new web apps on 
(like yesterday), always reproducing the problem.  But all of these web apps import my Java package at the top of the JSPs.


Separate question : does this Tomcat, contrary to the others, have the 
SecurityManager on ? or vice-versa ?


No it doesn't.  SecurityManager is not on any of the servers.  I have not changed catalina.policy, and I do not invoke 
Tomcat with the -security option.


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

Thanks, Chris.  I ran e2fsck with the -c option, which runs badblocks, when I tested it earlier.  And I just ran 
badblocks again - 0 bad blocks found.  I wish I could fix this by simply as swapping out a bad disk (notwithstanding 
Andre's desire for intellectual pursuits), but I really think it's software, either in some service mucking up the JVM 
or the JVM itself.  But it only manifests itself under Tomcat, and then only when this particular package is imported.


Christopher Schultz wrote:

Sam and David,

On 2/20/2009 1:36 PM, David Smith wrote:

Sam Hokin wrote:

It's a logical RAID array on four physical disks.  I've
run fsck on it (when this all first happened) and it's fine.

It _could_ be a disk issue.  I've seen disks that scan fine contain a
growing number of blocks causing read errors and continuous retries.


Yeah, you gotta run badblocks on it. fsck just checks the filesystem
integrity, not the physical disk.


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


Sam Hokin wrote:
I'd like to correct an error I made in my earlier report of this 
problem.  It turns out that the response delay in my simple test JSP IS 
during compilation!  I ran stat on the files in question, as well as 
looked at the time shown on the response page (which is all the test JSP 
does).  (I think I got confused by the output of the -verbose:class JVM 
option earlier.)



Restarting from the point above..
Leaving the current test jsp page in place, but taking a copy of it 
under another name, does the symptom then also show up on the copy ?

The same with the whole webapp, copied under another name.
I am saying "copy", not "move/rename", so as to really use another disk 
area.


Separate question : does this Tomcat, contrary to the others, have the 
SecurityManager on ? or vice-versa ?




-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


Christopher Schultz wrote:

-BEGIN PGP SIGNED MESSAGE-
Hash: SHA1

Sam and David,

On 2/20/2009 1:36 PM, David Smith wrote:

Sam Hokin wrote:

It's a logical RAID array on four physical disks.  I've
run fsck on it (when this all first happened) and it's fine.

It _could_ be a disk issue.  I've seen disks that scan fine contain a
growing number of blocks causing read errors and continuous retries.


Yeah, you gotta run badblocks on it. fsck just checks the filesystem
integrity, not the physical disk.

If there are problems with the disks themselves, the Raid controller 
should have a utility program allowing to inspect such, no ?
If they are hot-swap, you could also try to remove one of them and 
insert a new one, let him rebuild it and try again.  It will take a 
while to go through all 4 of them this way, but should not interrupt 
anything.


It would be quite a pity if this turned out to be a mere disk problem 
though.  Much less interesting than the current intellectual pursuit.



-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-20 Thread Christopher Schultz

-BEGIN PGP SIGNED MESSAGE-
Hash: SHA1

Sam and David,

On 2/20/2009 1:36 PM, David Smith wrote:
> Sam Hokin wrote:
>> It's a logical RAID array on four physical disks.  I've
>> run fsck on it (when this all first happened) and it's fine.
>
> It _could_ be a disk issue.  I've seen disks that scan fine contain a
> growing number of blocks causing read errors and continuous retries.

Yeah, you gotta run badblocks on it. fsck just checks the filesystem
integrity, not the physical disk.

- -chris
-BEGIN PGP SIGNATURE-
Version: GnuPG v1.4.9 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iEYEARECAAYFAkmfOKcACgkQ9CaO5/Lv0PCV5gCfUVQB8ycIyHeAxMBf3atW3LON
PIgAn1dV6ihbK5vovhr0s1xAh0LaI7JP
=NSDB
-END PGP SIGNATURE-

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

An update.  I've written a simple standalone Java routine that calls File.exists().  It never hangs.  In fact, I ran it 
against the class file that Tomcat creates from a test JSP; it doesn't hang, returns false for the (long) time it takes 
Tomcat to create the class file on the slow system, then returns true after the class file is created (and the HTTP 
response is sent).  I ran my routine as the tomcat user.


Since compilation seems to be the issue, I tried replacing Jasper JDT (by removing jasper-jdt.jar from /lib) with Ant 
(by placing ant.jar in /lib) and restarting Tomcat.  This did not improve my problem.  JSPs still compile slowly with 
Ant instead of JDT on the slow machine (and fast on the other machines).  I've reverted back to JDT.


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

Chuck's comment about JSP to Java translation done by Jasper reminded me that I should have included the time on the 
Java source file created during JSP compilation.  It shows that the Java source file was created immediately, but 
accessed again six seconds later (!), presumably by the compiler.


  File: 
`/usr/local/tomcat/work/Catalina/www.ims.net/_/org/apache/jsp/test4_jsp.java'
  Size: 2333Blocks: 8  IO Block: 4096   regular file
Device: fd00h/64768dInode: 10650454Links: 1
Access: (0644/-rw-r--r--)  Uid: (  501/  tomcat)   Gid: (  501/  tomcat)
Access: 2009-02-20 13:39:35.0 -0600
Modify: 2009-02-20 13:39:29.0 -0600
Change: 2009-02-20 13:39:29.0 -0600

In summary: test4.jsp accessed at 13:39:29; test4_jsp.java created at 13:39:29; test4_jsp.java accessed at 13:39:35; 
test4_jsp.class created at 13:40:17; HTTP response at 13:40:17.


I'm going to play with File.exists() in this and the other servers to see if there is some generic problem with file 
access on the slow server.




-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


Sam Hokin wrote:
I'd like to correct an error I made in my earlier report of this 
problem.  It turns out that the response delay in my simple test JSP IS 
during compilation!  


Ha !
If it may help, I remember seeing an earlier thread this week, I believe 
answered by Rainer Jung, providing some fancy compilations options.

Don't remember what the thread was about though.



-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

I'd like to correct an error I made in my earlier report of this problem.  It turns out that the response delay in my 
simple test JSP IS during compilation!  I ran stat on the files in question, as well as looked at the time shown on the 
response page (which is all the test JSP does).  (I think I got confused by the output of the -verbose:class JVM option 
earlier.)


Here's the file sequence from stat:

  File: `test4.jsp'
  Size: 146 Blocks: 8  IO Block: 4096   regular file
Device: fd00h/64768dInode: 7701336 Links: 1
Access: (0644/-rw-r--r--)  Uid: (  500/ sam)   Gid: (  100/   users)
Access: 2009-02-20 13:39:29.0 -0600 <--- Tomcat accesses the file
Modify: 2009-02-20 10:39:09.0 -0600
Change: 2009-02-20 13:39:06.0 -0600

  File: 
`/usr/local/tomcat/work/Catalina/www.ims.net/_/org/apache/jsp/test4_jsp.class'
  Size: 3520Blocks: 8  IO Block: 4096   regular file
Device: fd00h/64768dInode: 10650578Links: 1
Access: (0644/-rw-r--r--)  Uid: (  501/  tomcat)   Gid: (  501/  tomcat)
Access: 2009-02-20 13:40:17.0 -0600 <--- the compiled class appears 
almost a minute later
Modify: 2009-02-20 13:40:17.0 -0600
Change: 2009-02-20 13:40:17.0 -0600

The HTTP response came immediately after that, the page displaying: Fri Feb 20 
13:40:17 CST 2009.

As before, jstack reveals that the thread is stalling on java.io.File.exists(), or specifically 
java.io.UnixFileSystem.getBooleanAttributes(java.io.File).


On my other two servers, the exact same JSP as above is accessed, compiled and 
responds within one second.

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-20 Thread David Smith

Sam Hokin wrote:
> Christopher Schultz wrote:
>>
>> jstack.8.txt is the last thread dump where File.exists was stalled.
>>
>>> http://ims.net/jstack/jstack.9.txt
>>> http://ims.net/jstack/jstack.10.txt
>>> http://ims.net/jstack/jstack.11.txt
>>
>> The server appears to be idle, here.
>>
>> It's a little weird that thread 9770 has NO STACK INFO AT ALL.
>>
>>> http://ims.net/jstack/jstack.12.txt
>>> http://ims.net/jstack/jstack.13.txt
>>
>> Also idle.
>
> Yeah, I _thought_ it was still stalled on 9-11, but it looks like I
> misjudged the timing by a bit.  I was flipping back and forth between
> virtual windows, hitting jstack while checking if my browser had the
> response from the server.
>
>> Obviously, the File.exists method shouldn't be taking that long... it's
>> a pretty simple operation. Are you using an NFS or other network share?
>> Does your disk have any physical problems? Is this machine running next
>> to any equipment that generates a lot of stray alpha particles? :)
>
> Not that I know of. :) We now know it's hanging on
> java.io.File.exists(), though, so I suppose that's leading us
> somewhere.  It's a logical RAID array on four physical disks.  I've
> run fsck on it (when this all first happened) and it's fine.  And this
> problem persists no matter where the classes are on the disk; whether
> they're in a JAR file anywhere, or split out under WEB-INF/classes.  I
> don't think it can be a disk issue.  I guess I could write a
> standalone Java routine to play with the File.exists() method and see
> if I can reproduce the delay "manually"
>
>
It _could_ be a disk issue.  I've seen disks that scan fine contain a
growing number of blocks causing read errors and continuous retries.

--David


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

Christopher Schultz wrote:

jstack.8.txt is the last thread dump where File.exists was stalled.

http://ims.net/jstack/jstack.9.txt
http://ims.net/jstack/jstack.10.txt
http://ims.net/jstack/jstack.11.txt

The server appears to be idle, here.

It's a little weird that thread 9770 has NO STACK INFO AT ALL.

http://ims.net/jstack/jstack.12.txt
http://ims.net/jstack/jstack.13.txt

Also idle.

Yeah, I _thought_ it was still stalled on 9-11, but it looks like I misjudged the timing by a bit. I was flipping back
and forth between virtual windows, hitting jstack while checking if my browser had the response from the server.

Obviously, the File.exists method shouldn't be taking that long... it's
a pretty simple operation. Are you using an NFS or other network share?
Does your disk have any physical problems? Is this machine running next
to any equipment that generates a lot of stray alpha particles? :)

Not that I know of. :) We now know it's hanging on java.io.File.exists(), though, so I suppose that's leading us
somewhere. It's a logical RAID array on four physical disks. I've run fsck on it (when this all first happened) and
it's fine. And this problem persists no matter where the classes are on the disk; whether they're in a JAR file
anywhere, or split out under WEB-INF/classes. I don't think it can be a disk issue. I guess I could write a standalone
Java routine to play with the File.exists() method and see if I can reproduce the delay "manually"

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-20 Thread Christopher Schultz

-BEGIN PGP SIGNED MESSAGE-
Hash: SHA1

Sam,

On 2/20/2009 12:11 PM, Sam Hokin wrote:
> jstack.0.txt ran BEFORE my test request.

Your server is completely idle, here.

> jstack.1-11.txt ran DURING the long wait.

Observing jstack.1.txt, it looks like this is the only running thread
(complete stack trace shown just for this first one):

Thread 9994: (state = IN_NATIVE)
 - java.io.UnixFileSystem.getBooleanAttributes0(java.io.File) @bci=0
(Compiled frame; information may be imprecise)
 - java.io.UnixFileSystem.getBooleanAttributes(java.io.File) @bci=2,
line=228 (Compiled frame)
 - java.io.File.exists() @bci=20, line=733 (Compiled frame)
 - sun.misc.URLClassPath$FileLoader.getResource(java.lang.String,
boolean) @bci=136, line=995 (Compiled frame)
 - sun.misc.URLClassPath$FileLoader.findResource(java.lang.String,
boolean) @bci=3, line=962 (Compiled frame)
 - sun.misc.URLClassPath.findResource(java.lang.String, boolean)
@bci=17, line=145 (Compiled frame)
 - java.net.URLClassLoader$2.run() @bci=12, line=362 (Compiled frame)
 -
java.security.AccessController.doPrivileged(java.security.PrivilegedAction,
java.security.AccessControlContext) @bci=0 (Interpreted frame)
 - java.net.URLClassLoader.findResource(java.lang.String) @bci=13,
line=359 (Compiled frame)
 - java.lang.ClassLoader.getResource(java.lang.String) @bci=30, line=978
(Compiled frame)
 - java.lang.ClassLoader.getResource(java.lang.String) @bci=12, line=973
(Compiled frame)
 - java.lang.ClassLoader.getResourceAsStream(java.lang.String) @bci=2,
line=1168 (Interpreted frame)
 -
org.apache.catalina.loader.WebappClassLoader.getResourceAsStream(java.lang.String)
@bci=326, line=1205 (Interpreted frame)
 -
org.apache.jasper.servlet.JasperLoader.getResourceAsStream(java.lang.String)
@bci=5, line=144 (Interpreted frame)
 - org.apache.jasper.compiler.JDTCompiler$1.findType(java.lang.String)
@bci=89, line=193 (Compiled frame)
 - org.apache.jasper.compiler.JDTCompiler$1.findType(char[], char[][])
@bci=124, line=178 (Compiled frame)
 -
org.eclipse.jdt.internal.compiler.lookup.LookupEnvironment.askForType(org.eclipse.jdt.internal.compiler.lookup.PackageBinding,
char[]) @bci=27, line=122 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.lookup.PackageBinding.getType(char[])
@bci=16, line=126 (Interpreted frame)
 - org.eclipse.jdt.internal.compiler.lookup.Scope.findType(char[],
org.eclipse.jdt.internal.compiler.lookup.PackageBinding,
org.eclipse.jdt.internal.compiler.lookup.PackageBinding) @bci=14,
line=1351 (Compiled frame)
 -
org.eclipse.jdt.internal.compiler.lookup.Scope.getTypeOrPackage(char[],
int) @bci=1017, line=2408 (Compiled frame)
 - org.eclipse.jdt.internal.compiler.lookup.Scope.getPackage(char[][])
@bci=14, line=2090 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.ast.QualifiedTypeReference.getTypeBinding(org.eclipse.jdt.internal.compiler.lookup.Scope)
@bci=17, line=69 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.ast.TypeReference.resolveType(org.eclipse.jdt.internal.compiler.lookup.ClassScope)
@bci=36, line=163 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.ast.TypeReference.resolveSuperType(org.eclipse.jdt.internal.compiler.lookup.ClassScope)
@bci=2, line=114 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.lookup.ClassScope.findSupertype(org.eclipse.jdt.internal.compiler.ast.TypeReference)
@bci=35, line=1121 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.lookup.ClassScope.connectSuperclass()
@bci=157, line=835 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.lookup.ClassScope.connectTypeHierarchy()
@bci=34, line=960 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.lookup.CompilationUnitScope.connectTypeHierarchy()
@bci=20, line=290 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.lookup.LookupEnvironment.completeTypeBindings()
@bci=72, line=218 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.Compiler.internalBeginToCompile(org.eclipse.jdt.internal.compiler.env.ICompilationUnit[],
int) @bci=198, line=603 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.Compiler.beginToCompile(org.eclipse.jdt.internal.compiler.env.ICompilationUnit[])
@bci=19, line=357 (Interpreted frame)
 -
org.eclipse.jdt.internal.compiler.Compiler.compile(org.eclipse.jdt.internal.compiler.env.ICompilationUnit[])
@bci=6, line=371 (Interpreted frame)
 -
org.apache.jasper.compiler.JDTCompiler.generateClass(java.lang.String[])
@bci=837, line=413 (Interpreted frame)
 - org.apache.jasper.compiler.Compiler.compile(boolean, boolean)
@bci=30, line=317 (Interpreted frame)
 - org.apache.jasper.compiler.Compiler.compile(boolean) @bci=3, line=295
(Interpreted frame)
 - org.apache.jasper.compiler.Compiler.compile() @bci=2, line=282
(Interpreted frame)
 - org.apache.jasper.JspCompilationContext.compile() @bci=31, line=586
(Interpreted frame)
 -
org.apache.jasper.servlet.JspServletWrapper.service(javax.servlet.http.HttpServletRequest,
javax.servlet.http.HttpServletResponse, boolean) @bci=118, line=317
(

Re: very slow class loading on initial JSP/servlet request after restart

Caldarale, Charles R wrote:

Run jstack several times during the delay, and then let's compare the set of
thread dumps.

What is the CPU utilization during the delay?

OK, done. The CPU utilization during the delay is tiny, 1% or less. I've run jstack before, during, and after I've
done a first request on my tiny offending test JSP. Since the jstack output is lengthy (I've got several sites running
on this public server, unavoidably), I've thrown the resulting output on my server for easier viewing.

jstack.0.txt ran BEFORE my test request.
jstack.1-11.txt ran DURING the long wait.
jstack.12,13.txt ran AFTER the response was received.

http://ims.net/jstack/jstack.0.txt

http://ims.net/jstack/jstack.1.txt
http://ims.net/jstack/jstack.2.txt
http://ims.net/jstack/jstack.3.txt
http://ims.net/jstack/jstack.4.txt
http://ims.net/jstack/jstack.5.txt
http://ims.net/jstack/jstack.6.txt
http://ims.net/jstack/jstack.7.txt
http://ims.net/jstack/jstack.8.txt
http://ims.net/jstack/jstack.9.txt
http://ims.net/jstack/jstack.10.txt
http://ims.net/jstack/jstack.11.txt

http://ims.net/jstack/jstack.12.txt
http://ims.net/jstack/jstack.13.txt

I wish I could divine something informative from these. Perhaps one of you can.

I'm also trying to use Wireshark to see if there is some specific net activity that's going on during the long wait, as
suggested by David Smith.

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


Christopher Schultz wrote:

Sam,

On 2/19/2009 6:23 PM, Sam Hokin wrote:

The problem, which spontaneously appeared a few days before Christmas on
this one server, is that the initial request of a JSP or servlet takes
AGES to respond, usually exceeding several minutes.


Good... then you'll have plenty of time to /take a thread dump/ while
it's spinning its wheels.


Well, I have used a number of diagnostics, like jconsole, jstat and jhat, but haven't been able to glean anything 
informative from them about my issue.  I've run the -Xloggc JVM option, and watched it garbage collect, again not 
informing me of anything.  Yes, if I could figure out what the JVM is actually DOING doing the long wait, I'd hopefully 
be able to deal with it, but I honestly haven't been able to figure out how to do that.  What do you suggest?



I'll cast my hat into the ring: I suspect you're loading a resource that
wants to looking an external resource (like an XML file with a remote
DTD/Schema and validation is on in the parser) and the DNS is tripping
you up.


No, there are no external references in my Java package.  It's all just local 
class files.

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


Ron McNulty wrote:

Hi Sam

You jar - does it include any JSP tag files written as JSP fragments? 
There are known issues in this area. The dependency management seems to 
get confused, resulting in lots of unnecessary compilation of the .tag 
files


No, it doesn't, Ron.  But thanks for the heads-up on that.  The JAR just contains class files for a couple of packages. 
 And compilation occurs quickly; it's the loading of the compiled class that's taking forever, even if they're already 
compiled from a previous Tomcat run.  And, once the class is loaded (as indicated by the output line from the 
-verbose:class JVM option) execution is quick.  I've not been able to get any diagnostic to indicate what's going on 
during the interminable wait for pagename_jsp.class to load after the initial page request.


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


Caldarale, Charles R wrote:


1) What are the servers that don't have a problem?


One is a single AMD Athlon 64 2800+, running the 64-bit Sun JDK (same version).

The other is a dual AMD Athlon MP 2000+, running the 32-bit Sun JDK (same 
version).

And the "bad" server has "8" Intel Xeon E5310 CPUs running the 32-bit Sun JDK (it is indeed a dual quad-core, not a quad 
dual-core, as I incorrectly typed in my original post).



2) How much RAM is on each server?


The Athlon 64 has 1.5 GB RAM (2 GB swap).
The dual 32-bit Athlon has 1 GB RAM (2 GB swap).
The "bad" server has 2 GB RAM (2 GB swap).


3) Is the JDK 32- or 64-bit on each server?


32-bit on the two 32-bit machines, 64-bit on the 64-bit machine.


4) What's the Java heap size for Tomcat on each server?


I've played with heap size quite a bit to no avail.   Currently, all are 
running 768 MB with the following JDK options:

JAVA_OPTS="-Xms768m -Xmx768m -XX:NewSize=256m -XX:MaxNewSize=256m -XX:PermSize=128m 
-XX:MaxPermSize=128m"


5) Are you using the same file system on all three servers?  What is it (ext3, 
reiser, ???)?


Yes.  ext3 on all three machines, all are running current Fedora Core 9 distros (well, except for the new kernel which 
came out yesterday).


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-20 Thread David Smith

André Warnier wrote:
> Christopher Schultz wrote:
>> -BEGIN PGP SIGNED MESSAGE-
>> Hash: SHA1
>>
>> Sam,
>>
>> On 2/19/2009 6:23 PM, Sam Hokin wrote:
>>> The problem, which spontaneously appeared a few days before
>>> Christmas on
>>> this one server, is that the initial request of a JSP or servlet takes
>>> AGES to respond, usually exceeding several minutes.
>>
>> Good... then you'll have plenty of time to /take a thread dump/ while
>> it's spinning its wheels.
>>
>> I'll cast my hat into the ring: I suspect you're loading a resource that
>> wants to looking an external resource (like an XML file with a remote
>> DTD/Schema and validation is on in the parser) and the DNS is tripping
>> you up.
>>
> I would like to point out at this moment that my initial analysis (the
> one with the reindeers) does not look so bad after all.
>
> More seriously, and for my own and possibly the OP's edification : we
> thus have 8 cores/cpus available, and one webapp being loaded at
> Tomcat startup, which takes ages, but independently of class
> compilation, Java and Tomcat versions etc..  Say we have told Tomcat
> to start 100 threads.
> Does that mean that possibly 8 threads (or more) are all (rather
> busily) waiting for something in relation to some initialisation in
> the (rather suspect) classes belonging to that webapp ?
> The OP also mentions "the initial request takes ages".  So this
> initialisation would not happen really at Tomcat startup, but at the
> first request.  Any particular setup or circumstance that could be
> tried to change when this happens, just to see ?
>
>

Sounds to me like the webapp is waiting for something external to
respond -- possibly from the network and timing out.  In my experience
there is usually some extra latency on the first request due to
compiling jsps, but I can't imagine it being significant -- especially
on a really good box w/ multiple cores.  It'd be interesting to start up
wireshark on the server and see if there is any network traffic sourced
out of tomcat during the several minute wait.  Maybe a firewall was
installed or reconfigured or some dependent resource was shutdown around
Christmas.


--David

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-20 Thread János Löbb



On Feb 20, 2009, at 10:25 AM, André Warnier wrote:


Christopher Schultz wrote:

-BEGIN PGP SIGNED MESSAGE-
Hash: SHA1
Sam,
On 2/19/2009 6:23 PM, Sam Hokin wrote:
The problem, which spontaneously appeared a few days before  
Christmas on
this one server, is that the initial request of a JSP or servlet  
takes

AGES to respond, usually exceeding several minutes.

Good... then you'll have plenty of time to /take a thread dump/ while
it's spinning its wheels.
I'll cast my hat into the ring: I suspect you're loading a resource  
that

wants to looking an external resource (like an XML file with a remote
DTD/Schema and validation is on in the parser) and the DNS is  
tripping

you up.
I would like to point out at this moment that my initial analysis  
(the one with the reindeers) does not look so bad after all.


More seriously, and for my own and possibly the OP's edification :  
we thus have 8 cores/cpus available, and one webapp being loaded at  
Tomcat startup, which takes ages, but independently of class  
compilation, Java and Tomcat versions etc..  Say we have told Tomcat  
to start 100 threads.
Does that mean that possibly 8 threads (or more) are all (rather  
busily) waiting for something in relation to some initialisation in  
the (rather suspect) classes belonging to that webapp ?
The OP also mentions "the initial request takes ages".  So this  
initialisation would not happen really at Tomcat startup, but at the  
first request.  Any particular setup or circumstance that could be  
tried to change when this happens, just to see ?




No, it is definitely not the reindeers, but an octo-pussy :)

János
-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart


Christopher Schultz wrote:

-BEGIN PGP SIGNED MESSAGE-
Hash: SHA1

Sam,

On 2/19/2009 6:23 PM, Sam Hokin wrote:

The problem, which spontaneously appeared a few days before Christmas on
this one server, is that the initial request of a JSP or servlet takes
AGES to respond, usually exceeding several minutes.


Good... then you'll have plenty of time to /take a thread dump/ while
it's spinning its wheels.

I'll cast my hat into the ring: I suspect you're loading a resource that
wants to looking an external resource (like an XML file with a remote
DTD/Schema and validation is on in the parser) and the DNS is tripping
you up.

I would like to point out at this moment that my initial analysis (the 
one with the reindeers) does not look so bad after all.


More seriously, and for my own and possibly the OP's edification : we 
thus have 8 cores/cpus available, and one webapp being loaded at Tomcat 
startup, which takes ages, but independently of class compilation, Java 
and Tomcat versions etc..  Say we have told Tomcat to start 100 threads.
Does that mean that possibly 8 threads (or more) are all (rather busily) 
waiting for something in relation to some initialisation in the (rather 
suspect) classes belonging to that webapp ?
The OP also mentions "the initial request takes ages".  So this 
initialisation would not happen really at Tomcat startup, but at the 
first request.  Any particular setup or circumstance that could be tried 
to change when this happens, just to see ?


-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart

2009-02-20 Thread Christopher Schultz

-BEGIN PGP SIGNED MESSAGE-
Hash: SHA1

Sam,

On 2/19/2009 6:23 PM, Sam Hokin wrote:
> The problem, which spontaneously appeared a few days before Christmas on
> this one server, is that the initial request of a JSP or servlet takes
> AGES to respond, usually exceeding several minutes.

Good... then you'll have plenty of time to /take a thread dump/ while
it's spinning its wheels.

I'll cast my hat into the ring: I suspect you're loading a resource that
wants to looking an external resource (like an XML file with a remote
DTD/Schema and validation is on in the parser) and the DNS is tripping
you up.

But, I have been wrong before ;)

- -chris

-BEGIN PGP SIGNATURE-
Version: GnuPG v1.4.9 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iEYEARECAAYFAkmesdYACgkQ9CaO5/Lv0PCjKgCeKPDT3jvajquTE9DVpaOdJMKk
nGcAnj1l0Mcl5SzEHUWo6EFVRzhUFr8z
=aM8r
-END PGP SIGNATURE-

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

RE: very slow class loading on initial JSP/servlet request after restart

2009-02-20 Thread Peter Crowther

> From: André Warnier [mailto:a...@ice-sa.com]
> >> From: Sam Hokin [mailto:s...@ims.net]
> >> The server that's being a problem is a Dell PowerEdge
> >> 1950, quad dual core.

> Since we have 4 processors here (do we, really? I am not so familiar
> with the multi-core architecture), can each of these processors be
> running a thread of these apps/classes, where on a single processor
> there would be only one thread running ?

Quad dual-core*.  That's 4 silicon dies, each with two copies of "the core of" 
a CPU.  So (4 * 2) = 8 separate instruction execution units, 8 program 
counters, executing up to 8 instruction streams in parallel.

The cores on one die share some infrastructure like cache and memory access, 
but the interesting feature here is that this machine can run 8 threads 
concurrently.

- Peter

* Says the original poster.  Looking at the Dell site, I reckon it's actually 
dual quad-core - so two dies, 4 cores per die.  Still 8 concurrent threads, 
though.

-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org

Re: very slow class loading on initial JSP/servlet request after restart