Merge pull request #16708 from stuartwdouglas/timing-tests

Fix continuous testing timing output
quarkusio · Apr 27, 2021 · 6c26085 · 6c26085
2 parents bb6edf9 + c5170e2
commit 6c26085
Show file tree

Hide file tree

Showing 10 changed files with 62 additions and 41 deletions.
diff --git a/core/deployment/src/main/java/io/quarkus/deployment/dev/IsolatedDevModeMain.java b/core/deployment/src/main/java/io/quarkus/deployment/dev/IsolatedDevModeMain.java
@@ -328,7 +328,7 @@ public void close() {
     //the main entry point, but loaded inside the augmentation class loader
     @Override
     public void accept(CuratedApplication o, Map<String, Object> params) {
-        Timing.staticInitStarted(o.getBaseRuntimeClassLoader());
+        Timing.staticInitStarted(o.getBaseRuntimeClassLoader(), false);
         //https://github.com/quarkusio/quarkus/issues/9748
         //if you have an app with all daemon threads then the app thread
         //may be the only thread keeping the JVM alive

diff --git a/core/deployment/src/main/java/io/quarkus/deployment/dev/IsolatedRemoteDevModeMain.java b/core/deployment/src/main/java/io/quarkus/deployment/dev/IsolatedRemoteDevModeMain.java
@@ -179,7 +179,7 @@ public void close() {
     @Override
     public void accept(CuratedApplication o, Map<String, Object> o2) {
         LoggingSetupRecorder.handleFailedStart(); //we are not going to actually run an app
-        Timing.staticInitStarted(o.getBaseRuntimeClassLoader());
+        Timing.staticInitStarted(o.getBaseRuntimeClassLoader(), false);
         try {
             curatedApplication = o;
             Object potentialContext = o2.get(DevModeContext.class.getName());

diff --git a/core/deployment/src/main/java/io/quarkus/deployment/steps/MainClassBuildStep.java b/core/deployment/src/main/java/io/quarkus/deployment/steps/MainClassBuildStep.java
@@ -157,7 +157,8 @@ void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
 
         mv.invokeStaticMethod(CONFIGURE_STEP_TIME_ENABLED);
 
-        mv.invokeStaticMethod(MethodDescriptor.ofMethod(Timing.class, "staticInitStarted", void.class));
+        mv.invokeStaticMethod(MethodDescriptor.ofMethod(Timing.class, "staticInitStarted", void.class, boolean.class),
+                mv.load(launchMode.isAuxiliaryApplication()));
 
         // ensure that the config class is initialized
         mv.invokeStaticMethod(RunTimeConfigurationGenerator.C_ENSURE_INITIALIZED);
@@ -283,13 +284,14 @@ void build(List<StaticBytecodeRecorderBuildItem> staticInitTasks,
         ResultHandle featuresHandle = tryBlock.load(featureNames.stream().sorted().collect(Collectors.joining(", ")));
         tryBlock.invokeStaticMethod(
                 ofMethod(Timing.class, "printStartupTime", void.class, String.class, String.class, String.class, String.class,
-                        String.class, boolean.class),
+                        String.class, boolean.class, boolean.class),
                 tryBlock.load(applicationInfo.getName()),
                 tryBlock.load(applicationInfo.getVersion()),
                 tryBlock.load(Version.getVersion()),
                 featuresHandle,
                 activeProfile,
-                tryBlock.load(LaunchMode.DEVELOPMENT.equals(launchMode.getLaunchMode())));
+                tryBlock.load(LaunchMode.DEVELOPMENT.equals(launchMode.getLaunchMode())),
+                tryBlock.load(launchMode.isAuxiliaryApplication()));
 
         tryBlock.invokeStaticMethod(
                 ofMethod(QuarkusConsole.class, "start", void.class));

diff --git a/core/runtime/src/main/java/io/quarkus/runtime/Application.java b/core/runtime/src/main/java/io/quarkus/runtime/Application.java
@@ -197,7 +197,7 @@ public final void stop(Runnable afterStopTask) {
         } finally {
             stateLock.unlock();
         }
-        Timing.staticInitStopped();
+        Timing.staticInitStopped(auxilaryApplication);
         try {
             ShutdownRecorder.runShutdown();
             doStop();

diff --git a/core/runtime/src/main/java/io/quarkus/runtime/graal/TimingReplacement.java b/core/runtime/src/main/java/io/quarkus/runtime/graal/TimingReplacement.java
@@ -10,11 +10,11 @@
 final class TimingReplacement {
 
     @Alias
-    private static volatile long bootStartTime;
+    private static Timing main = null;
 
     @Substitute
     public static void mainStarted() {
-        bootStartTime = System.nanoTime();
+        main.bootStartTime = System.nanoTime();
     }
 
 }
diff --git a/...tx-http/deployment/src/main/java/io/quarkus/vertx/http/deployment/VertxHttpProcessor.java b/...tx-http/deployment/src/main/java/io/quarkus/vertx/http/deployment/VertxHttpProcessor.java
@@ -296,7 +296,8 @@ void openSocket(ApplicationStartBuildItem start,
                 httpBuildTimeConfig, httpConfiguration, launchMode.getLaunchMode(), startVirtual, startSocket,
                 eventLoopCount.getEventLoopCount(),
                 websocketSubProtocols.stream().map(bi -> bi.getWebsocketSubProtocols())
-                        .collect(Collectors.toList()));
+                        .collect(Collectors.toList()),
+                launchMode.isAuxiliaryApplication());
     }
 
     @BuildStep

diff --git a/...ons/vertx-http/runtime/src/main/java/io/quarkus/vertx/http/runtime/VertxHttpRecorder.java b/...ons/vertx-http/runtime/src/main/java/io/quarkus/vertx/http/runtime/VertxHttpRecorder.java
@@ -221,7 +221,7 @@ public static void startServerAfterFailedStart() {
                 public Integer get() {
                     return ProcessorInfo.availableProcessors() * 2; //this is dev mode, so the number of IO threads not always being 100% correct does not really matter in this case
                 }
-            }, null);
+            }, null, false);
 
         } catch (Exception e) {
             throw new RuntimeException(e);
@@ -237,7 +237,8 @@ public RuntimeValue<Router> initializeRouter(final Supplier<Vertx> vertxRuntimeV
     public void startServer(Supplier<Vertx> vertx, ShutdownContext shutdown,
             HttpBuildTimeConfig httpBuildTimeConfig, HttpConfiguration httpConfiguration,
             LaunchMode launchMode,
-            boolean startVirtual, boolean startSocket, Supplier<Integer> ioThreads, List<String> websocketSubProtocols)
+            boolean startVirtual, boolean startSocket, Supplier<Integer> ioThreads, List<String> websocketSubProtocols,
+            boolean auxiliaryApplication)
             throws IOException {
 
         if (startVirtual) {
@@ -247,7 +248,7 @@ public void startServer(Supplier<Vertx> vertx, ShutdownContext shutdown,
             // Start the server
             if (closeTask == null) {
                 doServerStart(vertx.get(), httpBuildTimeConfig, httpConfiguration, launchMode, ioThreads,
-                        websocketSubProtocols);
+                        websocketSubProtocols, auxiliaryApplication);
                 if (launchMode != LaunchMode.DEVELOPMENT) {
                     shutdown.addShutdownTask(closeTask);
                 }
@@ -459,7 +460,7 @@ private void warnIfDeprecatedHttpConfigPropertiesPresent(HttpConfiguration httpC
 
     private static void doServerStart(Vertx vertx, HttpBuildTimeConfig httpBuildTimeConfig,
             HttpConfiguration httpConfiguration, LaunchMode launchMode,
-            Supplier<Integer> eventLoops, List<String> websocketSubProtocols) throws IOException {
+            Supplier<Integer> eventLoops, List<String> websocketSubProtocols, boolean auxiliaryApplication) throws IOException {
         // Http server configuration
         HttpServerOptions httpServerOptions = createHttpServerOptions(httpConfiguration, launchMode, websocketSubProtocols);
         HttpServerOptions domainSocketOptions = createDomainSocketOptions(httpConfiguration, websocketSubProtocols);
@@ -532,12 +533,13 @@ public void handle(AsyncResult<Void> event) {
             throw new RuntimeException("Unable to start HTTP server", e);
         }
 
-        setHttpServerTiming(httpConfiguration.insecureRequests, httpServerOptions, sslConfig, domainSocketOptions);
+        setHttpServerTiming(httpConfiguration.insecureRequests, httpServerOptions, sslConfig, domainSocketOptions,
+                auxiliaryApplication);
     }
 
     private static void setHttpServerTiming(InsecureRequests insecureRequests, HttpServerOptions httpServerOptions,
             HttpServerOptions sslConfig,
-            HttpServerOptions domainSocketOptions) {
+            HttpServerOptions domainSocketOptions, boolean auxiliaryApplication) {
         String serverListeningMessage = "Listening on: ";
         int socketCount = 0;
 
@@ -561,7 +563,7 @@ private static void setHttpServerTiming(InsecureRequests insecureRequests, HttpS
             }
             serverListeningMessage += String.format("unix:%s", domainSocketOptions.getHost());
         }
-        Timing.setHttpServer(serverListeningMessage);
+        Timing.setHttpServer(serverListeningMessage, auxiliaryApplication);
     }
 
     /**

diff --git a/...rojects/bootstrap/runner/src/main/java/io/quarkus/bootstrap/runner/QuarkusEntryPoint.java b/...rojects/bootstrap/runner/src/main/java/io/quarkus/bootstrap/runner/QuarkusEntryPoint.java
@@ -21,7 +21,7 @@ public class QuarkusEntryPoint {
 
     public static void main(String... args) throws Throwable {
         System.setProperty("java.util.logging.manager", org.jboss.logmanager.LogManager.class.getName());
-        Timing.staticInitStarted();
+        Timing.staticInitStarted(false);
         doRun(args);
     }
 

diff --git a/independent-projects/bootstrap/runner/src/main/java/io/quarkus/bootstrap/runner/Timing.java b/independent-projects/bootstrap/runner/src/main/java/io/quarkus/bootstrap/runner/Timing.java
@@ -14,32 +14,44 @@
  */
 public class Timing {
 
-    private static volatile long bootStartTime = -1;
+    public volatile long bootStartTime = -1;
 
-    private static volatile long bootStopTime = -1;
+    private volatile long bootStopTime = -1;
 
-    private static volatile String httpServerInfo = "";
+    private volatile String httpServerInfo = "";
 
     private static final String UNSET_VALUE = "<<unset>>";
 
-    public static void staticInitStarted() {
-        if (bootStartTime < 0) {
-            bootStartTime = System.nanoTime();
+    private static final Timing main = new Timing();
+    private static final Timing auxiliary = new Timing();
+
+    private static Timing get(boolean anc) {
+        if (anc) {
+            return auxiliary;
+        }
+        return main;
+    }
+
+    public static void staticInitStarted(boolean auxiliary) {
+        Timing t = get(auxiliary);
+        if (t.bootStartTime < 0) {
+            t.bootStartTime = System.nanoTime();
         }
     }
 
-    public static void staticInitStarted(ClassLoader cl) {
+    public static void staticInitStarted(ClassLoader cl, boolean auxiliary) {
         try {
             Class<?> realTiming = cl.loadClass(Timing.class.getName());
-            realTiming.getMethod("staticInitStarted").invoke(null);
+            realTiming.getMethod("staticInitStarted", boolean.class).invoke(null, auxiliary);
         } catch (Exception e) {
             throw new RuntimeException(e);
         }
     }
 
-    public static void staticInitStopped() {
-        if (bootStopTime < 0) {
-            bootStopTime = System.nanoTime();
+    public static void staticInitStopped(boolean auxiliary) {
+        Timing t = get(auxiliary);
+        if (t.bootStopTime < 0) {
+            t.bootStopTime = System.nanoTime();
         }
     }
 
@@ -49,8 +61,9 @@ public static void staticInitStopped() {
      *
      * @param info
      */
-    public static void setHttpServer(String info) {
-        httpServerInfo = info;
+    public static void setHttpServer(String info, boolean auxiliary) {
+        Timing t = get(auxiliary);
+        t.httpServerInfo = info;
     }
 
     /**
@@ -60,7 +73,7 @@ public static void mainStarted() {
     }
 
     public static void restart() {
-        bootStartTime = System.nanoTime();
+        main.bootStartTime = System.nanoTime();
     }
 
     public static void restart(ClassLoader cl) {
@@ -73,8 +86,9 @@ public static void restart(ClassLoader cl) {
     }
 
     public static void printStartupTime(String name, String version, String quarkusVersion, String features, String profile,
-            boolean liveCoding) {
-        final long bootTimeNanoSeconds = System.nanoTime() - bootStartTime;
+            boolean liveCoding, boolean anc) {
+        Timing t = get(anc);
+        final long bootTimeNanoSeconds = System.nanoTime() - t.bootStartTime;
         final Logger logger = Logger.getLogger("io.quarkus");
         //Use a BigDecimal so we can render in seconds with 3 digits precision, as requested:
         final BigDecimal secondsRepresentation = convertToBigDecimalSeconds(bootTimeNanoSeconds);
@@ -83,26 +97,27 @@ public static void printStartupTime(String name, String version, String quarkusV
         final String nativeOrJvm = ImageInfo.inImageRuntimeCode() ? "native" : "on JVM";
         if (UNSET_VALUE.equals(safeAppName) || UNSET_VALUE.equals(safeAppVersion)) {
             logger.infof("Quarkus %s %s started in %ss. %s", quarkusVersion, nativeOrJvm, secondsRepresentation,
-                    httpServerInfo);
+                    t.httpServerInfo);
         } else {
             logger.infof("%s %s %s (powered by Quarkus %s) started in %ss. %s", name, version, nativeOrJvm, quarkusVersion,
-                    secondsRepresentation, httpServerInfo);
+                    secondsRepresentation, t.httpServerInfo);
         }
         logger.infof("Profile %s activated. %s", profile, liveCoding ? "Live Coding activated." : "");
         logger.infof("Installed features: [%s]", features);
-        bootStartTime = -1;
+        t.bootStartTime = -1;
     }
 
-    public static void printStopTime(String name, boolean auxilaryApplication) {
-        final long stopTimeNanoSeconds = System.nanoTime() - bootStopTime;
+    public static void printStopTime(String name, boolean auxiliaryApplication) {
+        Timing t = get(auxiliaryApplication);
+        final long stopTimeNanoSeconds = System.nanoTime() - t.bootStopTime;
         final Logger logger = Logger.getLogger("io.quarkus");
         final BigDecimal secondsRepresentation = convertToBigDecimalSeconds(stopTimeNanoSeconds);
         logger.infof("%s stopped in %ss",
                 (UNSET_VALUE.equals(name) || name == null || name.trim().isEmpty()) ? "Quarkus" : name,
                 secondsRepresentation);
-        bootStopTime = -1;
+        t.bootStopTime = -1;
 
-        if (!auxilaryApplication) {
+        if (!auxiliaryApplication) {
             /**
              * We can safely close log handlers after stop time has been printed.
              */

diff --git a/test-framework/junit5/src/main/java/io/quarkus/test/junit/QuarkusTestExtension.java b/test-framework/junit5/src/main/java/io/quarkus/test/junit/QuarkusTestExtension.java
@@ -315,7 +315,8 @@ private ExtensionState doJavaStart(ExtensionContext context, Class<? extends Qua
             // we need to write the Index to make it reusable from other parts of the testing infrastructure that run in different ClassLoaders
             TestClassIndexer.writeIndex(testClassesIndex, requiredTestClass);
 
-            Timing.staticInitStarted(curatedApplication.getBaseRuntimeClassLoader());
+            Timing.staticInitStarted(curatedApplication.getBaseRuntimeClassLoader(),
+                    curatedApplication.getQuarkusBootstrap().isAuxiliaryApplication());
             final Map<String, Object> props = new HashMap<>();
             props.put(TEST_LOCATION, testClassLocation);
             props.put(TEST_CLASS, requiredTestClass);