[GAL-241] option to log provisioning time at the end

core/src/main/java/org/jboss/galleon/Errors.java

@@ -505,6 +505,12 @@ static String layerNotFound(ConfigId layerId) {
         return "Failed to locate layer " + layerId + " in the the installation feature-pack layout";
     }
 
+    static String tookTime(String action, long startTimeNanos) {
+        final long timeMs = (System.nanoTime() - startTimeNanos) / 1000000;
+        final long timeSec = timeMs / 1000;
+        return action + " took " + timeSec + "." + (timeMs - timeSec * 1000) + " seconds";
+    }
+
     static void appendConfig(final StringBuilder buf, String model, String name) {
         if (model != null) {
             buf.append(" model ").append(model);

core/src/main/java/org/jboss/galleon/ProvisioningManager.java

@@ -71,6 +71,7 @@ public static class Builder extends UniverseResolverBuilder<Builder> {
         private ProvisioningLayoutFactory layoutFactory;
         private MessageWriter messageWriter;
         private UniverseResolver resolver;
+        private boolean logTime;
 
         private Builder() {
         }
@@ -123,6 +124,11 @@ public Builder setUniverseResolver(UniverseResolver resolver) throws Provisionin
             return this;
         }
 
+        public Builder setLogTime(boolean logTime) {
+            this.logTime = logTime;
+            return this;
+        }
+
         public ProvisioningManager build() throws ProvisioningException {
             return new ProvisioningManager(this);
         }
@@ -139,6 +145,7 @@ public static Builder builder() {
     private final String encoding;
     private final Path home;
     private final MessageWriter log;
+    private boolean logTime;
 
     private final UniverseResolver universeResolver;
     private ProvisioningLayoutFactory layoutFactory;
@@ -157,6 +164,7 @@ private ProvisioningManager(Builder builder) throws ProvisioningException {
         } else {
             universeResolver = builder.getUniverseResolver();
         }
+        this.logTime = builder.logTime;
     }
 
     /**
@@ -181,6 +189,24 @@ public Path getInstallationHome() {
         return home;
     }
 
+    /**
+     * Whether to log provisioning time
+     *
+     * @return  Whether provisioning time should be logged at the end
+     */
+    public boolean isLogTime() {
+        return logTime;
+    }
+
+    /**
+     * Whether to log provisioning time
+     *
+     * @return  Whether provisioning time should be logged at the end
+     */
+    public void setLogTime(boolean logTime) {
+        this.logTime = logTime;
+    }
+
     /**
      * Add named universe spec to the provisioning configuration
      *
@@ -592,6 +618,7 @@ private ProvisioningRuntime getRuntimeInternal(ProvisioningLayout<FeaturePackRun
         final ProvisioningRuntimeBuilder rtBuilder = ProvisioningRuntimeBuilder.newInstance(log)
                 .initRtLayout(layout)
                 .setEncoding(encoding)
+                .setLogTime(logTime)
                 .setFsDiff(fsDiff);
         if(setStagedDir) {
             rtBuilder.setStagedDir(home);
@@ -667,9 +694,7 @@ public FsDiff getFsDiff() throws ProvisioningException {
             final long startTime = System.nanoTime();
             final FsDiff fsDiff = FsDiff.diff(originalState, currentState);
             if (log.isVerboseEnabled()) {
-                final long timeMs = (System.nanoTime() - startTime) / 1000000;
-                final long timeSec = timeMs / 1000;
-                log.verbose("  filesystem diff took %d.%d seconds", timeSec, (timeMs - timeSec * 1000));
+                log.verbose(Errors.tookTime("  filesystem diff", startTime));
             }
             return fsDiff;
         }
@@ -771,9 +796,7 @@ private void persistHashes(ProvisioningRuntime runtime) throws ProvisioningExcep
             }
         }
         if(log.isVerboseEnabled()) {
-            final long timeMs = (System.nanoTime() - startTime) / 1000000;
-            final long timeSec = timeMs / 1000;
-            log.verbose("Hashing took %d.%d seconds", timeSec, (timeMs - timeSec * 1000));
+            log.verbose(Errors.tookTime("Hashing", startTime));
         }
     }
 

core/src/main/java/org/jboss/galleon/runtime/ProvisioningRuntime.java

@@ -57,6 +57,7 @@
 public class ProvisioningRuntime implements FeaturePackSet<FeaturePackRuntime>, AutoCloseable {
 
     private final long startTime;
+    private final boolean logTime;
     private ProvisioningConfig config;
     private FsDiff fsDiff;
     private final Path stagedDir;
@@ -67,6 +68,7 @@ public class ProvisioningRuntime implements FeaturePackSet<FeaturePackRuntime>,
 
     ProvisioningRuntime(final ProvisioningRuntimeBuilder builder, final MessageWriter messageWriter) throws ProvisioningException {
         this.startTime = builder.startTime;
+        this.logTime = builder.logTime;
         this.config = builder.config;
         this.layout = builder.layout.transform(new FeaturePackLayoutTransformer<FeaturePackRuntime, FeaturePackRuntimeBuilder>() {
             @Override
@@ -100,6 +102,10 @@ public FeaturePackRuntime transform(FeaturePackRuntimeBuilder other) throws Prov
         this.messageWriter = messageWriter;
     }
 
+    public boolean isLogTime() {
+        return logTime;
+    }
+
     /**
      * The target staged location
      *
@@ -327,10 +333,10 @@ public void close() {
                 IoUtils.recursiveDelete(stagedDir);
             }
         }
-        if (messageWriter.isVerboseEnabled()) {
-            final long time = System.currentTimeMillis() - startTime;
-            final long seconds = time / 1000;
-            messageWriter.verbose("Done in %d.%d seconds", seconds, (time - seconds * 1000));
+        if (logTime) {
+            messageWriter.print(Errors.tookTime("Provisioning", startTime));
+        } else if (messageWriter.isVerboseEnabled()) {
+            messageWriter.verbose(Errors.tookTime("Provisioning", startTime));
         }
     }
 }

core/src/main/java/org/jboss/galleon/runtime/ProvisioningRuntimeBuilder.java

@@ -84,6 +84,7 @@ public static ProvisioningRuntimeBuilder newInstance(final MessageWriter message
     }
 
     final long startTime;
+    boolean logTime;
     String encoding;
     ProvisioningConfig config;
     ProvisioningLayout<FeaturePackRuntimeBuilder> layout;
@@ -113,7 +114,7 @@ public static ProvisioningRuntimeBuilder newInstance(final MessageWriter message
     int includedPkgDeps;
 
     private ProvisioningRuntimeBuilder(final MessageWriter messageWriter) {
-        startTime = System.currentTimeMillis();
+        startTime = System.nanoTime();
         this.messageWriter = messageWriter;
     }
 
@@ -122,6 +123,11 @@ public ProvisioningRuntimeBuilder setEncoding(String encoding) {
         return this;
     }
 
+    public ProvisioningRuntimeBuilder setLogTime(boolean logTime) {
+        this.logTime = logTime;
+        return this;
+    }
+
     public ProvisioningRuntimeBuilder initRtLayout(ProvisioningLayout<FeaturePackRuntimeBuilder> configLayout) throws ProvisioningException {
         layout = configLayout;
         return this;

maven-plugin/src/main/java/org/jboss/galleon/maven/plugin/ProvisionStateMojo.java

@@ -1,5 +1,5 @@
 /*
- * Copyright 2016-2018 Red Hat, Inc. and/or its affiliates
+ * Copyright 2016-2019 Red Hat, Inc. and/or its affiliates
  * and other contributors as indicated by the @author tags.
  *
  * Licensed under the Apache License, Version 2.0 (the "License");
@@ -128,6 +128,12 @@ public class ProvisionStateMojo extends AbstractMojo {
     @Parameter(alias = "offline", defaultValue = "true")
     private boolean offline;
 
+    /**
+     * Whether to log provisioning time at the end
+     */
+    @Parameter(alias = "log-time", defaultValue = "false")
+    private boolean logTime;
+
     /**
      * A list of artifacts and paths pointing to feature-pack archives that should be resolved locally without
      * involving the universe-based feature-pack resolver at provisioning time.
@@ -165,6 +171,7 @@ private void doProvision() throws MojoExecutionException, ProvisioningException
         try (ProvisioningManager pm = ProvisioningManager.builder().addArtifactResolver(artifactResolver)
                 .setInstallationHome(installDir.toPath())
                 .setMessageWriter(new DefaultMessageWriter(System.out, System.err, getLog().isDebugEnabled()))
+                .setLogTime(logTime)
                 .build()) {
 
             for (FeaturePack fp : featurePacks) {