一、错误详情:

         我使用@Scheduled注解设置了一个定时任务,每两分钟去特定的网站采集数据,但是我发现运行了一段时间以后定时任务就停止了。已经两分钟过去了,但是定时任务并没有执行。

获取dubbo线程池活跃 dubbo线程池耗尽排查_java

 而且CPU和内存并没有什么异常。

获取dubbo线程池活跃 dubbo线程池耗尽排查_.net_02

二、错误排查:

一、线程日志排查法

1、先使用ps -ef | grep 应用名称 命令找到java程序的进程。

红色框部分就是应用的pid

获取dubbo线程池活跃 dubbo线程池耗尽排查_定时任务_03

2.然后通过 jstack -l PID > ./jstack.log 命令输出该进程下所有线程状态的文件

获取dubbo线程池活跃 dubbo线程池耗尽排查_获取dubbo线程池活跃_04

4.查看刚输出的jstack.log文件,查看线程详情

        因为@Scheduled的原理是在Spring启动的时候会创建一个只有一个线程的线程池,并用这个线程去执行线程任务,而且这个线程的名称通常带有schedule,我们在线程文件中寻找即可。可以发现,该线程一直处于运行状态,且停留在业务代码的57行。我们需要去看看57行代码写了什么。

获取dubbo线程池活跃 dubbo线程池耗尽排查_获取dubbo线程池活跃_05

 

"scheduling-1" #37 prio=5 os_prio=0 tid=0x00007fe6ac4e4800 nid=0xf125 runnable [0x00007fe68f2f2000]
    java.lang.Thread.State: RUNNABLE
     at java.net.SocketInputStream.socketRead0(Native Method)
     at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
     at java.net.SocketInputStream.read(SocketInputStream.java:171)
     at java.net.SocketInputStream.read(SocketInputStream.java:141)
     at sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:475)
     at sun.security.ssl.SSLSocketInputRecord.readFully(SSLSocketInputRecord.java:458)
     at sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(SSLSocketInputRecord.java:242)
     at sun.security.ssl.SSLSocketInputRecord.decode(SSLSocketInputRecord.java:180)
     at sun.security.ssl.SSLTransport.decode(SSLTransport.java:111)
     at sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1323)
     at sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1292)
     - locked <0x00000000fe9df980> (a sun.security.ssl.SSLSocketImpl)
     at sun.security.ssl.SSLSocketImpl.access$300(SSLSocketImpl.java:76)
     at sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:948)
     at java.io.BufferedInputStream.read1(BufferedInputStream.java:284)
     at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
     - locked <0x00000000feae2ab8> (a java.io.BufferedInputStream)
     at sun.net.www.http.ChunkedInputStream.fastRead(ChunkedInputStream.java:244)
     at sun.net.www.http.ChunkedInputStream.read(ChunkedInputStream.java:689)
     - locked <0x00000000feaf6bb0> (a sun.net.www.http.ChunkedInputStream)
     at java.io.FilterInputStream.read(FilterInputStream.java:133)
     at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(HttpURLConnection.java:3482)
     at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
     at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
     at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
     - locked <0x00000000feaf7f78> (a java.io.InputStreamReader)
     at java.io.InputStreamReader.read(InputStreamReader.java:184)
     at java.io.BufferedReader.fill(BufferedReader.java:161)
     at java.io.BufferedReader.readLine(BufferedReader.java:324)
     - locked <0x00000000feaf7f78> (a java.io.InputStreamReader)
     at java.io.BufferedReader.readLine(BufferedReader.java:389)
     at com.haiwang.hotel.task.ScheduleTask.testScheduleTask(ScheduleTask.java:57)
     at sun.reflect.GeneratedMethodAccessor8.invoke(Unknown Source)
     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
     at java.lang.reflect.Method.invoke(Method.java:498)
     at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84)
     at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
     at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:95)
     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
     at java.util.concurrent.FutureTask.run(FutureTask.java:266)
     at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
     at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
     at java.lang.Thread.run(Thread.java:750)

        可以看到第57行是一个循环读取响应的代码,服务器可能陷入了循环读取代码的陷阱。我怀疑是对方服务器不响应,导致我们这里一直无法读取。

获取dubbo线程池活跃 dubbo线程池耗尽排查_获取dubbo线程池活跃_06

        而且通过对调用修饰的分析发现监视器的拥有者都是和读相关的一些类,从这里也可以判断出,这个项目的读操作有问题,项目一直处于读的状态。因此需要设置读操作的超时时间。

获取dubbo线程池活跃 dubbo线程池耗尽排查_获取dubbo线程池活跃_07

 于是我加了超时时间,以防读取时间太久。

获取dubbo线程池活跃 dubbo线程池耗尽排查_获取dubbo线程池活跃_08

二、使用Arthas排查

1、启动 arthas

运行以下命令后会出现下面的画面:

curl -O https://arthas.aliyun.com/arthas-boot.jar

之后再运行一下命令出现对应的可以监听的应用:

java -jar arthas-boot.jar

获取dubbo线程池活跃 dubbo线程池耗尽排查_定时任务_09

 我们只有一个应用输入1即可,之后就会出现下面的画面

获取dubbo线程池活跃 dubbo线程池耗尽排查_.net_10

 2、查询线程状况

输入thread --all, 显示所有匹配的线程,出现下面的画面

获取dubbo线程池活跃 dubbo线程池耗尽排查_.net_11

         找到对应的线程,使用thread id命令, 显示指定线程的运行堆栈。发现该线程一直处于运行状态,且一直停留在第57行,发现了错误的罪魁祸首。

获取dubbo线程池活跃 dubbo线程池耗尽排查_获取dubbo线程池活跃_12

三、解决方法:

错误代码:

@Component
@Log4j2
public class ScheduleTask {

    @Autowired
    private SecondUserMapper secondUserMapper;

    @Scheduled(cron = "0 0/2 * * * ?") //定时任务注解+cron表达式
    public void testScheduleTask() throws IOException, InterruptedException {
        List<String> urlList = secondUserMapper.getRandomUrlList();
        Thread.sleep(3000);
        for (String s : urlList) {
            URL url = new URL(s);

            // 打开连接
            HttpURLConnection connection = (HttpURLConnection) url.openConnection();

            // 设置请求方法为GET
            connection.setRequestMethod("GET");
            // 添加自定义的请求头信息
            String agent = secondUserMapper.getRandomAgent();
            connection.addRequestProperty("User-Agent", agent);
            connection.addRequestProperty("Accept-Language", "en-US,en;q=0.9");

            // 获取服务器返回的状态码
            int responseCode = connection.getResponseCode();

            if (responseCode == HttpURLConnection.HTTP_OK) {
                // 读取服务器返回的数据
                BufferedReader reader = new BufferedReader(new InputStreamReader(connection.getInputStream()));

                String line;
                StringBuilder response = new StringBuilder();

                while ((line = reader.readLine()) != null) {
                    response.append(line);
                }

                reader.close();

                System.out.println("Server Response:" + responseCode);
            } else {
                System.out.println("Error Code: " + responseCode);
            }

            // 关闭连接
            connection.disconnect();
        }
        log.info("线程名称为{},线程状态为{}",Thread.currentThread().getName(),Thread.currentThread().getState().name());

    }
}

正确代码:

增加超时时间即可

@Component
@Log4j2
public class ScheduleTask {

    @Autowired
    private SecondUserMapper secondUserMapper;

    @Scheduled(cron = "0 0/2 * * * ?") //定时任务注解+cron表达式
    public void testScheduleTask() throws IOException, InterruptedException {
        List<String> urlList = secondUserMapper.getRandomUrlList();
        Thread.sleep(3000);
        for (String s : urlList) {
            URL url = new URL(s);

            // 打开连接
            HttpURLConnection connection = (HttpURLConnection) url.openConnection();

            // 设置请求方法为GET
            connection.setRequestMethod("GET");
            connection.setConnectTimeout(100000);
            connection.setReadTimeout(100000);
            // 添加自定义的请求头信息
            String agent = secondUserMapper.getRandomAgent();
            connection.addRequestProperty("User-Agent", agent);
            connection.addRequestProperty("Accept-Language", "en-US,en;q=0.9");

            // 获取服务器返回的状态码
            int responseCode = connection.getResponseCode();

            if (responseCode == HttpURLConnection.HTTP_OK) {
                // 读取服务器返回的数据
                BufferedReader reader = new BufferedReader(new InputStreamReader(connection.getInputStream()));

                String line;
                StringBuilder response = new StringBuilder();

                while ((line = reader.readLine()) != null) {
                    response.append(line);
                }

                reader.close();

                System.out.println("Server Response:" + responseCode);
            } else {
                System.out.println("Error Code: " + responseCode);
            }

            // 关闭连接
            connection.disconnect();
        }
        log.info("线程名称为{},线程状态为{}",Thread.currentThread().getName(),Thread.currentThread().getState().name());

    }
}

 之后定时任务就按时执行了

四、错误总结:

1、小批量的线程占用并不会对内存与CPU产生较大影响,但是却很影响业务

        例如上面的错误,只是一个线程占用而已,并没有对CPU和内存造成影响。即使我们平常用的线程池有32个线程,也不会对CPU和内存造成影响,这类错误很难察觉,一般的运维工具也无法监听出来。但是在我们的工作中线程池被占用满了就无法处理任务,在并发量大的情况下,即使占满一分钟都会对业务造成毁灭性打击,因此一定要注意。

2、不能用线程状态来判断是否被占用

        我们一般认为线程处于blocked状态的时候线程才是处于阻塞状态,但是这个状态只是对于计算机来说的。对于我们来说,只要业务不执行了,线程就是处于阻塞状态的,因此任何状态下的线程对于业务来说都是阻塞的。 我这个项目是爬虫项目,会去爬取别人网站的数据,有些网站识别爬虫之后不仅会拒绝你访问,还会通过一直不给响应使得你的服务器线程占满,进而导致你的爬虫服务器崩溃。

3、有些成熟的HTTP请求工具也是不设置超时时间的,需要注意

        类似于HttpClient,RestTemplate等HTTP请求工具的某些版本是不会自动设置超时时间的,还有一些第三方的SDK也是这样的,因此需要手动设置超时时间,否则会出现线程池耗尽的问题。

参考文章: 

thread | arthas