From 8ace69b58e6efd96d2a9825fd1735b33a76db61f Mon Sep 17 00:00:00 2001
From: Kirill Likhodedov <Kirill.Likhodedov@jetbrains.com>
Date: Fri, 25 May 2012 11:59:18 +0400
Subject: [PATCH] [git] Add debug logging for start and finish of all Git
 commands.

Log start in start(), because runInCurrentThread doesn't cover all usages of start() (some history commands are called via start()).
Log finish in runInCurrentThread(), because start() is async.
---
 .../src/git4idea/commands/GitCommand.java      |  4 ++++
 .../src/git4idea/commands/GitHandler.java      | 18 +++++++++++++++++-
 2 files changed, 21 insertions(+), 1 deletion(-)

diff --git a/plugins/git4idea/src/git4idea/commands/GitCommand.java b/plugins/git4idea/src/git4idea/commands/GitCommand.java
index 2528424c8d1a..11938ad7d5e2 100644
--- a/plugins/git4idea/src/git4idea/commands/GitCommand.java
+++ b/plugins/git4idea/src/git4idea/commands/GitCommand.java
@@ -136,4 +136,8 @@ public class GitCommand {
     return new GitCommand(this, LockingPolicy.READ);
   }
 
+  @Override
+  public String toString() {
+    return myName;
+  }
 }
diff --git a/plugins/git4idea/src/git4idea/commands/GitHandler.java b/plugins/git4idea/src/git4idea/commands/GitHandler.java
index c6c33d227d2d..237fe5416a43 100644
--- a/plugins/git4idea/src/git4idea/commands/GitHandler.java
+++ b/plugins/git4idea/src/git4idea/commands/GitHandler.java
@@ -96,6 +96,8 @@ public abstract class GitHandler {
   private Runnable mySuspendAction; // Suspend action used by {@link #suspendWriteLock()}
   private Runnable myResumeAction; // Resume action used by {@link #resumeWriteLock()}
 
+  private long myStartTime; // git execution start timestamp
+
 
   /**
    * A constructor
@@ -387,12 +389,19 @@ public abstract class GitHandler {
     checkNotStarted();
 
     try {
-      // setup environment
+      myStartTime = System.currentTimeMillis();
       if (!myProject.isDefault() && !mySilent && (myVcs != null)) {
         myVcs.showCommandLine("cd " + myWorkingDirectory);
         myVcs.showCommandLine(printableCommandLine());
+        LOG.info("cd " + myWorkingDirectory);
         LOG.info(myCommandLine.getCommandLineString());
       }
+      else {
+        LOG.debug("cd " + myWorkingDirectory);
+        LOG.debug(myCommandLine.getCommandLineString());
+      }
+
+      // setup environment
       if (!myNoSSHFlag && myProjectSettings.isIdeaSsh()) {
         GitSSHService ssh = GitSSHIdeaService.getInstance();
         myEnv.put(GitSSHHandler.GIT_SSH_ENV, ssh.getScriptPath().getPath());
@@ -721,6 +730,13 @@ public abstract class GitHandler {
           vcs.getCommandLock().writeLock().unlock();
           break;
       }
+
+      if (myStartTime > 0) {
+        LOG.debug(String.format("git %s took %s ms", myCommand, System.currentTimeMillis() - myStartTime));
+      }
+      else {
+        LOG.debug(String.format("git %s finished.", myCommand));
+      }
     }
   }