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.000065>
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.000064>
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
