tomcat-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Filip Hanik - Dev Lists <devli...@hanik.com>
Subject Re: Unlock accept issue
Date Mon, 10 Aug 2009 13:55:32 GMT
in either case, the "unlocker" thread should have set connect timeout 
and read timeout
in NIO, we do

s.connect(saddr,getSocketProperties().getUnlockTimeout());

Marcin, the best way for us to track this is for you to open a bugzilla 
issue.
http://issues.apache.org/bugzilla



On 08/10/2009 07:06 AM, BALCER, Marcin (Marcin) wrote:
> 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: dev-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: dev-help@tomcat.apache.org
>
>
>    


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


Mime
View raw message