启用侦探会减慢请求速度(很多)

Question

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

我可以做些什么来改善这一点吗？

这里有一些请求日志，在没有侦探的情况下需要 25 毫秒，在侦探的情况下需要 700 毫秒。(用户呼叫/团队调用/城市(：

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(( 来确定实例地址。当每个跨度接近时，方法被同步调用(在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;
    }
  }

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

此问题已在侦探 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

看起来您正在通过HTTP将Sleuth与Zipkin一起使用。您可以通过Spring Cloud Stream方法尝试使用Zipkin的侦探。我自己还没有做过基准测试，但它应该在理论上提高性能。

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

Answer 3

我想知道你选择了什么样的基准测试方法。您使用的是哪个版本的侦探？这也是您正在做的一个单一基准测试吗？它在您的计算机上吗？JVM升温了吗？是否执行了任何其他进程？进行基准测试并非易事...您可以使用JMH等工具做得更好。

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

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