diff --git a/platform/vcs-log/impl/src/com/intellij/vcs/log/data/index/VcsLogPersistentIndex.java b/platform/vcs-log/impl/src/com/intellij/vcs/log/data/index/VcsLogPersistentIndex.java index 368c1b0e173f..b54840d1c9fc 100644 --- a/platform/vcs-log/impl/src/com/intellij/vcs/log/data/index/VcsLogPersistentIndex.java +++ b/platform/vcs-log/impl/src/com/intellij/vcs/log/data/index/VcsLogPersistentIndex.java @@ -48,6 +48,7 @@ import com.intellij.vcs.log.impl.FatalErrorConsumer; import com.intellij.vcs.log.impl.VcsLogUtil; import com.intellij.vcs.log.ui.filter.VcsLogUserFilterImpl; import com.intellij.vcs.log.util.PersistentUtil; +import com.intellij.vcs.log.util.StopWatch; import gnu.trove.TIntHashSet; import gnu.trove.TIntProcedure; import org.jetbrains.annotations.NotNull; @@ -412,8 +413,8 @@ public class VcsLogPersistentIndex implements VcsLogIndex, Disposable { } } - LOG.info((System.currentTimeMillis() - time) / 1000.0 + - "sec for indexing " + + LOG.info(StopWatch.formatTime(System.currentTimeMillis() - time) + + " for indexing " + counter.newIndexedCommits + " new commits out of " + counter.allCommits); diff --git a/platform/vcs-log/impl/src/com/intellij/vcs/log/util/StopWatch.java b/platform/vcs-log/impl/src/com/intellij/vcs/log/util/StopWatch.java index 57c6d657005b..468fe9c43147 100644 --- a/platform/vcs-log/impl/src/com/intellij/vcs/log/util/StopWatch.java +++ b/platform/vcs-log/impl/src/com/intellij/vcs/log/util/StopWatch.java @@ -28,6 +28,10 @@ public class StopWatch { private static final Logger LOG = Logger.getInstance(StopWatch.class); + private static final String[] UNIT_NAMES = new String[]{"s", "m", "h"}; + private static final long[] UNITS = new long[]{1, 60, 60 * 60}; + private static final String MSEC_FORMAT = "%03d"; + private final long myStartTime; @NotNull private final String myOperation; @NotNull private final Map myDurationPerRoot; @@ -58,11 +62,42 @@ public class StopWatch { } public void report() { - String message = myOperation + " took " + (System.currentTimeMillis() - myStartTime) + " ms"; + String message = myOperation + " took " + formatTime(System.currentTimeMillis() - myStartTime); if (myDurationPerRoot.size() > 1) { message += "\n" + StringUtil.join(myDurationPerRoot.entrySet(), - entry -> " " + entry.getKey().getName() + ": " + entry.getValue() + " ms", "\n"); + entry -> " " + entry.getKey().getName() + ": " + formatTime(entry.getValue()), "\n"); } LOG.debug(message); } + + /** + * 1h 1m 1.001s + */ + @NotNull + public static String formatTime(long time) { + if (time < 1000 * UNITS[0]) { + return time + "ms"; + } + String result = ""; + long remainder = time / 1000; + long msec = time % 1000; + for (int i = UNITS.length - 1; i >= 0; i--) { + if (remainder < UNITS[i]) continue; + + long quotient = remainder / UNITS[i]; + remainder = remainder % UNITS[i]; + + if (i == 0) { + result += quotient + (msec == 0 ? "" : "." + String.format(MSEC_FORMAT, msec)) + UNIT_NAMES[i]; + } + else { + result += quotient + UNIT_NAMES[i] + " "; + if (remainder == 0 && msec != 0) { + result += "0." + String.format(MSEC_FORMAT, msec) + UNIT_NAMES[0]; + } + } + } + + return result; + } }