diff --git a/spring-boot-project/spring-boot-docs/src/docs/asciidoc/spring-boot-features.adoc b/spring-boot-project/spring-boot-docs/src/docs/asciidoc/spring-boot-features.adoc index 68657f322d..b2eee62509 100644 --- a/spring-boot-project/spring-boot-docs/src/docs/asciidoc/spring-boot-features.adoc +++ b/spring-boot-project/spring-boot-docs/src/docs/asciidoc/spring-boot-features.adoc @@ -443,6 +443,37 @@ This feature could also be useful for any service wrapper implementation. TIP: If you want to know on which HTTP port the application is running, get the property with a key of `local.server.port`. +[[boot-features-application-startup-tracking]] +=== Application Startup tracking +During the application startup, the `SpringApplication` and the `ApplicationContext` perform many tasks related to the application lifecycle, +the beans lifecycle or even processing application events. +With {spring-framework-api}/core/metrics/ApplicationStartup.html[ApplicationStartup`], Spring Framework {spring-framework-docs}/core.html#context-functionality-startup[allows you track the application startup sequence with `StartupStep`s]. +This data can be collected for profiling purposes, or just to have a better understanding of an application startup process. + +You can choose a `ApplicationStartup` implementation when setting up the `SpringApplication` instance. +For example, to use the `BufferingApplicationStartup`, you could write: + +[source,java,indent=0] +---- + public static void main(String[] args) { + SpringApplication app = new SpringApplication(MySpringConfiguration.class); + app.setApplicationStartup(new BufferingApplicationStartup(2048)); + app.run(args); + } +---- + +The first available implementation, `FlightRecorderApplicationStartup` is provided by Spring Framework. +It adds Spring-specific startup events to a Java Flight Recorder session and is meant for profiling applications and correlating their Spring context lifecycle with JVM events (such as allocations, GCs, class loading...). +Once configured, you can record data by running the application with the Flight Recorder enabled: + +[source,bash,indent=0] +---- + $ java -XX:StartFlightRecording:filename=recording.jfr,duration=10s -jar demo.jar +---- + +Spring Boot ships with the `BufferingApplicationStartup` variant; this implementation is meant for buffering the startup steps and draining them into an external metrics system. +Applications can ask for the bean of type `BufferingApplicationStartup` in any component. +Additionally, Spring Boot Actuator will <>. [[boot-features-external-config]] == Externalized Configuration diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/BufferedStartupStep.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/BufferedStartupStep.java new file mode 100644 index 0000000000..c674215002 --- /dev/null +++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/BufferedStartupStep.java @@ -0,0 +1,173 @@ +/* + * Copyright 2002-2020 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.boot.context.metrics.buffering; + +import java.util.Iterator; +import java.util.function.Consumer; +import java.util.function.Supplier; + +import org.springframework.core.metrics.StartupStep; + +/** + * {@link StartupStep} implementation to be buffered by + * {@link BufferingApplicationStartup}. Its processing time is recorded using + * {@link System#nanoTime()}. + * + * @author Brian Clozel + */ +class BufferedStartupStep implements StartupStep { + + private final String name; + + private final long id; + + private final Long parentId; + + private long startTime; + + private long endTime; + + private final DefaultTags tags; + + private final Consumer recorder; + + BufferedStartupStep(long id, String name, Long parentId, Consumer recorder) { + this.id = id; + this.parentId = parentId; + this.tags = new DefaultTags(); + this.name = name; + this.recorder = recorder; + } + + @Override + public String getName() { + return this.name; + } + + @Override + public long getId() { + return this.id; + } + + @Override + public Long getParentId() { + return this.parentId; + } + + @Override + public Tags getTags() { + return this.tags; + } + + @Override + public StartupStep tag(String key, String value) { + if (this.endTime != 0L) { + throw new IllegalStateException("StartupStep has already ended."); + } + this.tags.add(key, value); + return this; + } + + @Override + public StartupStep tag(String key, Supplier value) { + return this.tag(key, value.get()); + } + + @Override + public void end() { + this.recorder.accept(this); + } + + long getStartTime() { + return this.startTime; + } + + void recordStartTime(long startTime) { + this.startTime = startTime; + } + + long getEndTime() { + return this.endTime; + } + + void recordEndTime(long endTime) { + this.endTime = endTime; + } + + static class DefaultTags implements Tags { + + private Tag[] tags = new Tag[0]; + + void add(String key, String value) { + Tag[] newTags = new Tag[this.tags.length + 1]; + System.arraycopy(this.tags, 0, newTags, 0, this.tags.length); + newTags[newTags.length - 1] = new DefaultTag(key, value); + this.tags = newTags; + } + + @Override + public Iterator iterator() { + return new TagsIterator(); + } + + private class TagsIterator implements Iterator { + + private int idx = 0; + + @Override + public boolean hasNext() { + return this.idx < DefaultTags.this.tags.length; + } + + @Override + public Tag next() { + return DefaultTags.this.tags[this.idx++]; + } + + @Override + public void remove() { + throw new UnsupportedOperationException("tags are append only"); + } + + } + + } + + static class DefaultTag implements Tag { + + private final String key; + + private final String value; + + DefaultTag(String key, String value) { + this.key = key; + this.value = value; + } + + @Override + public String getKey() { + return this.key; + } + + @Override + public String getValue() { + return this.value; + } + + } + +} diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/BufferingApplicationStartup.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/BufferingApplicationStartup.java new file mode 100644 index 0000000000..10a41ae8aa --- /dev/null +++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/BufferingApplicationStartup.java @@ -0,0 +1,145 @@ +/* + * Copyright 2002-2020 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.boot.context.metrics.buffering; + +import java.time.Instant; +import java.util.ArrayDeque; +import java.util.ArrayList; +import java.util.Deque; +import java.util.List; +import java.util.concurrent.BlockingQueue; +import java.util.concurrent.LinkedBlockingQueue; +import java.util.function.Predicate; + +import org.springframework.core.metrics.ApplicationStartup; +import org.springframework.core.metrics.StartupStep; +import org.springframework.util.Assert; + +/** + * {@link ApplicationStartup} implementation that buffers {@link StartupStep steps} and + * records their timestamp as well as their processing time. + *

+ * Once recording has been {@link #startRecording() started}, steps are buffered up until + * the configured {@link #BufferingApplicationStartup(int) capacity}; after that, new + * steps are not recorded. + *

+ * There are several ways to keep the buffer size low: + *

    + *
  • configuring {@link #addFilter(Predicate) filters} to only record steps that are + * relevant to us. + *
  • {@link #drainBufferedTimeline() draining} the buffered steps. + *
+ * + * @author Brian Clozel + * @since 2.4.0 + */ +public class BufferingApplicationStartup implements ApplicationStartup { + + private Instant recordingStartTime; + + private long recordingStartNanos; + + private long currentSequenceId = 0; + + private final Deque currentSteps; + + private final BlockingQueue recordedSteps; + + private Predicate stepFilters = (step) -> true; + + /** + * Create a new buffered {@link ApplicationStartup} with a limited capacity and starts + * the recording of steps. + * @param capacity the configured capacity; once reached, new steps are not recorded. + */ + public BufferingApplicationStartup(int capacity) { + this.currentSteps = new ArrayDeque<>(); + this.currentSteps.offerFirst(this.currentSequenceId); + this.recordedSteps = new LinkedBlockingQueue<>(capacity); + startRecording(); + } + + /** + * Start the recording of steps and mark the beginning of the {@link StartupTimeline}. + * The class constructor already implicitly calls this, but it is possible to reset it + * as long as steps have not been recorded already. + * @throws IllegalStateException if called and {@link StartupStep} have been recorded + * already. + */ + public void startRecording() { + Assert.state(this.recordedSteps.isEmpty(), "Cannot restart recording once steps have been buffered."); + this.recordingStartTime = Instant.now(); + this.recordingStartNanos = getCurrentTime(); + } + + /** + * Add a predicate filter to the list of existing ones. + *

+ * A {@link StartupStep step} that doesn't match all filters will not be recorded. + * @param filter the predicate filter to add. + */ + public void addFilter(Predicate filter) { + this.stepFilters = this.stepFilters.and(filter); + } + + /** + * Return the {@link StartupTimeline timeline} as a snapshot of currently buffered + * steps. + *

+ * This will not remove steps from the buffer, see {@link #drainBufferedTimeline()} + * for its counterpart. + * @return a snapshot of currently buffered steps. + */ + public StartupTimeline getBufferedTimeline() { + return new StartupTimeline(this.recordingStartTime, this.recordingStartNanos, this.recordedSteps); + } + + /** + * Return the {@link StartupTimeline timeline} by pulling steps from the buffer. + *

+ * This removes steps from the buffer, see {@link #getBufferedTimeline()} for its + * read-only counterpart. + * @return buffered steps drained from the buffer. + */ + public StartupTimeline drainBufferedTimeline() { + List steps = new ArrayList<>(this.recordedSteps.size()); + this.recordedSteps.drainTo(steps); + return new StartupTimeline(this.recordingStartTime, this.recordingStartNanos, steps); + } + + @Override + public StartupStep start(String name) { + BufferedStartupStep step = new BufferedStartupStep(++this.currentSequenceId, name, + this.currentSteps.peekFirst(), this::record); + step.recordStartTime(getCurrentTime()); + this.currentSteps.offerFirst(this.currentSequenceId); + return step; + } + + private void record(BufferedStartupStep step) { + step.recordEndTime(getCurrentTime()); + if (this.stepFilters.test(step)) { + this.recordedSteps.offer(step); + } + this.currentSteps.removeFirst(); + } + + private long getCurrentTime() { + return System.nanoTime(); + } + +} diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/StartupTimeline.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/StartupTimeline.java new file mode 100644 index 0000000000..f901d5f761 --- /dev/null +++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/StartupTimeline.java @@ -0,0 +1,120 @@ +/* + * Copyright 2002-2020 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.boot.context.metrics.buffering; + +import java.time.Duration; +import java.time.Instant; +import java.util.Collection; +import java.util.List; +import java.util.stream.Collectors; + +import org.springframework.core.metrics.StartupStep; + +/** + * Represent the timeline of {@link StartupStep steps} recorded by + * {@link BufferingApplicationStartup}. Each {@link TimelineEvent} has a start and end + * time as well as a duration measured with nanosecond precision. + * + * @author Brian Clozel + * @since 2.4.0 + */ +public class StartupTimeline { + + private final Instant startTime; + + private final List events; + + StartupTimeline(Instant startTime, long startNanoTime, Collection events) { + this.startTime = startTime; + this.events = events.stream().map((event) -> new TimelineEvent(event, startTime, startNanoTime)) + .collect(Collectors.toList()); + } + + /** + * Return the start time of this timeline. + * @return the start time + */ + public Instant getStartTime() { + return this.startTime; + } + + /** + * Return the recorded events. + * @return the events + */ + public List getEvents() { + return this.events; + } + + /** + * Event on the current {@link StartupTimeline}. Each event has a start/end time, a + * precise duration and the complete {@link StartupStep} information associated with + * it. + */ + public static class TimelineEvent { + + private final StartupStep startupStep; + + private final Instant startTime; + + private final Instant endTime; + + private final Duration duration; + + TimelineEvent(BufferedStartupStep startupStep, Instant startupDate, long startupNanoTime) { + this.startupStep = startupStep; + this.startTime = startupDate.plus(Duration.ofNanos(startupStep.getStartTime() - startupNanoTime)); + this.endTime = startupDate.plus(Duration.ofNanos(startupStep.getEndTime() - startupNanoTime)); + this.duration = Duration.ofNanos(startupStep.getEndTime() - startupStep.getStartTime()); + } + + /** + * Return the start time of this event. + * @return the start time + */ + public Instant getStartTime() { + return this.startTime; + } + + /** + * Return the end time of this event. + * @return the end time + */ + public Instant getEndTime() { + return this.endTime; + } + + /** + * Return the duration of this event, i.e. the processing time of the associated + * {@link StartupStep} with nanoseconds precision. + * @return the event duration + */ + public Duration getDuration() { + return this.duration; + } + + /** + * Return the {@link StartupStep} information for this event. + * @return the step information. + */ + public StartupStep getStartupStep() { + return this.startupStep; + } + + } + +} diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/package-info.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/package-info.java new file mode 100644 index 0000000000..9e799ea08c --- /dev/null +++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/context/metrics/buffering/package-info.java @@ -0,0 +1,21 @@ +/* + * Copyright 2012-2020 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. + */ + +/** + * {@link org.springframework.core.metrics.ApplicationStartup} implementation for + * buffering steps and measuring their processing time. + */ +package org.springframework.boot.context.metrics.buffering; diff --git a/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/context/metrics/buffering/BufferingApplicationStartupTests.java b/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/context/metrics/buffering/BufferingApplicationStartupTests.java new file mode 100644 index 0000000000..8d6114262e --- /dev/null +++ b/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/context/metrics/buffering/BufferingApplicationStartupTests.java @@ -0,0 +1,103 @@ +/* + * Copyright 2012-2020 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.boot.context.metrics.buffering; + +import org.junit.jupiter.api.Test; + +import org.springframework.core.metrics.StartupStep; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.assertj.core.api.Assertions.assertThatThrownBy; + +/** + * Tests for {@link BufferingApplicationStartup}. + * + * @author Brian Clozel + */ +class BufferingApplicationStartupTests { + + @Test + void shouldNotRecordEventsWhenOverCapacity() { + BufferingApplicationStartup applicationStartup = new BufferingApplicationStartup(2); + applicationStartup.start("first").end(); + applicationStartup.start("second").end(); + applicationStartup.start("third").end(); + assertThat(applicationStartup.getBufferedTimeline().getEvents()).hasSize(2); + } + + @Test + void shouldNotRecordEventsWhenFiltered() { + BufferingApplicationStartup applicationStartup = new BufferingApplicationStartup(5); + applicationStartup.addFilter((step) -> step.getName().startsWith("spring")); + applicationStartup.start("spring.first").end(); + StartupStep filtered = applicationStartup.start("filtered.second"); + applicationStartup.start("spring.third").end(); + filtered.end(); + assertThat(applicationStartup.getBufferedTimeline().getEvents()).hasSize(2); + StartupTimeline.TimelineEvent firstEvent = applicationStartup.getBufferedTimeline().getEvents().get(0); + assertThat(firstEvent.getStartupStep().getId()).isEqualTo(1); + assertThat(firstEvent.getStartupStep().getParentId()).isEqualTo(0); + StartupTimeline.TimelineEvent secondEvent = applicationStartup.getBufferedTimeline().getEvents().get(1); + assertThat(secondEvent.getStartupStep().getId()).isEqualTo(3); + assertThat(secondEvent.getStartupStep().getParentId()).isEqualTo(2); + } + + @Test + void bufferShouldNotBeEmptyWhenGettingSnapshot() { + BufferingApplicationStartup applicationStartup = new BufferingApplicationStartup(2); + applicationStartup.start("first").end(); + applicationStartup.start("second").end(); + assertThat(applicationStartup.getBufferedTimeline().getEvents()).hasSize(2); + assertThat(applicationStartup.getBufferedTimeline().getEvents()).hasSize(2); + } + + @Test + void bufferShouldBeEmptyWhenDraining() { + BufferingApplicationStartup applicationStartup = new BufferingApplicationStartup(2); + applicationStartup.start("first").end(); + applicationStartup.start("second").end(); + assertThat(applicationStartup.drainBufferedTimeline().getEvents()).hasSize(2); + assertThat(applicationStartup.getBufferedTimeline().getEvents()).isEmpty(); + } + + @Test + void startRecordingShouldFailIfEventsWereRecorded() { + BufferingApplicationStartup applicationStartup = new BufferingApplicationStartup(2); + applicationStartup.start("first").end(); + assertThatThrownBy(applicationStartup::startRecording).isInstanceOf(IllegalStateException.class) + .hasMessage("Cannot restart recording once steps have been buffered."); + } + + @Test + void taggingShouldFailWhenEventAlreadyRecorded() { + BufferingApplicationStartup applicationStartup = new BufferingApplicationStartup(2); + StartupStep step = applicationStartup.start("first"); + step.end(); + assertThatThrownBy(() -> step.tag("name", "value")).isInstanceOf(IllegalStateException.class) + .hasMessage("StartupStep has already ended."); + } + + @Test + void taggingShouldFailWhenRemovingEntry() { + BufferingApplicationStartup applicationStartup = new BufferingApplicationStartup(2); + StartupStep step = applicationStartup.start("first"); + step.tag("name", "value"); + assertThatThrownBy(() -> step.getTags().iterator().remove()).isInstanceOf(UnsupportedOperationException.class) + .hasMessage("tags are append only"); + } + +}