netflix-feign spring-cloud-feign zipkin spring-cloud-sleuth

Enabling Sleuth slows requests down (a lot)

I use Spring Cloud Feign and Sleuth with a Zipkin server. My problem is that when I enable Sleuth, then any simple request takes at least 600ms. Note that for tests purposes, I've set the sampler percentage of Sleuth at 1.

Can I do something to improve that?

Here some log of a request which takes 25ms without Sleuth and 700ms with Sleuth. (user calls /teams which calls /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)

Solution

I belive you had problem with: org.springframework.cloud.sleuth.zipkin.ServerPropertiesEndpointLocator.

It uses InetUtils.findFirstNonLoopbackAddress() to determine instance address. Method is called synchronously when each span is close (in ZipkinSpanListener#convert). The workaround is to create custom org.springframework.cloud.sleuth.zipkin.EndpointLocator. You can use something like that:

class CachingEndpointLocator implements EndpointLocator {

    private final Endpoint endpoint;

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

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

And combine it with one of existing EndpointLocators. You can find them in: org.springframework.cloud.sleuth.zipkin.ZipkinAutoConfiguration.

This issue is already fixed in sleuth 2.X.X. Where: org.springframework.cloud.sleuth.zipkin2.DefaultEndpointLocator caches server address:

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