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