前言
事件起因源自一条报警
这个之前 SRE 添加的报警机制，报警经常出现在业务高峰，中途过十几分钟又会恢复正常；
暂时无线上问题，最近事情比较多，也没有时间跟踪报警（当报警非常多的时候，就和没有报警是一个效果）
排查步骤
最近临近大促，报警日渐频繁，需要排除系统风险
先找到一台机器，碰碰运气
这里不得不说，arthas 是个非常好使的工具 -- 真香
查询所有 BLOCKED 状态线程信息
arthas@1]$ thread --state BLOCKEDThreads Total: 963, NEW: 0, RUNNABLE: 137, BLOCKED: 29, WAITING: 541, TIMED_WAITING: 256, TERMINATED: 0
复制代码
列出结果：
ID NAME GROUP PRIORITY STATE %CPU DELTA_TIME TIME INTERRUPTED DAEMON 33962 pool-34-thread-1855 main 5 BLOCKED 0.06 0.000 0:2.019 false false 33814 pool-34-thread-1836 main 5 BLOCKED 0.0 0.000 0:1.455 false false 33819 pool-34-thread-1841 main 5 BLOCKED 0.0 0.000 0:1.789 false false 33821 pool-34-thread-1843 main 5 BLOCKED 0.0 0.000 0:0.977 false false 33822 pool-34-thread-1844 main 5 BLOCKED 0.0 0.000 0:1.857 false false 33963 pool-34-thread-1856 main 5 BLOCKED 0.0 0.000 0:0.983 false false 33964 pool-34-thread-1857 main 5 BLOCKED 0.0 0.000 0:0.861 false false 33966 pool-34-thread-1859 main 5 BLOCKED 0.0 0.000 0:1.287 false false 33967 pool-34-thread-1860 main 5 BLOCKED 0.0 0.000 0:1.555 false false 34224 pool-34-thread-1875 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34225 pool-34-thread-1876 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34226 pool-34-thread-1877 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34227 pool-34-thread-1878 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34228 pool-34-thread-1879 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34229 pool-34-thread-1880 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34230 pool-34-thread-1881 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34231 pool-34-thread-1882 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34232 pool-34-thread-1883 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34233 pool-34-thread-1884 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34234 pool-34-thread-1885 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34235 pool-34-thread-1886 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34236 pool-34-thread-1887 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34237 pool-34-thread-1888 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34238 pool-34-thread-1889 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34239 pool-34-thread-1890 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34240 pool-34-thread-1891 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34241 pool-34-thread-1892 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34242 pool-34-thread-1893 main 5 BLOCKED 0.0 0.000 0:0.000 false false 34243 pool-34-thread-1894 main 5 BLOCKED 0.0 0.000 0:0.000 false false
复制代码
排查具体线程 - 查看调用栈
查询结果
"pool-34-thread-1836" Id=33814 BLOCKED on com.google.common.eventbus.Subscriber$SynchronizedSubscriber@45b1236e owned by "pool-34-thread-1857" Id=33964 at com.google.common.eventbus.Subscriber$SynchronizedSubscriber.invokeSubscriberMethod(Subscriber.java:153) - blocked on com.google.common.eventbus.Subscriber$SynchronizedSubscriber@45b1236e at com.google.common.eventbus.Subscriber$1.run(Subscriber.java:80) 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:748)
复制代码
注意：上述两步不一定能拿到预期结果，
1. 因为 dubbo 的软负载，路由的不一定是当前机器；
2. 案发现场比较难抓，很有可能抓的时候，线程状态已经变了；
多试几次，总会有想要的结果
事后分析
配置监控观察信息
按 POD 分组
根据上一步的堆栈信息查看代码
EventBus 问题（摘自：Guava 问题排查文档）
先简单介绍下 EventBus，在业务逻辑中存在一种订阅发布的场景，跨服务的订阅发布可以使用 mq 等实现，内存中就可以使用 Guava EventBus 来实现：
单个时间 Event 可以被多个订阅方法去处理。
为了理解其中的实现逻辑，预计查看了 EventBus 实现类：
首先 EventBus 会获取所有注册的 @Subscribe 方法：
会根据 @Subscribe 的方法去创建一个 Subscriber：
创建的 Subscriber 有两类，这里有一个判断条件 isDeclaredThreadSafe(method)：
如果这个 Subscriber 申明了 @AllowConcurrentEvents 注解，则 new Subscriber(bus, listener, method)，如果没有申明了则 new SynchronizedSubscriber(bus, listener, method);
继续查看了 SynchronizedSubscriber：
SynchronizedSubscriber 在调用业务逻辑的时候，会使用 synchronized 块加锁，也就是说给了多线程但实际依旧是多线程抢占锁然后顺序执行，这样映射上面查看的 30 个线程池中只有一个线程在执行，其他的均 BLOCKED，BLOCKED 的线程都在等待锁。
继续验证此问题，诊断了 invokeSubscriberMethod 执行的耗时：
trace com.google.common.eventbus.Subscriber invokeSubscriberMethod
复制代码
从结果来看，invokeSubscriberMethod 执行时间要 200ms+，也 200ms 的开销也就是线程抢占所等待的时间，到此问题已经确认。
结论
Google guava 中的 AsyncEventBus 组件默认是同步处理，使用多线程但未设置 @AllowConcurrentEvents 会出现多线程之间的抢锁情况；
项目中，每类订阅者 Subscriber 是单例的，所以默认的 SynchronizedSubscriber 中 synchronized(this)，会导致该订阅者的所有任务是串行的；
生产者是多线程执行，就会导致订阅者阻塞
解决方案
因为订阅者执行任务，没有依赖关系可以最简单粗暴 添加 @AllowConcurrentEvents
个人建议：业务代码中异步执行事件，一定要做到原子化（方便扩展，遇到性能问题可以通过水平扩容解决）；
及时关注异常 - 千里之堤毁于蚁穴
参见文章：https://zhuanlan.zhihu.com/p/516710052 解决方案
参考文章
线程状态：
https://blog.csdn.net/hellozhxy/article/details/94739510
arthas 使用文档
https://arthas.aliyun.com/doc/thread.html
Guava 问题排查文档
https://zhuanlan.zhihu.com/p/516710052
评论