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

Question

我使用带有 Zipkin 服务器的 Spring Cloud Feign 和 Sleuth。我的问题是，当我启用 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

我相信你有问题：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;
    }
  }

并将其与现有的 EndpointLocator 之一结合起来。您可以在以下位置找到它们：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);
    }

Answer 2

您似乎在使用Sleuth with Zipkin via HTTP。您可以尝试Sleuth with Zipkin via Spring Cloud Stream 方法。我自己没有做过基准测试，但理论上应该会提高性能。

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

Answer 3

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

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

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