一、背景
近些年微服务大行其道，这就不得不说下它带来的好处。微服务可独立开发，独立部署，每个微服务都是一个完整的王国，不同业务对应不同的微服务，保证了业务的解耦，甚至可以根据业务特点选用最合适最高效的技术栈实现相应服务，实现微服务体系下采用多种语言等。但是凡事都有两面性，微服务带来好处的同时，也会引入一些其他问题，比如今天要探讨的微服务的链路追踪问题。
通常一个微服务架构的项目，由于服务数量众多，再加上业务的复杂性，通常一个请求会涉及到多个微服务的调用，这中间任何一个服务出现调用失败或者发生异常，会导致整个调用的失败，而这种错误很难去定位。所以微服务中必须实现链路追踪，这样可以跟进一个请求会涉及到哪些服务调用，服务调用的顺序是怎样的。从而可以保证每个请求步骤清晰可见，出现问题快速定位。
目前比较流行的链路追踪相关的技术有Cat、Zipkin、Pinpoint、SkyWalking等，这里主要探讨Zipkin。Zipkin是一款开源的分布式实时数据追踪系统（Distributed Tracking System），基于 Google Dapper的论文设计而来，由 Twitter 公司开发贡献。其主要功能是聚集来自各个异构系统的实时监控数据。
二、项目集成方案介绍
最近因项目需求，需要对现有SpringCloud项目进行链路追踪的集成，最后确定的技术方案为使用zipkin实现。通过对Zipkin官方文档的调研，了解到zipkin的落地方案大致可以概括为以下几种：
从上图可以看到，业务服务和zipkin传输链路数据可以基于直连的http或gRPC，或者也可以通过消息队列activemq、kafka或者rabbitmq；对于链路数据的存储，zipkin支持内存、cassandra、elasticsearch及mysql等。这里我们根据项目具体情况以及目前项目已经具有的资源，最终选用kafka作为连接业务服务和zipkinserver的通道，对链路数据使用elasticsearch存储。另外这里需要特别说明一点，基于内存存储的zipkinserver可以直接通过ui界面查看全局调用链情况；但是若存储使用其他方式，则全局调用链必须借助ZipkinDependency对存储的数据进行分析才能生成全局调用链，ZipkinDependency是一个sparkjob。
三、发现问题
确定了最终技术方案，开始着手对目前的所有服务进行集成。因为需要使用zipkin和kafka相关依赖及配置，这里为了集成方便，最终采用将这两者封装成SDK的方式，而业务服务只需要集成封装好的SDK即可。SDK封装完毕后使用自己编写的最简单的demo小项目完成了测试。
但接下来对业务项目的集成却没有那么顺利。
首先对业务网关进行了集成，集成完毕后部署测试，发现了一个奇怪的现象：在服务器上启动项目后，通过命令能够查看到相应的java进程，但是在尝试调用服务时原先没有问题的接口显示无法调用，进一步确认发现该服务对应的端口并没有被监听。
问题出现：添加了封装好的SDK后项目启动可以看到相应的java进程，但是相应接口并没有被监听。
四、 定位问题
第一点想到的是查看日志，看看是否启动时出现了错误，这里截取了日志的最后一段，由于篇幅限制之前全部省略。
……此处省略前面的日志……
2021-01-04 19:33:04,866 INFO [main] io.lettuce.core.EpollProvider.<clinit>(EpollProvider.java:64) - Starting with epoll library
2021-01-04 19:33:04,874 INFO [main] io.lettuce.core.KqueueProvider.<clinit>(KqueueProvider.java:70) - Starting without optional kqueue library
从全部的启动日志来看并没有看到明显的报错信息。但是这个日志很明显没有看到我们正常启动项目后的提示信息。
于是将引入的SDK剔除，重新启动项目，项目正常启动，可以发现服务的端口被正常监听。启动日志如下：
……此处省略前面的日志……
2021-01-04 19:44:11,764 INFO [main] io.lettuce.core.EpollProvider.<clinit>(EpollProvider.java:64) - Starting with epoll library
2021-01-04 19:44:11,774 INFO [main] io.lettuce.core.KqueueProvider.<clinit>(KqueueProvider.java:70) - Starting without optional kqueue library
……此处省略中间日志……
2021-01-04 19:44:17,275 INFO [main] org.springframework.boot.StartupInfoLogger.logStarted(StartupInfoLogger.java:61) - Started ZuulServerApplication in 19.193 seconds (JVM running for 20.482)
通过正常启动日志(下)和非正常启动日志(上)的对比可以发现：上面的日志明显只是到了正常启动的日志中间部分就停住了。
至此得出的结论：添加封装好的的SDK后，项目启动一半后就卡住，没有完成正常的启动，从而导致服务相应接口没有被监听。
接下来开始分析原因。SDK中封装有zipkin相关依赖，连接kafka的相关依赖；曾怀疑过是否由于引入的pom依赖和原先的产生了冲突；但是通过IDEA分析新引入的依赖并没有和原先依赖产生冲突。以下是SDK中封装的相关依赖。
<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-starter-zipkin</artifactId>
<version>2.2.3.RELEASE</version>
</dependency>
<dependency>
<groupId>org.springframework.kafka</groupId>
<artifactId>spring-kafka</artifactId>
<version>2.3.5.RELEASE</version>
</dependency>
为进一步确定，这次测试直接在原先项目中引入以下依赖，不引入SDK；
<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-starter-zipkin</artifactId>
<version>2.2.3.RELEASE</version>
</dependency>
再次进行测试，和引入SDK产生的结果一致，都是服务启动到一半就停止，服务器只能看到服务进程，而服务对应端口并没有被监听。至此稍微有些明朗，引入zipkin依赖导致原先项目无法正常启动。
接下来进一步确认原因，why？
尝试使用jstack命令对启动一半的java进程打印栈信息，这里省略了一些无关信息，只保留关键信息，在剔除正常运行的线程之后，找到了两个相关联但是阻塞的线程。
"lettuce-epollEventLoop-4-1" #25 daemon prio=5 os_prio=0 tid=0x00007fcd50ed4800 nid=0x3477 waiting for monitor entry [0x00007fcd024e4000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:204)
- waiting to lock <0x00000000c544a550> (a java.util.concurrent.ConcurrentHashMap)
…………………………………………
at brave.sampler.Sampler$$EnhancerBySpringCGLIB$$6916e951.isSampled(<generated>)
at brave.Tracer.decorateContext(Tracer.java:268)
at brave.Tracer.newRootContext(Tracer.java:204)
at brave.Tracer.newTrace(Tracer.java:151)
at brave.Tracer.nextSpan(Tracer.java:470)
at io.lettuce.core.tracing.BraveTracing$BraveTracer.nextSpan(BraveTracing.java:259)
…………………………………………
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:745)
"main" #1 prio=5 os_prio=0 tid=0x00007fcd50008800 nid=0x3404 waiting on condition [0x00007fcd581e6000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000f071c8b0> (a java.util.concurrent.CompletableFuture$WaitNode)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.CompletableFuture$WaitNode.block(CompletableFuture.java:271)
at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3226)
at java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:319)
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2224)
at io.lettuce.core.DefaultConnectionFuture.get(DefaultConnectionFuture.java:68)
at io.lettuce.core.AbstractRedisClient.getConnection(AbstractRedisClient.java:227)
at io.lettuce.core.RedisClient.connect(RedisClient.java:207)
…………………………………………
at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
- locked <0x00000000c544a550> (a java.util.concurrent.ConcurrentHashMap)
at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:321)
at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:52)
从以上可以获得以下一些信息：
main线程处于waiting状态，我们知道main线程是我们整个服务启动的入口，main处于waiting状态，这也解释了为什么服务启动一半卡住了。main被park，同时持有<0x00000000c544a550>锁；另外lettuce-epollEventLoop-4-1线程是BLOCK状态，它等待的正是main线程持有的<0x00000000c544a550>锁。可以看出main线程是在获取redis链接时被park(项目中确实使用了redis)，而lettuce-epollEventLoop-4-1是在执行和sleuth的Sampler初始化时需要获取main持有的锁而被阻塞，Sampler是sleuth中的采样器。
这里我们展开看一下lettuce-epollEventLoop-4-1在等待的锁到底是什么？
可以看到lettuce-epollEventLoop-4-1线程等待的锁是一个ConcurrentHashMap，我们找到DefaultSingletonBeanRegistry类中相应的getSingleton源码，可以看到这个锁正是spring容器在启动时创建bean实例时的单例对象列表，代码如下：
public class DefaultSingletonBeanRegistry extends SimpleAliasRegistry implements SingletonBeanRegistry {
private final Map<String, Object> singletonObjects = new ConcurrentHashMap<>(256);
/**省略无用代码**/
public Object getSingleton(String beanName, ObjectFactory<?> singletonFactory) {
/**省略无用代码**/
synchronized (this.singletonObjects) {
Object singletonObject = this.singletonObjects.get(beanName);
if (singletonObject == null) {
/**很多逻辑**/
}
return singletonObject;
}
}
/**省略无用代码**/
}
至此可以大致得出一个结论：加入zipkin相关依赖后，项目启动过程main线程被阻塞，是zipkin相关的采样器Sampler的初始化和Spring创建redis连接实例产生了死锁。
关于为什么会产生死锁的原因，SpringCloud的spring-cloud-sleuth子项目下有相关的issues，相应的issues和上述的现象基本一致。链接如下：https://github.com/spring-cloud/spring-cloud-sleuth/issues/1557
以下是项目的作者对产生这种现象的解释及他提供的解决方案：
By default samplers will work with the refresh scope mechanism. That means that you can change the sampling properties at runtime, refresh the application and the changes will be reflected. However, sometimes the fact of creating a proxy around samplers and calling it from too early (from @PostConstruct annotated method) may lead to dead locks. In such a case either create a sampler bean explicitly, or set the property spring.sleuth.sampler.refresh.enabled to false to disable the refresh scope support.
大致意思如下：
sleuth默认的采样器会使用spring的@RefreshScope注解机制。源码如下，可以看到默认的Sampler创建上使用了@RefreshScope注解。
@Configuration(proxyBeanMethods = false)
@ConditionalOnProperty(value = "spring.sleuth.enabled", matchIfMissing = true)
@EnableConfigurationProperties(SamplerProperties.class)
public class SamplerAutoConfiguration {
/**省略其他不相关代码*/
@Configuration(proxyBeanMethods = false)
@ConditionalOnBean(
type = "org.springframework.cloud.context.scope.refresh.RefreshScope")
protected static class RefreshScopedSamplerConfiguration {
@Bean
@RefreshScope
@ConditionalOnMissingBean
public Sampler defaultTraceSampler(SamplerProperties config) {
return samplerFromProps(config);
}
}
这虽然可以让项目在运行时更改采样器的相关属性信息，保证属性改变可以在项目运行时就被体现。但是这种情形下，过早创建这样的一个Sampler代理可能会导致死锁，但是导致死锁的原因作者并没有展开介绍。作者提供的解决方案：项目显式的创建一个采样器而不使用默认的，或者将属性spring.sleuth.sampler.refresh.enabled设置为false都可以解决这个问题。
接下来我们尝试从原理层面去理解为什么加入zipkin依赖会和redis相关产生死锁？
首先明确一点，main线程在初始化redis连接时需要持有singletonObjects这把锁， singletonObjects存放的是spring初始化的所有单例bean；创建连接时会被park，需要lettuce-epollEventLoop-4-1这个线程来unpark，lettuce-epollEventLoop-4-1负责redis的连接请求授权工作；这是前提，下面我们只需要搞清楚lettuce-epollEventLoop-4-1里面做了什么就能理解死锁的原因了。lettuce-epollEventLoop-4-1负责向redis服务器发起授权请求，然后在有zipkin依赖和没有zipkin依赖时就有了区别，分水岭在下面：
//
public class CommandHandler extends ChannelDuplexHandler implements HasQueuedCommands {
// 省略了很多其它属性
private final boolean tracingEnabled; // 是否开启追踪
// 生省略了很多其它方法
private void writeSingleCommand(ChannelHandlerContext ctx, RedisCommand<?, ?, ?> command, ChannelPromise promise) {
// 有zipkin会执行if判断中代码，否则不执行
if (tracingEnabled && command instanceof CompleteableCommand) {
// …………省略一些代码………………
Tracer.Span span = tracer.nextSpan(context);
// …………省略一些代码………………
}
ctx.write(command, promise);
}
}
以上代码是Redis的java驱动包Lettuce中的一个方法，可以看到该类中有一个属性tracingEnabled，属性表示是否开启追踪，这个属性没有添加zipkin依赖时的值为false，上述if判断中的代码不会执行，这样lettuce-epollEventLoop-4-1在执行完redis授权请求后就正常的unpark main线程，程序正常启动；当添加了zipkin依赖后，redis在初始化时能察觉到项目中已经引入了链路追踪的功能，这时tracingEnabled属性是true，会执行if判断中的代码，代码逻辑包含创建sleuth的采样器，而默认的采样器创建就是我们上面说的基于@RefreshScope注解创建的采样器；而基于@RefreshScope机制的采样器的创建是需要获取spring中的singletonObjects的锁的，而此时锁被main线程持有，这时就形成了出现死锁的最简单的那种情形。main持有锁被阻塞，需要lettuce-epollEventLoop-4-1唤醒，lettuce-epollEventLoop-4-1在执行过程中发现要获取main持有的锁，从而形成了死锁。
五、解决问题
其实明白原因后问题就好解决了，这里确定解决方案为自定义一个Sampler，这样Sampler创建就不会使用默认的基于@RefreshScope的默认创建。在原先的SDK基础上增加自定义采样器的配置，使用的是基于百分比采样的ProbabilityBasedSampler 。增加的代码如下：
@Configuration
public class SleuthSamplerConfiguration {
@Value("${sleuth.sampler.probability}")
private String probability;
@Bean
public Sampler defaultSampler() throws Exception {
Float f = new Float(probability);
SamplerProperties samplerProperties = new SamplerProperties();
samplerProperties.setProbability(f);
ProbabilityBasedSampler sampler = new ProbabilityBasedSampler(samplerProperties);
return sampler;
}
}
升级SDK，和项目集成测试，问题解决。
六、问题复盘
针对上述问题从发现到解决，在回顾整个过程时有一些反思：
- 对于项目引入新的技术需慎重，一定需要保证和项目集成测试且对原先业务不产生影响；仅仅使用demo验证远远不够，因为无法预知包含不同依赖的微服务会不会和新引入的产生冲突。
- 对于这种隐藏较深的问题的解决过程其实是不断收集碎片化信息，最后发现碎片化信息之间的关联，最后组合信息产生答案的过程；因此需要从多个角度试解问题，这样得到的信息才能更加立体化。
- 发现问题到解决问题花费了较长的时间，应该适时的和周边同事沟通，看看能不能提供不同的思路，一个人很容易陷入思维定式而走不出来。这里问题真正开始解决是在看到github上的issue和另外一篇帖子https://blog.csdn.net/u011039332/article/details/107423951，所以往往有时候你和答案之间的距离就是一句不同思维方式的建议。
