47670 – Unlock accept issue

Bug 47670 - Unlock accept issue

Summary: Unlock accept issue

Status:	RESOLVED DUPLICATE of bug 48470

Alias:	None

Product:	Tomcat 6
Classification:	Unclassified
Component:	Catalina (show other bugs)
Version:	6.0.14
Hardware:	PC Linux

Importance:	P2 normal (vote)
Target Milestone:	default
Assignee:	Tomcat Developers Mailing List

URL:
Keywords:

Depends on:
Blocks:

Reported:	2009-08-10 07:29 UTC by Marcin
Modified:	2010-01-11 09:44 UTC (History)
CC List:	0 users

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.

Description Marcin 2009-08-10 07:29:30 UTC

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());
			}

		}
	}

}

Comment 1 Mark Thomas 2009-12-13 16:32:51 UTC

Given that the server is heavily loaded at the time, there is clearly more more going on here than just the call to unlockAccept(). Changing the shut down code feels too like addressing the symptom rather than the cause at this point.

Before making any changes I'd like to understand what else is going on at the point where this delay occurs. Please provide 3 complete stack traces taken roughly 10s apart during the period where the delay occurs.

It would also be helpful if you could try a newer JVM and Tomcat version to see if that has any impact on the delay as I have tried various things to reproduce this and, so far, have been unable to reproduce it.

Comment 2 Mark Thomas 2010-01-11 09:44:06 UTC

I think I know what is going on here now. Bug 48470 has the explanation. A patch to fix this has been proposed for 6.0.x

*** This bug has been marked as a duplicate of bug 48470 ***