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