记录一次错误使用java.util.Timer引发的OutOfMemory事件

问题描述及背景

      最近协助排查了关于OutOfMemory的问题，项目是通过java命令启动，最初发现项目因OutOfMemory异常停止服务，结果想用kill命令停止服务时，报错：No Child Processes

       首先排查No Child Processes的原因，基本上有以下两个原因：
       1、可能是用户的线程满了导致的
       2、可能是僵尸进程太多导致

具体分析过程

1.  使用ps -ef| grep 用户名 |grep java|grep -v grep 查看用户下所有的java进程
2. 使用ps -efL | grep 用户名 | wc -l 查看用户下的线程数
3. 使用ps -efL|grep pid |grep -v grep |wc -l 查看该进程下线程的数量
4. 使用ulimit -a 查看系统设置的max user processes数是否大于第2步查询出来的线程数，不出意外的话，应该和第2部查出来的相等或稍大于
5. 根据第3步判断出该运行项目的线程创建不正常

问题定位过程

1. 因为业务流程都正常处理完了，所以首先考虑到可能是应用里哪个对象在使用后没有释放，所以排查了一下代码，发现该关闭的connection、socket和stream都关闭了。
2. 后尝试用jstack命令（jstack -l pid > 文件名），结果发现服务器上的jdk下没有jstack、jstat、jmap等工具，只能考虑先在本地复现情况，参考应用的代码，在本地写了简单的测试代码，如下：

   package com.timer;
   
   import java.lang.management.ManagementFactory;
   import java.lang.management.ThreadMXBean;
   import java.util.Date;
   import java.util.Timer;
   import java.util.TimerTask;
   
   public class TimerTestMain {
       private final Timer timer = new Timer();
       public void startService() {
           timer.schedule( new TimerTask() {
               @Override
               public void run() {
                   String processName = ManagementFactory.getRuntimeMXBean().getName();
                   System.out.println("当前进程信息：" + processName + ", 当前线程名称：" + Thread.currentThread().getName());
                   ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean();
                   System.out.println("当前时间"+ new Date() +"当前进程中的线程数：" + threadMXBean.getThreadCount());
                   TimerTestMain timerTestMain = new TimerTestMain();
                   timerTestMain.callJob();
               }
           },new Date(),1*20*1000);  // 20s执行一次
       }
   
       private void callJob() {
           System.out.println("当前线程名称：" + Thread.currentThread().getName());
           System.out.println("=============================");
       }
   
       public static void main(String[] args) {
           TimerTestMain timerTestMain = new TimerTestMain();
           timerTestMain.startService();
       }
   }
   

   其中核心的代码如下：

 

         代码运行起来的效果如下：

          

      从日志上可以看出，代码生成的进程中，线程数一直在增加，且正好和设定的执行间隔时间20s一致。

      3.在本地使用jstack -l pid命令，导出堆栈信息进行查看，发现堆栈信息里有很多"timer-*"的线程，如下图：

     

      根据以上堆栈信息，确定在进程中有很多Timer的线程在WAITING，所以就把目光定位到了Timer这个对象上。回头再来看下代码，可以发现在代码的startService()方法中，发现里边定义的TimerTask的run方法里重新顶一个了主类的对象，然后使用新对象执行calljob()方法。于是有增加了两个日志输出，以确定在哪里新建出来的线程：

      

       新代码的日志如下： 

        有以上日志，可以看出，在执行完新对象创建后，线程数增加了1。但为何加1，且继续往下看分析。让我们移步到主类TimerTestMain上，因为没有构造方法，所以定位到了私有变量Timer上，因为没有static修饰符，所以每次创建对象时，都创建一个新的Timer对象。

        为什么新建个Timer对象，就是新建一个线程呢？我们来看看Timer的构造方法：

  

 

        有以上Timer的构造函数可以看出，Timer对象在调用时都会创建一个线程，线程的run方法里调用了一个mainLoop()的方法，在该方法里会出现执行queue.wait方法(条件是任务队列queue为空且newTasksMayBeScheduled=true，这两个条件在new Timer对像时即满足。这也正式在堆栈信息里会出现：

"Timer-5" #17 prio=5 os_prio=0 tid=0x0000000018d5e000 nid=0x574 in Object.wait() [0x000000001b31f000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000d7199740> (a java.util.TaskQueue)
	at java.lang.Object.wait(Object.java:502)
	at java.util.TimerThread.mainLoop(Timer.java:526)
	- locked <0x00000000d7199740> (a java.util.TaskQueue)
	at java.util.TimerThread.run(Timer.java:505)

       我们再深入了解下Timer下一步处理，在什么时候queue.wait会继续执行。首先我们使用的时候，会先new一个Timer对象，然后再执行schedule()方法，然后我们看下schedule的实现

       在以上schedule()方法的实现中，我们可以看到，这里会把传入的Task对象加入到queue中，当加入的是第一个时，就会执行queue.notify()，结束mainLoop()中的wait()，进而调起task的run方法。

问题总结

      通过以上的分析，相信大家已经明白问题出现的原因了，接下来我们大致总结一下：

      1、对于Timer的使用，至少会创建两个线程，一个是Timer自身的守护线程，一个是任务队列中的Task线程。Timer自身的守护线程是在Timer对象创建时就会创建并启动的，且会一直等待加入Task线程后，定时调起Task线程。

      2、项目中的代码，问题就在于错误的使用了Timer对象。首先不建议在应用对象初始化时就new Timer，建议在方法中，调用schedule之前再创建实例；其次在Task的run方法中，不应该再new一个新的主类对象去调用自身的calljob()方法，直接调用即可。

      最后建议将代码调整为：

package com.timer;

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadMXBean;
import java.util.Date;
import java.util.Timer;
import java.util.TimerTask;

public class TimerTestMain {
    public void startService() {
        Timer timer = new Timer();
        timer.schedule( new TimerTask() {
            @Override
            public void run() {
                String processName = ManagementFactory.getRuntimeMXBean().getName();
                System.out.println("当前进程信息：" + processName + ", 当前线程名称：" + Thread.currentThread().getName());
                ThreadMXBean threadMXBean = ManagementFactory.getThreadMXBean();
                System.out.println("1、当前时间"+ new Date() +"当前进程中的线程数：" + threadMXBean.getThreadCount());
//                TimerTestMain timerTestMain = new TimerTestMain();
                System.out.println("2、当前时间"+ new Date() +"当前进程中的线程数：" + threadMXBean.getThreadCount());
                callJob();
                System.out.println("3、当前时间"+ new Date() +"当前进程中的线程数：" + threadMXBean.getThreadCount());
            }
        },new Date(),1*20*1000);  // 20s执行一次
    }

    private void callJob() {
        System.out.println("当前线程名称：" + Thread.currentThread().getName());
        System.out.println("=============================");
    }

    public static void main(String[] args) {
        TimerTestMain timerTestMain = new TimerTestMain();
        timerTestMain.startService();
    }
}

        再次执行，发现不会再出现之前的现象。 当然对于自动任务调度，现在有很多优秀的框架，像xxl-job、quartz等等，建议在实际使用中考虑使用这些成熟的框架。

         学无止境，在解决问题中一探究竟，多总结，多思考，方可不断进步。