一芭概、背景

近些年微服務(wù)大行其道辛蚊，這就不得不說下它帶來的好處污它。微服務(wù)可獨(dú)立開發(fā)石景，獨(dú)立部署，每個(gè)微服務(wù)都是一個(gè)完整的王國(guó)菇夸，不同業(yè)務(wù)對(duì)應(yīng)不同的微服務(wù)悼院，保證了業(yè)務(wù)的解耦淮逊，甚至可以根據(jù)業(yè)務(wù)特點(diǎn)選用最合適最高效的技術(shù)棧實(shí)現(xiàn)相應(yīng)服務(wù)侠坎，實(shí)現(xiàn)微服務(wù)體系下采用多種語言等蚁趁。但是凡事都有兩面性，微服務(wù)帶來好處的同時(shí)实胸，也會(huì)引入一些其他問題他嫡，比如今天要探討的微服務(wù)的鏈路追蹤問題。
通常一個(gè)微服務(wù)架構(gòu)的項(xiàng)目庐完，由于服務(wù)數(shù)量眾多涮瞻，再加上業(yè)務(wù)的復(fù)雜性，通常一個(gè)請(qǐng)求會(huì)涉及到多個(gè)微服務(wù)的調(diào)用假褪，這中間任何一個(gè)服務(wù)出現(xiàn)調(diào)用失敗或者發(fā)生異常，會(huì)導(dǎo)致整個(gè)調(diào)用的失敗近顷，而這種錯(cuò)誤很難去定位生音。所以微服務(wù)中必須實(shí)現(xiàn)鏈路追蹤宁否，這樣可以跟進(jìn)一個(gè)請(qǐng)求會(huì)涉及到哪些服務(wù)調(diào)用，服務(wù)調(diào)用的順序是怎樣的缀遍。從而可以保證每個(gè)請(qǐng)求步驟清晰可見慕匠，出現(xiàn)問題快速定位。
目前比較流行的鏈路追蹤相關(guān)的技術(shù)有Cat域醇、Zipkin台谊、Pinpoint、SkyWalking等譬挚，這里主要探討Zipkin锅铅。Zipkin是一款開源的分布式實(shí)時(shí)數(shù)據(jù)追蹤系統(tǒng)（Distributed Tracking System），基于 Google Dapper的論文設(shè)計(jì)而來减宣，由 Twitter 公司開發(fā)貢獻(xiàn)盐须。其主要功能是聚集來自各個(gè)異構(gòu)系統(tǒng)的實(shí)時(shí)監(jiān)控?cái)?shù)據(jù)。

二漆腌、項(xiàng)目集成方案介紹

最近因項(xiàng)目需求贼邓，需要對(duì)現(xiàn)有SpringCloud項(xiàng)目進(jìn)行鏈路追蹤的集成，最后確定的技術(shù)方案為使用zipkin實(shí)現(xiàn)闷尿。通過對(duì)Zipkin官方文檔的調(diào)研塑径，了解到zipkin的落地方案大致可以概括為以下幾種：

從上圖可以看到，業(yè)務(wù)服務(wù)和zipkin傳輸鏈路數(shù)據(jù)可以基于直連的http或gRPC填具，或者也可以通過消息隊(duì)列activemq统舀、kafka或者rabbitmq；對(duì)于鏈路數(shù)據(jù)的存儲(chǔ)灌旧，zipkin支持內(nèi)存绑咱、cassandra、elasticsearch及mysql等枢泰。這里我們根據(jù)項(xiàng)目具體情況以及目前項(xiàng)目已經(jīng)具有的資源描融，最終選用kafka作為連接業(yè)務(wù)服務(wù)和zipkinserver的通道，對(duì)鏈路數(shù)據(jù)使用elasticsearch存儲(chǔ)衡蚂。另外這里需要特別說明一點(diǎn)窿克，基于內(nèi)存存儲(chǔ)的zipkinserver可以直接通過ui界面查看全局調(diào)用鏈情況；但是若存儲(chǔ)使用其他方式毛甲，則全局調(diào)用鏈必須借助ZipkinDependency對(duì)存儲(chǔ)的數(shù)據(jù)進(jìn)行分析才能生成全局調(diào)用鏈年叮，ZipkinDependency是一個(gè)sparkjob。

三玻募、發(fā)現(xiàn)問題

確定了最終技術(shù)方案只损，開始著手對(duì)目前的所有服務(wù)進(jìn)行集成。因?yàn)樾枰褂脄ipkin和kafka相關(guān)依賴及配置，這里為了集成方便跃惫，最終采用將這兩者封裝成SDK的方式叮叹，而業(yè)務(wù)服務(wù)只需要集成封裝好的SDK即可。SDK封裝完畢后使用自己編寫的最簡(jiǎn)單的demo小項(xiàng)目完成了測(cè)試爆存。
但接下來對(duì)業(yè)務(wù)項(xiàng)目的集成卻沒有那么順利蛉顽。
首先對(duì)業(yè)務(wù)網(wǎng)關(guān)進(jìn)行了集成，集成完畢后部署測(cè)試先较，發(fā)現(xiàn)了一個(gè)奇怪的現(xiàn)象：在服務(wù)器上啟動(dòng)項(xiàng)目后携冤，通過命令能夠查看到相應(yīng)的java進(jìn)程，但是在嘗試調(diào)用服務(wù)時(shí)原先沒有問題的接口顯示無法調(diào)用闲勺，進(jìn)一步確認(rèn)發(fā)現(xiàn)該服務(wù)對(duì)應(yīng)的端口并沒有被監(jiān)聽曾棕。
問題出現(xiàn)：添加了封裝好的SDK后項(xiàng)目啟動(dòng)可以看到相應(yīng)的java進(jìn)程，但是相應(yīng)接口并沒有被監(jiān)聽霉翔。

四睁蕾、 定位問題

第一點(diǎn)想到的是查看日志，看看是否啟動(dòng)時(shí)出現(xiàn)了錯(cuò)誤债朵，這里截取了日志的最后一段子眶，由于篇幅限制之前全部省略。

……此處省略前面的日志……
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

從全部的啟動(dòng)日志來看并沒有看到明顯的報(bào)錯(cuò)信息序芦。但是這個(gè)日志很明顯沒有看到我們正常啟動(dòng)項(xiàng)目后的提示信息臭杰。
于是將引入的SDK剔除，重新啟動(dòng)項(xiàng)目谚中，項(xiàng)目正常啟動(dòng)渴杆，可以發(fā)現(xiàn)服務(wù)的端口被正常監(jiān)聽。啟動(dòng)日志如下：

……此處省略前面的日志……
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)

通過正常啟動(dòng)日志(下)和非正常啟動(dòng)日志(上)的對(duì)比可以發(fā)現(xiàn)：上面的日志明顯只是到了正常啟動(dòng)的日志中間部分就停住了宪塔。
至此得出的結(jié)論：添加封裝好的的SDK后磁奖，項(xiàng)目啟動(dòng)一半后就卡住，沒有完成正常的啟動(dòng)某筐，從而導(dǎo)致服務(wù)相應(yīng)接口沒有被監(jiān)聽比搭。
接下來開始分析原因。SDK中封裝有zipkin相關(guān)依賴南誊，連接kafka的相關(guān)依賴身诺；曾懷疑過是否由于引入的pom依賴和原先的產(chǎn)生了沖突；但是通過IDEA分析新引入的依賴并沒有和原先依賴產(chǎn)生沖突抄囚。以下是SDK中封裝的相關(guān)依賴霉赡。

        <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>

為進(jìn)一步確定，這次測(cè)試直接在原先項(xiàng)目中引入以下依賴幔托，不引入SDK穴亏；

        <dependency>
            <groupId>org.springframework.cloud</groupId>
            <artifactId>spring-cloud-starter-zipkin</artifactId>
            <version>2.2.3.RELEASE</version>
        </dependency>

再次進(jìn)行測(cè)試，和引入SDK產(chǎn)生的結(jié)果一致，都是服務(wù)啟動(dòng)到一半就停止迫肖，服務(wù)器只能看到服務(wù)進(jìn)程锅劝，而服務(wù)對(duì)應(yīng)端口并沒有被監(jiān)聽。至此稍微有些明朗蟆湖，引入zipkin依賴導(dǎo)致原先項(xiàng)目無法正常啟動(dòng)。
接下來進(jìn)一步確認(rèn)原因玻粪，why隅津？
嘗試使用jstack命令對(duì)啟動(dòng)一半的java進(jìn)程打印棧信息，這里省略了一些無關(guān)信息劲室，只保留關(guān)鍵信息伦仍，在剔除正常運(yùn)行的線程之后，找到了兩個(gè)相關(guān)聯(lián)但是阻塞的線程很洋。

"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狀態(tài)充蓝，我們知道m(xù)ain線程是我們整個(gè)服務(wù)啟動(dòng)的入口，main處于waiting狀態(tài)喉磁，這也解釋了為什么服務(wù)啟動(dòng)一半卡住了谓苟。main被park，同時(shí)持有<0x00000000c544a550>鎖协怒；另外lettuce-epollEventLoop-4-1線程是BLOCK狀態(tài)涝焙，它等待的正是main線程持有的<0x00000000c544a550>鎖≡邢荆可以看出main線程是在獲取redis鏈接時(shí)被park(項(xiàng)目中確實(shí)使用了redis)仑撞，而lettuce-epollEventLoop-4-1是在執(zhí)行和sleuth的Sampler初始化時(shí)需要獲取main持有的鎖而被阻塞，Sampler是sleuth中的采樣器妖滔。
這里我們展開看一下lettuce-epollEventLoop-4-1在等待的鎖到底是什么隧哮？
可以看到lettuce-epollEventLoop-4-1線程等待的鎖是一個(gè)ConcurrentHashMap，我們找到DefaultSingletonBeanRegistry類中相應(yīng)的getSingleton源碼座舍，可以看到這個(gè)鎖正是spring容器在啟動(dòng)時(shí)創(chuàng)建bean實(shí)例時(shí)的單例對(duì)象列表沮翔，代碼如下：

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;
        }
    }
    /**省略無用代碼**/
}

至此可以大致得出一個(gè)結(jié)論：加入zipkin相關(guān)依賴后，項(xiàng)目啟動(dòng)過程main線程被阻塞簸州，是zipkin相關(guān)的采樣器Sampler的初始化和Spring創(chuàng)建redis連接實(shí)例產(chǎn)生了死鎖鉴竭。

關(guān)于為什么會(huì)產(chǎn)生死鎖的原因，SpringCloud的spring-cloud-sleuth子項(xiàng)目下有相關(guān)的issues岸浑，相應(yīng)的issues和上述的現(xiàn)象基本一致搏存。鏈接如下：https://github.com/spring-cloud/spring-cloud-sleuth/issues/1557
以下是項(xiàng)目的作者對(duì)產(chǎn)生這種現(xiàn)象的解釋及他提供的解決方案：
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默認(rèn)的采樣器會(huì)使用spring的@RefreshScope注解機(jī)制。源碼如下矢洲，可以看到默認(rèn)的Sampler創(chuàng)建上使用了@RefreshScope注解璧眠。

@Configuration(proxyBeanMethods = false)
@ConditionalOnProperty(value = "spring.sleuth.enabled", matchIfMissing = true)
@EnableConfigurationProperties(SamplerProperties.class)
public class SamplerAutoConfiguration {

        /**省略其他不相關(guān)代碼*/

    @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);
        }
    }

這雖然可以讓項(xiàng)目在運(yùn)行時(shí)更改采樣器的相關(guān)屬性信息，保證屬性改變可以在項(xiàng)目運(yùn)行時(shí)就被體現(xiàn)。但是這種情形下责静，過早創(chuàng)建這樣的一個(gè)Sampler代理可能會(huì)導(dǎo)致死鎖袁滥，但是導(dǎo)致死鎖的原因作者并沒有展開介紹。作者提供的解決方案：項(xiàng)目顯式的創(chuàng)建一個(gè)采樣器而不使用默認(rèn)的灾螃，或者將屬性spring.sleuth.sampler.refresh.enabled設(shè)置為false都可以解決這個(gè)問題题翻。

接下來我們嘗試從原理層面去理解為什么加入zipkin依賴會(huì)和redis相關(guān)產(chǎn)生死鎖？
首先明確一點(diǎn)腰鬼，main線程在初始化redis連接時(shí)需要持有singletonObjects這把鎖嵌赠， singletonObjects存放的是spring初始化的所有單例bean；創(chuàng)建連接時(shí)會(huì)被park熄赡，需要lettuce-epollEventLoop-4-1這個(gè)線程來unpark姜挺，lettuce-epollEventLoop-4-1負(fù)責(zé)redis的連接請(qǐng)求授權(quán)工作；這是前提彼硫，下面我們只需要搞清楚lettuce-epollEventLoop-4-1里面做了什么就能理解死鎖的原因了炊豪。lettuce-epollEventLoop-4-1負(fù)責(zé)向redis服務(wù)器發(fā)起授權(quán)請(qǐng)求，然后在有zipkin依賴和沒有zipkin依賴時(shí)就有了區(qū)別拧篮，分水嶺在下面：

// 
public class CommandHandler extends ChannelDuplexHandler implements HasQueuedCommands {
    // 省略了很多其它屬性    
    private final boolean tracingEnabled;  // 是否開啟追蹤    
    // 生省略了很多其它方法
    private void writeSingleCommand(ChannelHandlerContext ctx, RedisCommand<?, ?, ?> command, ChannelPromise promise) {
        // 有zipkin會(huì)執(zhí)行if判斷中代碼词渤，否則不執(zhí)行
        if (tracingEnabled && command instanceof CompleteableCommand) {
            // …………省略一些代碼………………
            Tracer.Span span = tracer.nextSpan(context);
            // …………省略一些代碼………………
        }
        ctx.write(command, promise);
    }
}

以上代碼是Redis的java驅(qū)動(dòng)包Lettuce中的一個(gè)方法，可以看到該類中有一個(gè)屬性tracingEnabled他托，屬性表示是否開啟追蹤掖肋，這個(gè)屬性沒有添加zipkin依賴時(shí)的值為false，上述if判斷中的代碼不會(huì)執(zhí)行赏参，這樣lettuce-epollEventLoop-4-1在執(zhí)行完redis授權(quán)請(qǐng)求后就正常的unpark main線程志笼，程序正常啟動(dòng)；當(dāng)添加了zipkin依賴后把篓，redis在初始化時(shí)能察覺到項(xiàng)目中已經(jīng)引入了鏈路追蹤的功能纫溃，這時(shí)tracingEnabled屬性是true，會(huì)執(zhí)行if判斷中的代碼韧掩，代碼邏輯包含創(chuàng)建sleuth的采樣器紊浩，而默認(rèn)的采樣器創(chuàng)建就是我們上面說的基于@RefreshScope注解創(chuàng)建的采樣器；而基于@RefreshScope機(jī)制的采樣器的創(chuàng)建是需要獲取spring中的singletonObjects的鎖的疗锐，而此時(shí)鎖被main線程持有坊谁，這時(shí)就形成了出現(xiàn)死鎖的最簡(jiǎn)單的那種情形。main持有鎖被阻塞滑臊，需要lettuce-epollEventLoop-4-1喚醒口芍，lettuce-epollEventLoop-4-1在執(zhí)行過程中發(fā)現(xiàn)要獲取main持有的鎖，從而形成了死鎖雇卷。

五鬓椭、解決問題

其實(shí)明白原因后問題就好解決了颠猴，這里確定解決方案為自定義一個(gè)Sampler，這樣Sampler創(chuàng)建就不會(huì)使用默認(rèn)的基于@RefreshScope的默認(rèn)創(chuàng)建小染。在原先的SDK基礎(chǔ)上增加自定義采樣器的配置翘瓮，使用的是基于百分比采樣的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;
  }
}

升級(jí)SDK裤翩，和項(xiàng)目集成測(cè)試资盅，問題解決。

六踊赠、問題復(fù)盤

針對(duì)上述問題從發(fā)現(xiàn)到解決律姨，在回顧整個(gè)過程時(shí)有一些反思：

1. 對(duì)于項(xiàng)目引入新的技術(shù)需慎重，一定需要保證和項(xiàng)目集成測(cè)試且對(duì)原先業(yè)務(wù)不產(chǎn)生影響臼疫；僅僅使用demo驗(yàn)證遠(yuǎn)遠(yuǎn)不夠，因?yàn)闊o法預(yù)知包含不同依賴的微服務(wù)會(huì)不會(huì)和新引入的產(chǎn)生沖突扣孟。
2. 對(duì)于這種隱藏較深的問題的解決過程其實(shí)是不斷收集碎片化信息烫堤，最后發(fā)現(xiàn)碎片化信息之間的關(guān)聯(lián)，最后組合信息產(chǎn)生答案的過程凤价；因此需要從多個(gè)角度試解問題鸽斟，這樣得到的信息才能更加立體化。
3. 發(fā)現(xiàn)問題到解決問題花費(fèi)了較長(zhǎng)的時(shí)間利诺，應(yīng)該適時(shí)的和周邊同事溝通富蓄，看看能不能提供不同的思路，一個(gè)人很容易陷入思維定式而走不出來慢逾。這里問題真正開始解決是在看到github上的issue和另外一篇帖子https://blog.csdn.net/u011039332/article/details/107423951立倍，所以往往有時(shí)候你和答案之間的距離就是一句不同思維方式的建議。