1480 speedup npm install step for npm based formatters

CHANGES.md

@@ -10,6 +10,11 @@ This document is intended for Spotless developers.
 We adhere to the [keepachangelog](https://keepachangelog.com/en/1.0.0/) format (starting after version `1.27.0`).
 
 ## [Unreleased]
+### Added
+* Introduce `TimedLogger` to allow for logging of time taken by a task using slf4j ([#1590](https://github.com/diffplug/spotless/pull/1590))
+* `npm`-based formatters now support caching of `node_modules` directory ([#1590](https://github.com/diffplug/spotless/pull/1590))
+### Fixed
+* Reduce logging-noise created by `npm`-based formatters ([#1590](https://github.com/diffplug/spotless/pull/1590) fixes [#1582](https://github.com/diffplug/spotless/issues/1582))
 
 ## [2.35.0] - 2023-02-10
 ### Added

lib/build.gradle

@@ -56,6 +56,8 @@ tasks.named("check").configure {
 
 dependencies {
 	compileOnly 'org.slf4j:slf4j-api:2.0.0'
+	testCommonImplementation 'org.slf4j:slf4j-api:2.0.0'
+
 	// zero runtime reqs is a hard requirements for spotless-lib
 	// if you need a dep, put it in lib-extra
 	testCommonImplementation "org.junit.jupiter:junit-jupiter:$VER_JUNIT"

lib/src/main/java/com/diffplug/spotless/TimedLogger.java

@@ -0,0 +1,226 @@
+/*
+ * Copyright 2023 DiffPlug
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *     http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package com.diffplug.spotless;
+
+import static com.diffplug.spotless.LazyArgLogger.lazy;
+
+import java.util.List;
+import java.util.Objects;
+import java.util.stream.Stream;
+
+import javax.annotation.Nonnull;
+
+import org.slf4j.Logger;
+
+/**
+ * A logger that logs the time it took to execute a block of code.
+ */
+public class TimedLogger {
+
+	public static final String MESSAGE_PREFIX_BEGIN = "[BEGIN] ";
+
+	public static final String MESSAGE_PREFIX_END = "[END] ";
+
+	public static final String MESSAGE_SUFFIX_TOOK = " (took {})";
+
+	private final Logger logger;
+	private final Ticker ticker;
+
+	private TimedLogger(@Nonnull Logger logger, Ticker ticker) {
+		this.logger = Objects.requireNonNull(logger);
+		this.ticker = ticker;
+	}
+
+	public static TimedLogger forLogger(@Nonnull Logger logger) {
+		return forLogger(logger, Ticker.systemTicker());
+	}
+
+	public static TimedLogger forLogger(@Nonnull Logger logger, Ticker ticker) {
+		return new TimedLogger(logger, ticker);
+	}
+
+	public TimedExec withInfo(@Nonnull String message, Object... args) {
+		return new TimedExec(logger::isInfoEnabled, logger::info, ticker, message, args);
+	}
+
+	public TimedExec withDebug(@Nonnull String message, Object... args) {
+		return new TimedExec(logger::isDebugEnabled, logger::debug, ticker, message, args);
+	}
+
+	public TimedExec withTrace(@Nonnull String message, Object... args) {
+		return new TimedExec(logger::isTraceEnabled, logger::trace, ticker, message, args);
+	}
+
+	public TimedExec withWarn(@Nonnull String message, Object... args) {
+		return new TimedExec(logger::isWarnEnabled, logger::warn, ticker, message, args);
+	}
+
+	public TimedExec withError(@Nonnull String message, Object... args) {
+		return new TimedExec(logger::isErrorEnabled, logger::error, ticker, message, args);
+	}
+
+	public static class Timed implements AutoCloseable {
+
+		@Nonnull
+		private final String msg;
+
+		@Nonnull
+		private final List<Object> params;
+		@Nonnull
+		private final LogToLevelMethod delegatedLogger;
+		@Nonnull
+		private final Ticker ticker;
+
+		private final long startedAt;
+
+		public Timed(@Nonnull Ticker ticker, @Nonnull String msg, @Nonnull List<Object> params, @Nonnull LogToLevelMethod delegatedLogger) {
+			this.ticker = Objects.requireNonNull(ticker);
+			this.msg = Objects.requireNonNull(msg);
+			this.params = List.copyOf(Objects.requireNonNull(params));
+			this.delegatedLogger = Objects.requireNonNull(delegatedLogger);
+			this.startedAt = ticker.read();
+			logStart();
+		}
+
+		private void logStart() {
+			delegatedLogger.log(MESSAGE_PREFIX_BEGIN + msg, params.toArray());
+		}
+
+		private void logEnd() {
+			delegatedLogger.log(MESSAGE_PREFIX_END + msg + MESSAGE_SUFFIX_TOOK, paramsForEnd());
+		}
+
+		@Override
+		public final void close() {
+			logEnd();
+		}
+
+		private Object[] paramsForEnd() {
+			if (params.isEmpty() || !(params.get(params.size() - 1) instanceof Throwable)) {
+				// if the last element is not a throwable, we can add the duration as the last element
+				return Stream.concat(params.stream(), Stream.of(lazy(this::durationString))).toArray();
+			}
+			// if the last element is a throwable, we have to add the duration before the last element
+			return Stream.concat(
+					params.stream().limit(params.size() - 1),
+					Stream.of(lazy(this::durationString),
+							params.get(params.size() - 1)))
+					.toArray();
+		}
+
+		private String durationString() {
+			long duration = ticker.read() - startedAt;
+			if (duration < 1000) {
+				return duration + "ms";
+			} else if (duration < 1000 * 60) {
+				long seconds = duration / 1000;
+				long millis = duration - seconds * 1000;
+				return seconds + "." + millis + "s";
+			} else {
+				// output in the format 3m 4.321s
+				long minutes = duration / (1000 * 60);
+				long seconds = (duration - minutes * 1000 * 60) / 1000;
+				long millis = duration - minutes * 1000 * 60 - seconds * 1000;
+				return minutes + "m" + (seconds + millis > 0 ? " " + seconds + "." + millis + "s" : "");
+			}
+		}
+	}
+
+	public static final class NullStopWatchLogger extends Timed {
+		private static final NullStopWatchLogger INSTANCE = new NullStopWatchLogger();
+
+		private NullStopWatchLogger() {
+			super(Ticker.systemTicker(), "", List.of(), (m, a) -> {});
+		}
+	}
+
+	interface Ticker {
+		long read();
+
+		static Ticker systemTicker() {
+			return System::currentTimeMillis;
+		}
+	}
+
+	static class TestTicker implements Ticker {
+		private long time = 0;
+
+		@Override
+		public long read() {
+			return time;
+		}
+
+		public void tickMillis(long millis) {
+			time += millis;
+		}
+	}
+
+	public static class TimedExec {
+		@Nonnull
+		private final LogActiveMethod logActiveMethod;
+		@Nonnull
+		private final LogToLevelMethod logMethod;
+		@Nonnull
+		private final Ticker ticker;
+		@Nonnull
+		private final String message;
+		@Nonnull
+		private final Object[] args;
+
+		public TimedExec(LogActiveMethod logActiveMethod, LogToLevelMethod logMethod, Ticker ticker, String message, Object... args) {
+			this.logActiveMethod = Objects.requireNonNull(logActiveMethod);
+			this.logMethod = Objects.requireNonNull(logMethod);
+			this.ticker = Objects.requireNonNull(ticker);
+			this.message = Objects.requireNonNull(message);
+			this.args = Objects.requireNonNull(args);
+		}
+
+		public void run(ThrowingEx.Runnable r) {
+			try (Timed ignore = timed()) {
+				ThrowingEx.run(r);
+			}
+		}
+
+		public <T> T call(ThrowingEx.Supplier<T> s) {
+			try (Timed ignore = timed()) {
+				return ThrowingEx.get(s);
+			}
+		}
+
+		public void runChecked(ThrowingEx.Runnable r) throws Exception {
+			try (Timed ignore = timed()) {
+				r.run();
+			}
+		}
+
+		private Timed timed() {
+			if (logActiveMethod.isLogLevelActive()) {
+				return new Timed(ticker, message, List.of(args), logMethod);
+			}
+			return NullStopWatchLogger.INSTANCE;
+		}
+	}
+
+	@FunctionalInterface
+	private interface LogActiveMethod {
+		boolean isLogLevelActive();
+	}
+
+	@FunctionalInterface
+	private interface LogToLevelMethod {
+		void log(String message, Object... args);
+	}
+}

lib/src/main/java/com/diffplug/spotless/npm/EslintFormatterStep.java

@@ -15,7 +15,6 @@
  */
 package com.diffplug.spotless.npm;
 
-import static com.diffplug.spotless.LazyArgLogger.lazy;
 import static java.util.Objects.requireNonNull;
 
 import java.io.File;
@@ -71,13 +70,13 @@ public static Map<String, String> defaultDevDependenciesWithEslint(String versio
 		return Collections.singletonMap("eslint", version);
 	}
 
-	public static FormatterStep create(Map<String, String> devDependencies, Provisioner provisioner, File projectDir, File buildDir, NpmPathResolver npmPathResolver, EslintConfig eslintConfig) {
+	public static FormatterStep create(Map<String, String> devDependencies, Provisioner provisioner, File projectDir, File buildDir, File cacheDir, NpmPathResolver npmPathResolver, EslintConfig eslintConfig) {
 		requireNonNull(devDependencies);
 		requireNonNull(provisioner);
 		requireNonNull(projectDir);
 		requireNonNull(buildDir);
 		return FormatterStep.createLazy(NAME,
-				() -> new State(NAME, devDependencies, projectDir, buildDir, npmPathResolver, eslintConfig),
+				() -> new State(NAME, devDependencies, projectDir, buildDir, cacheDir, npmPathResolver, eslintConfig),
 				State::createFormatterFunc);
 	}
 
@@ -89,20 +88,20 @@ private static class State extends NpmFormatterStepStateBase implements Serializ
 		@SuppressFBWarnings("SE_TRANSIENT_FIELD_NOT_RESTORED")
 		private transient EslintConfig eslintConfigInUse;
 
-		State(String stepName, Map<String, String> devDependencies, File projectDir, File buildDir, NpmPathResolver npmPathResolver, EslintConfig eslintConfig) throws IOException {
+		State(String stepName, Map<String, String> devDependencies, File projectDir, File buildDir, File cacheDir, NpmPathResolver npmPathResolver, EslintConfig eslintConfig) throws IOException {
 			super(stepName,
 					new NpmConfig(
 							replaceDevDependencies(
 									NpmResourceHelper.readUtf8StringFromClasspath(EslintFormatterStep.class, "/com/diffplug/spotless/npm/eslint-package.json"),
 									new TreeMap<>(devDependencies)),
-							"eslint",
 							NpmResourceHelper.readUtf8StringFromClasspath(EslintFormatterStep.class,
 									"/com/diffplug/spotless/npm/common-serve.js",
 									"/com/diffplug/spotless/npm/eslint-serve.js"),
 							npmPathResolver.resolveNpmrcContent()),
 					new NpmFormatterStepLocations(
 							projectDir,
 							buildDir,
+							cacheDir,
 							npmPathResolver::resolveNpmExecutable,
 							npmPathResolver::resolveNodeExecutable));
 			this.origEslintConfig = requireNonNull(eslintConfig.verify());
@@ -116,7 +115,7 @@ protected void prepareNodeServerLayout() throws IOException {
 				// If any config files are provided, we need to make sure they are at the same location as the node modules
 				// as eslint will try to resolve plugin/config names relatively to the config file location and some
 				// eslint configs contain relative paths to additional config files (such as tsconfig.json e.g.)
-				logger.info("Copying config file <{}> to <{}> and using the copy", origEslintConfig.getEslintConfigPath(), nodeServerLayout.nodeModulesDir());
+				logger.debug("Copying config file <{}> to <{}> and using the copy", origEslintConfig.getEslintConfigPath(), nodeServerLayout.nodeModulesDir());
 				File configFileCopy = NpmResourceHelper.copyFileToDir(origEslintConfig.getEslintConfigPath(), nodeServerLayout.nodeModulesDir());
 				this.eslintConfigInUse = this.origEslintConfig.withEslintConfigPath(configFileCopy).verify();
 			}
@@ -162,8 +161,6 @@ public EslintFilePathPassingFormatterFunc(File projectDir, File nodeModulesDir,
 
 		@Override
 		public String applyWithFile(String unix, File file) throws Exception {
-			logger.info("formatting String '{}[...]' in file '{}'", lazy(() -> unix.substring(0, Math.min(50, unix.length()))), file);
-
 			Map<FormatOption, Object> eslintCallOptions = new HashMap<>();
 			setConfigToCallOptions(eslintCallOptions);
 			setFilePathToCallOptions(eslintCallOptions, file);