Tomcat启动停止慢问题查找解决

Tomcat启动停止慢问题查找解决

一、概述

  使用封装的tomcat组件进行web服务部署时，导致tomcat服务在服务启动和停止中用时比较长，结合tomcat的运行日志进行问题分析。

运行日志如下：

 

二、tomcat服务停止慢问题

1、现象

根据tomcat的运行日志发现，进行了3次tomcat停止操作过程中，第一次tomcat服务停止用时接近5分钟，第二次和第三次tomcat服务停止用时仅10秒。

Line 9: 30-Aug-2017 10:39:44.981 信息 [Thread-3861] org.apache.catalina.core.StandardService.stopInternal Stopping service Catalina
Line 61218: 30-Aug-2017 10:44:36.076 信息 [Thread-3861] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-apr-8081"]
Line 61219: 30-Aug-2017 10:44:36.278 信息 [Thread-3861] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["ajp-apr-8009"]
Line 61279: 30-Aug-2017 11:11:09.873 信息 [Thread-102] org.apache.catalina.core.StandardService.stopInternal Stopping service Catalina
Line 62640: 30-Aug-2017 11:11:18.030 信息 [Thread-102] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-apr-8081"]
Line 62641: 30-Aug-2017 11:11:18.084 信息 [Thread-102] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["ajp-apr-8009"]
Line 62810: 30-Aug-2017 13:54:20.342 信息 [Thread-788] org.apache.catalina.core.StandardService.stopInternal Stopping service Catalina
Line 73508: 30-Aug-2017 13:54:29.552 信息 [Thread-788] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["http-apr-8081"]
Line 73509: 30-Aug-2017 13:54:29.608 信息 [Thread-788] org.apache.coyote.AbstractProtocol.stop Stopping ProtocolHandler ["ajp-apr-8009"]

 

2、问题分析及结果

通过查看tomcat运行日志发现如下问题：

（1）通过查看tomcat日志catalina.2017-08-30.log，在关闭tomcat的 web服务时无法去掉已经注册的DruidDriver，为了内存泄漏，tomcat强制去掉了注册的DruidDriver，通过日志查看多个应用中都使用了druid连接池，并出现了这个问题。

日志：

The web application [paf]registered the JDBC driver [com.alibaba.druid.proxy.DruidDriver] but failed tounregister it when the web application was stopped. To prevent a memory leak,the JDBC Driver has been forcibly

 

结论：tomcat需要强制关闭多个DruidDirver来防止内存泄漏导致服务关闭用时过长。

解决方法：通过添加监听器，在停止服务时自动关闭注册的DruidDirver

示例代码：

@WebListener

public class ContextFinalizerimplements ServletContextListener {

 

private static final Logger LOGGER =LoggerFactory.getLogger(ContextFinalizer.class);

 

public voidcontextInitialized(ServletContextEvent sce) {

}

//停止服务时主动关闭一些资源

public voidcontextDestroyed(ServletContextEvent sce) {

   Enumeration<Driver> drivers = DriverManager.getDrivers();

   Driver d = null;

   while (drivers.hasMoreElements()) {

       try {

            d = drivers.nextElement();

            DriverManager.deregisterDriver(d);

           LOGGER.warn(String.format("Driver %s deregistered", d));

       }

       catch (SQLException ex) {

           LOGGER.warn(String.format("Error deregistering driver %s", d),ex);

       }

   }

   try {

       AbandonedConnectionCleanupThread.shutdown();

   }

   catch (InterruptedException e) {

       logger.warn("SEVERE problem cleaning up: " + e.getMessage());

       e.printStackTrace();

   }

 }

}

 

（2）通过查看tomcat日志catalina.2017-08-30.log，在关闭tomcat时会清除掉引用线程，但是无法停止线程，可能会导致内存泄漏，通过日志查看多个应用中都出现了线程无法停止的异常信息。

日志：

the web application [xxx]appears to have started a thread named [pool-Runtime-data-thread-1] but hasfailed to stop it. This is very likely to create a memory leak. Stack trace ofthread:

 sun.misc.Unsafe.park(Native Method)

 java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)

java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)

 java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)

 java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)

 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)

 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

 java.lang.Thread.run(Thread.java:748)

 

 结论：tomcat会等待应用的线程关闭之后才会将停止，由于众多线程无法正常停止，导致tomcat停止时间过长。

解决方法：服务关闭时要手动关闭服务创建的线程及线程池。

示例代码：

1.  public void contextDestroyed(ServletContextEvent sce) {    

2.        destroyThreads();    

3.  }    

4.  private void destroyThreads(){  

5.        final Set<Thread> threads = Thread.getAllStackTraces().keySet();    

6.        for (Thread thread : threads) {                

7.        if(thread.getName().equals("your thread identifier")){  

8.             synchronized (this) {    

9.               try {    

10.                 thread.stop();    

11.                   return;  

12.              } catch (Exception e) {    

13.              }    

14.         }    

15.     }    

16. }  

3、tomcat处理机制

（1）      tomcat默认提供了关闭数据库连接驱动的操作JdbcLeakPrevention类中的clearJdbcDriverRegistrations方法，但是还是要提醒开发者在服务关闭时要主动去处理操作。

public List<String>clearJdbcDriverRegistrations() throws SQLException {

       List<String> driverNames =new ArrayList<>();

 

       /*

         * DriverManager.getDrivers() has anasty side-effect of registering

         * drivers that are visible to thisclass loader but haven't yet been

         * loaded. Therefore, the first call tothis method a) gets the list

         * of originally loaded drivers and b)triggers the unwanted

         * side-effect. The second call getsthe complete list of drivers

         * ensuring that both original driversand any loaded as a result of the

         * side-effects are all de-registered.

         */

       HashSet<Driver> originalDrivers =new HashSet<>();

       Enumeration<Driver> drivers =DriverManager.getDrivers();

       while (drivers.hasMoreElements()){

           originalDrivers.add(drivers.nextElement());

       }

       drivers = DriverManager.getDrivers();

       while (drivers.hasMoreElements()){

           Driver driver = drivers.nextElement();

           // Only unload the drivers this web app loaded

           if (driver.getClass().getClassLoader() !=

                this.getClass().getClassLoader()) {

                continue;

           }

           // Only report drivers that were originallyregistered. Skip any

           // that were registered as a side-effect ofthis code.

           if (originalDrivers.contains(driver)) {

                driverNames.add(driver.getClass().getCanonicalName());

           }

           DriverManager.deregisterDriver(driver);

       }

       return driverNames;

    }

（2）      tomcat默认提供了关闭服务中的线程和线程池操作，但是开发者还是要注意在服务关闭时主动去管理线程及线程池的关闭操作，否则可能导致服务无法停止，在tomcat的WebappClassLoaderBase类中提供了clearReferencesThreads来停止线程和线程池等相关的操作，其实现原理是获取线程调用stop方法，但存在无法将线程关闭的问题。

private voidclearReferencesThreads() {

       Thread[] threads = getThreads();

       List<Thread> executorThreadsToStop = newArrayList<>();

 

       // Iterate over the set of threads

       for (Threadthread : threads) {

           if (thread!= null) {

                ClassLoader ccl = thread.getContextClassLoader();

                if(ccl ==this) {

                    //Don't warn about this thread

                    if(thread ==Thread.currentThread()) {

                        continue;

                    }

 

                    finalString threadName = thread.getName();

 

                    //JVM controlled threads

                    ThreadGroup tg = thread.getThreadGroup();

                    if(tg !=null &&JVM_THREAD_GROUP_NAMES.contains(tg.getName())) {

                        // HttpClient keep-alive threads

                        if(clearReferencesHttpClientKeepAliveThread&&

                                threadName.equals("Keep-Alive-Timer")) {

                            thread.setContextClassLoader(parent);

                            log.debug(sm.getString("webappClassLoader.checkThreadsHttpClient"));

                        }

 

                        // Don't warn about remaining JVM controlled threads

                        continue;

                    }

 

                    //Skip threads that have already died

                    if(!thread.isAlive()) {

                        continue;

                    }

 

                    //TimerThread can be stopped safely so treat separately

                    //"java.util.TimerThread" in Sun/Oracle JDK

                    //"java.util.Timer$TimerImpl" in Apache Harmony and in IBM JDK

                    if(thread.getClass().getName().startsWith("java.util.Timer") &&

                           clearReferencesStopTimerThreads) {

                       clearReferencesStopTimerThread(thread);

                        continue;

                    }

 

                    if(isRequestThread(thread)) {

                        log.warn(sm.getString("webappClassLoader.stackTraceRequestThread",

                                getContextName(), threadName,getStackTrace(thread)));

                    }else {

                        log.warn(sm.getString("webappClassLoader.stackTrace",

                                getContextName(), threadName,getStackTrace(thread)));

                    }

 

                    //Don't try an stop the threads unless explicitly

                    //configured to do so

                    if(!clearReferencesStopThreads) {

                        continue;

                    }

 

                    //If the thread has been started via an executor, try

                    //shutting down the executor

                    booleanusingExecutor = false;

                    try{

 

                        // Runnable wrappedby Thread

                        // "target" in Sun/Oracle JDK

                        // "runnable" in IBM JDK

                        // "action" in Apache Harmony

                        Object target = null;

                        for (StringfieldName : newString[] {"target","runnable","action" }){

                            try {

                                FieldtargetField = thread.getClass().getDeclaredField(fieldName);

                                targetField.setAccessible(true);

                                target = targetField.get(thread);

                                break;

                            } catch (NoSuchFieldException nfe) {

                                continue;

                            }

                        }

 

                        // "java.util.concurrent" code is in public domain,

                        // so all implementations are similar

                        if (target!= null&& target.getClass().getCanonicalName() != null &&

                                target.getClass().getCanonicalName().equals(

                                "java.util.concurrent.ThreadPoolExecutor.Worker")) {

                            Field executorField= target.getClass().getDeclaredField("this$0");

                            executorField.setAccessible(true);

                            Object executor = executorField.get(target);

                            if (executorinstanceof ThreadPoolExecutor) {

                                ((ThreadPoolExecutor)executor).shutdownNow();

                                usingExecutor = true;

                            }

                        }

                    }catch (SecurityException| NoSuchFieldException | IllegalArgumentException |

                           IllegalAccessException e) {

                        log.warn(sm.getString("webappClassLoader.stopThreadFail",

                                thread.getName(),getContextName()), e);

                    }

 

                    if(usingExecutor) {

                        // Executor may take a short time to stop all the

                        // threads. Make a note of threads that should be

                        // stopped and check them at the end of the method.

                        executorThreadsToStop.add(thread);

                    }else {

                        // This method is deprecated and for good reason. This

                        // is very risky code but is the only option at this

                        // point. A *very* good reason for apps to do this

                        // clean-up themselves.

                        thread.stop();

                    }

                }

           }

       }

 

       // If thread stopping is enabled, executorthreads should have been

       // stopped above when the executor was shutdown but that depends on the

       // thread correctly handling the interrupt.Give all the executor

       // threads a few seconds shutdown and if theyare still running

       // Give threads up to 2 seconds to shutdown

       int count =0;

       for (Threadt : executorThreadsToStop) {

           while (t.isAlive()&& count < 100) {

                try{

                    Thread.sleep(20);

                }catch (InterruptedExceptione) {

                    //Quit the while loop

                    break;

                }

                count++;

           }

           if (t.isAlive()){

                //This method is deprecated and for good reason. This is

                //very risky code but is the only option at this point.

                // A*very* good reason for apps to do this clean-up

                //themselves.

                t.stop();

           }

       }

    }

 

三、tomcat服务启动慢问题

1、war服务分析

（1）war包大小如下

（2）war加载使用时间如下

总结：

（1）      war包的大小对war包的加载没有太大的影响。

（2）      tomcat的启动时间差不多是war加载的时间和。

2、war服务启动

Tomcat启动及war服务解压初始化日志如下：

30-Aug-201713:55:22.622 信息 [localhost-startStop-1] org.apache.catalina.core.ApplicationContext.log2 Spring WebApplicationInitializers detected on classpath

30-Aug-201713:55:37.058 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Initializing Spring embeddedWebApplicationContext

30-Aug-201713:55:49.573 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log 2 SpringWebApplicationInitializers detected on classpath

30-Aug-201713:56:03.179 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Initializing Spring embeddedWebApplicationContext

30-Aug-201713:56:37.885 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log SpringWebApplicationInitializers detected on classpath:[org.springframework.boot.autoconfigure.jersey.JerseyAutoConfiguration$JerseyWebApplicationInitializer@4ac3f5e7]

30-Aug-201713:56:37.923 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Set web app root systemproperty: 'webapp.root.ems' = [E:\haitun\August\agent\product\@tomcat8_1.0.0\bin\@tomcat8.javaweb\webapps\xxs\]

30-Aug-201713:56:38.833 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Initializing log4j from[classpath:shared-log4j.xml]

30-Aug-201713:56:39.230 信息 [localhost-startStop-1] org.apache.catalina.core.ApplicationContext.logInitializing Spring root WebApplicationContext

30-Aug-201713:57:09.519 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log SpringWebApplicationInitializers detected on classpath: [org.springframework.boot.autoconfigure.jersey.JerseyAutoConfiguration$JerseyWebApplicationInitializer@81a45dc]

30-Aug-201713:57:10.040 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Initializing Spring rootWebApplicationContext

30-Aug-201713:57:22.813 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Initializing SpringFrameworkServlet 'springmvc'

30-Aug-201713:57:30.792 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Spring WebApplicationInitializersdetected on classpath:[org.springframework.boot.autoconfigure.jersey.JerseyAutoConfiguration$JerseyWebApplicationInitializer@e36e974]

30-Aug-201713:57:31.391 信息 [localhost-startStop-1] org.apache.catalina.core.ApplicationContext.logInitializing Spring root WebApplicationContext

30-Aug-201713:57:38.546 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Initializing SpringFrameworkServlet 'springmvc'

30-Aug-2017 13:57:46.634信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log SpringWebApplicationInitializers detected on classpath:[org.springframework.boot.autoconfigure.jersey.JerseyAutoConfiguration$JerseyWebApplicationInitializer@49113005]

30-Aug-201713:57:46.847 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Initializing Spring rootWebApplicationContext

30-Aug-201713:57:52.828 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Initializing SpringFrameworkServlet 'springmvc'

30-Aug-201713:57:59.493 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log SpringWebApplicationInitializers detected on classpath:[org.springframework.boot.autoconfigure.jersey.JerseyAutoConfiguration$JerseyWebApplicationInitializer@79a83d0c]

30-Aug-201713:58:03.578 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Initializing Spring rootWebApplicationContext

30-Aug-201713:58:09.144 信息 [localhost-startStop-1] org.apache.catalina.core.ApplicationContext.logInitializing Spring FrameworkServlet 'springmvc'

30-Aug-201713:58:29.092 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log 1 SpringWebApplicationInitializers detected on classpath

30-Aug-201713:58:33.209 信息 [localhost-startStop-1]org.apache.catalina.core.ApplicationContext.log Initializing SpringFrameworkServlet 'dispatcherServlet'

30-Aug-201713:59:20.591 信息 [http-apr-8081-exec-2]org.apache.catalina.core.ApplicationContext.log Initializing SpringFrameworkServlet 'dispatcherServlet'

30-Aug-201713:59:20.592 信息 [http-apr-8081-exec-7]org.apache.catalina.core.ApplicationContext.log Initializing SpringFrameworkServlet 'dispatcherServlet'

总结：日志输出正常，主要打印出了SpringBean容器初始化的日志，加载正常。通过对8个war包的分析，有几个war（xxf、pxs和rxs）加载只需要十几秒，几个war（xms、xexms）加载特别慢，其中xms用时接近70秒，xexms接近45秒，tomcat对war包的加载是串行处理的，所有的war包加载时间总和就导致应用启动过慢。此外，需要说明一点，war包的加载与war包的大小没有太大的关系，可以忽略其影响。

3、启动问题分析

通过上面启动日志分析，我们发现确实是因为war包的一些自身原因导致的war加载过慢问题，并且我们发现war的启动是按照顺序来了，猜测tomcat的处理实现机制是单线程处理的，接下来我们看tomcat处理war的实现。

Tomcat提供了war处理的方法deployWARs方法，在实现中我们发现其创建了一个线程池

ExecutorService es =host.getStartStopExecutor()

并接下来对每个war的处理都创建了一个线程并将线程DeployWar添加到线程池中

es.submit(new DeployWar(this, cn, war))

 

protectedvoid deployWARs(File appBase, String[] files){

 

        if(files ==null)

            return;

 

        ExecutorService es = host.getStartStopExecutor();

        List<Future<?>> results =new ArrayList<>();

 

        for(int i =0; i < files.length; i++){

 

            if(files[i].equalsIgnoreCase("META-INF"))

                continue;

            if(files[i].equalsIgnoreCase("WEB-INF"))

                continue;

            File war =new File(appBase, files[i]);

            if(files[i].toLowerCase(Locale.ENGLISH).endsWith(".war")&&

                    war.isFile()&&!invalidWars.contains(files[i])){

 

                ContextName cn =new ContextName(files[i],true);

 

                if(isServiced(cn.getName())){

                    continue;

                }

                if(deploymentExists(cn.getName())){

                    DeployedApplication app = deployed.get(cn.getName());

                    boolean unpackWAR = unpackWARs;

                    if(unpackWAR && host.findChild(cn.getName())instanceof StandardContext){

                        unpackWAR =((StandardContext) host.findChild(cn.getName())).getUnpackWAR();

                    }

                    if(!unpackWAR && app !=null){

                        // Need to check for a directory thatshould not be

                        // there

                        File dir =new File(appBase, cn.getBaseName());

                        if(dir.exists()){

                            if(!app.loggedDirWarning){

                                log.warn(sm.getString(

                                        "hostConfig.deployWar.hiddenDir",

                                        dir.getAbsoluteFile(),

                                        war.getAbsoluteFile()));

                                app.loggedDirWarning =true;

                            }

                        }else{

                            app.loggedDirWarning =false;

                        }

                    }

                    continue;

                }

 

                // Check for WARs with /../ /./ or similarsequences in the name

                if(!validateContextPath(appBase, cn.getBaseName())){

                    log.error(sm.getString(

                            "hostConfig.illegalWarName", files[i]));

                    invalidWars.add(files[i]);

                    continue;

                }

                //创建线程进行war处理并将线程添加到线程池中

                results.add(es.submit(new DeployWar(this, cn, war)));

            }

        }

 

       

        for(Future<?> result : results){

            try{

               result.get();

            }catch(Exception e){

                log.error(sm.getString(

                        "hostConfig.deployWar.threaded.error"), e);

            }

        }

    }

 

tomcat通过线程池来处理war服务，为什么war服务感觉还是按照单线程来处理的，实现的机制就是tomcat的ExecutorService es = host.getStartStopExecutor()默认只提供了一个线程，可以通过在tomcat的server.xml中增加配置项startStopThreads来修改线程池中线程个数。

<Hostname="localhost"  appBase="webapps"

            unpackWARs="true"autoDeploy="true"startStopThreads="8">

通过配置startStopThreads线程数可以通过多线程完成war服务的启动和停止操作，减少tomcat服务的启动和停止时间。

五、总结

1、tomcat默认配置是通过单线程来处理war服务的启动和停止的，当存在多个war服务时会影响tomcat服务的启动和停止时间，可以通过配置startStopThreads参数来通过多线程处理war服务的启动和停止，减少tomcat服务的启动和停止时间。

2、tomcat服务停止慢的一个原因是在停止war服务时需要停止war服务中的一些线程、线程池、数据库连接等其他资源，虽然tomcat默认提供了数据库和线程、线程池关闭相关的功能，但对war服务中的实现不一定起作用，需要每个war服务主动去管理在服务停止时相关资源的释放。