Currently, startup metrics missing JVM startup time presented in logs. Example startup log contains line:
Started Application in 15.463 seconds (JVM running for 30.308)
It is produced by StartupInfoLogger.
Thanks to this contribution metric application.started.jvm.time will contain gauge with value closed to 30.308.
Comment From: jonatan-ivanov
Thank you for the PR!
Have you seen process.uptime from UptimeMetrics?
Also, I think what you are measuring here is not the "Time taken (ms) to start the JVM". It is the uptime of the JVM (time since the JVM started) as ManagementFactory.getRuntimeMXBean().getUptime() suggests.
Comment From: wyhasany
@jonatan-ivanov I've seen that metric, it constantly grows that's why it's difficult to figure out how many time passed for process startup (aka context refresh). It can be measured before and after context refresh. Even if the very first metric would show process startup time it would be difficult to create query to get it from dataseries DB. I'm just applying the logic already used in StartupInfoLogger.
Comment From: jonatan-ivanov
Yes, since it should measure uptime, it must grow as time passes.
I don't really understand the rest of your comment, could you please explain it with an example? Right now it seems to me that process.uptime is the same what you are trying to introduce here (they use the same method: ManagementFactory.getRuntimeMXBean().getUptime()) therefore tis PR seems redundant to me. What am I missing?
Comment From: wyhasany
New metric, of course, uses the very same source: ManagementFactory.getRuntimeMXBean().getUptime(). However, it is calculated only once on context refresh, while process.uptime is calculated continuously. As the name suggests:
- application.started.jvm.time - shows the time of JVM process startup.
- process.uptime - shows the process uptime.
Comment From: jonatan-ivanov
However, it is calculated only once on context refresh, while process.uptime is calculated continuously
Oh I see, I did not notice this is registering a number to the TimeGauge instead of the method, thank you for clarifying that.
Though my understanding might be still different than yours a bit. I think this is still not measuring the JVM startup time as its description entails:
Time taken (ms) to start the JVM
This is measuring the JVM uptime around the point when the application started event was emitted not the JVM startup time. These two can be different. Let's say starting the Spring context takes an hour (I'm evil and I put a thread.sleep into a bean definition). In this case this metric that says "Time taken (ms) to start the JVM" will report 1 hour but the JVM startup time should have been in the milliseconds range.
I think what you wrote in the description might have the same misunderstanding.
Currently, startup metrics missing JVM startup time presented in logs. Example startup log contains line:
Started Application in 15.463 seconds (JVM running for 30.308)
What's in the logs is not the JVM startup time but the JVM uptime around the point the app was started.
With these, I guess my question is: do you want a metric to measure the JVM startup time (could be tricky and I think the JVM should measure this for us) or you want a metric that tells you what was the JVM uptime when the app was started. If the latter, the implementation looks good to me we "just" need to do a few things:
1. Find a name and a description that reflects what we are measuring, e.g.: process.started.time and Process uptime (ms) when the application started
2. The signature of one of the ctors is changed, this is a breaking change we should avoid, can you introduce a new ctor instead and mark the one you modified deprecated?
3. Maybe add more verifications and do some extra checks for the value (should be greater than app start time)
Also, I would use the word process instead of jvm since if you use GraalVM native-image, your app will run on SubstrateVM which is not a JVM, if you upgrade your logs will change to reflect this:
Started Boot3WithWebSampleApplication in 2.012 seconds (process running for 2.413)
Comment From: jonatan-ivanov
I marked this for team meeting to figure out the name and the description of a metric that reports the process uptime at the point when the app started, similarly to what you can find in the startup logs:
Started Boot3WithWebSampleApplication in 2.012 seconds (process running for 2.413)
We publish a metric for the first one (application.started.time) but we don't have one for the second one ("process running for" at the time the app started event was emitted). I was thinking about these:
- name: process.started.time
- description: Process uptime (ms) when the application started
Comment From: wyhasany
@jonatan-ivanov Definitely, I would like a metric that indicates the JVM uptime when the application was started. I will implement your suggestions shortly. Thank you for your valuable input. Please review this pull request again.
Comment From: jonatan-ivanov
Thank you! Let me discuss this with the team hopefully next week and we will get back to you after.
Comment From: philwebb
Thanks for the PR @wyhasany. We discussed this today on a team call and we'd prefer not to add an additional startup metric at this point. We're concerned that folks might find the additional metric confusing, especially if they are using a traditional war deployment where the server says up for a long period of time.
If you want to add this metric to your own applications, you should be able to do so by writing something similar to StartupTimeMetricsListener.
We can always see if we get any other requests for this feature, but for now we'd like to keep things as simple as possible.
Thanks anyway!