From 8e16e5ea35a898004eaff998e2890470ba3765af Mon Sep 17 00:00:00 2001 From: Juergen Hoeller Date: Tue, 8 Aug 2023 01:48:58 +0200 Subject: [PATCH] Revise StopWatch for flexible time units in nanosecond precision Closes gh-25803 --- .../autoproxy/benchmark/BenchmarkTests.java | 8 +- .../org/springframework/util/StopWatch.java | 278 +++++++++++------- .../springframework/util/StopWatchTests.java | 4 +- 3 files changed, 171 insertions(+), 119 deletions(-) diff --git a/spring-context/src/test/java/org/springframework/aop/aspectj/autoproxy/benchmark/BenchmarkTests.java b/spring-context/src/test/java/org/springframework/aop/aspectj/autoproxy/benchmark/BenchmarkTests.java index df5d587e6a..563d2cd146 100644 --- a/spring-context/src/test/java/org/springframework/aop/aspectj/autoproxy/benchmark/BenchmarkTests.java +++ b/spring-context/src/test/java/org/springframework/aop/aspectj/autoproxy/benchmark/BenchmarkTests.java @@ -117,7 +117,7 @@ class BenchmarkTests { sw.stop(); // System.out.println(sw.prettyPrint()); ac.close(); - return sw.getLastTaskTimeMillis(); + return sw.getTotalTimeMillis(); } private long testBeforeAdviceWithoutJoinPoint(String file, int howmany, String technology) { @@ -139,7 +139,7 @@ class BenchmarkTests { sw.stop(); // System.out.println(sw.prettyPrint()); ac.close(); - return sw.getLastTaskTimeMillis(); + return sw.getTotalTimeMillis(); } private long testAfterReturningAdviceWithoutJoinPoint(String file, int howmany, String technology) { @@ -162,7 +162,7 @@ class BenchmarkTests { sw.stop(); // System.out.println(sw.prettyPrint()); ac.close(); - return sw.getLastTaskTimeMillis(); + return sw.getTotalTimeMillis(); } private long testMix(String file, int howmany, String technology) { @@ -191,7 +191,7 @@ class BenchmarkTests { sw.stop(); // System.out.println(sw.prettyPrint()); ac.close(); - return sw.getLastTaskTimeMillis(); + return sw.getTotalTimeMillis(); } } diff --git a/spring-core/src/main/java/org/springframework/util/StopWatch.java b/spring-core/src/main/java/org/springframework/util/StopWatch.java index 505c27dbd1..1735e6acd1 100644 --- a/spring-core/src/main/java/org/springframework/util/StopWatch.java +++ b/spring-core/src/main/java/org/springframework/util/StopWatch.java @@ -1,5 +1,5 @@ /* - * Copyright 2002-2021 the original author or authors. + * Copyright 2002-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. @@ -19,6 +19,7 @@ package org.springframework.util; import java.text.NumberFormat; import java.util.ArrayList; import java.util.List; +import java.util.Locale; import java.util.concurrent.TimeUnit; import org.springframework.lang.Nullable; @@ -37,12 +38,18 @@ import org.springframework.lang.Nullable; * work and in development, rather than as part of production applications. * *

As of Spring Framework 5.2, running time is tracked and reported in - * nanoseconds. + * nanoseconds. As of 6.1, the default time unit for String renderings is + * seconds with decimal points in nanosecond precision. Custom renderings with + * specific time units can be requested through {@link #prettyPrint(TimeUnit)}. * * @author Rod Johnson * @author Juergen Hoeller * @author Sam Brannen * @since May 2, 2001 + * @see #start() + * @see #stop() + * @see #shortSummary() + * @see #prettyPrint() */ public class StopWatch { @@ -82,8 +89,8 @@ public class StopWatch { } /** - * Construct a new {@code StopWatch} with the given ID. - *

The ID is handy when we have output from multiple stop watches and need + * Construct a new {@code StopWatch} with the given id. + *

The id is handy when we have output from multiple stop watches and need * to distinguish between them. *

Does not start any task. * @param id identifier for this stop watch @@ -94,8 +101,8 @@ public class StopWatch { /** - * Get the ID of this {@code StopWatch}, as specified on construction. - * @return the ID (empty String by default) + * Get the id of this {@code StopWatch}, as specified on construction. + * @return the id (empty String by default) * @since 4.2.2 * @see #StopWatch(String) */ @@ -105,9 +112,8 @@ public class StopWatch { /** * Configure whether the {@link TaskInfo} array is built over time. - *

Set this to {@code false} when using a {@code StopWatch} for millions - * of intervals; otherwise, the {@code TaskInfo} structure will consume - * excessive memory. + *

Set this to {@code false} when using a {@code StopWatch} for millions of + * tasks; otherwise, the {@code TaskInfo} structure will consume excessive memory. *

Default is {@code true}. */ public void setKeepTaskList(boolean keepTaskList) { @@ -181,85 +187,45 @@ public class StopWatch { return this.currentTaskName; } + /** + * Get the name of the last task. + * @see TaskInfo#getTaskName() + * @deprecated as of 6.1, in favor of {@link #getLastTaskInfo()} + */ + @Deprecated(since = "6.1") + public String getLastTaskName() throws IllegalStateException { + return getLastTaskInfo().getTaskName(); + } + /** * Get the time taken by the last task in nanoseconds. * @since 5.2 - * @see #getLastTaskTimeMillis() + * @see TaskInfo#getTimeNanos() + * @deprecated as of 6.1, in favor of {@link #getLastTaskInfo()} */ + @Deprecated(since = "6.1") public long getLastTaskTimeNanos() throws IllegalStateException { - if (this.lastTaskInfo == null) { - throw new IllegalStateException("No tasks run: can't get last task interval"); - } - return this.lastTaskInfo.getTimeNanos(); + return getLastTaskInfo().getTimeNanos(); } /** * Get the time taken by the last task in milliseconds. - * @see #getLastTaskTimeNanos() + * @see TaskInfo#getTimeMillis() + * @deprecated as of 6.1, in favor of {@link #getLastTaskInfo()} */ + @Deprecated(since = "6.1") public long getLastTaskTimeMillis() throws IllegalStateException { - if (this.lastTaskInfo == null) { - throw new IllegalStateException("No tasks run: can't get last task interval"); - } - return this.lastTaskInfo.getTimeMillis(); - } - - /** - * Get the name of the last task. - */ - public String getLastTaskName() throws IllegalStateException { - if (this.lastTaskInfo == null) { - throw new IllegalStateException("No tasks run: can't get last task name"); - } - return this.lastTaskInfo.getTaskName(); + return getLastTaskInfo().getTimeMillis(); } /** * Get the last task as a {@link TaskInfo} object. */ public TaskInfo getLastTaskInfo() throws IllegalStateException { - if (this.lastTaskInfo == null) { - throw new IllegalStateException("No tasks run: can't get last task info"); - } + Assert.state(this.lastTaskInfo != null, "No tasks run"); return this.lastTaskInfo; } - - /** - * Get the total time in nanoseconds for all tasks. - * @since 5.2 - * @see #getTotalTimeMillis() - * @see #getTotalTimeSeconds() - */ - public long getTotalTimeNanos() { - return this.totalTimeNanos; - } - - /** - * Get the total time in milliseconds for all tasks. - * @see #getTotalTimeNanos() - * @see #getTotalTimeSeconds() - */ - public long getTotalTimeMillis() { - return nanosToMillis(this.totalTimeNanos); - } - - /** - * Get the total time in seconds for all tasks. - * @see #getTotalTimeNanos() - * @see #getTotalTimeMillis() - */ - public double getTotalTimeSeconds() { - return nanosToSeconds(this.totalTimeNanos); - } - - /** - * Get the number of tasks timed. - */ - public int getTaskCount() { - return this.taskCount; - } - /** * Get an array of the data for tasks performed. */ @@ -270,56 +236,142 @@ public class StopWatch { return this.taskList.toArray(new TaskInfo[0]); } - /** - * Get a short description of the total running time. + * Get the number of tasks timed. */ - public String shortSummary() { - return "StopWatch '" + getId() + "': running time = " + getTotalTimeNanos() + " ns"; + public int getTaskCount() { + return this.taskCount; } /** - * Generate a string with a table describing all tasks performed. - *

For custom reporting, call {@link #getTaskInfo()} and use the task info - * directly. + * Get the total time for all tasks in nanoseconds. + * @since 5.2 + * @see #getTotalTime(TimeUnit) + */ + public long getTotalTimeNanos() { + return this.totalTimeNanos; + } + + /** + * Get the total time for all tasks in milliseconds. + * @see #getTotalTime(TimeUnit) + */ + public long getTotalTimeMillis() { + return TimeUnit.NANOSECONDS.toMillis(this.totalTimeNanos); + } + + /** + * Get the total time for all tasks in seconds. + * @see #getTotalTime(TimeUnit) + */ + public double getTotalTimeSeconds() { + return getTotalTime(TimeUnit.SECONDS); + } + + /** + * Get the total time for all tasks in the requested time unit + * (with decimal points in nanosecond precision). + * @param timeUnit the unit to use + * @since 6.1 + * @see #getTotalTimeNanos() + * @see #getTotalTimeMillis() + * @see #getTotalTimeSeconds() + */ + public double getTotalTime(TimeUnit timeUnit) { + return (double) this.totalTimeNanos / TimeUnit.NANOSECONDS.convert(1, timeUnit); + } + + + /** + * Generate a table describing all tasks performed in seconds + * (with decimal points in nanosecond precision). + *

For custom reporting, call {@link #getTaskInfo()} and use the data directly. + * @see #prettyPrint(TimeUnit) + * @see #getTotalTimeSeconds() + * @see TaskInfo#getTimeSeconds() */ public String prettyPrint() { - StringBuilder sb = new StringBuilder(shortSummary()); - sb.append('\n'); + return prettyPrint(TimeUnit.SECONDS); + } + + /** + * Generate a table describing all tasks performed in the requested time unit + * (with decimal points in nanosecond precision). + *

For custom reporting, call {@link #getTaskInfo()} and use the data directly. + * @param timeUnit the unit to use for rendering total time and task time + * @since 6.1 + * @see #prettyPrint() + * @see #getTotalTime(TimeUnit) + * @see TaskInfo#getTime(TimeUnit) + */ + public String prettyPrint(TimeUnit timeUnit) { + NumberFormat nf = NumberFormat.getNumberInstance(Locale.ENGLISH); + nf.setMaximumFractionDigits(9); + nf.setGroupingUsed(false); + + NumberFormat pf = NumberFormat.getPercentInstance(Locale.ENGLISH); + pf.setMinimumIntegerDigits(2); + pf.setGroupingUsed(false); + + StringBuilder sb = new StringBuilder(128); + sb.append("StopWatch '").append(getId()).append("': "); + String total = (timeUnit == TimeUnit.NANOSECONDS ? + nf.format(getTotalTimeNanos()) : nf.format(getTotalTime(timeUnit))); + sb.append(total).append(" ").append(timeUnit.name().toLowerCase(Locale.ENGLISH)); + int width = Math.max(sb.length(), 40); + sb.append("\n"); + if (!this.keepTaskList) { sb.append("No task info kept"); } else { - sb.append("---------------------------------------------\n"); - sb.append("ns % Task name\n"); - sb.append("---------------------------------------------\n"); - NumberFormat nf = NumberFormat.getNumberInstance(); - nf.setMinimumIntegerDigits(9); - nf.setGroupingUsed(false); - NumberFormat pf = NumberFormat.getPercentInstance(); - pf.setMinimumIntegerDigits(3); - pf.setGroupingUsed(false); + String line = "-".repeat(width) + "\n"; + String unitName = timeUnit.name(); + unitName = unitName.charAt(0) + unitName.substring(1).toLowerCase(Locale.ENGLISH); + unitName = String.format("%-12s", unitName); + sb.append(line); + sb.append(unitName).append(" % Task name\n"); + sb.append(line); + int digits = total.indexOf('.'); + if (digits < 0) { + digits = total.length(); + } + nf.setMinimumIntegerDigits(digits); + nf.setMaximumFractionDigits(10 - digits); + for (TaskInfo task : getTaskInfo()) { - sb.append(nf.format(task.getTimeNanos())).append(" "); - sb.append(pf.format((double) task.getTimeNanos() / getTotalTimeNanos())).append(" "); + sb.append(String.format("%-14s", (timeUnit == TimeUnit.NANOSECONDS ? + nf.format(task.getTimeNanos()) : nf.format(task.getTime(timeUnit))))); + sb.append(String.format("%-8s", + pf.format(task.getTimeSeconds() / getTotalTimeSeconds()))); sb.append(task.getTaskName()).append('\n'); } } + return sb.toString(); } /** - * Generate an informative string describing all tasks performed - *

For custom reporting, call {@link #getTaskInfo()} and use the task info - * directly. + * Get a short description of the total running time in seconds. + * @see #prettyPrint() + * @see #prettyPrint(TimeUnit) + */ + public String shortSummary() { + return "StopWatch '" + getId() + "': " + getTotalTimeSeconds() + " seconds"; + } + + /** + * Generate an informative string describing all tasks performed in seconds. + * @see #prettyPrint() + * @see #prettyPrint(TimeUnit) */ @Override public String toString() { StringBuilder sb = new StringBuilder(shortSummary()); if (this.keepTaskList) { for (TaskInfo task : getTaskInfo()) { - sb.append("; [").append(task.getTaskName()).append("] took ").append(task.getTimeNanos()).append(" ns"); - long percent = Math.round(100.0 * task.getTimeNanos() / getTotalTimeNanos()); + sb.append("; [").append(task.getTaskName()).append("] took ").append(task.getTimeSeconds()).append(" seconds"); + long percent = Math.round(100.0 * task.getTimeSeconds() / getTotalTimeSeconds()); sb.append(" = ").append(percent).append('%'); } } @@ -330,15 +382,6 @@ public class StopWatch { } - private static long nanosToMillis(long duration) { - return TimeUnit.NANOSECONDS.toMillis(duration); - } - - private static double nanosToSeconds(long duration) { - return duration / 1_000_000_000.0; - } - - /** * Nested class to hold data about one task executed within the {@code StopWatch}. */ @@ -361,33 +404,42 @@ public class StopWatch { } /** - * Get the time in nanoseconds this task took. + * Get the time this task took in nanoseconds. * @since 5.2 - * @see #getTimeMillis() - * @see #getTimeSeconds() + * @see #getTime(TimeUnit) */ public long getTimeNanos() { return this.timeNanos; } /** - * Get the time in milliseconds this task took. - * @see #getTimeNanos() - * @see #getTimeSeconds() + * Get the time this task took in milliseconds. + * @see #getTime(TimeUnit) */ public long getTimeMillis() { - return nanosToMillis(this.timeNanos); + return TimeUnit.NANOSECONDS.toMillis(this.timeNanos); } /** - * Get the time in seconds this task took. - * @see #getTimeMillis() - * @see #getTimeNanos() + * Get the time this task took in seconds. + * @see #getTime(TimeUnit) */ public double getTimeSeconds() { - return nanosToSeconds(this.timeNanos); + return getTime(TimeUnit.SECONDS); } + /** + * Get the time this task took in the requested time unit + * (with decimal points in nanosecond precision). + * @param timeUnit the unit to use + * @since 6.1 + * @see #getTimeNanos() + * @see #getTimeMillis() + * @see #getTimeSeconds() + */ + public double getTime(TimeUnit timeUnit) { + return (double) this.timeNanos / TimeUnit.NANOSECONDS.convert(1, timeUnit); + } } } diff --git a/spring-core/src/test/java/org/springframework/util/StopWatchTests.java b/spring-core/src/test/java/org/springframework/util/StopWatchTests.java index 396a06263b..7239a9b8e6 100644 --- a/spring-core/src/test/java/org/springframework/util/StopWatchTests.java +++ b/spring-core/src/test/java/org/springframework/util/StopWatchTests.java @@ -1,5 +1,5 @@ /* - * Copyright 2002-2021 the original author or authors. + * Copyright 2002-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. @@ -47,7 +47,7 @@ class StopWatchTests { @Test void failureToStartBeforeGettingTimings() { - assertThatIllegalStateException().isThrownBy(stopWatch::getLastTaskTimeMillis); + assertThatIllegalStateException().isThrownBy(stopWatch::getLastTaskInfo); } @Test