Use consistent time unit format in logs

Author: mezz

Core/src/main/java/mezz/jei/core/util/LoggedTimer.java

@@ -18,6 +18,6 @@ public void start(String message) {
 
 	public void stop() {
 		stopWatch.stop();
-		LOGGER.info("{} took {}", message, stopWatch);
+		LOGGER.info("{} took {}", message, TimeUtil.toHumanString(stopWatch.elapsed()));
 	}
 }

Core/src/main/java/mezz/jei/core/util/TimeUtil.java

@@ -0,0 +1,40 @@
+package mezz.jei.core.util;
+
+import java.time.Duration;
+import java.util.Locale;
+import java.util.concurrent.TimeUnit;
+
+public class TimeUtil {
+	public static String toHumanString(Duration duration) {
+		TimeUnit unit = getSmallestUnit(duration);
+		long nanos = duration.toNanos();
+		double value = (double) nanos / TimeUnit.NANOSECONDS.convert(1, unit);
+		return String.format(Locale.ROOT, "%.4g %s", value, unitToString(unit));
+	}
+
+	private static TimeUnit getSmallestUnit(Duration duration) {
+		if (duration.toDays() > 0) {
+			return TimeUnit.DAYS;
+		}
+		if (duration.toHours() > 0) {
+			return TimeUnit.HOURS;
+		}
+		if (duration.toMinutes() > 0) {
+			return TimeUnit.MINUTES;
+		}
+		if (duration.toSeconds() > 0) {
+			return TimeUnit.SECONDS;
+		}
+		if (duration.toMillis() > 0) {
+			return TimeUnit.MILLISECONDS;
+		}
+		if (duration.toNanos() > 1000) {
+			return TimeUnit.MICROSECONDS;
+		}
+		return TimeUnit.NANOSECONDS;
+	}
+
+	private static String unitToString(TimeUnit unit) {
+		return unit.name().toLowerCase(Locale.ROOT);
+	}
+}

Library/src/main/java/mezz/jei/library/load/PluginCaller.java

@@ -2,6 +2,7 @@
 
 import com.google.common.base.Stopwatch;
 import mezz.jei.api.IModPlugin;
+import mezz.jei.core.util.TimeUtil;
 import mezz.jei.library.plugins.vanilla.VanillaPlugin;
 import net.minecraft.resources.ResourceLocation;
 import org.apache.logging.log4j.LogManager;
@@ -35,6 +36,6 @@ public static void callOnPlugins(String title, List<IModPlugin> plugins, Consume
 			}
 		}
 
-		LOGGER.info("{} took {}", title, stopwatch);
+		LOGGER.info("{} took {}", title, TimeUtil.toHumanString(stopwatch.elapsed()));
 	}
 }

Library/src/main/java/mezz/jei/library/load/PluginCallerTimerRunnable.java

@@ -1,20 +1,11 @@
 package mezz.jei.library.load;
 
+import mezz.jei.core.util.TimeUtil;
 import net.minecraft.resources.ResourceLocation;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
 
 import java.time.Duration;
-import java.util.Locale;
-import java.util.concurrent.TimeUnit;
-
-import static java.util.concurrent.TimeUnit.DAYS;
-import static java.util.concurrent.TimeUnit.HOURS;
-import static java.util.concurrent.TimeUnit.MICROSECONDS;
-import static java.util.concurrent.TimeUnit.MILLISECONDS;
-import static java.util.concurrent.TimeUnit.MINUTES;
-import static java.util.concurrent.TimeUnit.NANOSECONDS;
-import static java.util.concurrent.TimeUnit.SECONDS;
 
 public class PluginCallerTimerRunnable {
 	private static final Logger LOGGER = LogManager.getLogger();
@@ -39,48 +30,16 @@ public void check() {
 		Duration elapsed = Duration.ofNanos(System.nanoTime() - this.startTime);
 		long elapsedMs = elapsed.toMillis();
 		if (elapsedMs > nextLongReportDurationMs) {
-			LOGGER.error("{}: {} is running and has taken {} so far", title, pluginUid, toHumanString(elapsed));
+			LOGGER.error("{}: {} is running and has taken {} so far", title, pluginUid, TimeUtil.toHumanString(elapsed));
 			nextLongReportDurationMs += longReportDurationInterval;
 		}
 	}
 
 	public void stop() {
 		Duration elapsed = Duration.ofNanos(System.nanoTime() - this.startTime);
 		if (elapsed.toMillis() > startReportDurationMs) {
-			LOGGER.info("{}: {} took {}", title, pluginUid, toHumanString(elapsed));
-		}
-	}
-
-	private static String toHumanString(Duration duration) {
-		TimeUnit unit = getSmallestUnit(duration);
-		long nanos = duration.toNanos();
-		double value = (double) nanos / NANOSECONDS.convert(1, unit);
-		return String.format(Locale.ROOT, "%.4g %s", value, unitToString(unit));
-	}
-
-	private static TimeUnit getSmallestUnit(Duration duration) {
-		if (duration.toDays() > 0) {
-			return DAYS;
+			LOGGER.info("{}: {} took {}", title, pluginUid, TimeUtil.toHumanString(elapsed));
 		}
-		if (duration.toHours() > 0) {
-			return HOURS;
-		}
-		if (duration.toMinutes() > 0) {
-			return MINUTES;
-		}
-		if (duration.toSeconds() > 0) {
-			return SECONDS;
-		}
-		if (duration.toMillis() > 0) {
-			return MILLISECONDS;
-		}
-		if (duration.toNanos() > 1000) {
-			return MICROSECONDS;
-		}
-		return NANOSECONDS;
 	}
 
-	private static String unitToString(TimeUnit unit) {
-		return unit.name().toLowerCase(Locale.ROOT);
-	}
 }

Library/src/main/java/mezz/jei/library/recipes/PluginManager.java

@@ -5,6 +5,7 @@
 import mezz.jei.api.recipe.IFocusGroup;
 import mezz.jei.api.recipe.advanced.IRecipeManagerPlugin;
 import mezz.jei.api.recipe.types.IRecipeType;
+import mezz.jei.core.util.TimeUtil;
 import mezz.jei.library.recipes.collect.RecipeTypeData;
 import org.apache.logging.log4j.LogManager;
 import org.apache.logging.log4j.Logger;
@@ -86,12 +87,12 @@ private <T> Stream<T> getRecipes(IRecipeManagerPlugin plugin, IRecipeType<T> rec
 	}
 
 	private <T> T safeCallPlugin(IRecipeManagerPlugin plugin, Supplier<T> supplier, T defaultValue) {
-		Stopwatch stopWatch = Stopwatch.createStarted();
+		Stopwatch stopwatch = Stopwatch.createStarted();
 		try {
 			T result = supplier.get();
-			stopWatch.stop();
-			if (stopWatch.elapsed(TimeUnit.MILLISECONDS) > 10) {
-				LOGGER.warn("Recipe registry plugin is slow, took {}. {}", stopWatch, plugin.getClass());
+			stopwatch.stop();
+			if (stopwatch.elapsed(TimeUnit.MILLISECONDS) > 10) {
+				LOGGER.warn("Recipe registry plugin is slow, took {}. {}", TimeUtil.toHumanString(stopwatch.elapsed()), plugin.getClass());
 			}
 			return result;
 		} catch (RuntimeException | LinkageError e) {