
001/* 002 * #%L 003 * HAPI FHIR - Core Library 004 * %% 005 * Copyright (C) 2014 - 2025 Smile CDR, Inc. 006 * %% 007 * Licensed under the Apache License, Version 2.0 (the "License"); 008 * you may not use this file except in compliance with the License. 009 * You may obtain a copy of the License at 010 * 011 * http://www.apache.org/licenses/LICENSE-2.0 012 * 013 * Unless required by applicable law or agreed to in writing, software 014 * distributed under the License is distributed on an "AS IS" BASIS, 015 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 016 * See the License for the specific language governing permissions and 017 * limitations under the License. 018 * #L% 019 */ 020package ca.uhn.fhir.util; 021 022import com.google.common.annotations.VisibleForTesting; 023import org.apache.commons.lang3.Validate; 024import org.apache.commons.lang3.time.DateUtils; 025 026import java.text.DecimalFormat; 027import java.text.NumberFormat; 028import java.util.Date; 029import java.util.LinkedList; 030import java.util.concurrent.TimeUnit; 031 032/** 033 * A multipurpose stopwatch which can be used to time tasks and produce 034 * human readable output about task duration, throughput, estimated task completion, 035 * etc. 036 * <p> 037 * <p> 038 * <b>Thread Safety Note: </b> StopWatch is not intended to be thread safe. 039 * </p> 040 * 041 * @since HAPI FHIR 3.3.0 042 */ 043public class StopWatch { 044 045 // TODO KHS it is risky for this to be a static field. Safer to make it non-static, but that will require 046 // TODO KHS significant rework of StopWatchTest 047 private static Long ourNowForUnitTest; 048 private long myStarted = now(); 049 private TaskTiming myCurrentTask; 050 private LinkedList<TaskTiming> myTasks; 051 052 /** 053 * Constructor 054 */ 055 public StopWatch() { 056 super(); 057 } 058 059 /** 060 * Constructor 061 * 062 * @param theStart The time to record as the start for this timer 063 */ 064 public StopWatch(Date theStart) { 065 myStarted = theStart.getTime(); 066 } 067 068 /** 069 * Constructor 070 * 071 * @param theStart The time that the stopwatch was started 072 */ 073 public StopWatch(long theStart) { 074 myStarted = theStart; 075 } 076 077 private void addNewlineIfContentExists(StringBuilder theB) { 078 if (theB.length() > 0) { 079 theB.append("\n"); 080 } 081 } 082 083 /** 084 * Finish the counter on the current task (which was started by calling 085 * {@link #startTask(String)}. This method has no effect if no task 086 * is currently started so it's ok to call it more than once. 087 */ 088 public void endCurrentTask() { 089 ensureTasksListExists(); 090 if (myCurrentTask != null) { 091 myCurrentTask.setEnd(now()); 092 } 093 myCurrentTask = null; 094 } 095 096 private void ensureTasksListExists() { 097 if (myTasks == null) { 098 myTasks = new LinkedList<>(); 099 } 100 } 101 102 /** 103 * Returns a nice human-readable display of the time taken per 104 * operation. Note that this may not actually output the number 105 * of milliseconds if the time taken per operation was very long (over 106 * 10 seconds) 107 * 108 * @see #formatMillis(long) 109 */ 110 public String formatMillisPerOperation(long theNumOperations) { 111 double millisPerOperation = (((double) getMillis()) / Math.max(1.0, theNumOperations)); 112 return formatMillis(millisPerOperation); 113 } 114 115 /** 116 * Returns a string providing the durations of all tasks collected by {@link #startTask(String)} 117 */ 118 public String formatTaskDurations() { 119 120 ensureTasksListExists(); 121 StringBuilder b = new StringBuilder(); 122 123 if (myTasks.size() > 0) { 124 long delta = myTasks.getFirst().getStart() - myStarted; 125 if (delta > 10) { 126 addNewlineIfContentExists(b); 127 b.append("Before first task"); 128 b.append(": "); 129 b.append(formatMillis(delta)); 130 } 131 } else { 132 b.append("No tasks"); 133 } 134 135 TaskTiming last = null; 136 for (TaskTiming nextTask : myTasks) { 137 138 if (last != null) { 139 long delta = nextTask.getStart() - last.getEnd(); 140 if (delta > 10) { 141 addNewlineIfContentExists(b); 142 b.append("Between"); 143 b.append(": "); 144 b.append(formatMillis(delta)); 145 } 146 } 147 148 addNewlineIfContentExists(b); 149 b.append(nextTask.getTaskName()); 150 b.append(": "); 151 long delta = nextTask.getMillis(); 152 b.append(formatMillis(delta)); 153 154 last = nextTask; 155 } 156 157 if (myTasks.size() > 0) { 158 long delta = now() - myTasks.getLast().getEnd(); 159 if (delta > 10) { 160 addNewlineIfContentExists(b); 161 b.append("After last task"); 162 b.append(": "); 163 b.append(formatMillis(delta)); 164 } 165 } 166 167 return b.toString(); 168 } 169 170 /** 171 * Determine the current throughput per unit of time (specified in theUnit) 172 * assuming that theNumOperations operations have happened. 173 * <p> 174 * For example, if this stopwatch has 2 seconds elapsed, and this method is 175 * called for theNumOperations=30 and TimeUnit=SECONDS, 176 * this method will return 15 177 * </p> 178 * 179 * @see #getThroughput(long, TimeUnit) 180 */ 181 public String formatThroughput(long theNumOperations, TimeUnit theUnit) { 182 double throughput = getThroughput(theNumOperations, theUnit); 183 return formatThroughput(throughput); 184 } 185 186 /** 187 * Given an amount of something completed so far, and a total amount, calculates how long it will take for something to complete 188 * 189 * @param theCompleteToDate The amount so far 190 * @param theTotal The total (must be higher than theCompleteToDate 191 * @return A formatted amount of time 192 */ 193 public String getEstimatedTimeRemaining(double theCompleteToDate, double theTotal) { 194 double millis = getMillis(); 195 return formatEstimatedTimeRemaining(theCompleteToDate, theTotal, millis); 196 } 197 198 /** 199 * Given an amount of something completed so far, and a total amount, calculates how long it will take for something to complete 200 * 201 * @param theCompleteToDate The amount so far 202 * @param theTotal The total (must be higher than theCompleteToDate 203 * @return A formatted amount of time 204 */ 205 public static String formatEstimatedTimeRemaining(double theCompleteToDate, double theTotal, double millis) { 206 long millisRemaining = (long) (((theTotal / theCompleteToDate) * millis) - millis); 207 return formatMillis(millisRemaining); 208 } 209 210 public long getMillis(Date theNow) { 211 return theNow.getTime() - myStarted; 212 } 213 214 public long getMillis() { 215 long now = now(); 216 return now - myStarted; 217 } 218 219 public long getMillisAndRestart() { 220 long now = now(); 221 long retVal = now - myStarted; 222 myStarted = now; 223 return retVal; 224 } 225 226 /** 227 * @param theNumOperations Ok for this to be 0, it will be treated as 1 228 */ 229 public long getMillisPerOperation(long theNumOperations) { 230 return (long) (((double) getMillis()) / Math.max(1.0, theNumOperations)); 231 } 232 233 public Date getStartedDate() { 234 return new Date(myStarted); 235 } 236 237 /** 238 * Determine the current throughput per unit of time (specified in theUnit) 239 * assuming that theNumOperations operations have happened. 240 * <p> 241 * For example, if this stopwatch has 2 seconds elapsed, and this method is 242 * called for theNumOperations=30 and TimeUnit=SECONDS, 243 * this method will return 15 244 * </p> 245 * 246 * @see #formatThroughput(long, TimeUnit) 247 */ 248 public double getThroughput(long theNumOperations, TimeUnit theUnit) { 249 long millis = getMillis(); 250 return getThroughput(theNumOperations, millis, theUnit); 251 } 252 253 public void restart() { 254 myStarted = now(); 255 } 256 257 /** 258 * Starts a counter for a sub-task 259 * <p> 260 * <b>Thread Safety Note: </b> This method is not threadsafe! Do not use subtasks in a 261 * multithreaded environment. 262 * </p> 263 * 264 * @param theTaskName Note that if theTaskName is blank or empty, no task is started 265 */ 266 public void startTask(String theTaskName) { 267 endCurrentTask(); 268 Validate.notBlank(theTaskName, "Task name must not be blank"); 269 myCurrentTask = new TaskTiming().setTaskName(theTaskName).setStart(now()); 270 myTasks.add(myCurrentTask); 271 } 272 273 /** 274 * Formats value in an appropriate format. See {@link #formatMillis(long)}} 275 * for a description of the format 276 * 277 * @see #formatMillis(long) 278 */ 279 @Override 280 public String toString() { 281 return formatMillis(getMillis()); 282 } 283 284 /** 285 * Format a throughput number (output does not include units) into 286 * a number suitable for logging. 287 * <p> 288 * This method tries to use a suitable amount of precision for logging. 289 * For numbers above 1000 it includes no decimal. 290 * For numbers between 100 and 1000 it includes one decimal. 291 * For numbers below 100 it includes two decimals. 292 * </p> 293 */ 294 public static String formatThroughput(double throughput) { 295 return formatDouble(throughput); 296 } 297 298 /** 299 * This method tries to use a suitable amount of precision for logging. 300 * For numbers above 1000 it includes no decimal. 301 * For numbers between 100 and 1000 it includes one decimal. 302 * For numbers below 100 it includes two decimals. 303 */ 304 static String formatDouble(double theDouble) { 305 double abs = Math.abs(theDouble); 306 if (abs > 1000) { 307 return Long.toString(Math.round(theDouble)); 308 } 309 if (abs > 100) { 310 return Double.toString(Math.round(theDouble * 10.0) / 10.0); 311 } 312 return Double.toString(Math.round(theDouble * 100.0) / 100.0); 313 } 314 315 /** 316 * Calculate throughput 317 * 318 * @param theNumOperations The number of operations completed 319 * @param theMillisElapsed The time elapsed 320 * @param theUnit The unit for the throughput 321 */ 322 public static double getThroughput(long theNumOperations, long theMillisElapsed, TimeUnit theUnit) { 323 if (theNumOperations <= 0) { 324 return 0.0f; 325 } 326 long millisElapsed = Math.max(1, theMillisElapsed); 327 long periodMillis = theUnit.toMillis(1); 328 329 double denominator = ((double) millisElapsed) / ((double) periodMillis); 330 331 double throughput = (double) theNumOperations / denominator; 332 if (throughput > theNumOperations) { 333 throughput = theNumOperations; 334 } 335 336 return throughput; 337 } 338 339 private static NumberFormat getDayFormat() { 340 return new DecimalFormat("0.0"); 341 } 342 343 private static NumberFormat getTenDayFormat() { 344 return new DecimalFormat("0"); 345 } 346 347 private static NumberFormat getSubMillisecondMillisFormat() { 348 return new DecimalFormat("0.000"); 349 } 350 351 /** 352 * Append a right-aligned and zero-padded numeric value to a `StringBuilder`. 353 */ 354 static void appendRightAlignedNumber( 355 StringBuilder theStringBuilder, String thePrefix, int theNumberOfDigits, long theValueToAppend) { 356 theStringBuilder.append(thePrefix); 357 if (theNumberOfDigits > 1) { 358 int pad = (theNumberOfDigits - 1); 359 for (long xa = theValueToAppend; xa > 9 && pad > 0; xa /= 10) { 360 pad--; 361 } 362 for (int xa = 0; xa < pad; xa++) { 363 theStringBuilder.append('0'); 364 } 365 } 366 theStringBuilder.append(theValueToAppend); 367 } 368 369 /** 370 * Formats a number of milliseconds for display (e.g. 371 * in a log file), tailoring the output to how big 372 * the value actually is. 373 * <p> 374 * Example outputs: 375 * </p> 376 * <ul> 377 * <li>133ms</li> 378 * <li>00:00:10.223</li> 379 * <li>1.7 days</li> 380 * <li>64 days</li> 381 * </ul> 382 */ 383 public static String formatMillis(long theMillis) { 384 return formatMillis((double) theMillis); 385 } 386 387 /** 388 * Formats a number of milliseconds for display (e.g. 389 * in a log file), tailoring the output to how big 390 * the value actually is. 391 * <p> 392 * Example outputs: 393 * </p> 394 * <ul> 395 * <li>133ms</li> 396 * <li>00:00:10.223</li> 397 * <li>1.7 days</li> 398 * <li>64 days</li> 399 * </ul> 400 */ 401 public static String formatMillis(double theMillis) { 402 StringBuilder buf = new StringBuilder(20); 403 if (theMillis > 0.0 && theMillis < 1.0) { 404 buf.append(getSubMillisecondMillisFormat().format(theMillis)); 405 buf.append("ms"); 406 } else if (theMillis < (10 * DateUtils.MILLIS_PER_SECOND)) { 407 buf.append((int) theMillis); 408 buf.append("ms"); 409 } else if (theMillis >= DateUtils.MILLIS_PER_DAY) { 410 double days = theMillis / DateUtils.MILLIS_PER_DAY; 411 if (days >= 10) { 412 buf.append(getTenDayFormat().format(days)); 413 buf.append(" days"); 414 } else if (days != 1.0f) { 415 buf.append(getDayFormat().format(days)); 416 buf.append(" days"); 417 } else { 418 buf.append(getDayFormat().format(days)); 419 buf.append(" day"); 420 } 421 } else { 422 long millisAsLong = (long) theMillis; 423 appendRightAlignedNumber( 424 buf, "", 2, ((millisAsLong % DateUtils.MILLIS_PER_DAY) / DateUtils.MILLIS_PER_HOUR)); 425 appendRightAlignedNumber( 426 buf, ":", 2, ((millisAsLong % DateUtils.MILLIS_PER_HOUR) / DateUtils.MILLIS_PER_MINUTE)); 427 appendRightAlignedNumber( 428 buf, ":", 2, ((millisAsLong % DateUtils.MILLIS_PER_MINUTE) / DateUtils.MILLIS_PER_SECOND)); 429 if (theMillis <= DateUtils.MILLIS_PER_MINUTE) { 430 appendRightAlignedNumber(buf, ".", 3, (millisAsLong % DateUtils.MILLIS_PER_SECOND)); 431 } 432 } 433 return buf.toString(); 434 } 435 436 private static long now() { 437 if (ourNowForUnitTest != null) { 438 return ourNowForUnitTest; 439 } 440 return System.currentTimeMillis(); 441 } 442 443 @VisibleForTesting 444 public static void setNowForUnitTest(Long theNowForUnitTest) { 445 ourNowForUnitTest = theNowForUnitTest; 446 } 447 448 private static class TaskTiming { 449 private long myStart; 450 private long myEnd; 451 private String myTaskName; 452 453 public long getEnd() { 454 if (myEnd == 0) { 455 return now(); 456 } 457 return myEnd; 458 } 459 460 public TaskTiming setEnd(long theEnd) { 461 myEnd = theEnd; 462 return this; 463 } 464 465 public long getMillis() { 466 return getEnd() - getStart(); 467 } 468 469 public long getStart() { 470 return myStart; 471 } 472 473 public TaskTiming setStart(long theStart) { 474 myStart = theStart; 475 return this; 476 } 477 478 public String getTaskName() { 479 return myTaskName; 480 } 481 482 public TaskTiming setTaskName(String theTaskName) { 483 myTaskName = theTaskName; 484 return this; 485 } 486 } 487}