启用 Sleuth 会减慢请求速度（很多）

Question

我将 Spring Cloud Feign 和 Sleuth 与 Zipkin 服务器一起使用。我的问题是，当我启用 Sleuth 时，任何简单的请求都至少需要 600 毫秒。请注意，出于测试目的，我将 Sleuth 的采样器百分比设置为 1。

我可以做些什么来改善它吗？

这里有一些请求日志，没有 Sleuth 需要 25 毫秒，有 Sleuth 需要 700 毫秒。（用户调用 /teams 调用 /cities）：

13:46:46.064 [http-nio-8080-exec-3] DEBUG o.s.c.s.instrument.web.TraceFilter - Received a request to uri [/teams] that should not be sampled [false]
13:46:46.064 [http-nio-8080-exec-3] DEBUG o.s.c.s.instrument.web.TraceFilter - No parent span present - creating a new span
13:46:46.065 [http-nio-8080-exec-3] DEBUG o.s.web.servlet.DispatcherServlet - DispatcherServlet with name 'dispatcherServlet' processing GET request for [/teams]
13:46:46.078 [http-nio-8080-exec-3] DEBUG o.s.c.s.i.w.TraceHandlerInterceptor - Handling span [Trace: 99b8ae8aa88157a6, Span: 99b8ae8aa88157a6, Parent: null, exportable:true]
13:46:46.078 [http-nio-8080-exec-3] DEBUG o.s.c.s.i.w.TraceHandlerInterceptor - Adding a method tag with value [getTeams] to a span [Trace: 99b8ae8aa88157a6, Span: 99b8ae8aa88157a6, Parent: null, exportable:true]
13:46:46.078 [http-nio-8080-exec-3] DEBUG o.s.c.s.i.w.TraceHandlerInterceptor - Adding a class tag with value [TeamService] to a span [Trace: 99b8ae8aa88157a6, Span: 99b8ae8aa88157a6, Parent: null, exportable:true]
13:46:46.083 [hystrix-cities-2] DEBUG o.s.c.s.i.h.SleuthHystrixConcurrencyStrategy$HystrixTraceCallable - Continuing span [Trace: 99b8ae8aa88157a6, Span: 99b8ae8aa88157a6, Parent: null, exportable:true]
13:46:46.084 [hystrix-cities-2] DEBUG o.s.c.s.i.w.c.feign.TraceFeignClient - Created new Feign span [Trace: 99b8ae8aa88157a6, Span: 4cea0c5e2e662ea3, Parent: 99b8ae8aa88157a6, exportable:true]
13:46:46.084 [hystrix-cities-2] DEBUG o.s.c.s.i.w.c.feign.TraceFeignClient - The modified request equals GET http://localhost:8080/cities HTTP/1.1
X-B3-ParentSpanId: 99b8ae8aa88157a6
X-B3-Sampled: 1
X-B3-TraceId: 99b8ae8aa88157a6
X-Span-Name: http:/cities
X-B3-SpanId: 4cea0c5e2e662ea3

13:46:46.101 [http-nio-8080-exec-5] DEBUG o.s.c.s.instrument.web.TraceFilter - Received a request to uri [/cities] that should not be sampled [false]
13:46:46.101 [http-nio-8080-exec-5] DEBUG o.s.c.s.instrument.web.TraceFilter - Found a parent span [Trace: 99b8ae8aa88157a6, Span: 4cea0c5e2e662ea3, Parent: 99b8ae8aa88157a6, exportable:true] in the request
13:46:46.101 [http-nio-8080-exec-5] DEBUG o.s.c.s.instrument.web.TraceFilter - Parent span is [Trace: 99b8ae8aa88157a6, Span: 4cea0c5e2e662ea3, Parent: 99b8ae8aa88157a6, exportable:true]
13:46:46.101 [http-nio-8080-exec-5] DEBUG o.s.b.w.f.OrderedRequestContextFilter - Bound request context to thread: org.apache.catalina.connector.RequestFacade@36324069
13:46:46.101 [http-nio-8080-exec-5] DEBUG o.s.web.servlet.DispatcherServlet - DispatcherServlet with name 'dispatcherServlet' processing GET request for [/cities]
13:46:46.105 [http-nio-8080-exec-5] DEBUG o.s.c.s.i.w.TraceHandlerInterceptor - Handling span [Trace: 99b8ae8aa88157a6, Span: 4cea0c5e2e662ea3, Parent: 99b8ae8aa88157a6, exportable:true]
13:46:46.105 [http-nio-8080-exec-5] DEBUG o.s.c.s.i.w.TraceHandlerInterceptor - Adding a method tag with value [getCities] to a span [Trace: 99b8ae8aa88157a6, Span: 4cea0c5e2e662ea3, Parent: 99b8ae8aa88157a6, exportable:true]
13:46:46.105 [http-nio-8080-exec-5] DEBUG o.s.c.s.i.w.TraceHandlerInterceptor - Adding a class tag with value [cityService] to a span [Trace: 99b8ae8aa88157a6, Span: 4cea0c5e2e662ea3, Parent: 99b8ae8aa88157a6, exportable:true]
13:46:46.106 [http-nio-8080-exec-5] DEBUG o.s.w.s.m.m.a.RequestResponseBodyMethodProcessor - Written [com.citymanager.entity.City@320dc277] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@33bb3f86]
13:46:46.107 [http-nio-8080-exec-5] DEBUG o.s.c.s.instrument.web.TraceFilter - Trying to send the parent span [Trace: 99b8ae8aa88157a6, Span: 4cea0c5e2e662ea3, Parent: 99b8ae8aa88157a6, exportable:true] to Zipkin
13:46:46.107 [http-nio-8080-exec-5] DEBUG o.s.c.s.z.ServerPropertiesEndpointLocator - Span will contain serviceName [city-manager]
13:46:46.109 [hystrix-cities-2] DEBUG o.s.c.s.i.w.c.feign.TraceFeignClient - Closing Feign span and logging CR [Trace: 99b8ae8aa88157a6, Span: 4cea0c5e2e662ea3, Parent: 99b8ae8aa88157a6, exportable:true]
13:46:46.109 [hystrix-cities-2] DEBUG o.s.c.s.i.w.c.feign.TraceFeignClient - Closing Feign span [Trace: 99b8ae8aa88157a6, Span: 4cea0c5e2e662ea3, Parent: 99b8ae8aa88157a6, exportable:true]
13:46:46.109 [hystrix-cities-2] DEBUG o.s.c.s.z.ServerPropertiesEndpointLocator - Span will contain serviceName [city-manager]
13:46:46.459 [http-nio-8080-exec-5] DEBUG o.s.c.s.instrument.web.TraceFilter - Closing the span [Trace: 99b8ae8aa88157a6, Span: 4cea0c5e2e662ea3, Parent: 99b8ae8aa88157a6, exportable:true] since the response was successful
13:46:46.464 [hystrix-cities-2] DEBUG o.s.w.c.HttpMessageConverterExtractor - Reading [class com.citymanager.entity.City] as "application/json;charset=UTF-8" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@33bb3f86]
13:46:46.465 [hystrix-cities-2] DEBUG o.s.c.s.i.h.SleuthHystrixConcurrencyStrategy$HystrixTraceCallable - Detaching span since it was continued [Trace: 99b8ae8aa88157a6, Span: 99b8ae8aa88157a6, Parent: null, exportable:true]
13:46:46.466 [http-nio-8080-exec-3] DEBUG o.s.w.s.m.m.a.RequestResponseBodyMethodProcessor - Written [com.citymanager.entity.Team@3c35ed9b] as "application/json" using [org.springframework.http.converter.json.MappingJackson2HttpMessageConverter@33bb3f86]
13:46:46.466 [http-nio-8080-exec-3] DEBUG o.s.web.servlet.DispatcherServlet - Successfully completed request
13:46:46.467 [http-nio-8080-exec-3] DEBUG o.s.c.s.instrument.web.TraceFilter - Closing the span [Trace: 99b8ae8aa88157a6, Span: 99b8ae8aa88157a6, Parent: null, exportable:true] since the response was successful
13:46:46.467 [http-nio-8080-exec-3] DEBUG o.s.c.s.z.ServerPropertiesEndpointLocator - Span will contain serviceName [city-manager]
13:46:46.857 [AsyncReporter(org.springframework.cloud.sleuth.zipkin.RestTemplateSender@42519b72)] DEBUG o.s.web.client.RestTemplate - Created POST request for "http://localhost:9411/api/v1/spans"
13:46:46.857 [AsyncReporter(org.springframework.cloud.sleuth.zipkin.RestTemplateSender@42519b72)] DEBUG o.s.web.client.RestTemplate - Setting request Accept header to [text/plain, application/json, application/*+json, */*]
13:46:46.857 [AsyncReporter(org.springframework.cloud.sleuth.zipkin.RestTemplateSender@42519b72)] DEBUG o.s.web.client.RestTemplate - Writing [[B@1aecb2f4] as "application/json" using [org.springframework.http.converter.ByteArrayHttpMessageConverter@4414cc2d]
13:46:46.885 [AsyncReporter(org.springframework.cloud.sleuth.zipkin.RestTemplateSender@42519b72)] DEBUG o.s.web.client.RestTemplate - POST request for "http://localhost:9411/api/v1/spans" resulted in 202 (null)

Answer 1

您似乎在使用 Sleuth with Zipkin via HTTP. You can try the Sleuth with Zipkin via Spring Cloud Stream 方法。我自己没做过benchmark，不过理论上应该能提升性能。

请参阅文档：https://cloud.spring.io/spring-cloud-sleuth/spring-cloud-sleuth.html#_sleuth_with_zipkin_via_spring_cloud_stream

Answer 2

不知道您选择了什么样的基准测试方法。您使用的是哪个版本的 Sleuth？这也是您正在做的单一基准测试吗？它在你的电脑上吗？ JVM 变热了吗？是否执行了其他进程？做基准测试不是那么容易...您可以使用像 JMH 这样的工具来做得更好。

顺便说一句，尝试关闭 DEBUG 日志记录级别并再次检查结果。

我们正在对 Sleuth 进行基准测试，从我们看到的情况来看，添加 Sleuth 后延迟增加了大约 20 毫秒。绝对不是 600 毫秒。

Answer 3

我相信您遇到了以下问题：org.springframework.cloud.sleuth.zipkin.ServerPropertiesEndpointLocator。

它使用InetUtils.findFirstNonLoopbackAddress() 来确定实例地址。当每个 span 关闭时（在 ZipkinSpanListener#convert 中），方法被同步调用。解决方法是创建自定义 org.springframework.cloud.sleuth.zipkin.EndpointLocator。您可以使用类似的东西：

class CachingEndpointLocator implements EndpointLocator {

    private final Endpoint endpoint;

    CachingEndpointLocator(EndpointLocator delegate) {
      this.endpoint = delegate.local();
    }

    @Override
    public Endpoint local() {
      return endpoint;
    }
  }

并将其与现有的 EndpointLocators 之一结合。您可以在以下位置找到它们：org.springframework.cloud.sleuth.zipkin.ZipkinAutoConfiguration.

此问题已在 sleuth 2.X.X 中修复。其中：org.springframework.cloud.sleuth.zipkin2.DefaultEndpointLocator缓存服务器地址：

    public DefaultEndpointLocator(Registration registration,
            ServerProperties serverProperties, Environment environment,
            ZipkinProperties zipkinProperties, InetUtils inetUtils) {
        this.registration = registration;
        this.serverProperties = serverProperties;
        this.environment = environment;
        this.zipkinProperties = zipkinProperties;
        this.firstNonLoopbackAddress = findFirstNonLoopbackAddress(inetUtils);
    }

启用 Sleuth 会减慢请求速度（很多）

Enabling Sleuth slows requests down (a lot)

zipkin

netflix-feign

spring-cloud-feign

spring-cloud-sleuth