[log] Added time measurements to the VCS log

platform/vcs-log/impl/src/com/intellij/vcs/log/data/VcsLogDataHolder.java

@@ -35,6 +35,7 @@ import com.intellij.util.containers.HashSet;
 import com.intellij.util.messages.Topic;
 import com.intellij.util.ui.UIUtil;
 import com.intellij.vcs.log.*;
+import com.intellij.vcs.log.util.StopWatch;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
 
@@ -210,6 +211,7 @@ public class VcsLogDataHolder implements Disposable {
   }
 
   public void initialize(@NotNull final Consumer<VcsLogDataHolder> onInitialized) {
+    final StopWatch initSw = StopWatch.start("initialize");
     // complete refresh => other scheduled refreshes are not interesting
     // TODO: interrupt the current task as well instead of waiting for it to finish, since the result is invalid anyway
     myDataLoaderQueue.clear();
@@ -229,11 +231,13 @@ public class VcsLogDataHolder implements Disposable {
             loadAllLog(); // after first part is loaded and shown to the user, start loading the whole log in background
           }
         });
+        initSw.report();
       }
     }, "Loading recent history...");
   }
 
   private void readCurrentUser() {
+    StopWatch sw = StopWatch.start("readCurrentUser");
     for (Map.Entry<VirtualFile, VcsLogProvider> entry : myLogProviders.entrySet()) {
       VirtualFile root = entry.getKey();
       try {
@@ -249,6 +253,7 @@ public class VcsLogDataHolder implements Disposable {
         LOG.warn("Couldn't read the username from root " + root, e);
       }
     }
+    sw.report();
   }
 
   private void resetState() {
@@ -271,6 +276,7 @@ public class VcsLogDataHolder implements Disposable {
     runInBackground(new ThrowableConsumer<ProgressIndicator, VcsException>() {
       @Override
       public void consume(ProgressIndicator indicator) throws VcsException {
+        StopWatch methodLog = StopWatch.start("loadAllLog");
         try {
           Consumer<VcsUser> userRegistry = new Consumer<VcsUser>() {
             @Override
@@ -283,13 +289,17 @@ public class VcsLogDataHolder implements Disposable {
           for (Map.Entry<VirtualFile, VcsLogProvider> entry : myLogProviders.entrySet()) {
             VirtualFile root = entry.getKey();
             VcsLogProvider logProvider = entry.getValue();
-            logs.put(root, compactHashes(logProvider.readAllHashes(root, userRegistry)));
+            StopWatch sw = StopWatch.start("readAllHashes for " + root.getName());
+            List<TimedVcsCommit> allCommits = logProvider.readAllHashes(root, userRegistry);
+            sw.report();
+            logs.put(root, compactHashes(allCommits));
             refs.put(root, logProvider.readAllRefs(root));
           }
           DataPack existingDataPack = myLogData.getDataPack();
           // keep existing data pack: we don't want to rebuild the graph,
           // we just make the whole log structure available for our cunning refresh procedure of if user requests the whole graph
           myLogData = new LogData(logs, refs, myLogData.getTopCommits(), existingDataPack, true);
+          methodLog.report();
         }
         finally {
           myEntireLogLoadWaiter.countDown();
@@ -372,6 +382,7 @@ public class VcsLogDataHolder implements Disposable {
     if (myLogData == null || !myLogData.isFullLogReady()) {
       LOG.error("The full log is not ready!");
     }
+    StopWatch methodLog = StopWatch.start("smartRefresh");
 
     Map<VirtualFile, List<? extends TimedVcsCommit>> logsToBuild = ContainerUtil.newHashMap();
     Map<VirtualFile, Collection<VcsRef>> refsByRoot = ContainerUtil.newHashMap();
@@ -407,6 +418,7 @@ public class VcsLogDataHolder implements Disposable {
     myLogData = new LogData(logsToBuild, refsByRoot, topPartOfTheLog, dataPack, true);
 
     handleOnSuccessInEdt(onSuccess, dataPack);
+    methodLog.report();
   }
 
   /**
@@ -420,6 +432,7 @@ public class VcsLogDataHolder implements Disposable {
    * doesn't change the saved log skeleton.
    */
   private void loadFromVcs(int commitCount, ProgressIndicator indicator, final Consumer<DataPack> onSuccess) throws VcsException {
+    StopWatch methodSW = StopWatch.start("loadFromVcs");
     Map<VirtualFile, List<? extends TimedVcsCommit>> logsToBuild = ContainerUtil.newHashMap();
     Map<VirtualFile, Collection<VcsRef>> refsByRoot = ContainerUtil.newHashMap();
 
@@ -432,13 +445,17 @@ public class VcsLogDataHolder implements Disposable {
       refsByRoot.put(root, info.newRefs);
     }
 
+    StopWatch sw = StopWatch.start("multi-repo join");
     List<? extends TimedVcsCommit> compoundLog = myMultiRepoJoiner.join(logsToBuild.values());
+    sw.report();
 
     // even if the full log was already loaded (and possibly presented to the user),
     // build only the data that was retrieved from the VCS:
     // if it is not one of the initial refreshes, then it is filtering, and then the DataPack will change anyway.
+    sw = StopWatch.start("DataPack.build");
     DataPack dataPack = DataPack.build(convertToGraphCommits(compoundLog), collectAllRefs(refsByRoot), indicator,
                                        myHashGetter, myIndexGetter);
+    sw.report();
 
     if (myLogData != null && myLogData.isFullLogReady()) {
       // reuse the skeleton, since it didn't change, because it is not a refresh
@@ -451,22 +468,29 @@ public class VcsLogDataHolder implements Disposable {
 
     myContainingBranchesGetter.clearCache();
     handleOnSuccessInEdt(onSuccess, dataPack);
+    methodSW.report();
   }
 
   private Set<Map.Entry<VirtualFile, RecentCommitsInfo>> collectInfoFromVcs(boolean ordered, int commitsCount) throws VcsException {
+    StopWatch methodTime = StopWatch.start("collectInfoFromVcs");
     Map<VirtualFile, RecentCommitsInfo> infoByRoot = ContainerUtil.newHashMap();
     for (Map.Entry<VirtualFile, VcsLogProvider> entry : myLogProviders.entrySet()) {
       VirtualFile root = entry.getKey();
       VcsLogProvider logProvider = entry.getValue();
 
+      StopWatch sw = StopWatch.start("readFirstBlock for " + root.getName());
       List<? extends VcsFullCommitDetails> firstBlockDetails = logProvider.readFirstBlock(root, ordered, commitsCount);
+      sw.report();
+      sw = StopWatch.start("readAllRefs for" + root.getName());
       Collection<VcsRef> newRefs = logProvider.readAllRefs(root);
+      sw.report();
       storeTopCommitsDetailsInCache(firstBlockDetails);
       storeUsers(firstBlockDetails);
       List<TimedVcsCommit> firstBlockCommits = getCommitsFromDetails(firstBlockDetails);
 
       infoByRoot.put(root, new RecentCommitsInfo(firstBlockCommits, newRefs));
     }
+    methodTime.report();
     return infoByRoot.entrySet();
   }
 

platform/vcs-log/impl/src/com/intellij/vcs/log/util/StopWatch.java

@@ -0,0 +1,41 @@
+/*
+ * Copyright 2000-2014 JetBrains s.r.o.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package com.intellij.vcs.log.util;
+
+import com.intellij.openapi.diagnostic.Logger;
+import org.jetbrains.annotations.NotNull;
+
+public class StopWatch {
+
+  private static final Logger LOG = Logger.getInstance(StopWatch.class);
+
+  private final long myStartTime;
+  @NotNull private final String myOperation;
+
+  private StopWatch(@NotNull String operation) {
+    myOperation = operation;
+    myStartTime = System.currentTimeMillis();
+  }
+
+  public static StopWatch start(@NotNull String operation) {
+    return new StopWatch(operation);
+  }
+
+  public void report() {
+    LOG.debug(myOperation + " took " + (System.currentTimeMillis() - myStartTime) + " ms");
+  }
+
+}

plugins/git4idea/src/git4idea/history/GitHistoryUtils.java

@@ -42,6 +42,7 @@ import com.intellij.util.concurrency.Semaphore;
 import com.intellij.util.containers.ContainerUtil;
 import com.intellij.vcs.log.*;
 import com.intellij.vcs.log.impl.HashImpl;
+import com.intellij.vcs.log.util.StopWatch;
 import git4idea.*;
 import git4idea.branch.GitBranchUtil;
 import git4idea.commands.*;
@@ -740,11 +741,16 @@ public class GitHistoryUtils {
     h.addParameters("--full-history", "--sparse");
     h.endOptions();
 
+    StopWatch sw = StopWatch.start("git log --all-details");
     String output = h.run();
+    sw.report();
 
+    sw = StopWatch.start("parsing");
     List<GitLogRecord> records = parser.parse(output);
+    sw.report();
 
-    return ContainerUtil.mapNotNull(records, new Function<GitLogRecord, GitCommit>() {
+    sw = StopWatch.start("Creating GitCommit objects");
+    List<GitCommit> gitCommits = ContainerUtil.mapNotNull(records, new Function<GitLogRecord, GitCommit>() {
       @Override
       public GitCommit fun(GitLogRecord record) {
         try {
@@ -756,6 +762,8 @@ public class GitHistoryUtils {
         }
       }
     });
+    sw.report();
+    return gitCommits;
   }
 
   private static GitCommit createCommit(@NotNull Project project, @NotNull VirtualFile root, @NotNull GitLogRecord record)