Jetty startup delay

Question

I'm trying to figure out what would be causing a 1 minute delay in the startup of Jetty. Is it a configuration problem, my application, or something else?

I have Jetty 7 (jetty-7.0.1.v20091125 25 November 2009) installed on a server and I deploy a 45MB ROOT.war file into the webapps directory. This is the only webapp configured in Jetty. I then start Jetty with the command:

java -DSTOP.PORT=8079 -DSTOP.KEY=mystopkey -Denv=stage -jar start.jar etc/jetty-logging.xml etc/jetty.xml &

I get two lines of output right after doing this:

2010-03-07 14:20:06.642:INFO::Logging to StdErrLog::DEBUG=false via org.eclipse.jetty.util.log.StdErrLog
2010-03-07 14:20:06.710:INFO::Redirecting stderr/stdout to /home/zing/jetty-distribution-7.0.1.v20091125/logs/2010_03_07.stderrout.log

When I press the enter key, I get my command prompt back. Looking at the log file (logs/2010_03_07.stderrout.log), I see the following at the beginning:

2010-03-07 14:08:50.396:INFO::jetty-7.0.1.v20091125
2010-03-07 14:08:50.495:INFO::Extract jar:file:/home/zing/jetty-distribution-7.0.1.v20091125/webapps/ROOT.war!/ to /tmp/Jetty_0_0_0_0_8080_ROOT.war___.8te0nm/webapp
2010-03-07 14:08:52.599:INFO::NO JSP Support for , did not find org.apache.jasper.servlet.JspServlet
2010-03-07 14:09:51.379:INFO::Set web app root system property: 'webapp.root' = [/tmp/Jetty_0_0_0_0_8080_ROOT.war___.8te0nm/webapp]
2010-03-07 14:09:51.585:INFO::Initializing Spring root WebApplicationContext
INFO  - ContextLoader              - Root WebApplicationContext: initialization started
INFO  - XmlWebApplicationContext   - Refreshing Root WebApplicationContext: startup date [Sun Mar 07 14:09:51 PST 2010]; root of context hierarchy
...

Notice the 1 minute long pause between the 3rd and 4th lines. What is Jetty doing at this point? What other things could be going on? It doesn't even look like it has started my Spring initialization yet.

Note that I checked my /tmp directory to see if it was simply the time to unpack my war file, but the file had been completely unpacked even at the start of this 1 minute delay.

UPDATE:

Thanks to suggestions, I added DEBUG logging. I found that about 2 seconds was used to extract the war file. But then there is about a 41 second delay on Init SecureRandom:

2010-03-07 21:54:45.414:DBUG::Starting SessionHandler@79884a40@
2010-03-07 21:54:45.414:DBUG::Starting org.eclipse.jetty.server.session.HashSessionManager@5fe8ce8
2010-03-07 21:54:45.416:DBUG::Container org.eclipse.jetty.server.Server@35175422 + org.eclipse.jetty.server.session.HashSessionIdManager@1d96f4b5 as sessionIdManager
2010-03-07 21:54:45.416:DBUG::Starting org.eclipse.jetty.server.session.HashSessionIdManager@1d96f4b5
2010-03-07 21:54:45.416:DBUG::Init SecureRandom.
2010-03-07 21:55:26.244:DBUG::STARTED org.eclipse.jetty.server.session.HashSessionIdManager@1d96f4b5
2010-03-07 21:55:26.247:DBUG::STARTED org.eclipse.jetty.server.session.HashSessionManager@5fe8ce8
2010-03-07 21:55:26.248:DBUG::Starting ConstraintSecurityHandler@6b9cd75a@
2010-03-07 21:55:26.261:DBUG::Starting ServletHandler@62c2ee15@

What is SecureRandom, and why would it be causing this delay?

SOLUTION:

It looks like I'm running into a problem with my system not having enough load. I've just set this up as a new staging server, and there is nobody using it except me. So the system doesn't have enough entropy for the random number generator to generate enough randomness quickly.

Answer 1

Jetty 7 (and maybe lower):

Set the (very) verbose debug logging with -Dorg.eclipse.jetty.util.log.DEBUG=true (see Jetty/Starting/Porting to Jetty 7) and try to see what is happening during this minute.

As a side note, you'll probably need jsp support so you should pass -DOPTIONS=Server,deploy,jsp when starting (see Running Jetty-7.0.x).

And if you don't need fancy things from Jetty 7.x, then you should stick with Jetty 6 instead of Jetty 7 eclipse (more stable, less problems because of the Eclipse migration, better documentation, easier to use).

Jetty 8:

In Jetty 8.1: System Property [org.eclipse.jetty.util.log.DEBUG] has been deprecated! (Use org.eclipse.jetty.LEVEL=DEBUG instead)