Tomcat starts slow

[Maxim Kuleshov <ma...@gmail.com>]

Hi!

Tomcat on my ubuntu 8.04 (x64) server starts too slow.

I tried both bundled ubuntu version (tomcat 5.5.25) and newer tomcat
6.0.29.
The start time does not depend on application installed - even empty
tomcat distribution starts slow.

I googled that problem is somehow related to random generator - but I
disabled all SSL - and nothing changed.

The most of the time consumes Catalina initialization. It lasts
more than three minutes. The following lines from catalina.out log near
time gap (turned on finest log level)

[catalina.out]
....
10.08.2010 11:27:00 org.apache.catalina.core.ContainerBase addChildInternal
FINE: Add child StandardHost[localhost] StandardEngine[Catalina]
10.08.2010 11:27:00 org.apache.catalina.connector.Connector initialize
FINE: Creating name for connect
Catalina:type=Connector,port=7080
10.08.2010 11:30:09 org.apache.coyote.http11.Http11Protocol init
INFO: Initializing Coyote HTTP/1.1 on http-7080
10.08.2010 11:30:09 org.apache.catalina.connector.Connector initialize
FINE: Creating name for connector Catalina:type=Connector,port=7009
10.08.2010 11:30:09 org.apache.catalina.startup.Catalina load
INFO: Initialization processed in 189344 ms
....

Sending QUIT to java does not produces dump of hanging thread - even
after that soft 'killing' - tomcat continue to start.

Re: Tomcat starts slow

[Maxim Kuleshov <ma...@gmail.com>]

2010/8/10 Christopher Schultz <ch...@christopherschultz.net>

>
> It could be that Tomcat is attempting to resolve the SYSTEM URL for
> certain XML files it uses to configure itself. Could you re-enable the
> DROP and take a thread dump during the long wait? That will help
> nail-down the problem. Perhaps Tomcat can be modified so that it does
> not perform this look-up.
>
>
Oh, it's my misunderstanding - I made thread dump earlier, but thought
it only being produced for non-blocked by I/O threads, so it's not complete
and useless.

Now, I reviewed old dump and made new one. That's it - "main" thread hangs
in some socket operation.

Full thread dump Java HotSpot(TM) 64-Bit Server VM (14.2-b01 mixed mode):

"Attach Listener" daemon prio=10 tid=0x00007f60aeec7000 nid=0x6275 waiting
on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"GC Daemon" daemon prio=10 tid=0x00007f60aecc3800 nid=0x6254 in
Object.wait() [0x0000000040c31000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00007f60b4e701d0> (a sun.misc.GC$LatencyLock)
at sun.misc.GC$Daemon.run(GC.java:100)
- locked <0x00007f60b4e701d0> (a sun.misc.GC$LatencyLock)

"Low Memory Detector" daemon prio=10 tid=0x00000000401a9800 nid=0x6252
runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread1" daemon prio=10 tid=0x00007f60a8001000 nid=0x6251 waiting
on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x00000000401a5000 nid=0x6250 waiting
on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00000000401a3000 nid=0x624f
runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x0000000040184800 nid=0x624e in
Object.wait() [0x0000000041e07000]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00007f60b4e70ac0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
- locked <0x00007f60b4e70ac0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x000000004017d800 nid=0x624d in
Object.wait() [0x0000000041d06000]
   java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00007f60b4e701b0> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0x00007f60b4e701b0> (a java.lang.ref.Reference$Lock)

"main" prio=10 tid=0x0000000040113000 nid=0x6243 runnable
[0x0000000041fc0000]
   java.lang.Thread.State: RUNNABLE
at java.net.PlainSocketImpl.initProto(Native Method)
at java.net.PlainSocketImpl.<clinit>(PlainSocketImpl.java:84)
at java.net.ServerSocket.setImpl(ServerSocket.java:236)
at java.net.ServerSocket.<init>(ServerSocket.java:178)
at java.net.ServerSocket.<init>(ServerSocket.java:141)
at
org.apache.tomcat.util.net.DefaultServerSocketFactory.createSocket(DefaultServerSocketFactory.java:50)
at org.apache.tomcat.util.net.JIoEndpoint.init(JIoEndpoint.java:538)
at org.apache.coyote.http11.Http11Protocol.init(Http11Protocol.java:176)
at org.apache.catalina.connector.Connector.initialize(Connector.java:1014)
at
org.apache.catalina.core.StandardService.initialize(StandardService.java:680)
- locked <0x00007f60b4ec2650> (a [Lorg.apache.catalina.connector.Connector;)
at
org.apache.catalina.core.StandardServer.initialize(StandardServer.java:795)
at org.apache.catalina.startup.Catalina.load(Catalina.java:524)
at org.apache.catalina.startup.Catalina.load(Catalina.java:548)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.apache.catalina.startup.Bootstrap.load(Bootstrap.java:261)
at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)

"VM Thread" prio=10 tid=0x0000000040176800 nid=0x624c runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x000000004011d000 nid=0x6244
runnable

"GC task thread#1 (ParallelGC)" prio=10 tid=0x000000004011f000 nid=0x6245
runnable

"GC task thread#2 (ParallelGC)" prio=10 tid=0x0000000040120800 nid=0x6246
runnable

"GC task thread#3 (ParallelGC)" prio=10 tid=0x0000000040122800 nid=0x6247
runnable

"GC task thread#4 (ParallelGC)" prio=10 tid=0x0000000040124800 nid=0x6248
runnable

"GC task thread#5 (ParallelGC)" prio=10 tid=0x0000000040126000 nid=0x6249
runnable

"GC task thread#6 (ParallelGC)" prio=10 tid=0x0000000040128000 nid=0x624a
runnable

"GC task thread#7 (ParallelGC)" prio=10 tid=0x000000004012a000 nid=0x624b
runnable

"VM Periodic Task Thread" prio=10 tid=0x00000000401ac000 nid=0x6253 waiting
on condition

JNI global references: 956

Re: Tomcat starts slow

[Christopher Schultz <ch...@christopherschultz.net>]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Maxim,

On 8/10/2010 8:58 AM, Maxim Kuleshov wrote:
>> Tomcat on my ubuntu 8.04 (x64) server starts too slow.
>>
> I resolved this problem. I strace'd tomcat's start and figured out it
> stucks in 'connect' method to ipv6 loopback (::1). Than I tcpdump'ed
> loopback and noticed many connect fails.

It could be that Tomcat is attempting to resolve the SYSTEM URL for
certain XML files it uses to configure itself. Could you re-enable the
DROP and take a thread dump during the long wait? That will help
nail-down the problem. Perhaps Tomcat can be modified so that it does
not perform this look-up.

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

iEYEARECAAYFAkxhgJoACgkQ9CaO5/Lv0PDzTQCgpjjK7H1jXJ44PGn5y/NyGjN3
rMoAnA8dMC4j5J4V9ENqP7YbEbH+uAW5
=izOO
-----END PGP SIGNATURE-----

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

Re: Tomcat starts slow

[Tobias Crefeld <tc...@cataneo.eu>]

Am Tue, 10 Aug 2010 16:58:45 +0400
schrieb Maxim Kuleshov <ma...@gmail.com>:

> But for some reason tomcat wants IPv6 connection and while time
> (retries * timeout) passed - it hangs at start.
> 
> And I even don't know - what subsystem use such kind of
> interconnection (via IPv6 loopback).

Just an idea: Tomcat is trying to establish a listener at
localhost:8005 for shutdown-requests during start. 

AFAIK you can change the port number but not the host address. Maybe
you have an /etc/hosts- or a DNS-entry that translates localhost to an
IPv6-address. 


Regards,
 Tobias.

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

Re: Tomcat starts slow

[Maxim Kuleshov <ma...@gmail.com>]

>
>
> Tomcat on my ubuntu 8.04 (x64) server starts too slow.
>
>
>
I resolved this problem. I strace'd tomcat's start and figured out it
stucks in 'connect' method to ipv6 loopback (::1). Than I tcpdump'ed
loopback and noticed many connect fails.

The problem was IPv6 policy set to drop and no any additional rules
added, even loopback pass-through (though, IPv4 configured to accept all
lo<->lo traffic).

But for some reason tomcat wants IPv6 connection and while time
(retries * timeout) passed - it hangs at start.

And I even don't know - what subsystem use such kind of interconnection
(via IPv6 loopback).