From cd2e2c2d49b85209451794a4de2f454faba983e3 Mon Sep 17 00:00:00 2001 From: Marcin Grzejszczak Date: Wed, 30 Oct 2019 13:09:30 +0100 Subject: [PATCH] Configure Reactor instrumentation to wrap onLastOperator or onEachOperator with this feature we would allow user to pick whether they instrument on each or on last operator. fixes gh-1478 --- .../SpringWebFluxOnLastBenchmark.java | 29 +++++ .../main/asciidoc/spring-cloud-sleuth.adoc | 4 + .../reactor/SleuthReactorProperties.java | 18 ++- .../TraceReactorAutoConfiguration.java | 113 ++++++++++++++++-- ...utoConfigurationAccessorConfiguration.java | 9 +- .../reactor/sample/FlatMapTests.java | 30 +++++ 6 files changed, 191 insertions(+), 12 deletions(-) create mode 100644 benchmarks/src/main/java/org/springframework/cloud/sleuth/benchmarks/jmh/benchmarks/SpringWebFluxOnLastBenchmark.java diff --git a/benchmarks/src/main/java/org/springframework/cloud/sleuth/benchmarks/jmh/benchmarks/SpringWebFluxOnLastBenchmark.java b/benchmarks/src/main/java/org/springframework/cloud/sleuth/benchmarks/jmh/benchmarks/SpringWebFluxOnLastBenchmark.java new file mode 100644 index 000000000..b050885a6 --- /dev/null +++ b/benchmarks/src/main/java/org/springframework/cloud/sleuth/benchmarks/jmh/benchmarks/SpringWebFluxOnLastBenchmark.java @@ -0,0 +1,29 @@ +/* + * Copyright 2013-2019 the original author or authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * https://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.springframework.cloud.sleuth.benchmarks.jmh.benchmarks; + +public class SpringWebFluxOnLastBenchmark extends SpringWebFluxBenchmarks { + + @Override + protected String[] runArgs() { + return new String[] { "--spring.jmx.enabled=false", + "--spring.application.name=defaultTraceContextWithOnLastOperator", + "--spring.sleuth.enabled=true", + "--spring.sleuth.reactor.on-each-operator=false" }; + } + +} diff --git a/docs/src/main/asciidoc/spring-cloud-sleuth.adoc b/docs/src/main/asciidoc/spring-cloud-sleuth.adoc index 64c226409..b6778a884 100644 --- a/docs/src/main/asciidoc/spring-cloud-sleuth.adoc +++ b/docs/src/main/asciidoc/spring-cloud-sleuth.adoc @@ -1413,6 +1413,10 @@ IMPORTANT: We don't support baggage propagation for JMS We instrument the Zuul Ribbon integration by enriching the Ribbon requests with tracing information. To disable Zuul support, set the `spring.sleuth.zuul.enabled` property to `false`. +=== Project Reactor + +For projects depending on Project Reactor such as Spring Cloud Gateway, we suggest turning the `spring.sleuth.reactor.decorate-on-each` option to `false`. That way an increased performance gain should be observed in comparison to the standard instrumentation mechanism. What this option does is it will wrap decorate `onLast` operator instead of `onEach` which will result in creation of far fewer objects. The downside of this is that when Project Reactor will change threads, the trace propagation will continue without issues, however anything relying on the `ThreadLocal` such as e.g. MDC entries can be buggy. + == Running examples You can see the running examples deployed in the https://run.pivotal.io/[Pivotal Web Services]. diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/reactor/SleuthReactorProperties.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/reactor/SleuthReactorProperties.java index 01e06c6ae..5ad4bea31 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/reactor/SleuthReactorProperties.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/reactor/SleuthReactorProperties.java @@ -24,7 +24,7 @@ import org.springframework.boot.context.properties.ConfigurationProperties; * @author Marcin Grzejszczak * @since 2.0.2 */ -@ConfigurationProperties("spring.sleuth.reactor.enabled") +@ConfigurationProperties("spring.sleuth.reactor") public class SleuthReactorProperties { /** @@ -32,6 +32,14 @@ public class SleuthReactorProperties { */ private boolean enabled = true; + /** + * When true decorates on each operator, will be less performing, but logging will + * always contain the tracing entries in each operator. When false decorates on last + * operator, will be more performing, but logging might not always contain the tracing + * entries. + */ + private boolean decorateOnEach = true; + public boolean isEnabled() { return this.enabled; } @@ -40,4 +48,12 @@ public class SleuthReactorProperties { this.enabled = enabled; } + public boolean isDecorateOnEach() { + return this.decorateOnEach; + } + + public void setDecorateOnEach(boolean decorateOnEach) { + this.decorateOnEach = decorateOnEach; + } + } diff --git a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/reactor/TraceReactorAutoConfiguration.java b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/reactor/TraceReactorAutoConfiguration.java index af5751e0f..bc94169e9 100644 --- a/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/reactor/TraceReactorAutoConfiguration.java +++ b/spring-cloud-sleuth-core/src/main/java/org/springframework/cloud/sleuth/instrument/reactor/TraceReactorAutoConfiguration.java @@ -27,6 +27,7 @@ import reactor.core.scheduler.Schedulers; import org.springframework.beans.BeansException; import org.springframework.beans.factory.BeanFactory; +import org.springframework.beans.factory.annotation.Autowired; import org.springframework.beans.factory.config.ConfigurableListableBeanFactory; import org.springframework.beans.factory.support.BeanDefinitionRegistry; import org.springframework.beans.factory.support.BeanDefinitionRegistryPostProcessor; @@ -35,11 +36,18 @@ import org.springframework.boot.autoconfigure.condition.ConditionalOnBean; import org.springframework.boot.autoconfigure.condition.ConditionalOnClass; import org.springframework.boot.autoconfigure.condition.ConditionalOnMissingBean; import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty; +import org.springframework.boot.context.properties.EnableConfigurationProperties; +import org.springframework.cloud.context.scope.refresh.RefreshScope; +import org.springframework.cloud.context.scope.refresh.RefreshScopeRefreshedEvent; import org.springframework.cloud.sleuth.instrument.async.TraceableScheduledExecutorService; import org.springframework.cloud.sleuth.instrument.web.TraceWebFluxAutoConfiguration; +import org.springframework.context.ApplicationListener; import org.springframework.context.ConfigurableApplicationContext; import org.springframework.context.annotation.Bean; import org.springframework.context.annotation.Configuration; +import org.springframework.core.env.ConfigurableEnvironment; + +import static org.springframework.cloud.sleuth.instrument.reactor.TraceReactorAutoConfiguration.TraceReactorConfiguration.SLEUTH_TRACE_REACTOR_KEY; /** * {@link org.springframework.boot.autoconfigure.EnableAutoConfiguration @@ -53,6 +61,7 @@ import org.springframework.context.annotation.Configuration; @ConditionalOnProperty(value = "spring.sleuth.reactor.enabled", matchIfMissing = true) @ConditionalOnClass(Mono.class) @AutoConfigureAfter(TraceWebFluxAutoConfiguration.class) +@EnableConfigurationProperties(SleuthReactorProperties.class) public class TraceReactorAutoConfiguration { static final String SLEUTH_REACTOR_EXECUTOR_SERVICE_KEY = "sleuth"; @@ -66,6 +75,32 @@ public class TraceReactorAutoConfiguration { private static final Log log = LogFactory.getLog(TraceReactorConfiguration.class); + @Autowired + BeanFactory beanFactory; + + @PreDestroy + public void cleanupHooks() { + if (log.isTraceEnabled()) { + log.trace("Cleaning up hooks"); + } + SleuthReactorProperties reactorProperties = this.beanFactory + .getBean(SleuthReactorProperties.class); + if (reactorProperties.isDecorateOnEach()) { + if (log.isTraceEnabled()) { + log.trace("Resetting onEach operator instrumentation"); + } + Hooks.resetOnEachOperator(SLEUTH_TRACE_REACTOR_KEY); + } + else { + if (log.isTraceEnabled()) { + log.trace("Resetting onLast operator instrumentation"); + } + Hooks.resetOnLastOperator(SLEUTH_TRACE_REACTOR_KEY); + } + Schedulers + .removeExecutorServiceDecorator(SLEUTH_REACTOR_EXECUTOR_SERVICE_KEY); + } + @Bean // for tests @ConditionalOnMissingBean @@ -79,23 +114,67 @@ public class TraceReactorAutoConfiguration { return new HookRegisteringBeanDefinitionRegistryPostProcessor(context); } - @PreDestroy - public void cleanupHooks() { - if (log.isTraceEnabled()) { - log.trace("Cleaning up hooks"); + @Configuration + @ConditionalOnClass(RefreshScope.class) + static class HooksRefresherConfiguration { + + @Bean + HooksRefresher hooksRefresher(SleuthReactorProperties reactorProperties, + ConfigurableApplicationContext context) { + return new HooksRefresher(reactorProperties, context); } - Hooks.resetOnEachOperator(SLEUTH_TRACE_REACTOR_KEY); - Schedulers - .removeExecutorServiceDecorator(SLEUTH_REACTOR_EXECUTOR_SERVICE_KEY); + } } } +class HooksRefresher implements ApplicationListener { + + private static final Log log = LogFactory.getLog(HooksRefresher.class); + + private final SleuthReactorProperties reactorProperties; + + private final ConfigurableApplicationContext context; + + HooksRefresher(SleuthReactorProperties reactorProperties, + ConfigurableApplicationContext context) { + this.reactorProperties = reactorProperties; + this.context = context; + } + + @Override + public void onApplicationEvent(RefreshScopeRefreshedEvent event) { + if (log.isDebugEnabled()) { + log.debug("Context refreshed, will reset hooks and then re-register them"); + } + Hooks.resetOnEachOperator(SLEUTH_TRACE_REACTOR_KEY); + Hooks.resetOnLastOperator(SLEUTH_TRACE_REACTOR_KEY); + if (this.reactorProperties.isDecorateOnEach()) { + if (log.isTraceEnabled()) { + log.trace("Decorating onEach operator instrumentation"); + } + Hooks.onEachOperator(SLEUTH_TRACE_REACTOR_KEY, + ReactorSleuth.scopePassingSpanOperator(this.context)); + } + else { + if (log.isTraceEnabled()) { + log.trace("Decorating onLast operator instrumentation"); + } + Hooks.onLastOperator(SLEUTH_TRACE_REACTOR_KEY, + ReactorSleuth.scopePassingSpanOperator(this.context)); + } + } + +} + class HookRegisteringBeanDefinitionRegistryPostProcessor implements BeanDefinitionRegistryPostProcessor { + private static final Log log = LogFactory + .getLog(HookRegisteringBeanDefinitionRegistryPostProcessor.class); + private final ConfigurableApplicationContext context; HookRegisteringBeanDefinitionRegistryPostProcessor( @@ -115,9 +194,23 @@ class HookRegisteringBeanDefinitionRegistryPostProcessor } void setupHooks(BeanFactory beanFactory) { - Hooks.onEachOperator( - TraceReactorAutoConfiguration.TraceReactorConfiguration.SLEUTH_TRACE_REACTOR_KEY, - ReactorSleuth.scopePassingSpanOperator(this.context)); + ConfigurableEnvironment environment = this.context.getEnvironment(); + boolean decorateOnEach = environment.getProperty( + "spring.sleuth.reactor.decorate-on-each", Boolean.class, true); + if (decorateOnEach) { + if (log.isTraceEnabled()) { + log.trace("Decorating onEach operator instrumentation"); + } + Hooks.onEachOperator(SLEUTH_TRACE_REACTOR_KEY, + ReactorSleuth.scopePassingSpanOperator(this.context)); + } + else { + if (log.isTraceEnabled()) { + log.trace("Decorating onLast operator instrumentation"); + } + Hooks.onLastOperator(SLEUTH_TRACE_REACTOR_KEY, + ReactorSleuth.scopePassingSpanOperator(this.context)); + } Schedulers.setExecutorServiceDecorator( TraceReactorAutoConfiguration.SLEUTH_REACTOR_EXECUTOR_SERVICE_KEY, (scheduler, diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/TraceReactorAutoConfigurationAccessorConfiguration.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/TraceReactorAutoConfigurationAccessorConfiguration.java index 1ef6662e4..7cbf973f6 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/TraceReactorAutoConfigurationAccessorConfiguration.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/TraceReactorAutoConfigurationAccessorConfiguration.java @@ -18,9 +18,14 @@ package org.springframework.cloud.sleuth.instrument.reactor; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; +import reactor.core.publisher.Hooks; +import reactor.core.scheduler.Schedulers; import org.springframework.context.ConfigurableApplicationContext; +import static org.springframework.cloud.sleuth.instrument.reactor.TraceReactorAutoConfiguration.SLEUTH_REACTOR_EXECUTOR_SERVICE_KEY; +import static org.springframework.cloud.sleuth.instrument.reactor.TraceReactorAutoConfiguration.TraceReactorConfiguration.SLEUTH_TRACE_REACTOR_KEY; + /** * @author Marcin Grzejszczak */ @@ -37,7 +42,9 @@ public final class TraceReactorAutoConfigurationAccessorConfiguration { if (log.isTraceEnabled()) { log.trace("Cleaning up hooks"); } - new TraceReactorAutoConfiguration.TraceReactorConfiguration().cleanupHooks(); + Hooks.resetOnEachOperator(SLEUTH_TRACE_REACTOR_KEY); + Hooks.resetOnLastOperator(SLEUTH_TRACE_REACTOR_KEY); + Schedulers.removeExecutorServiceDecorator(SLEUTH_REACTOR_EXECUTOR_SERVICE_KEY); } public static void setup(ConfigurableApplicationContext context) { diff --git a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/sample/FlatMapTests.java b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/sample/FlatMapTests.java index ac52b464d..0d3a0a477 100644 --- a/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/sample/FlatMapTests.java +++ b/spring-cloud-sleuth-core/src/test/java/org/springframework/cloud/sleuth/instrument/reactor/sample/FlatMapTests.java @@ -37,6 +37,7 @@ import org.springframework.boot.WebApplicationType; import org.springframework.boot.autoconfigure.EnableAutoConfiguration; import org.springframework.boot.builder.SpringApplicationBuilder; import org.springframework.boot.test.rule.OutputCapture; +import org.springframework.cloud.context.refresh.ContextRefresher; import org.springframework.cloud.sleuth.DisableWebFluxSecurity; import org.springframework.cloud.sleuth.instrument.reactor.Issue866Configuration; import org.springframework.cloud.sleuth.instrument.reactor.TraceReactorAutoConfigurationAccessorConfiguration; @@ -84,6 +85,35 @@ public class FlatMapTests { "security.basic.enabled=false", "management.security.enabled=false") .run(); + assertReactorTracing(context); + } + + @Test + public void should_work_with_flat_maps_with_on_last_operator_instrumentation() { + // given + ConfigurableApplicationContext context = new SpringApplicationBuilder( + FlatMapTests.TestConfiguration.class, Issue866Configuration.class) + .web(WebApplicationType.REACTIVE) + .properties("server.port=0", "spring.jmx.enabled=false", + "spring.sleuth.reactor.decorate-on-each=false", + "spring.application.name=TraceWebFlux2Tests", + "security.basic.enabled=false", + "management.security.enabled=false") + .run(); + assertReactorTracing(context); + + try { + System.setProperty("spring.sleuth.reactor.decorate-on-each", "true"); + // trigger context refreshed + context.getBean(ContextRefresher.class).refresh(); + assertReactorTracing(context); + } + finally { + System.clearProperty("spring.sleuth.reactor.decorate-on-each"); + } + } + + private void assertReactorTracing(ConfigurableApplicationContext context) { ArrayListSpanReporter accumulator = context.getBean(ArrayListSpanReporter.class); int port = context.getBean(Environment.class).getProperty("local.server.port", Integer.class);