001/* 002 * Copyright 2002-2019 the original author or authors. 003 * 004 * Licensed under the Apache License, Version 2.0 (the "License"); 005 * you may not use this file except in compliance with the License. 006 * You may obtain a copy of the License at 007 * 008 * https://www.apache.org/licenses/LICENSE-2.0 009 * 010 * Unless required by applicable law or agreed to in writing, software 011 * distributed under the License is distributed on an "AS IS" BASIS, 012 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 013 * See the License for the specific language governing permissions and 014 * limitations under the License. 015 */ 016 017package org.springframework.util; 018 019import java.text.NumberFormat; 020import java.util.LinkedList; 021import java.util.List; 022import java.util.concurrent.TimeUnit; 023 024import org.springframework.lang.Nullable; 025 026/** 027 * Simple stop watch, allowing for timing of a number of tasks, exposing total 028 * running time and running time for each named task. 029 * 030 * <p>Conceals use of {@link System#nanoTime()}, improving the readability of 031 * application code and reducing the likelihood of calculation errors. 032 * 033 * <p>Note that this object is not designed to be thread-safe and does not use 034 * synchronization. 035 * 036 * <p>This class is normally used to verify performance during proof-of-concept 037 * work and in development, rather than as part of production applications. 038 * 039 * <p>As of Spring Framework 5.2, running time is tracked and reported in 040 * nanoseconds. 041 * 042 * @author Rod Johnson 043 * @author Juergen Hoeller 044 * @author Sam Brannen 045 * @since May 2, 2001 046 */ 047public class StopWatch { 048 049 /** 050 * Identifier of this {@code StopWatch}. 051 * <p>Handy when we have output from multiple stop watches and need to 052 * distinguish between them in log or console output. 053 */ 054 private final String id; 055 056 private boolean keepTaskList = true; 057 058 private final List<TaskInfo> taskList = new LinkedList<>(); 059 060 /** Start time of the current task. */ 061 private long startTimeNanos; 062 063 /** Name of the current task. */ 064 @Nullable 065 private String currentTaskName; 066 067 @Nullable 068 private TaskInfo lastTaskInfo; 069 070 private int taskCount; 071 072 /** Total running time. */ 073 private long totalTimeNanos; 074 075 076 /** 077 * Construct a new {@code StopWatch}. 078 * <p>Does not start any task. 079 */ 080 public StopWatch() { 081 this(""); 082 } 083 084 /** 085 * Construct a new {@code StopWatch} with the given ID. 086 * <p>The ID is handy when we have output from multiple stop watches and need 087 * to distinguish between them. 088 * <p>Does not start any task. 089 * @param id identifier for this stop watch 090 */ 091 public StopWatch(String id) { 092 this.id = id; 093 } 094 095 096 /** 097 * Get the ID of this {@code StopWatch}, as specified on construction. 098 * @return the ID (empty String by default) 099 * @since 4.2.2 100 * @see #StopWatch(String) 101 */ 102 public String getId() { 103 return this.id; 104 } 105 106 /** 107 * Configure whether the {@link TaskInfo} array is built over time. 108 * <p>Set this to {@code false} when using a {@code StopWatch} for millions 109 * of intervals; otherwise, the {@code TaskInfo} structure will consume 110 * excessive memory. 111 * <p>Default is {@code true}. 112 */ 113 public void setKeepTaskList(boolean keepTaskList) { 114 this.keepTaskList = keepTaskList; 115 } 116 117 118 /** 119 * Start an unnamed task. 120 * <p>The results are undefined if {@link #stop()} or timing methods are 121 * called without invoking this method first. 122 * @see #start(String) 123 * @see #stop() 124 */ 125 public void start() throws IllegalStateException { 126 start(""); 127 } 128 129 /** 130 * Start a named task. 131 * <p>The results are undefined if {@link #stop()} or timing methods are 132 * called without invoking this method first. 133 * @param taskName the name of the task to start 134 * @see #start() 135 * @see #stop() 136 */ 137 public void start(String taskName) throws IllegalStateException { 138 if (this.currentTaskName != null) { 139 throw new IllegalStateException("Can't start StopWatch: it's already running"); 140 } 141 this.currentTaskName = taskName; 142 this.startTimeNanos = System.nanoTime(); 143 } 144 145 /** 146 * Stop the current task. 147 * <p>The results are undefined if timing methods are called without invoking 148 * at least one pair of {@code start()} / {@code stop()} methods. 149 * @see #start() 150 * @see #start(String) 151 */ 152 public void stop() throws IllegalStateException { 153 if (this.currentTaskName == null) { 154 throw new IllegalStateException("Can't stop StopWatch: it's not running"); 155 } 156 long lastTime = System.nanoTime() - this.startTimeNanos; 157 this.totalTimeNanos += lastTime; 158 this.lastTaskInfo = new TaskInfo(this.currentTaskName, lastTime); 159 if (this.keepTaskList) { 160 this.taskList.add(this.lastTaskInfo); 161 } 162 ++this.taskCount; 163 this.currentTaskName = null; 164 } 165 166 /** 167 * Determine whether this {@code StopWatch} is currently running. 168 * @see #currentTaskName() 169 */ 170 public boolean isRunning() { 171 return (this.currentTaskName != null); 172 } 173 174 /** 175 * Get the name of the currently running task, if any. 176 * @since 4.2.2 177 * @see #isRunning() 178 */ 179 @Nullable 180 public String currentTaskName() { 181 return this.currentTaskName; 182 } 183 184 /** 185 * Get the time taken by the last task in nanoseconds. 186 * @since 5.2 187 * @see #getLastTaskTimeMillis() 188 */ 189 public long getLastTaskTimeNanos() throws IllegalStateException { 190 if (this.lastTaskInfo == null) { 191 throw new IllegalStateException("No tasks run: can't get last task interval"); 192 } 193 return this.lastTaskInfo.getTimeNanos(); 194 } 195 196 /** 197 * Get the time taken by the last task in milliseconds. 198 * @see #getLastTaskTimeNanos() 199 */ 200 public long getLastTaskTimeMillis() throws IllegalStateException { 201 if (this.lastTaskInfo == null) { 202 throw new IllegalStateException("No tasks run: can't get last task interval"); 203 } 204 return this.lastTaskInfo.getTimeMillis(); 205 } 206 207 /** 208 * Get the name of the last task. 209 */ 210 public String getLastTaskName() throws IllegalStateException { 211 if (this.lastTaskInfo == null) { 212 throw new IllegalStateException("No tasks run: can't get last task name"); 213 } 214 return this.lastTaskInfo.getTaskName(); 215 } 216 217 /** 218 * Get the last task as a {@link TaskInfo} object. 219 */ 220 public TaskInfo getLastTaskInfo() throws IllegalStateException { 221 if (this.lastTaskInfo == null) { 222 throw new IllegalStateException("No tasks run: can't get last task info"); 223 } 224 return this.lastTaskInfo; 225 } 226 227 228 /** 229 * Get the total time in nanoseconds for all tasks. 230 * @since 5.2 231 * @see #getTotalTimeMillis() 232 * @see #getTotalTimeSeconds() 233 */ 234 public long getTotalTimeNanos() { 235 return this.totalTimeNanos; 236 } 237 238 /** 239 * Get the total time in milliseconds for all tasks. 240 * @see #getTotalTimeNanos() 241 * @see #getTotalTimeSeconds() 242 */ 243 public long getTotalTimeMillis() { 244 return nanosToMillis(this.totalTimeNanos); 245 } 246 247 /** 248 * Get the total time in seconds for all tasks. 249 * @see #getTotalTimeNanos() 250 * @see #getTotalTimeMillis() 251 */ 252 public double getTotalTimeSeconds() { 253 return nanosToSeconds(this.totalTimeNanos); 254 } 255 256 /** 257 * Get the number of tasks timed. 258 */ 259 public int getTaskCount() { 260 return this.taskCount; 261 } 262 263 /** 264 * Get an array of the data for tasks performed. 265 */ 266 public TaskInfo[] getTaskInfo() { 267 if (!this.keepTaskList) { 268 throw new UnsupportedOperationException("Task info is not being kept!"); 269 } 270 return this.taskList.toArray(new TaskInfo[0]); 271 } 272 273 274 /** 275 * Get a short description of the total running time. 276 */ 277 public String shortSummary() { 278 return "StopWatch '" + getId() + "': running time = " + getTotalTimeNanos() + " ns"; 279 } 280 281 /** 282 * Generate a string with a table describing all tasks performed. 283 * <p>For custom reporting, call {@link #getTaskInfo()} and use the task info 284 * directly. 285 */ 286 public String prettyPrint() { 287 StringBuilder sb = new StringBuilder(shortSummary()); 288 sb.append('\n'); 289 if (!this.keepTaskList) { 290 sb.append("No task info kept"); 291 } 292 else { 293 sb.append("---------------------------------------------\n"); 294 sb.append("ns % Task name\n"); 295 sb.append("---------------------------------------------\n"); 296 NumberFormat nf = NumberFormat.getNumberInstance(); 297 nf.setMinimumIntegerDigits(9); 298 nf.setGroupingUsed(false); 299 NumberFormat pf = NumberFormat.getPercentInstance(); 300 pf.setMinimumIntegerDigits(3); 301 pf.setGroupingUsed(false); 302 for (TaskInfo task : getTaskInfo()) { 303 sb.append(nf.format(task.getTimeNanos())).append(" "); 304 sb.append(pf.format((double) task.getTimeNanos() / getTotalTimeNanos())).append(" "); 305 sb.append(task.getTaskName()).append("\n"); 306 } 307 } 308 return sb.toString(); 309 } 310 311 /** 312 * Generate an informative string describing all tasks performed 313 * <p>For custom reporting, call {@link #getTaskInfo()} and use the task info 314 * directly. 315 */ 316 @Override 317 public String toString() { 318 StringBuilder sb = new StringBuilder(shortSummary()); 319 if (this.keepTaskList) { 320 for (TaskInfo task : getTaskInfo()) { 321 sb.append("; [").append(task.getTaskName()).append("] took ").append(task.getTimeNanos()).append(" ns"); 322 long percent = Math.round(100.0 * task.getTimeNanos() / getTotalTimeNanos()); 323 sb.append(" = ").append(percent).append("%"); 324 } 325 } 326 else { 327 sb.append("; no task info kept"); 328 } 329 return sb.toString(); 330 } 331 332 333 private static long nanosToMillis(long duration) { 334 return TimeUnit.NANOSECONDS.toMillis(duration); 335 } 336 337 private static double nanosToSeconds(long duration) { 338 return duration / 1_000_000_000.0; 339 } 340 341 342 /** 343 * Nested class to hold data about one task executed within the {@code StopWatch}. 344 */ 345 public static final class TaskInfo { 346 347 private final String taskName; 348 349 private final long timeNanos; 350 351 TaskInfo(String taskName, long timeNanos) { 352 this.taskName = taskName; 353 this.timeNanos = timeNanos; 354 } 355 356 /** 357 * Get the name of this task. 358 */ 359 public String getTaskName() { 360 return this.taskName; 361 } 362 363 /** 364 * Get the time in nanoseconds this task took. 365 * @since 5.2 366 * @see #getTimeMillis() 367 * @see #getTimeSeconds() 368 */ 369 public long getTimeNanos() { 370 return this.timeNanos; 371 } 372 373 /** 374 * Get the time in milliseconds this task took. 375 * @see #getTimeNanos() 376 * @see #getTimeSeconds() 377 */ 378 public long getTimeMillis() { 379 return nanosToMillis(this.timeNanos); 380 } 381 382 /** 383 * Get the time in seconds this task took. 384 * @see #getTimeMillis() 385 * @see #getTimeNanos() 386 */ 387 public double getTimeSeconds() { 388 return nanosToSeconds(this.timeNanos); 389 } 390 391 } 392 393}