一次排查Java线程数异常–线程池使用不当造成线程数升高

Java对多线程有良好的支持,并且提供了方便使用的线程池框架(Executor)。但如果使用不当,可能会带来一些不安全的隐患。本文将分享一次由于随意创建线程池造成线程数持续增加的问题。

一、背景

首先看一个图,下图是线上服务器Java线程数的监控图。

图中每个下降的点都是在该时间点有上线操作,Tomcat重启的原因。其他时间,线程数呈线性增长趋势,最高点已经快到3千了。非常恐怖!如果不是因为有频繁的上线操作,线上服务很快就会出问题。

二、问题调查分析

将监控图时间点往回拉,定位到线程数异常开始的时间点。查看当天提交记录,发现一处与线程有关的修改。代码如下:

 1    /**
 2      * 异步执行操作
 3      */
 4     private void asyncDoSomething() {
 5         ExecutorService executorService = Executors.newSingleThreadExecutor();  6         ExecutorService executorService = new ThreadPoolExecutor(1, 1, 0L, TimeUnit.MILLISECONDS, new LinkedBlockingQueue<Runnable>(1));
 7         executorService.submit(new Runnable() {
 8             @Override
 9             public void run() {
10                 // 此处仅使用示例代码
11                 System.out.println("do something async...");
12             }
13         });
14     }

我们先不讨论此处线程池使用是否正确,仅就此处修改而言,将原有 Executors.newSingleThreadExecutor() 替换为 new ThreadPoolExecutor(1, 1, 0L, TimeUnit.MILLISECONDS, new LinkedBlockingQueue<Runnable>(1)) ,似乎并无不妥(这么修改,是为了遵循阿里规约)。实现的功能都是创建一个单线程池

1.dump线程栈分析

既然代码上未发现明显问题,那就转而直接查看线上问题。执行 $jps -v 查找到Java程序对应的进程号,然后执行 $jstack ${pid_num} > thread_dump.log ,将对应Java程序的线程栈信息转储到thread_dump.log文件中。(注意,如果当前操作用户不是启动Java程序的用户,需要执行 $sudo -u user_name jstack ${pid_num} > thread_dump.log )。

截取部分线程栈信息如下:

"pool-165671-thread-1" #188938 prio=5 os_prio=0 tid=0x00007f1a38040000 nid=0x7f19 waiting on condition [0x00007f19065b9000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000dbb0a178> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
        - None

"pool-164990-thread-1" #188175 prio=5 os_prio=0 tid=0x00007f1a5402c800 nid=0x7a61 waiting on condition [0x00007f18d0d5e000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000d8c1ef78> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
        - None

线程栈信息即是在java程序中,所有线程的调用栈信息。其中包含了线程名、线程当前状态等内容。

经统计发现,当前Java程序一共有845个线程,其中803个线程处于线程阻塞等待状态:WAITING (parking)。而所有该状态的线程名字均为 pool-xxxxx-thread-1 ,即该线程属于某单线程池。

进一步分析 ThreadPoolExecutor 源码后发现,ThreadPoolExecutor 默认使用 DefaultThreadFactory 构造的线程池前缀即为pool-xxxxx-thread-1 ,如所示:

1         DefaultThreadFactory() {
2             SecurityManager s = System.getSecurityManager();
3             group = (s != null) ? s.getThreadGroup() :
4                                   Thread.currentThread().getThreadGroup();
5             namePrefix = "pool-" +
6                           poolNumber.getAndIncrement() +
7                          "-thread-";
8         }

目前基本确定问题该问题是此处使用 ThreadPoolExecutor引起的。其实原因不复杂:程序每次调用asyncDoSomething方法时,均会创建一个新的线程池来执行任务。但在执行任务后并未关闭该线程池,造成线程无法被回收,线程一直处于等待状态。因而线程数会随时间线性上升。

2.分析Executors创建线程池方式

为什么原来使用 Executors.newSingleThreadExecutor() 时未出现这个问题呢?仍然是查看源码:

1 public static ExecutorService newSingleThreadExecutor() {
2         return new FinalizableDelegatedExecutorService
3             (new ThreadPoolExecutor(1, 1,
4                                     0L, TimeUnit.MILLISECONDS,
5                                     new LinkedBlockingQueue<Runnable>()));
6}

原来该方法并不是直接new一个ThreadPoolExecutor对象返回,而是使用了一个代理类进行代理。进一步查看 FinalizableDelegatedExecutorService  源码:

1     static class FinalizableDelegatedExecutorService
2         extends DelegatedExecutorService {
3         FinalizableDelegatedExecutorService(ExecutorService executor) {
4             super(executor);
5         }
6         protected void finalize() {
7             super.shutdown(); 8         }
9     }

在这个代理类中,实现了finalize方法,并在finalize方法中关闭线程池。根据finalize的特性,在GC时会调用finalize方法。因此 Executors.newSingleThreadExecutor()在每次垃圾回收时触发未被使用的线程池关闭,所以没有出现线程数持续上升的问题。

三、总结

这个问题是由于线程池使用不当造成的。使用线程池是为了避免重复、频繁地创建、销毁线程,进而对多个线程进行复用。以上线程池的使用明显未达到该目的,并因为线程池未关闭而造成线程无法被回收,线程数持续增加。

对以上代码进行修改后如下:

1     /** 固定大小线程池:核心线程数10,最大线程数10,空闲线程存活时长120秒,等待队列无界 */
2     private static final ExecutorService EXECUTOR_SERVICE = new ThreadPoolExecutor(10,
3             10,
4             120L,
5             TimeUnit.MILLISECONDS,
6             new LinkedBlockingQueue<Runnable>(),
7             new ThreadFactoryBuilder().setNameFormat("do-something-thread-pool-%d").build(),
8             new ThreadPoolExecutor.AbortPolicy());
 1 /**
 2      * 异步执行操作
 3      */
 4     private void asyncDoSomething() {
 5         EXECUTOR_SERVICE.submit(new Runnable() {
 6             @Override
 7             public void run() {
 8                     // 此处仅使用示例代码
 9                     System.out.println("do something async...");
10                 }
11         });
12     }

定义一个统一的线程池,在每次调用asyncDoSomething方法时,都向该线程池提交一个任务。

修改后,线程数维持在一个比较稳定的量。