记一次线上Spring和Dubbo死锁排查

问题

前不久线上发现有系统间数据没有同步,排查一通下来发现应该是 MQ 消息没有被消费,通过 MQ Console 发现,未被消费的消息全都集中的一台机器上(消息投放的queue 以及 rebalance 关系),此时我有两个怀疑,一是消费者线程挂了,二是此服务分配到的消息队列出了什么莫名的问题。由于正值业务高峰,领导第一时间重启了服务,重启后一切恢复正常。排查由于一些其它事项,也到此中断。

然而没过多久,我听到其它需求项目组在测试环境出现了相同的问题,也是消息不消费了,导致业务异常。我立马找到对应服务 dump 了线程。

我将 dump 文件通过 visualVM 打开,然后得到了很明显的提示:Found one Java-level deadlock:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
"ConsumeMessageThread_1":
waiting to lock monitor 0x00007f1350390f18 (object 0x000000008024ebc0, a java.util.concurrent.ConcurrentHashMap),
which is held by "main"
"main":
waiting to lock monitor 0x00007f1330071f18 (object 0x0000000080fb6318, a org.apache.dubbo.config.deploy.DefaultModuleDeployer),
which is held by "Thread-26"
"Thread-26":
waiting to lock monitor 0x00007f1350390f18 (object 0x000000008024ebc0, a java.util.concurrent.ConcurrentHashMap),
which is held by "main"

Java stack information for the threads listed above:
===================================================
"ConsumeMessageThread_1":
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:187)
- waiting to lock <0x000000008024ebc0> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.beans.factory.support.AbstractBeanFactory.isTypeMatch(AbstractBeanFactory.java:486)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.doGetBeanNamesForType(DefaultListableBeanFactory.java:432)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeanNamesForType(DefaultListableBeanFactory.java:403)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeansOfType(DefaultListableBeanFactory.java:515)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.getBeansOfType(DefaultListableBeanFactory.java:508)
at org.springframework.context.support.AbstractApplicationContext.getBeansOfType(AbstractApplicationContext.java:1186)
...
at org.apache.rocketmq.client.impl.consumer.ConsumeMessageConcurrentlyService$ConsumeRequest.run(ConsumeMessageConcurrentlyService.java:411)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
"main":
at org.apache.dubbo.config.deploy.DefaultModuleDeployer.startSync(DefaultModuleDeployer.java)
- waiting to lock <0x0000000080fb6318> (a org.apache.dubbo.config.deploy.DefaultModuleDeployer)
at org.apache.dubbo.config.deploy.DefaultModuleDeployer.start(DefaultModuleDeployer.java:139)
at org.apache.dubbo.config.ReferenceConfig.get(ReferenceConfig.java:228)
...
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:162)
at org.springframework.beans.factory.support.ConstructorResolver.instantiateUsingFactoryMethod(ConstructorResolver.java:588)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateUsingFactoryMethod(AbstractAutowireCapableBeanFactory.java:1173)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:1067)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:513)
at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:483)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:306)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:230)
- locked <0x000000008024ebc0> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:302)
at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:197)
at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:761)
at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:867)
at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:543)
- locked <0x00000000804b98b0> (a java.lang.Object)
at org.springframework.boot.context.embedded.EmbeddedWebApplicationContext.refresh(EmbeddedWebApplicationContext.java:122)
at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:693)
at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:360)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:303)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1118)
at org.springframework.boot.SpringApplication.run(SpringApplication.java:1107)
at com.internet.saasbillmanager.ApplicationMain.main(ApplicationMain.java:46)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)
at org.springframework.boot.loader.Launcher.launch(Launcher.java:87)
at org.springframework.boot.loader.Launcher.launch(Launcher.java:51)
at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:52)
"Thread-26":
at org.springframework.context.event.AbstractApplicationEventMulticaster.getApplicationListeners(AbstractApplicationEventMulticaster.java:185)
- waiting to lock <0x000000008024ebc0> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:128)
at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:393)
at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:347)
at org.apache.dubbo.config.spring.context.DubboDeployApplicationListener.publishEvent(DubboDeployApplicationListener.java:91)
at org.apache.dubbo.config.spring.context.DubboDeployApplicationListener.access$000(DubboDeployApplicationListener.java:47)
at org.apache.dubbo.config.spring.context.DubboDeployApplicationListener$1.onStarted(DubboDeployApplicationListener.java:70)
at org.apache.dubbo.config.spring.context.DubboDeployApplicationListener$1.onStarted(DubboDeployApplicationListener.java:62)
at org.apache.dubbo.common.deploy.AbstractDeployer.setStarted(AbstractDeployer.java:121)
at org.apache.dubbo.config.deploy.DefaultApplicationDeployer.onStarted(DefaultApplicationDeployer.java:989)
at org.apache.dubbo.config.deploy.DefaultApplicationDeployer.checkState(DefaultApplicationDeployer.java:868)
- locked <0x0000000080fa6c10> (a java.lang.Object)
at org.apache.dubbo.config.deploy.DefaultApplicationDeployer.notifyModuleChanged(DefaultApplicationDeployer.java:851)
at org.apache.dubbo.config.deploy.DefaultModuleDeployer.onModuleStarted(DefaultModuleDeployer.java:264)
at org.apache.dubbo.config.deploy.DefaultModuleDeployer.startSync(DefaultModuleDeployer.java:171)
- locked <0x0000000080fb6318> (a org.apache.dubbo.config.deploy.DefaultModuleDeployer)
at org.apache.dubbo.config.deploy.DefaultModuleDeployer.start(DefaultModuleDeployer.java:139)
at org.apache.dubbo.config.ReferenceConfig.get(ReferenceConfig.java:228)
at org.apache.dubbo.config.spring.ReferenceBean.getCallProxy(ReferenceBean.java:346)
at org.apache.dubbo.config.spring.ReferenceBean.access$100(ReferenceBean.java:99)
at org.apache.dubbo.config.spring.ReferenceBean$DubboReferenceLazyInitTargetSource.createObject(ReferenceBean.java:353)
at org.springframework.aop.target.AbstractLazyCreationTargetSource.getTarget(AbstractLazyCreationTargetSource.java:86)
- locked <0x0000000085b49868> (a org.apache.dubbo.config.spring.ReferenceBean$DubboReferenceLazyInitTargetSource)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:192)
...
at com.xxl.job.core.thread.JobThread.run(JobThread.java:152)

Found 1 deadlock.

这里有 3 个线程:

  • “ConsumeMessageThread_1” MQ 消费者线程

  • “main”: 主线程

  • “Thread-26”: XXL-JOB 执行线程

其实主要是这两个线程引发的问题:

  • “main”: 主线程

  • “Thread-26”: XXL-JOB 执行线程

MQ 消费者线程是正好撞在枪口上了。

涉及两个锁:

  • DefaultModuleDeployer:object monitor lock

  • DefaultSingletonBeanRegistry.singletonObjects:object monitor lock

暂且将第一个称为 Dubbo 锁,第二个称为 Spring 锁。

“main”: 主线程做的事情是初始化一个基础服务(Dubbo Consumer)注册到 Spring 和 Dubbo 中, 而其先获取到了 Spring 锁,再去获取 Dubbo 锁。

“Thread-26”:job 线程是由 xxljob 触发后执行一个任务,需要调用一个远程的 Dubbo 服务,于是 先获取了 Dubbo 锁,再去获取 Spring 锁。

于是两个线程就互相锁死了,而 MQ 消费者线程,也要去Bean Container 中获取 Bean,也需要获取 Spring 锁,也就卡死了。

解决方案

这个问题由于是在启动过程中发生,所以我设想了两个解决方案(没有好的契机去解决这个问题,只能等到有相关需求了),其实思路是同一个,那就是将出问题的 Bean 给延迟加载:

  • 将“基础服务”Bean 给@Lazy。
  • 将“XxlJobSpringExecutor”在spring启动完成之后再注册进容器,避免启动过程中收到任务的执行命令。

什么?Lombok有坑?

事情是这样的,前段时间有个线上bug需要我去排查:
1

首先看了CAT的调用链,并没有发现什么问题,所有的服务都是正常处理结束。

于是我要了一个traceId,去排查日志,也是没有发现什么问题。

我拉下了生产版本的代码,走查了一下逻辑,并没有发现什么大问题,所以这注定是一个细节问题。

由于这是一个可以复现的问题,所以让测试大佬在测试环境模拟了下有问题的数据,于是我开始Debug了。

一行一行代码的看,一个一个变量的watch,最终发现了问题。

2

首先是同事新增了如下代码:

3

然后数据的OwnerId都是null:

4

紧接着执行了这个removeAll:

5

可是这为什么会出问题呢?

原来是list中的对象,是同事新加的,继承了原有的对象:

6

并且使用了Lombok的Data注解。这个注解会生成equals方法:

7

removeAll是调用的equals判断对象是否相同,equals方法重写后,导致只要这两个对象的ownerId都为空就会认为相同。

可以看到一个@Data注解相当于加了6个注解:

8

怎么解决这个问题呢?既然问题出在equals,那么有没有什么办法让子类生成的equals中也能包含基类的属性呢?

是有的:

1
@EqualsAndHashCode(callSuper = true)

加上这个注解就可以了。

可以看到@Data注解做的事情太多了,会发生你意想不到的情况,实际是不太推荐无脑使用的,建议还是自己组合需要的注解。

Dubbo调用超时那些事儿

其实之前很早就看过dubbo源码中关于超时这部分的处理逻辑,但是没有记录下来,最近在某脉上看到有人问了这个问题,想着再回顾一下。

开始

从dubbo的请求开始,看看dubbo(2.6.6)在超时这块是怎么处理的:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeChannel#request(java.lang.Object, int) 
@Override
public ResponseFuture request(Object request, int timeout) throws RemotingException {
if (closed) {
throw new RemotingException(this.getLocalAddress(), null, "Failed to send request " + request + ", cause: The channel " + this + " is closed!");
}
// create request.
Request req = new Request();
req.setVersion(Version.getProtocolVersion());
req.setTwoWay(true);
req.setData(request);
DefaultFuture future = new DefaultFuture(channel, req, timeout);
try {
channel.send(req);
} catch (RemotingException e) {
future.cancel();
throw e;
}
return future;
}
阅读更多

Java双亲委派机制的妙用

最近在项目中看到一段通过easyexcel导出动态表头的实现,开始我以为是easyexcel官方的实现,其中有这样一段代码:

1
2
3
4
5
6
7
8
//将动态表头上传至ThreadLocal
saveToThreadLocal(clz, result);

private <T> void saveToThreadLocal(Class<T> clz, List<String> result) {
Map<Class,List<String>> paramMap = new ConcurrentHashMap<>();
paramMap.put(clz, result);
ThreadLocalUtil.FIELD_CACHE_MAP.set(paramMap);
}
阅读更多

Mybatis Mapper 源码分析

天天都在用的Mybatis,为啥调用一个Mapper接口就能执行SQL,你有没有想过这个问题?

这一切都得从 @MapperScan 这个注解开始说起。打开这个注解定义可以看到:

阅读更多

被Chrome一个bug坑了

1

相信Chrome浏览器开发者工具中的Preview你不陌生,但是就这玩意有一个bug。

事情是这样的,前端跟我说你接口有bug,返回的数据不正确。听到bug,我反手就是一个你会不会用。

阅读更多

Lambda应用与浅析

引入

在Java8之前创建一个线程的写法(之一):

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
public class LambdaTest {



public static void main(String[] args) {

new Thread(new Runnable() {

@Override

public void run() {

System.out.println("hello inner class!");

}

});

}

}
阅读更多

Netty中FastThreadLocal源码解析

简介

ThreadLocal一个特殊变体,当从FastThreadLocalThread访问时,可获得更高的访问性能。
在内部, FastThreadLocal在数组中使用常量索引来查找变量,而不是使用哈希码和哈希表。 尽管看似非常微妙,但与使用哈希表相比,它在性能上却有一点优势,并且在经常访问时很有用。
要利用此线程局部变量,您的线程必须是FastThreadLocalThread或其子类型。 由于这个原因,默认情况下, DefaultThreadFactory创建的所有线程均为FastThreadLocalThread
请注意,只有在扩展FastThreadLocalThread线程上才可以使用快速路径,因为它需要一个特殊的字段来存储必要的状态。 任何其他类型的线程的访问都回退到常规ThreadLocal

上面这段描述来自FastThreadLocal源码中的文档,从中可以知道FastThreadLocal必须和FastThreadLocalThread或其子类型一起使用才可以达到Fast的效果。

阅读更多

记一次线上死锁排查

前段时间偶尔会收到线上MySQL死锁告警通知,由于有补偿机制,最终业务会处理成功,所以没太关心。

1
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction

最近又收到了相同的告警,可能不是偶然事件,于是开始排查。
首先翻看了日志,结合代码,没有发现什么问题。事发时应该也没有什么大批量并发事件。

阅读更多