Spring/spring-framework
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Revise StopWatch for flexible time units in nanosecond precision

Browse Source 
Closes gh-25803
This commit is contained in:
Juergen Hoeller
2023-08-08 01:48:58 +02:00
parent dedb58f7ed
commit 8e16e5ea35
3 changed files with 171 additions and 119 deletions
Download Patch File Download Diff File Expand all files Collapse all files

8
spring-context/src/test/java/org/springframework/aop/aspectj/autoproxy/benchmark/BenchmarkTests.java
View File

@@ -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();
}
}

278
spring-core/src/main/java/org/springframework/util/StopWatch.java
View File

@@ -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.
*
* <p>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.
* <p>The ID is handy when we have output from multiple stop watches and need
* Construct a new {@code StopWatch} with the given id.
* <p>The id is handy when we have output from multiple stop watches and need
* to distinguish between them.
* <p>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.
* <p>Set this to {@code false} when using a {@code StopWatch} for millions
* of intervals; otherwise, the {@code TaskInfo} structure will consume
* excessive memory.
* <p>Set this to {@code false} when using a {@code StopWatch} for millions of
* tasks; otherwise, the {@code TaskInfo} structure will consume excessive memory.
* <p>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.
* <p>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).
* <p>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).
* <p>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
* <p>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);
}
}
}

4
spring-core/src/test/java/org/springframework/util/StopWatchTests.java
View File

@@ -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