Add startup time metrics #27878

onobc · 2021-09-05T21:16:39Z

@wilkinsona I picked your draft changes up and added the Actuator side of things.

TODO

Add docs

Here is what the metric looks like in Wavefront.

onobc · 2021-09-05T21:39:19Z

...uator/src/main/java/org/springframework/boot/actuate/metrics/startup/StartupTimeMetrics.java

+			return;
+		}
+		TimeGauge
+				.builder("spring.boot.application.started", () -> event.getStartupTime().toMillis(),


@mbazos I know you had mentioned the following possible metric candidates for a StartupTimeMetrics.

jvm start time

application start time

spring context start time

spring context start time

Just to clarify that the StartupInfoLogger is actually logging "spring context start time" which corresponds to the ApplicationStartedEvent (the app is live but not ready for requests yet - it still has to invoke any runners). This pull request logs this startup time.

application start time

The "application start time" I am guessing would correspond to the ApplicationReadyEvent (the app is live and the app is ready for requests - all runners have been invoked). This pull request does not log this startup time. It could easily be added though and it would allow users to get an idea how much their runners are adding to startup time.

jvm start time

The StartupInfoLogger is logging "jvm uptime" which corresponds to how many ms the JVM has been up. This could also give an idea of the contribution the JVM has on the startup time. This pull request does not log this startup time either but it could easily be added.

@wilkinsona @mbazos
Wdyt about me adding in the 2 above metrics?

Fixes gh-26729

onobc · 2021-09-06T23:01:54Z

I added the startup time to the ApplicationReadyEvent as well. You can tell by the graph below which portion of the startup time is due to the runners (I think its helpful). I am waiting to push that 2nd commit though until I get a nod on adding the metric.

onobc · 2021-09-08T01:44:31Z

I went ahead and pushes the subsequent commits that add the times for application.running and the jvm uptime as the point that the application is in ready state.

Looks like this in WF...

philwebb · 2021-09-10T15:23:54Z

spring-boot-project/spring-boot/src/main/java/org/springframework/boot/SpringApplication.java

 			refreshContext(context);
 			afterRefresh(context, applicationArguments);
 			stopWatch.stop();
+			stopWatch.start("applicationReady");


I think this should be moved to past the listeners.started call

So the application.ready.time is the total time from the app run() to the end of the runners and not just the portion of time that the runners took. I will give an example to make sure we are on the same page:

hh:mm:ss step

00:00:00 jvm is started

00:00:04 run is invoked

00:00:08 context has been refreshed

00:00:12 runners done executing

The "base T0" time from the app perspective is 00:00:04. Which gives the following:

application.started.time: 4s (00:00:04 -> 00:00:08)

application.ready.time: 8s (00:00:04 -> 00:00:12)

application.ready.jvm.time: 12s (00:00:00 -> 00:00:12)

Is that what you were thinking as well?

philwebb · 2021-09-10T15:29:48Z

Thanks very much for the PR @Bono007.

We discussed some aspects of this today on our call and we think that the timer names should be changed from:

spring.boot.application.started
spring.boot.application.running

to:

application.started.time
application.ready.time

We're also wondering if there should be configuration options to change them.

Do you have any time to update the PR in that direction? If not, we can handle it when we merge.

onobc · 2021-09-11T02:54:14Z

Thanks very much for the PR @Bono007.

My pleasure @philwebb

We discussed some aspects of this today on our call and we think that the timer names should be changed from:
spring.boot.application.started
spring.boot.application.running
to:
application.started.time
application.ready.time

I ❤️ these new names - they were too verbose and in lockstep w/ the application event names. I went back and forth and just submitted these in hopes that I would get some feedback from team (I meant to call this out in comment). Ugghh naming... :)

One follow up question though, spring.boot.application.running.jvm change to default name of jvm.read.time or application.ready.jvm.time, or something else?

We're also wondering if there should be configuration options to change them.

I have went back/forth on the ability to change metric names (in general, not just here) and one hand its great because it allows consumers to name the metrics what they want for their custom requirements. On the other hand, it allows consumers to name the metrics what they want. This can lead to a somewhat standard metric name such as "mongodb.driver.commands" now being called "acme.company.mongodb.driver.or.whatever". I know the instrumentation in Micrometer tends to stay on the hardcoded side. I notice that SpringBoot has started to allow customization of most of the meters. I am ok w/ either approach but just wanted to bring this up.

Do you have any time to update the PR in that direction? If not, we can handle it when we merge.

Absolutely. On it now.

….started.[ready|ready.jvm].time`

.../src/main/java/org/springframework/boot/actuate/autoconfigure/metrics/MetricsProperties.java

...springframework/boot/actuate/autoconfigure/metrics/startup/StartupTimeMetricsProperties.java

...uator/src/main/java/org/springframework/boot/actuate/metrics/startup/StartupTimeMetrics.java

wilkinsona · 2021-09-11T19:39:39Z

One follow up question though, spring.boot.application.running.jvm change to default name of jvm.read.time or application.ready.jvm.time, or something else?

Ah, that reminds me of the other thing we discussed. We don't think this should be part of Spring Boot. Instead, it feels like a general JVM metric that could be provided my Micrometer.

onobc · 2021-09-11T21:48:45Z

One follow up question though, spring.boot.application.running.jvm change to default name of jvm.read.time or application.ready.jvm.time, or something else?

Ah, that reminds me of the other thing we discussed. We don't think this should be part of Spring Boot. Instead, it feels like a general JVM metric that could be provided my Micrometer.

Yep, I agree w/ that. It was really added here as a convenience to see how much of the Spring Boot startup attributed to the overall JVM uptime (or vice-versa). The thing that Micrometer will not have is knowing that the application is ready (aka Spring event listener).

There is already the UptimeMetrics which gives the JVM start time and uptime so that may be able to be used and correlated w/ these metrics. Or consumers could easily add a custom metric that listens for the app ready (like the JVM metric in this proposal).

Either way, I will push another commit that removes the JVM metric.

See spring-projectsgh-27878

See gh-27878

snicoll · 2021-09-16T12:10:23Z

Thanks again, Chris.

See gh-27878

spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Sep 5, 2021

onobc commented Sep 5, 2021

View reviewed changes

onobc added 2 commits September 5, 2021 21:05

Add startup time metrics

5fb06f2

Fixes gh-26729

Add startup time for application ready

e0b5edd

onobc added 2 commits September 7, 2021 13:20

Add JVM uptime to startup metrics.

c01880a

Rename startup metrics to 'spring.boot.startup.<state>'

21ea6e7

wilkinsona added the for: team-meeting An issue we'd like to discuss as a team to make progress label Sep 8, 2021

philwebb reviewed Sep 10, 2021

View reviewed changes

philwebb added type: enhancement A general enhancement and removed status: waiting-for-triage An issue we've not yet triaged for: team-meeting An issue we'd like to discuss as a team to make progress labels Sep 10, 2021

philwebb added this to the 2.6.x milestone Sep 10, 2021

philwebb mentioned this pull request Sep 10, 2021

Publish a metric for the application's startup time #26729

Closed

onobc added 2 commits September 10, 2021 22:35

Rename metrics from spring.boot.startup.app.<state> to `application…

36282a6

….started.[ready|ready.jvm].time`

Made startup metric names configurable

214d9ab

onobc commented Sep 11, 2021

View reviewed changes

.../src/main/java/org/springframework/boot/actuate/autoconfigure/metrics/MetricsProperties.java Outdated Show resolved Hide resolved

onobc commented Sep 11, 2021

View reviewed changes

...springframework/boot/actuate/autoconfigure/metrics/startup/StartupTimeMetricsProperties.java Outdated Show resolved Hide resolved

onobc commented Sep 11, 2021

View reviewed changes

...uator/src/main/java/org/springframework/boot/actuate/metrics/startup/StartupTimeMetrics.java Outdated Show resolved Hide resolved

onobc commented Sep 11, 2021

View reviewed changes

...uator/src/main/java/org/springframework/boot/actuate/metrics/startup/StartupTimeMetrics.java Show resolved Hide resolved

onobc requested a review from philwebb September 11, 2021 04:39

Moved startup metric names configurability out of metric config props

869afb8

Removed JVM metric

55e0414

snicoll self-assigned this Sep 16, 2021

snicoll removed this from the 2.6.x milestone Sep 16, 2021

snicoll added this to the 2.6.0-M3 milestone Sep 16, 2021

snicoll pushed a commit to snicoll/spring-boot that referenced this pull request Sep 16, 2021

Add startup time metrics

695c963

See spring-projectsgh-27878

snicoll added a commit to snicoll/spring-boot that referenced this pull request Sep 16, 2021

Polish "Add startup time metrics"

a70faed

See spring-projectsgh-27878

snicoll pushed a commit that referenced this pull request Sep 16, 2021

Add startup time metrics

2e67963

See gh-27878

snicoll added a commit that referenced this pull request Sep 16, 2021

Polish "Add startup time metrics"

c62a681

See gh-27878

snicoll closed this in ce95e09 Sep 16, 2021

sdeleuze added a commit to sdeleuze/spring-native that referenced this pull request Sep 20, 2021

Adapt to spring-projects/spring-boot#27878

5734e17

philwebb added a commit that referenced this pull request Sep 21, 2021

Polish "Add startup time metrics"

98a0e07

See gh-27878

hh:mm:ss	step
00:00:00	jvm is started
00:00:04	`run` is invoked
00:00:08	context has been refreshed
00:00:12	runners done executing

Add startup time metrics #27878

Add startup time metrics #27878

Uh oh!

Conversation

onobc commented Sep 5, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

onobc Sep 5, 2021

Choose a reason for hiding this comment

spring context start time

application start time

jvm start time

Uh oh!

onobc commented Sep 6, 2021

Uh oh!

onobc commented Sep 8, 2021

Uh oh!

philwebb Sep 10, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

onobc Sep 11, 2021

Choose a reason for hiding this comment

Uh oh!

philwebb commented Sep 10, 2021

Uh oh!

onobc commented Sep 11, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

wilkinsona commented Sep 11, 2021

Uh oh!

onobc commented Sep 11, 2021

Uh oh!

snicoll commented Sep 16, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

onobc commented Sep 5, 2021 •

edited

Loading

philwebb Sep 10, 2021 •

edited

Loading

onobc commented Sep 11, 2021 •

edited

Loading