tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "BALCER, Marcin (Marcin)" <bal...@alcatel-lucent.com>
Subject Unlock accept issue
Date Tue, 28 Jul 2009 11:55:16 GMT
Hi
I am having problem when shutting down tomcat.

Tomcat: 6.0.14.
OS: Linux  2.6.16.21-0.8-smp #1 SMP Mon Jul 3 18:25:39 UTC 2006 x86_64
Java: "1.5.0_14" Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_14-b03) Java
HotSpot(TM) 64-Bit Server VM (build 1.5.0_14-b03, mixed mode)

The scenario is as follows:

org.apache.tomcat.util.net.JIoEndpoint.pause is called
        calls: unlockAccept();

org.apache.tomcat.util.net.JIoEndpoint.stop is called
        calls: unlockAccept();

The second call is not necessary when the connector has already been paused in my opinion.
Please consider changing the JioEndpoint code as follows:

  public void stop() {
        if (running) {
            running = false;
            if (!paused) {
                unlockAccept();
            }
        }
    }

The same problem exists in org.apache.tomcat.util.net.AprEndpoint


In my scenario Tomcat is stopped under heavy load. From tomcat logs I can see that most of
the "stop time" is consumed to by the unlockAccept method (see stack trace and logs below).

Tomcat log:
2009-07-28 13:34:12,914 (  ) INFO  org.apache.coyote.http11.Http11Protocol [221] - Pausing
Coyote HTTP/1.1 on http-8800
2009-07-28 13:34:13,921 (  ) INFO  org.apache.catalina.core.StandardService [576] - Stopping
service internal
2009-07-28 13:34:13,921 (  ) INFO  org.apache.catalina.core.StandardService [576] - Stopping
service internal
2009-07-28 13:35:05,290 (  ) INFO  org.apache.coyote.http11.Http11Protocol [237] - Stopping
Coyote HTTP/1.1 on http-8800
2009-07-28 13:38:14,295 (  ) INFO  org.apache.coyote.http11.Http11Protocol [221] - Pausing
Coyote HTTP/1.1 on http-7080
2009-07-28 13:38:14,295 (  ) INFO  org.apache.coyote.http11.Http11Protocol [221] - Pausing
Coyote HTTP/1.1 on http-7443
2009-07-28 13:38:15,381 (  ) INFO  org.apache.catalina.core.StandardService [576] - Stopping
service main
2009-07-28 13:38:15,381 (  ) INFO  org.apache.catalina.core.StandardService [576] - Stopping
service main
2009-07-28 13:38:15,621 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 28 instance(s) to be deallocated
2009-07-28 13:38:15,621 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 28 instance(s) to be deallocated
2009-07-28 13:38:16,737 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 24 instance(s) to be deallocated
2009-07-28 13:38:16,737 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 24 instance(s) to be deallocated
2009-07-28 13:38:17,778 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 24 instance(s) to be deallocated
2009-07-28 13:38:17,778 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 24 instance(s) to be deallocated
2009-07-28 13:38:17,885 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 75 instance(s) to be deallocated
2009-07-28 13:38:17,885 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 75 instance(s) to be deallocated
2009-07-28 13:38:19,004 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 59 instance(s) to be deallocated
2009-07-28 13:38:19,004 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 59 instance(s) to be deallocated
2009-07-28 13:38:20,044 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 47 instance(s) to be deallocated
2009-07-28 13:38:20,044 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 47 instance(s) to be deallocated
2009-07-28 13:38:20,855 (  ) INFO  org.apache.coyote.http11.Http11Protocol [237] - Stopping
Coyote HTTP/1.1 on http-7080
2009-07-28 13:38:20,859 (  ) INFO  org.apache.coyote.http11.Http11Protocol [237] - Stopping
Coyote HTTP/1.1 on http-7443
2009-07-28 13:38:20,860 (  ) INFO  org.apache.coyote.http11.Http11NioProtocol [183] - Pausing
Coyote HTTP/1.1 on http-8080
2009-07-28 13:38:20,860 (  ) INFO  org.apache.coyote.http11.Http11NioProtocol [183] - Pausing
Coyote HTTP/1.1 on http-8443
2009-07-28 13:38:21,866 (  ) INFO  org.apache.catalina.core.StandardService [576] - Stopping
service comet
2009-07-28 13:38:21,866 (  ) INFO  org.apache.catalina.core.StandardService [576] - Stopping
service comet
2009-07-28 13:38:21,867 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 84 instance(s) to be deallocated
2009-07-28 13:38:21,867 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 84 instance(s) to be deallocated
2009-07-28 13:38:22,910 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 72 instance(s) to be deallocated
2009-07-28 13:38:22,910 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 72 instance(s) to be deallocated
2009-07-28 13:38:23,954 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 63 instance(s) to be deallocated
2009-07-28 13:38:23,954 (  ) INFO  org.apache.catalina.core.StandardWrapper [1355] - Waiting
for 63 instance(s) to be deallocated
2009-07-28 13:38:24,397 (  ) INFO  org.apache.coyote.http11.Http11NioProtocol [199] - Stopping
Coyote HTTP/1.1 on http-8080
2009-07-28 13:38:24,540 (  ) INFO  org.apache.coyote.http11.Http11NioProtocol [199] - Stopping
Coyote HTTP/1.1 on http-8443

Simple listener class added to each context, host, engine, connector, service to log the event
(source code added below):

Tue Jul 28 13:34:12 CEST 2009 Event. type:before_stop Source:StandardService[internal] class:class
org.apache.catalina.core.StandardService
Tue Jul 28 13:34:13 CEST 2009 Event. type:stop Source:StandardService[internal] class:class
org.apache.catalina.core.StandardService
Tue Jul 28 13:34:13 CEST 2009 Event. type:before_stop Source:StandardEngine[internal] class:class
org.apache.catalina.core.StandardEngine
Tue Jul 28 13:34:13 CEST 2009 Event. type:stop Source:StandardEngine[internal] class:class
org.apache.catalina.core.StandardEngine
Tue Jul 28 13:34:13 CEST 2009 Event. type:before_stop Source:StandardEngine[internal].StandardHost[localhost]
class:class org.apache.catalina.core.StandardHost
Tue Jul 28 13:34:13 CEST 2009 Event. type:stop Source:StandardEngine[internal].StandardHost[localhost]
class:class org.apache.catalina.core.StandardHost
Tue Jul 28 13:34:13 CEST 2009 Event. type:before_stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/messagehandler]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:34:13 CEST 2009 Event. type:stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/messagehandler]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:34:14 CEST 2009 Event. type:after_stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/messagehandler]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:34:14 CEST 2009 Event. type:before_stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/clientregistry]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:34:14 CEST 2009 Event. type:stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/clientregistry]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:34:14 CEST 2009 Event. type:after_stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/clientregistry]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:34:14 CEST 2009 Event. type:before_stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/smtpmda]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:34:14 CEST 2009 Event. type:stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/smtpmda]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:34:15 CEST 2009 Event. type:after_stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/smtpmda]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:34:15 CEST 2009 Event. type:before_stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/smppmda]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:35:05 CEST 2009 Event. type:stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/smppmda]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:35:05 CEST 2009 Event. type:after_stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/smppmda]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:35:05 CEST 2009 Event. type:before_stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/smppmsa]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:35:05 CEST 2009 Event. type:stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/smppmsa]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:35:05 CEST 2009 Event. type:after_stop Source:StandardEngine[internal].StandardHost[localhost].StandardContext[/smppmsa]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:35:05 CEST 2009 Event. type:after_stop Source:StandardEngine[internal].StandardHost[localhost]
class:class org.apache.catalina.core.StandardHost
Tue Jul 28 13:35:05 CEST 2009 Event. type:after_stop Source:StandardEngine[internal] class:class
org.apache.catalina.core.StandardEngine
Tue Jul 28 13:35:05 CEST 2009 Event. type:stop Source:org.apache.catalina.connector.Connector@7ec78e02
class:class org.apache.catalina.connector.Connector port=8800 info:org.apache.catalina.connector.Connector/2.1
ProtocolHandlerClassNameorg.apache.coyote.http11.Http11Protocol

HERE 3min 5s

Tue Jul 28 13:38:14 CEST 2009 Event. type:after_stop Source:StandardService[internal] class:class
org.apache.catalina.core.StandardService
Tue Jul 28 13:38:14 CEST 2009 Event. type:before_stop Source:StandardService[main] class:class
org.apache.catalina.core.StandardService
Tue Jul 28 13:38:15 CEST 2009 Event. type:stop Source:StandardService[main] class:class org.apache.catalina.core.StandardService
Tue Jul 28 13:38:15 CEST 2009 Event. type:before_stop Source:StandardEngine[main] class:class
org.apache.catalina.core.StandardEngine
Tue Jul 28 13:38:15 CEST 2009 Event. type:stop Source:StandardEngine[main] class:class org.apache.catalina.core.StandardEngine
Tue Jul 28 13:38:15 CEST 2009 Event. type:before_stop Source:StandardEngine[main].StandardHost[localhost]
class:class org.apache.catalina.core.StandardHost
Tue Jul 28 13:38:15 CEST 2009 Event. type:stop Source:StandardEngine[main].StandardHost[localhost]
class:class org.apache.catalina.core.StandardHost
Tue Jul 28 13:38:15 CEST 2009 Event. type:before_stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:20 CEST 2009 Event. type:stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/]
class:class org.apache.catalina.core.StandardContext
log4j:WARN No appenders could be found for logger (org.springframework.transaction.interceptor.TransactionInterceptor).
log4j:WARN Please initialize the log4j system properly.
Tue Jul 28 13:38:20 CEST 2009 Event. type:after_stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:20 CEST 2009 Event. type:before_stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/Download]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:20 CEST 2009 Event. type:stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/Download]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:20 CEST 2009 Event. type:after_stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/Download]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:20 CEST 2009 Event. type:before_stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/tomcatMonitor]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:20 CEST 2009 Event. type:stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/tomcatMonitor]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:20 CEST 2009 Event. type:after_stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/tomcatMonitor]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:20 CEST 2009 Event. type:before_stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/manager]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:20 CEST 2009 Event. type:stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/manager]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:20 CEST 2009 Event. type:after_stop Source:StandardEngine[main].StandardHost[localhost].StandardContext[/manager]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:20 CEST 2009 Event. type:after_stop Source:StandardEngine[main].StandardHost[localhost]
class:class org.apache.catalina.core.StandardHost
Tue Jul 28 13:38:20 CEST 2009 Event. type:after_stop Source:StandardEngine[main] class:class
org.apache.catalina.core.StandardEngine
Tue Jul 28 13:38:20 CEST 2009 Event. type:stop Source:org.apache.catalina.connector.Connector@14e44dd3
class:class org.apache.catalina.connector.Connector port=7080 info:org.apache.catalina.connector.Connector/2.1
ProtocolHandlerClassNameorg.apache.coyote.http11.Http11Protocol
Tue Jul 28 13:38:20 CEST 2009 Event. type:stop Source:org.apache.catalina.connector.Connector@28278a47
class:class org.apache.catalina.connector.Connector port=7443 info:org.apache.catalina.connector.Connector/2.1
ProtocolHandlerClassNameorg.apache.coyote.http11.Http11Protocol
Tue Jul 28 13:38:20 CEST 2009 Event. type:after_stop Source:StandardService[main] class:class
org.apache.catalina.core.StandardService
Tue Jul 28 13:38:20 CEST 2009 Event. type:before_stop Source:StandardService[comet] class:class
org.apache.catalina.core.StandardService
Tue Jul 28 13:38:21 CEST 2009 Event. type:stop Source:StandardService[comet] class:class org.apache.catalina.core.StandardService
Tue Jul 28 13:38:21 CEST 2009 Event. type:before_stop Source:StandardEngine[comet] class:class
org.apache.catalina.core.StandardEngine
Tue Jul 28 13:38:21 CEST 2009 Event. type:stop Source:StandardEngine[comet] class:class org.apache.catalina.core.StandardEngine
Tue Jul 28 13:38:21 CEST 2009 Event. type:before_stop Source:StandardEngine[comet].StandardHost[localhost]
class:class org.apache.catalina.core.StandardHost
Tue Jul 28 13:38:21 CEST 2009 Event. type:stop Source:StandardEngine[comet].StandardHost[localhost]
class:class org.apache.catalina.core.StandardHost
Tue Jul 28 13:38:21 CEST 2009 Event. type:before_stop Source:StandardEngine[comet].StandardHost[localhost].StandardContext[/notifservlet]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:24 CEST 2009 Event. type:stop Source:StandardEngine[comet].StandardHost[localhost].StandardContext[/notifservlet]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:24 CEST 2009 Event. type:after_stop Source:StandardEngine[comet].StandardHost[localhost].StandardContext[/notifservlet]
class:class org.apache.catalina.core.StandardContext
Tue Jul 28 13:38:24 CEST 2009 Event. type:after_stop Source:StandardEngine[comet].StandardHost[localhost]
class:class org.apache.catalina.core.StandardHost
Tue Jul 28 13:38:24 CEST 2009 Event. type:after_stop Source:StandardEngine[comet] class:class
org.apache.catalina.core.StandardEngine
Tue Jul 28 13:38:24 CEST 2009 Event. type:stop Source:org.apache.catalina.connector.Connector@64fe7a67
class:class org.apache.catalina.connector.Connector port=8080 info:org.apache.catalina.connector.Connector/2.1
ProtocolHandlerClassNameorg.apache.coyote.http11.Http11NioProtocol
Tue Jul 28 13:38:24 CEST 2009 Event. type:stop Source:org.apache.catalina.connector.Connector@3a6bf80b
class:class org.apache.catalina.connector.Connector port=8443 info:org.apache.catalina.connector.Connector/2.1
ProtocolHandlerClassNameorg.apache.coyote.http11.Http11NioProtocol
Tue Jul 28 13:38:24 CEST 2009 Event. type:after_stop Source:StandardService[comet] class:class
org.apache.catalina.core.StandardService


The stack trace recorded by sending -QUIT signal to JVM when stop process freezes from 3 minutes:

"main" prio=1 tid=0x0000000040116130 nid=0x5695 runnable [0x00007fff40c01000..0x00007fff40c02640]
        at java.net.PlainSocketImpl.socketConnect(Native Method)
        at java.net.PlainSocketImpl.doConnect(PlainSocketImpl.java:333)
        - locked <0x00002ac3b7257bd0> (a java.net.SocksSocketImpl)
        at java.net.PlainSocketImpl.connectToAddress(PlainSocketImpl.java:195)
        at java.net.PlainSocketImpl.connect(PlainSocketImpl.java:182)
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:366)
        at java.net.Socket.connect(Socket.java:520)
        at java.net.Socket.connect(Socket.java:470)
        at java.net.Socket.<init>(Socket.java:367)
        at java.net.Socket.<init>(Socket.java:180)
        at org.apache.tomcat.util.net.JIoEndpoint.unlockAccept(JIoEndpoint.java:584)
        at org.apache.tomcat.util.net.JIoEndpoint.stop(JIoEndpoint.java:552)
        at org.apache.tomcat.util.net.JIoEndpoint.destroy(JIoEndpoint.java:561)
        at org.apache.coyote.http11.Http11Protocol.destroy(Http11Protocol.java:238)
        at org.apache.catalina.connector.Connector.stop(Connector.java:1190)
        at org.apache.catalina.core.StandardService.stop(StandardService.java:593)
        - locked <0x00002ac2915796d0> (a [Lorg.apache.catalina.connector.Connector;)
        at org.apache.catalina.core.StandardServer.stop(StandardServer.java:744)
        at org.apache.catalina.startup.Catalina.stop(Catalina.java:616)
        at org.apache.catalina.startup.Catalina.start(Catalina.java:591)
        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:585)
        at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:288)
        at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:413)


Source code of listener used for debugging:
package listeners;

import java.util.Date;

import org.apache.catalina.LifecycleEvent;
import org.apache.catalina.connector.Connector;

public class TomcatListener implements org.apache.catalina.LifecycleListener {

        public void lifecycleEvent(LifecycleEvent event) {
                if (event != null) {
                        Object source = event.getSource();
                        if (source == null) {
                                source = "null";
                        }
                        if (event.getType().equalsIgnoreCase("periodic")) {
                                return;
                        }
                        if (source instanceof Connector) {
                                Connector connector = (Connector) source;
                                System.out.println(new Date() + " Event. type:"
                                                + event.getType() + " Source:" + source +
" class:"
                                                + source.getClass() + " port=" + connector.getPort()
                                                + " info:" + connector.getInfo()
                                                + " ProtocolHandlerClassName"
                                                + connector.getProtocolHandlerClassName());
                        } else {
                                System.out.println(new Date() + " Event. type:"
                                                + event.getType() + " Source:" + source +
" class:"
                                                + source.getClass());
                        }

                }
        }

}

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


Mime
View raw message