From e25886f2de508f5c412293cecd43ec7c997738a0 Mon Sep 17 00:00:00 2001 From: Andy Wilkinson Date: Fri, 15 Sep 2023 16:46:03 +0100 Subject: [PATCH] Consider checkpoint restoration when logging start time and uptime Closes gh-37084 --- .../spring-boot-parent/build.gradle | 7 ++ spring-boot-project/spring-boot/build.gradle | 1 + .../boot/SpringApplication.java | 106 +++++++++++++++++- .../boot/StartupInfoLogger.java | 23 ++-- .../boot/StartupInfoLoggerTests.java | 57 +++++++++- 5 files changed, 170 insertions(+), 24 deletions(-) diff --git a/spring-boot-project/spring-boot-parent/build.gradle b/spring-boot-project/spring-boot-parent/build.gradle index de20568d7a..d259269ce8 100644 --- a/spring-boot-project/spring-boot-parent/build.gradle +++ b/spring-boot-project/spring-boot-parent/build.gradle @@ -48,6 +48,13 @@ bom { ] } } + library("Crac", "1.4.0") { + group("org.crac") { + modules = [ + "crac" + ] + } + } library("Jakarta Inject", "2.0.1") { group("jakarta.inject") { modules = [ diff --git a/spring-boot-project/spring-boot/build.gradle b/spring-boot-project/spring-boot/build.gradle index ebc27fffe7..bad1e5e57f 100644 --- a/spring-boot-project/spring-boot/build.gradle +++ b/spring-boot-project/spring-boot/build.gradle @@ -56,6 +56,7 @@ dependencies { optional("org.assertj:assertj-core") optional("org.apache.groovy:groovy") optional("org.apache.groovy:groovy-xml") + optional("org.crac:crac") optional("org.eclipse.jetty:jetty-alpn-conscrypt-server") optional("org.eclipse.jetty:jetty-client") optional("org.eclipse.jetty:jetty-util") diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/SpringApplication.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/SpringApplication.java index 6af18efefe..b7b1d308e7 100644 --- a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/SpringApplication.java +++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/SpringApplication.java @@ -17,6 +17,7 @@ package org.springframework.boot; import java.lang.StackWalker.StackFrame; +import java.lang.management.ManagementFactory; import java.time.Duration; import java.util.ArrayList; import java.util.Arrays; @@ -35,6 +36,7 @@ import java.util.stream.Stream; import org.apache.commons.logging.Log; import org.apache.commons.logging.LogFactory; +import org.crac.management.CRaCMXBean; import org.springframework.aot.AotDetector; import org.springframework.beans.BeansException; @@ -301,10 +303,10 @@ public class SpringApplication { * @return a running {@link ApplicationContext} */ public ConfigurableApplicationContext run(String... args) { + Startup startup = Startup.create(); if (this.registerShutdownHook) { SpringApplication.shutdownHook.enableShutdowHookAddition(); } - long startTime = System.nanoTime(); DefaultBootstrapContext bootstrapContext = createBootstrapContext(); ConfigurableApplicationContext context = null; configureHeadlessProperty(); @@ -319,11 +321,11 @@ public class SpringApplication { prepareContext(bootstrapContext, context, environment, listeners, applicationArguments, printedBanner); refreshContext(context); afterRefresh(context, applicationArguments); - Duration timeTakenToStartup = Duration.ofNanos(System.nanoTime() - startTime); + startup.started(); if (this.logStartupInfo) { - new StartupInfoLogger(this.mainApplicationClass).logStarted(getApplicationLog(), timeTakenToStartup); + new StartupInfoLogger(this.mainApplicationClass).logStarted(getApplicationLog(), startup); } - listeners.started(context, timeTakenToStartup); + listeners.started(context, startup.timeTakenToStarted()); callRunners(context, applicationArguments); } catch (Throwable ex) { @@ -335,8 +337,7 @@ public class SpringApplication { } try { if (context.isRunning()) { - Duration timeTakenToReady = Duration.ofNanos(System.nanoTime() - startTime); - listeners.ready(context, timeTakenToReady); + listeners.ready(context, startup.ready()); } } catch (Throwable ex) { @@ -1657,4 +1658,97 @@ public class SpringApplication { } + abstract static class Startup { + + private Duration timeTakenToStarted; + + abstract long startTime(); + + abstract Long processUptime(); + + abstract String action(); + + final Duration started() { + long now = System.currentTimeMillis(); + this.timeTakenToStarted = Duration.ofMillis(now - startTime()); + return this.timeTakenToStarted; + } + + private Duration ready() { + long now = System.currentTimeMillis(); + return Duration.ofMillis(now - startTime()); + } + + Duration timeTakenToStarted() { + return this.timeTakenToStarted; + } + + static Startup create() { + if (ClassUtils.isPresent("jdk.crac.management.CRaCMXBean", Startup.class.getClassLoader())) { + return new CracStartup(); + } + return new StandardStartup(); + } + + } + + private static class CracStartup extends Startup { + + private final StandardStartup fallback = new StandardStartup(); + + @Override + Long processUptime() { + long uptime = CRaCMXBean.getCRaCMXBean().getUptimeSinceRestore(); + return (uptime >= 0) ? uptime : this.fallback.processUptime(); + } + + @Override + String action() { + if (restoreTime() >= 0) { + return "Restored"; + } + return this.fallback.action(); + } + + private long restoreTime() { + return CRaCMXBean.getCRaCMXBean().getRestoreTime(); + } + + @Override + long startTime() { + long restoreTime = restoreTime(); + if (restoreTime >= 0) { + return restoreTime; + } + return this.fallback.startTime(); + } + + } + + private static class StandardStartup extends Startup { + + private final Long startTime = System.currentTimeMillis(); + + @Override + long startTime() { + return this.startTime; + } + + @Override + Long processUptime() { + try { + return ManagementFactory.getRuntimeMXBean().getUptime(); + } + catch (Throwable ex) { + return null; + } + } + + @Override + String action() { + return "Started"; + } + + } + } diff --git a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/StartupInfoLogger.java b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/StartupInfoLogger.java index 1f3104bb60..98e4ac32a6 100644 --- a/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/StartupInfoLogger.java +++ b/spring-boot-project/spring-boot/src/main/java/org/springframework/boot/StartupInfoLogger.java @@ -1,5 +1,5 @@ /* - * Copyright 2012-2022 the original author or authors. + * Copyright 2012-2023 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. @@ -16,13 +16,12 @@ package org.springframework.boot; -import java.lang.management.ManagementFactory; -import java.time.Duration; import java.util.concurrent.Callable; import org.apache.commons.logging.Log; import org.springframework.aot.AotDetector; +import org.springframework.boot.SpringApplication.Startup; import org.springframework.boot.system.ApplicationHome; import org.springframework.boot.system.ApplicationPid; import org.springframework.context.ApplicationContext; @@ -52,9 +51,9 @@ class StartupInfoLogger { applicationLog.debug(LogMessage.of(this::getRunningMessage)); } - void logStarted(Log applicationLog, Duration timeTakenToStartup) { + void logStarted(Log applicationLog, Startup startup) { if (applicationLog.isInfoEnabled()) { - applicationLog.info(getStartedMessage(timeTakenToStartup)); + applicationLog.info(getStartedMessage(startup)); } } @@ -79,20 +78,18 @@ class StartupInfoLogger { return message; } - private CharSequence getStartedMessage(Duration timeTakenToStartup) { + private CharSequence getStartedMessage(Startup startup) { StringBuilder message = new StringBuilder(); - message.append("Started"); + message.append(startup.action()); appendApplicationName(message); message.append(" in "); - message.append(timeTakenToStartup.toMillis() / 1000.0); + message.append(startup.timeTakenToStarted().toMillis() / 1000.0); message.append(" seconds"); - try { - double uptime = ManagementFactory.getRuntimeMXBean().getUptime() / 1000.0; + Long uptimeMs = startup.processUptime(); + if (uptimeMs != null) { + double uptime = uptimeMs / 1000.0; message.append(" (process running for ").append(uptime).append(")"); } - catch (Throwable ex) { - // No JVM time available - } return message; } diff --git a/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/StartupInfoLoggerTests.java b/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/StartupInfoLoggerTests.java index 6bcd00527f..a6b1c90ba6 100644 --- a/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/StartupInfoLoggerTests.java +++ b/spring-boot-project/spring-boot/src/test/java/org/springframework/boot/StartupInfoLoggerTests.java @@ -16,11 +16,10 @@ package org.springframework.boot; -import java.time.Duration; - import org.apache.commons.logging.Log; import org.junit.jupiter.api.Test; +import org.springframework.boot.SpringApplication.Startup; import org.springframework.boot.system.ApplicationPid; import static org.assertj.core.api.Assertions.assertThat; @@ -72,11 +71,59 @@ class StartupInfoLoggerTests { @Test void startedFormat() { given(this.log.isInfoEnabled()).willReturn(true); - Duration timeTakenToStartup = Duration.ofMillis(10); - new StartupInfoLogger(getClass()).logStarted(this.log, timeTakenToStartup); + new StartupInfoLogger(getClass()).logStarted(this.log, new TestStartup(1345L, "Started")); then(this.log).should() .info(assertArg((message) -> assertThat(message.toString()).matches("Started " + getClass().getSimpleName() - + " in \\d+\\.\\d{1,3} seconds \\(process running for \\d+\\.\\d{1,3}\\)"))); + + " in \\d+\\.\\d{1,3} seconds \\(process running for 1.345\\)"))); + } + + @Test + void startedWithoutUptimeFormat() { + given(this.log.isInfoEnabled()).willReturn(true); + new StartupInfoLogger(getClass()).logStarted(this.log, new TestStartup(null, "Started")); + then(this.log).should() + .info(assertArg((message) -> assertThat(message.toString()) + .matches("Started " + getClass().getSimpleName() + " in \\d+\\.\\d{1,3} seconds"))); + } + + @Test + void restoredFormat() { + given(this.log.isInfoEnabled()).willReturn(true); + new StartupInfoLogger(getClass()).logStarted(this.log, new TestStartup(null, "Restored")); + then(this.log).should() + .info(assertArg((message) -> assertThat(message.toString()) + .matches("Restored " + getClass().getSimpleName() + " in \\d+\\.\\d{1,3} seconds"))); + } + + static class TestStartup extends Startup { + + private final long startTime = System.currentTimeMillis(); + + private final Long uptime; + + private final String action; + + TestStartup(Long uptime, String action) { + this.uptime = uptime; + this.action = action; + started(); + } + + @Override + long startTime() { + return this.startTime; + } + + @Override + Long processUptime() { + return this.uptime; + } + + @Override + String action() { + return this.action; + } + } }