记一次多线程与countdownlanch死锁

gpl不想说话
484 阅读5分钟

场景介绍

使用xxl-job作为定时任务分发平台，xxl-job-client中的httphandler执行器调用对用功能实现的url。总体实现了功能的定时调度，日平均5万次，有些任务耗时较多，一些任务耗时较少。

http服务侧，使用了线程池接收xxl-job-client任务的调度（失去了时间监控的功能）

@GetMapping("task_do")
public ResponseEntity<ApiResponse> taskDo() {
    taskExecuteService.addTask(new RunService("任务中心-数据同步",new Runnable() {
        @Override
        public void run() {
            dataCenterService.syncData();
        }
    }));
    return ResponseEntity.ok(ApiResponse.ofSuccess(ApiCode.Common.SYSTEM_SUCCESS));
}

runService实现内部的时间监控

public class RunService implements Runnable {
    private String name;
    private Runnable runnable;

    public RunService(String name, Runnable runnable) {
        this.name = name;
        this.runnable = runnable;
    }

    @Override
    public void run() {
        long startT = System.currentTimeMillis();
        log.info("任务名称：「{}」，开始执行:{}", name, startT);
        if (runnable != null) {
            runnable.run();
        }
        long endT = System.currentTimeMillis();
        log.info("任务名称：「{}」，结束执行:{}，耗时：{}", name, endT, endT - startT);
    }
}

死锁场景

由于业务需要，需要同步多家的数据，所以在任务的内部同样使用了线程池添加任务，外层添加countDownLatch 确认任务是否全部完成，此处使用伪代码


package com.example.demo;

import cn.hutool.core.math.MathUtil;
import cn.hutool.core.thread.NamedThreadFactory;
import cn.hutool.core.thread.ThreadUtil;
import cn.hutool.core.util.RandomUtil;
import cn.hutool.core.util.StrUtil;
import com.alibaba.fastjson.JSON;
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;

import java.math.BigDecimal;
import java.util.Arrays;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.concurrent.*;
import java.util.concurrent.atomic.AtomicInteger;

/**
 * @Classname ThreadTest
 * @Description TODO
 * @Date 2022/6/27 12:01 下午
 * @Author by
 */
@Slf4j
public class ThreadTest {
    //和生产环境保持一致
    static ExecutorService fixedThreadPool = new ThreadPoolExecutor(4, 1000, 10, TimeUnit.SECONDS, new LinkedBlockingQueue(20000), new NamedThreadFactory("定时任务执行线程",false), (r, executor) -> {
        log.warn("任务执行线程：超过线程执行数量");
        executor.execute(r);
    });
    //优化后配置
    //static ExecutorService fixedThreadPool = new ThreadPoolExecutor(50, 1000, 10, TimeUnit.SECONDS, new LinkedBlockingQueue(10), new NamedThreadFactory("定时任务执行线程-",false), (r, executor) -> {
    //    log.warn("任务执行线程：超过线程执行数量");
    //    executor.execute(r);
    //});

    //static ExecutorService fixedThreadPool2 = new ThreadPoolExecutor(50, 1000, 10, TimeUnit.SECONDS, new LinkedBlockingQueue(10), new NamedThreadFactory("业务执行线程-",false), (r, executor) -> {
    //    log.warn("业务执行线程：超过线程执行数量");
    //    executor.execute(r);
    //});
    //模拟xxl-job任务
    ScheduledExecutorService scheduledExecutorService = ThreadUtil.createScheduledExecutor(5);

    @Test
    public void test() {
        /**
         * 所发生的条件：
         *      定时任务执行慢+定时任务并发度低
         *      使用了同一个线程池：等待线程池和执行线程池相同
         */
        List<String> marketIds = Arrays.asList("1", "2", "3", "4");
        //模拟xxl-job任务添加ticker查询任务（生产环境为2分钟一次）
        scheduledExecutorService.scheduleAtFixedRate(() -> {
            //使用同一线程池，添加任务
            fixedThreadPool.execute(()->{
                log.info("开始同步数据========");
                CountDownLatch countDownLatch = new CountDownLatch(marketIds.size());
                //使用同一线程池，执行任务
                marketIds.forEach(marketEnum -> fixedThreadPool.execute(() -> {
                    try {
                        log.info("执行查询任务");
                        ThreadUtil.safeSleep(10000);
                    } catch (Exception e) {
                        log.error("数据处理", e);
                    } finally {
                        countDownLatch.countDown();
                    }
                }));
                try {
                    countDownLatch.await();
                } catch (Exception e) {

                }
                log.info("结束同步数据========");
            });
        }, 1000, 120000L, TimeUnit.MILLISECONDS);
        //模拟xxl-job添加其他任务（生产环境为2分钟一次，此处加大）
        scheduledExecutorService.scheduleAtFixedRate(() ->
                fixedThreadPool.execute(() -> {
                    log.info("执行其他任务");
                    //模拟执行其他任务耗时
                    ThreadUtil.safeSleep(RandomUtil.randomInt(1,100)*1000);
                }), 1000, 1000L, TimeUnit.MILLISECONDS);
        while (true) {
            ThreadUtil.safeSleep(60000);
        }
    }

}

09:49:12.775 [定时任务执行线程1] INFO com.example.demo.ThreadTest - 开始同步数据========
09:49:12.775 [定时任务执行线程2] INFO com.example.demo.ThreadTest - 执行其他任务
09:49:12.778 [定时任务执行线程3] INFO com.example.demo.ThreadTest - 执行查询任务
09:49:12.778 [定时任务执行线程4] INFO com.example.demo.ThreadTest - 执行查询任务
09:49:22.783 [定时任务执行线程3] INFO com.example.demo.ThreadTest - 执行查询任务
09:49:22.783 [定时任务执行线程4] INFO com.example.demo.ThreadTest - 执行查询任务
09:49:32.784 [定时任务执行线程4] INFO com.example.demo.ThreadTest - 开始同步数据========
09:49:32.784 [定时任务执行线程3] INFO com.example.demo.ThreadTest - 执行其他任务
09:49:32.784 [定时任务执行线程1] INFO com.example.demo.ThreadTest - 结束同步数据========
09:49:32.785 [定时任务执行线程1] INFO com.example.demo.ThreadTest - 开始同步数据========
09:49:42.783 [定时任务执行线程2] INFO com.example.demo.ThreadTest - 执行其他任务
09:50:16.786 [定时任务执行线程3] INFO com.example.demo.ThreadTest - 开始同步数据========
09:50:28.784 [定时任务执行线程2] INFO com.example.demo.ThreadTest - 执行其他任务
09:50:30.786 [定时任务执行线程2] INFO com.example.demo.ThreadTest - 开始同步数据========

进入死锁无其他日志

原因分析

死锁问题排查

这个问题排查比较简单，使用jstack命令可以看出命令都处于等待状态

"定时任务执行线程3" #22 prio=5 os_prio=31 cpu=1.14ms elapsed=140.44s tid=0x000000015c38f000 nid=0x6c03 waiting on condition  [0x000000016f676000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000006ceb81c48> (a java.util.concurrent.CountDownLatch$Sync)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.11/AbstractQueuedSynchronizer.java:885)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(java.base@11.0.11/AbstractQueuedSynchronizer.java:1039)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(java.base@11.0.11/AbstractQueuedSynchronizer.java:1345)
	at java.util.concurrent.CountDownLatch.await(java.base@11.0.11/CountDownLatch.java:232)
	at com.example.demo.ThreadTest.lambda$test$3(ThreadTest.java:72)
	at com.example.demo.ThreadTest$$Lambda$307/0x0000000800187c40.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

   Locked ownable synchronizers:
	- <0x00000006cec39f78> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"定时任务执行线程4" #23 prio=5 os_prio=31 cpu=1.00ms elapsed=140.44s tid=0x000000015ead6000 nid=0x8803 waiting on condition  [0x000000016f882000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000006cea013a8> (a java.util.concurrent.CountDownLatch$Sync)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(java.base@11.0.11/AbstractQueuedSynchronizer.java:885)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(java.base@11.0.11/AbstractQueuedSynchronizer.java:1039)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(java.base@11.0.11/AbstractQueuedSynchronizer.java:1345)
	at java.util.concurrent.CountDownLatch.await(java.base@11.0.11/CountDownLatch.java:232)
	at com.example.demo.ThreadTest.lambda$test$3(ThreadTest.java:72)
	at com.example.demo.ThreadTest$$Lambda$307/0x0000000800187c40.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

   Locked ownable synchronizers:
	- <0x00000006cec3a358> (a java.util.concurrent.ThreadPoolExecutor$Worker)

问题分析

如果仅从代码上分析，是不可能产生死锁的，线上环境正常运行两天。 问题主要在于对同一线程队列资源的抢占和不和预期的时间消耗，此处模拟比较极端。 问题点：

  • 核心线程为4，队列长度为20000，意味短时间无法新增更多线程
  • 同步任务有4个，无法快速完成执行任务
  • 其他任务占用，使线程池中的其他线程始终无法处理同步任务，导致外部线程一直wait
  • 一旦wait，意味着核心线程数被消耗，从4 -> 3 -> 2 -> 1 逐步消耗完成

未理解的问题

  • 队列是按先进先出的方式,只能臆想的判定，定时任务优先级更高，比内部添加的任务更高

问题确认

  • 使用了同一个线程池执行，消耗就意味着执行线程减少（fixedThreadPool在内外两层都使用了）
  • 线程池扩展理解错误，只有队列满了之后，才会扩展线程执行,达到难度较大
10:16:11.993 [pool-1-thread-2] INFO com.example.demo.ThreadTest - 线程数:4,活动线程数:4,线程池数量:1000,队列总数:409
  • 核心线程数配置较少，一旦发生极端情况，数据同步比较慢，就很容易发生线程等待，即死锁（比较特殊，等待线程资源释放）

优化

  • 核心线程数配置优化，队列最大数优化（模拟压测）
  • 定时任务接收线程池和内部业务线程池分离。保障定时任务执行其他线程

其他

线上故障，绩效无了。

慎重使用多线程。

avatar
文章
阅读
粉丝