From 70bb70d4459e121ae44897cd02f4f37eec3a8d9c Mon Sep 17 00:00:00 2001 From: Kirill Likhodedov Date: Mon, 3 Mar 2014 14:40:21 +0400 Subject: [PATCH] [log] Added time measurements to the VCS log --- .../vcs/log/data/VcsLogDataHolder.java | 26 +++++++++++- .../com/intellij/vcs/log/util/StopWatch.java | 41 +++++++++++++++++++ .../src/git4idea/history/GitHistoryUtils.java | 10 ++++- 3 files changed, 75 insertions(+), 2 deletions(-) create mode 100644 platform/vcs-log/impl/src/com/intellij/vcs/log/util/StopWatch.java diff --git a/platform/vcs-log/impl/src/com/intellij/vcs/log/data/VcsLogDataHolder.java b/platform/vcs-log/impl/src/com/intellij/vcs/log/data/VcsLogDataHolder.java index f5fc5f495173..046095165e8b 100644 --- a/platform/vcs-log/impl/src/com/intellij/vcs/log/data/VcsLogDataHolder.java +++ b/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 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 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() { @Override public void consume(ProgressIndicator indicator) throws VcsException { + StopWatch methodLog = StopWatch.start("loadAllLog"); try { Consumer userRegistry = new Consumer() { @Override @@ -283,13 +289,17 @@ public class VcsLogDataHolder implements Disposable { for (Map.Entry 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 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> logsToBuild = ContainerUtil.newHashMap(); Map> 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 onSuccess) throws VcsException { + StopWatch methodSW = StopWatch.start("loadFromVcs"); Map> logsToBuild = ContainerUtil.newHashMap(); Map> 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 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> collectInfoFromVcs(boolean ordered, int commitsCount) throws VcsException { + StopWatch methodTime = StopWatch.start("collectInfoFromVcs"); Map infoByRoot = ContainerUtil.newHashMap(); for (Map.Entry entry : myLogProviders.entrySet()) { VirtualFile root = entry.getKey(); VcsLogProvider logProvider = entry.getValue(); + StopWatch sw = StopWatch.start("readFirstBlock for " + root.getName()); List firstBlockDetails = logProvider.readFirstBlock(root, ordered, commitsCount); + sw.report(); + sw = StopWatch.start("readAllRefs for" + root.getName()); Collection newRefs = logProvider.readAllRefs(root); + sw.report(); storeTopCommitsDetailsInCache(firstBlockDetails); storeUsers(firstBlockDetails); List firstBlockCommits = getCommitsFromDetails(firstBlockDetails); infoByRoot.put(root, new RecentCommitsInfo(firstBlockCommits, newRefs)); } + methodTime.report(); return infoByRoot.entrySet(); } 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 new file mode 100644 index 000000000000..0d6dcb51351e --- /dev/null +++ b/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"); + } + +} diff --git a/plugins/git4idea/src/git4idea/history/GitHistoryUtils.java b/plugins/git4idea/src/git4idea/history/GitHistoryUtils.java index f4cc163da2e3..af986a9375d5 100644 --- a/plugins/git4idea/src/git4idea/history/GitHistoryUtils.java +++ b/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 records = parser.parse(output); + sw.report(); - return ContainerUtil.mapNotNull(records, new Function() { + sw = StopWatch.start("Creating GitCommit objects"); + List gitCommits = ContainerUtil.mapNotNull(records, new Function() { @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)