Skip to content

Commit e25886f

Browse files
wilkinsonawilkinsona
committed
Consider checkpoint restoration when logging start time and uptime
Closes gh-37084
1 parent b883c59 commit e25886f

File tree

5 files changed

+170
-24
lines changed

5 files changed

+170
-24
lines changed

‎spring-boot-project/spring-boot-parent/build.gradle‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -48,6 +48,13 @@ bom {
4848
]
4949
}
5050
}
51+
library("Crac", "1.4.0") {
52+
group("org.crac") {
53+
modules = [
54+
"crac"
55+
]
56+
}
57+
}
5158
library("Jakarta Inject", "2.0.1") {
5259
group("jakarta.inject") {
5360
modules = [

‎spring-boot-project/spring-boot/build.gradle‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -56,6 +56,7 @@ dependencies {
5656
optional("org.assertj:assertj-core")
5757
optional("org.apache.groovy:groovy")
5858
optional("org.apache.groovy:groovy-xml")
59+
optional("org.crac:crac")
5960
optional("org.eclipse.jetty:jetty-alpn-conscrypt-server")
6061
optional("org.eclipse.jetty:jetty-client")
6162
optional("org.eclipse.jetty:jetty-util")

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

Lines changed: 100 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@
1717
package org.springframework.boot;
1818

1919
import java.lang.StackWalker.StackFrame;
20+
import java.lang.management.ManagementFactory;
2021
import java.time.Duration;
2122
import java.util.ArrayList;
2223
import java.util.Arrays;
@@ -35,6 +36,7 @@
3536

3637
import org.apache.commons.logging.Log;
3738
import org.apache.commons.logging.LogFactory;
39+
import org.crac.management.CRaCMXBean;
3840

3941
import org.springframework.aot.AotDetector;
4042
import org.springframework.beans.BeansException;
@@ -301,10 +303,10 @@ private Optional<Class<?>> findMainClass(Stream<StackFrame> stack) {
301303
* @return a running {@link ApplicationContext}
302304
*/
303305
public ConfigurableApplicationContext run(String... args) {
306+
Startup startup = Startup.create();
304307
if (this.registerShutdownHook) {
305308
SpringApplication.shutdownHook.enableShutdowHookAddition();
306309
}
307-
long startTime = System.nanoTime();
308310
DefaultBootstrapContext bootstrapContext = createBootstrapContext();
309311
ConfigurableApplicationContext context = null;
310312
configureHeadlessProperty();
@@ -319,11 +321,11 @@ public ConfigurableApplicationContext run(String... args) {
319321
prepareContext(bootstrapContext, context, environment, listeners, applicationArguments, printedBanner);
320322
refreshContext(context);
321323
afterRefresh(context, applicationArguments);
322-
Duration timeTakenToStartup = Duration.ofNanos(System.nanoTime() - startTime);
324+
startup.started();
323325
if (this.logStartupInfo) {
324-
new StartupInfoLogger(this.mainApplicationClass).logStarted(getApplicationLog(), timeTakenToStartup);
326+
new StartupInfoLogger(this.mainApplicationClass).logStarted(getApplicationLog(), startup);
325327
}
326-
listeners.started(context, timeTakenToStartup);
328+
listeners.started(context, startup.timeTakenToStarted());
327329
callRunners(context, applicationArguments);
328330
}
329331
catch (Throwable ex) {
@@ -335,8 +337,7 @@ public ConfigurableApplicationContext run(String... args) {
335337
}
336338
try {
337339
if (context.isRunning()) {
338-
Duration timeTakenToReady = Duration.ofNanos(System.nanoTime() - startTime);
339-
listeners.ready(context, timeTakenToReady);
340+
listeners.ready(context, startup.ready());
340341
}
341342
}
342343
catch (Throwable ex) {
@@ -1657,4 +1658,97 @@ public void run() {
16571658

16581659
}
16591660

1661+
abstract static class Startup {
1662+
1663+
private Duration timeTakenToStarted;
1664+
1665+
abstract long startTime();
1666+
1667+
abstract Long processUptime();
1668+
1669+
abstract String action();
1670+
1671+
final Duration started() {
1672+
long now = System.currentTimeMillis();
1673+
this.timeTakenToStarted = Duration.ofMillis(now - startTime());
1674+
return this.timeTakenToStarted;
1675+
}
1676+
1677+
private Duration ready() {
1678+
long now = System.currentTimeMillis();
1679+
return Duration.ofMillis(now - startTime());
1680+
}
1681+
1682+
Duration timeTakenToStarted() {
1683+
return this.timeTakenToStarted;
1684+
}
1685+
1686+
static Startup create() {
1687+
if (ClassUtils.isPresent("jdk.crac.management.CRaCMXBean", Startup.class.getClassLoader())) {
1688+
return new CracStartup();
1689+
}
1690+
return new StandardStartup();
1691+
}
1692+
1693+
}
1694+
1695+
private static class CracStartup extends Startup {
1696+
1697+
private final StandardStartup fallback = new StandardStartup();
1698+
1699+
@Override
1700+
Long processUptime() {
1701+
long uptime = CRaCMXBean.getCRaCMXBean().getUptimeSinceRestore();
1702+
return (uptime >= 0) ? uptime : this.fallback.processUptime();
1703+
}
1704+
1705+
@Override
1706+
String action() {
1707+
if (restoreTime() >= 0) {
1708+
return "Restored";
1709+
}
1710+
return this.fallback.action();
1711+
}
1712+
1713+
private long restoreTime() {
1714+
return CRaCMXBean.getCRaCMXBean().getRestoreTime();
1715+
}
1716+
1717+
@Override
1718+
long startTime() {
1719+
long restoreTime = restoreTime();
1720+
if (restoreTime >= 0) {
1721+
return restoreTime;
1722+
}
1723+
return this.fallback.startTime();
1724+
}
1725+
1726+
}
1727+
1728+
private static class StandardStartup extends Startup {
1729+
1730+
private final Long startTime = System.currentTimeMillis();
1731+
1732+
@Override
1733+
long startTime() {
1734+
return this.startTime;
1735+
}
1736+
1737+
@Override
1738+
Long processUptime() {
1739+
try {
1740+
return ManagementFactory.getRuntimeMXBean().getUptime();
1741+
}
1742+
catch (Throwable ex) {
1743+
return null;
1744+
}
1745+
}
1746+
1747+
@Override
1748+
String action() {
1749+
return "Started";
1750+
}
1751+
1752+
}
1753+
16601754
}

‎spring-boot-project/spring-boot/src/main/java/org/springframework/boot/StartupInfoLogger.java‎

Lines changed: 10 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
/*
2-
* Copyright 2012-2022 the original author or authors.
2+
* Copyright 2012-2023 the original author or authors.
33
*
44
* Licensed under the Apache License, Version 2.0 (the "License");
55
* you may not use this file except in compliance with the License.
@@ -16,13 +16,12 @@
1616

1717
package org.springframework.boot;
1818

19-
import java.lang.management.ManagementFactory;
20-
import java.time.Duration;
2119
import java.util.concurrent.Callable;
2220

2321
import org.apache.commons.logging.Log;
2422

2523
import org.springframework.aot.AotDetector;
24+
import org.springframework.boot.SpringApplication.Startup;
2625
import org.springframework.boot.system.ApplicationHome;
2726
import org.springframework.boot.system.ApplicationPid;
2827
import org.springframework.context.ApplicationContext;
@@ -52,9 +51,9 @@ void logStarting(Log applicationLog) {
5251
applicationLog.debug(LogMessage.of(this::getRunningMessage));
5352
}
5453

55-
void logStarted(Log applicationLog, Duration timeTakenToStartup) {
54+
void logStarted(Log applicationLog, Startup startup) {
5655
if (applicationLog.isInfoEnabled()) {
57-
applicationLog.info(getStartedMessage(timeTakenToStartup));
56+
applicationLog.info(getStartedMessage(startup));
5857
}
5958
}
6059

@@ -79,20 +78,18 @@ private CharSequence getRunningMessage() {
7978
return message;
8079
}
8180

82-
private CharSequence getStartedMessage(Duration timeTakenToStartup) {
81+
private CharSequence getStartedMessage(Startup startup) {
8382
StringBuilder message = new StringBuilder();
84-
message.append("Started");
83+
message.append(startup.action());
8584
appendApplicationName(message);
8685
message.append(" in ");
87-
message.append(timeTakenToStartup.toMillis() / 1000.0);
86+
message.append(startup.timeTakenToStarted().toMillis() / 1000.0);
8887
message.append(" seconds");
89-
try {
90-
double uptime = ManagementFactory.getRuntimeMXBean().getUptime() / 1000.0;
88+
Long uptimeMs = startup.processUptime();
89+
if (uptimeMs != null) {
90+
double uptime = uptimeMs / 1000.0;
9191
message.append(" (process running for ").append(uptime).append(")");
9292
}
93-
catch (Throwable ex) {
94-
// No JVM time available
95-
}
9693
return message;
9794
}
9895

‎spring-boot-project/spring-boot/src/test/java/org/springframework/boot/StartupInfoLoggerTests.java‎

Lines changed: 52 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -16,11 +16,10 @@
1616

1717
package org.springframework.boot;
1818

19-
import java.time.Duration;
20-
2119
import org.apache.commons.logging.Log;
2220
import org.junit.jupiter.api.Test;
2321

22+
import org.springframework.boot.SpringApplication.Startup;
2423
import org.springframework.boot.system.ApplicationPid;
2524

2625
import static org.assertj.core.api.Assertions.assertThat;
@@ -72,11 +71,59 @@ void startingFormatInAotMode() {
7271
@Test
7372
void startedFormat() {
7473
given(this.log.isInfoEnabled()).willReturn(true);
75-
Duration timeTakenToStartup = Duration.ofMillis(10);
76-
new StartupInfoLogger(getClass()).logStarted(this.log, timeTakenToStartup);
74+
new StartupInfoLogger(getClass()).logStarted(this.log, new TestStartup(1345L, "Started"));
7775
then(this.log).should()
7876
.info(assertArg((message) -> assertThat(message.toString()).matches("Started " + getClass().getSimpleName()
79-
+ " in \\d+\\.\\d{1,3} seconds \\(process running for \\d+\\.\\d{1,3}\\)")));
77+
+ " in \\d+\\.\\d{1,3} seconds \\(process running for 1.345\\)")));
78+
}
79+
80+
@Test
81+
void startedWithoutUptimeFormat() {
82+
given(this.log.isInfoEnabled()).willReturn(true);
83+
new StartupInfoLogger(getClass()).logStarted(this.log, new TestStartup(null, "Started"));
84+
then(this.log).should()
85+
.info(assertArg((message) -> assertThat(message.toString())
86+
.matches("Started " + getClass().getSimpleName() + " in \\d+\\.\\d{1,3} seconds")));
87+
}
88+
89+
@Test
90+
void restoredFormat() {
91+
given(this.log.isInfoEnabled()).willReturn(true);
92+
new StartupInfoLogger(getClass()).logStarted(this.log, new TestStartup(null, "Restored"));
93+
then(this.log).should()
94+
.info(assertArg((message) -> assertThat(message.toString())
95+
.matches("Restored " + getClass().getSimpleName() + " in \\d+\\.\\d{1,3} seconds")));
96+
}
97+
98+
static class TestStartup extends Startup {
99+
100+
private final long startTime = System.currentTimeMillis();
101+
102+
private final Long uptime;
103+
104+
private final String action;
105+
106+
TestStartup(Long uptime, String action) {
107+
this.uptime = uptime;
108+
this.action = action;
109+
started();
110+
}
111+
112+
@Override
113+
long startTime() {
114+
return this.startTime;
115+
}
116+
117+
@Override
118+
Long processUptime() {
119+
return this.uptime;
120+
}
121+
122+
@Override
123+
String action() {
124+
return this.action;
125+
}
126+
80127
}
81128

82129
}

0 commit comments

Comments
 (0)