Polish "Add startup time metrics"

See gh-27878
This commit is contained in:
Phillip Webb
2021-09-21 13:38:46 -07:00
parent c9dc40a465
commit 98a0e07dd5
15 changed files with 148 additions and 152 deletions

View File

@@ -78,7 +78,6 @@ import org.springframework.util.ClassUtils;
import org.springframework.util.CollectionUtils;
import org.springframework.util.ObjectUtils;
import org.springframework.util.ReflectionUtils;
import org.springframework.util.StopWatch;
import org.springframework.util.StringUtils;
/**
@@ -286,8 +285,7 @@ public class SpringApplication {
* @return a running {@link ApplicationContext}
*/
public ConfigurableApplicationContext run(String... args) {
StopWatch stopWatch = new StopWatch();
stopWatch.start();
long startTime = System.nanoTime();
DefaultBootstrapContext bootstrapContext = createBootstrapContext();
ConfigurableApplicationContext context = null;
configureHeadlessProperty();
@@ -303,23 +301,20 @@ public class SpringApplication {
prepareContext(bootstrapContext, context, environment, listeners, applicationArguments, printedBanner);
refreshContext(context);
afterRefresh(context, applicationArguments);
stopWatch.stop();
Duration startedTime = Duration.ofMillis(stopWatch.getTotalTimeMillis());
stopWatch.start();
Duration timeTakeToStartup = Duration.ofNanos(System.nanoTime() - startTime);
if (this.logStartupInfo) {
new StartupInfoLogger(this.mainApplicationClass).logStarted(getApplicationLog(), startedTime);
new StartupInfoLogger(this.mainApplicationClass).logStarted(getApplicationLog(), timeTakeToStartup);
}
listeners.started(context, startedTime);
listeners.started(context, timeTakeToStartup);
callRunners(context, applicationArguments);
}
catch (Throwable ex) {
handleRunFailure(context, ex, listeners);
throw new IllegalStateException(ex);
}
try {
stopWatch.stop();
listeners.running(context, Duration.ofMillis(stopWatch.getTotalTimeMillis()));
Duration timeTakenToReady = Duration.ofNanos(System.nanoTime() - startTime);
listeners.ready(context, timeTakenToReady);
}
catch (Throwable ex) {
handleRunFailure(context, ex, null);

View File

@@ -77,13 +77,11 @@ public interface SpringApplicationRunListener {
* {@link CommandLineRunner CommandLineRunners} and {@link ApplicationRunner
* ApplicationRunners} have not been called.
* @param context the application context.
* @since 2.0.0
* @deprecated since 2.6.0 for removal in 2.8.0 in favour of
* {@link #started(ConfigurableApplicationContext, Duration)}
* @param timeTaken the time taken to start the application or {@code null} if unknown
* @since 2.6.0
*/
@Deprecated
default void started(ConfigurableApplicationContext context) {
started(context, null);
default void started(ConfigurableApplicationContext context, Duration timeTaken) {
started(context);
}
/**
@@ -91,12 +89,12 @@ public interface SpringApplicationRunListener {
* {@link CommandLineRunner CommandLineRunners} and {@link ApplicationRunner
* ApplicationRunners} have not been called.
* @param context the application context.
* @param startedTime the time taken to start the application or {@code null} if
* unknown
* @since 2.6.0
* @since 2.0.0
* @deprecated since 2.6.0 for removal in 2.8.0 in favor of
* {@link #started(ConfigurableApplicationContext, Duration)}
*/
default void started(ConfigurableApplicationContext context, Duration startedTime) {
started(context);
@Deprecated
default void started(ConfigurableApplicationContext context) {
}
/**
@@ -104,26 +102,25 @@ public interface SpringApplicationRunListener {
* been refreshed and all {@link CommandLineRunner CommandLineRunners} and
* {@link ApplicationRunner ApplicationRunners} have been called.
* @param context the application context.
* @deprecated since 2.6.0 for removal in 2.8.0 in favour of
* {@link #running(ConfigurableApplicationContext, Duration)}
* @param timeTaken the time taken for the application to be ready or {@code null} if
* unknown
* @since 2.6.0
*/
default void ready(ConfigurableApplicationContext context, Duration timeTaken) {
running(context);
}
/**
* Called immediately before the run method finishes, when the application context has
* been refreshed and all {@link CommandLineRunner CommandLineRunners} and
* {@link ApplicationRunner ApplicationRunners} have been called.
* @param context the application context.
* @deprecated since 2.6.0 for removal in 2.8.0 in favor of
* {@link #ready(ConfigurableApplicationContext, Duration)}
* @since 2.0.0
*/
@Deprecated
default void running(ConfigurableApplicationContext context) {
running(context, null);
}
/**
* Called immediately before the run method finishes, when the application context has
* been refreshed and all {@link CommandLineRunner CommandLineRunners} and
* {@link ApplicationRunner ApplicationRunners} have been called.
* @param context the application context.
* @param readyTime the time taken for the application to be ready to service requests
* or {@code null} if unknown
* @since 2.6.0
*/
default void running(ConfigurableApplicationContext context, Duration readyTime) {
running(context);
}
/**

View File

@@ -74,12 +74,12 @@ class SpringApplicationRunListeners {
doWithListeners("spring.boot.application.context-loaded", (listener) -> listener.contextLoaded(context));
}
void started(ConfigurableApplicationContext context, Duration startupTime) {
doWithListeners("spring.boot.application.started", (listener) -> listener.started(context, startupTime));
void started(ConfigurableApplicationContext context, Duration timeTaken) {
doWithListeners("spring.boot.application.started", (listener) -> listener.started(context, timeTaken));
}
void running(ConfigurableApplicationContext context, Duration startupTime) {
doWithListeners("spring.boot.application.running", (listener) -> listener.running(context, startupTime));
void ready(ConfigurableApplicationContext context, Duration timeTaken) {
doWithListeners("spring.boot.application.running", (listener) -> listener.ready(context, timeTaken));
}
void failed(ConfigurableApplicationContext context, Throwable exception) {

View File

@@ -56,9 +56,9 @@ class StartupInfoLogger {
applicationLog.debug(LogMessage.of(this::getRunningMessage));
}
void logStarted(Log applicationLog, Duration startupTime) {
void logStarted(Log applicationLog, Duration timeTakeToStartup) {
if (applicationLog.isInfoEnabled()) {
applicationLog.info(getStartedMessage(startupTime));
applicationLog.info(getStartedMessage(timeTakeToStartup));
}
}
@@ -83,12 +83,12 @@ class StartupInfoLogger {
return message;
}
private CharSequence getStartedMessage(Duration startupTime) {
private CharSequence getStartedMessage(Duration timeTakeToStartup) {
StringBuilder message = new StringBuilder();
message.append("Started ");
appendApplicationName(message);
message.append(" in ");
message.append(startupTime.toMillis() / 1000.0);
message.append(timeTakeToStartup.toMillis() / 1000.0);
message.append(" seconds");
try {
double uptime = ManagementFactory.getRuntimeMXBean().getUptime() / 1000.0;

View File

@@ -37,7 +37,7 @@ public class ApplicationReadyEvent extends SpringApplicationEvent {
private final ConfigurableApplicationContext context;
private final Duration readyTime;
private final Duration timeTaken;
/**
* Create a new {@link ApplicationReadyEvent} instance.
@@ -57,14 +57,14 @@ public class ApplicationReadyEvent extends SpringApplicationEvent {
* @param application the current application
* @param args the arguments the application is running with
* @param context the context that was being created
* @param readyTime the time taken to get the application ready to service requests
* @param timeTaken the time taken to get the application ready to service requests
* @since 2.6.0
*/
public ApplicationReadyEvent(SpringApplication application, String[] args, ConfigurableApplicationContext context,
Duration readyTime) {
Duration timeTaken) {
super(application, args);
this.context = context;
this.readyTime = readyTime;
this.timeTaken = timeTaken;
}
/**
@@ -79,9 +79,10 @@ public class ApplicationReadyEvent extends SpringApplicationEvent {
* Return the time taken for the application to be ready to service requests, or
* {@code null} if unknown.
* @return the time taken to be ready to service requests
* @since 2.6.0
*/
public Duration getReadyTime() {
return this.readyTime;
public Duration getTimeTaken() {
return this.timeTaken;
}
}

View File

@@ -36,7 +36,7 @@ public class ApplicationStartedEvent extends SpringApplicationEvent {
private final ConfigurableApplicationContext context;
private final Duration startedTime;
private final Duration timeTaken;
/**
* Create a new {@link ApplicationStartedEvent} instance.
@@ -57,14 +57,14 @@ public class ApplicationStartedEvent extends SpringApplicationEvent {
* @param application the current application
* @param args the arguments the application is running with
* @param context the context that was being created
* @param startedTime the time taken to start the application
* @param timeTaken the time taken to start the application
* @since 2.6.0
*/
public ApplicationStartedEvent(SpringApplication application, String[] args, ConfigurableApplicationContext context,
Duration startedTime) {
Duration timeTaken) {
super(application, args);
this.context = context;
this.startedTime = startedTime;
this.timeTaken = timeTaken;
}
/**
@@ -78,9 +78,10 @@ public class ApplicationStartedEvent extends SpringApplicationEvent {
/**
* Return the time taken to start the application, or {@code null} if unknown.
* @return the startup time
* @since 2.6.0
*/
public Duration getStartedTime() {
return this.startedTime;
public Duration getTimeTaken() {
return this.timeTaken;
}
}

View File

@@ -104,14 +104,14 @@ public class EventPublishingRunListener implements SpringApplicationRunListener,
}
@Override
public void started(ConfigurableApplicationContext context, Duration startedTime) {
context.publishEvent(new ApplicationStartedEvent(this.application, this.args, context, startedTime));
public void started(ConfigurableApplicationContext context, Duration timeTaken) {
context.publishEvent(new ApplicationStartedEvent(this.application, this.args, context, timeTaken));
AvailabilityChangeEvent.publish(context, LivenessState.CORRECT);
}
@Override
public void running(ConfigurableApplicationContext context, Duration readyTime) {
context.publishEvent(new ApplicationReadyEvent(this.application, this.args, context, readyTime));
public void ready(ConfigurableApplicationContext context, Duration timeTaken) {
context.publishEvent(new ApplicationReadyEvent(this.application, this.args, context, timeTaken));
AvailabilityChangeEvent.publish(context, ReadinessState.ACCEPTING_TRAFFIC);
}

View File

@@ -363,7 +363,7 @@ class SpringApplicationTests {
void applicationRunningEventListener() {
SpringApplication application = new SpringApplication(ExampleConfig.class);
application.setWebApplicationType(WebApplicationType.NONE);
AtomicReference<ApplicationReadyEvent> reference = setupListener(application, ApplicationReadyEvent.class);
AtomicReference<ApplicationReadyEvent> reference = addListener(application, ApplicationReadyEvent.class);
this.context = application.run("--foo=bar");
assertThat(application).isSameAs(reference.get().getSpringApplication());
}
@@ -372,7 +372,7 @@ class SpringApplicationTests {
void contextRefreshedEventListener() {
SpringApplication application = new SpringApplication(ExampleConfig.class);
application.setWebApplicationType(WebApplicationType.NONE);
AtomicReference<ContextRefreshedEvent> reference = setupListener(application, ContextRefreshedEvent.class);
AtomicReference<ContextRefreshedEvent> reference = addListener(application, ContextRefreshedEvent.class);
this.context = application.run("--foo=bar");
assertThat(this.context).isSameAs(reference.get().getApplicationContext());
// Custom initializers do not switch off the defaults
@@ -405,18 +405,18 @@ class SpringApplicationTests {
void applicationStartedEventHasStartedTime() {
SpringApplication application = new SpringApplication(ExampleConfig.class);
application.setWebApplicationType(WebApplicationType.NONE);
AtomicReference<ApplicationStartedEvent> reference = setupListener(application, ApplicationStartedEvent.class);
AtomicReference<ApplicationStartedEvent> reference = addListener(application, ApplicationStartedEvent.class);
this.context = application.run();
assertThat(reference.get()).isNotNull().extracting(ApplicationStartedEvent::getStartedTime).isNotNull();
assertThat(reference.get()).isNotNull().extracting(ApplicationStartedEvent::getTimeTaken).isNotNull();
}
@Test
void applicationReadyEventHasReadyTime() {
SpringApplication application = new SpringApplication(ExampleConfig.class);
application.setWebApplicationType(WebApplicationType.NONE);
AtomicReference<ApplicationReadyEvent> reference = setupListener(application, ApplicationReadyEvent.class);
AtomicReference<ApplicationReadyEvent> reference = addListener(application, ApplicationReadyEvent.class);
this.context = application.run();
assertThat(reference.get()).isNotNull().extracting(ApplicationReadyEvent::getReadyTime).isNotNull();
assertThat(reference.get()).isNotNull().extracting(ApplicationReadyEvent::getTimeTaken).isNotNull();
}
@Test
@@ -1252,24 +1252,10 @@ class SpringApplicationTests {
&& ((AvailabilityChangeEvent<?>) argument).getState().equals(state);
}
private <T extends ApplicationEvent> AtomicReference<T> setupListener(SpringApplication application,
Class<T> targetEventType) {
final AtomicReference<T> reference = new AtomicReference<>();
class TestEventListener implements SmartApplicationListener {
@Override
@SuppressWarnings("unchecked")
public void onApplicationEvent(ApplicationEvent event) {
reference.set((T) event);
}
@Override
public boolean supportsEventType(Class<? extends ApplicationEvent> eventType) {
return targetEventType.isAssignableFrom(eventType);
}
}
application.addListeners(new TestEventListener());
private <E extends ApplicationEvent> AtomicReference<E> addListener(SpringApplication application,
Class<E> eventType) {
AtomicReference<E> reference = new AtomicReference<>();
application.addListeners(new TestEventListener<>(eventType, reference));
return reference;
}
@@ -1302,6 +1288,30 @@ class SpringApplicationTests {
};
}
static class TestEventListener<E extends ApplicationEvent> implements SmartApplicationListener {
private final Class<E> eventType;
private final AtomicReference<E> reference;
TestEventListener(Class<E> eventType, AtomicReference<E> reference) {
this.eventType = eventType;
this.reference = reference;
}
@Override
public boolean supportsEventType(Class<? extends ApplicationEvent> eventType) {
return this.eventType.isAssignableFrom(eventType);
}
@Override
@SuppressWarnings("unchecked")
public void onApplicationEvent(ApplicationEvent event) {
this.reference.set((E) event);
}
}
@Configuration
static class InaccessibleConfiguration {

View File

@@ -25,7 +25,6 @@ import org.junit.jupiter.api.Test;
import org.mockito.ArgumentCaptor;
import org.springframework.boot.system.ApplicationPid;
import org.springframework.util.StopWatch;
import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.BDDMockito.given;
@@ -56,11 +55,9 @@ class StartupInfoLoggerTests {
@Test
void startedFormat() {
StopWatch stopWatch = new StopWatch();
stopWatch.start();
given(this.log.isInfoEnabled()).willReturn(true);
stopWatch.stop();
new StartupInfoLogger(getClass()).logStarted(this.log, Duration.ofMillis(stopWatch.getTotalTimeMillis()));
Duration timeTakeToStartup = Duration.ofMillis(10);
new StartupInfoLogger(getClass()).logStarted(this.log, timeTakeToStartup);
ArgumentCaptor<Object> captor = ArgumentCaptor.forClass(Object.class);
verify(this.log).info(captor.capture());
assertThat(captor.getValue().toString()).matches("Started " + getClass().getSimpleName()

View File

@@ -74,7 +74,7 @@ class EventPublishingRunListenerTests {
context.refresh();
this.runListener.started(context, null);
checkApplicationEvents(ApplicationStartedEvent.class, AvailabilityChangeEvent.class);
this.runListener.running(context, null);
this.runListener.ready(context, null);
checkApplicationEvents(ApplicationReadyEvent.class, AvailabilityChangeEvent.class);
}