Merge changes I1c53f64c,If9896304,I90adc761 into stable-3.4

* changes:
  Log cpu usage in sshd_log
  Encapsulate fields of SshScope.Context
  Log "-" for missing log fields in sshd_log

6 files changed, 79 insertions, 22 deletions

diff --git a/Documentation/logs.txt b/Documentation/logs.txt
index 6624366044..e68ff872ac 100644
--- a/Documentation/logs.txt
+++ b/Documentation/logs.txt
@@ -84,6 +84,9 @@ Log format:
 * `wait`: command wait time, time in milliseconds the command waited for an execution thread.
 * `exec`: command execution time, time in milliseconds to execute the command.
 * `status`: status code. 0 means success, any other value is an error.
+* `total_cpu`: total CPU time, CPU time in milliseconds to execute command.
+* `user_cpu`: user mode CPU time, CPU time in user mode in milliseconds to execute command.
+  CPU time in kernel mode is `total_cpu - user_cpu`.
 
 The `git-upload-pack` command provides the following additional fields after the `exec`
 and before the `status` field. All times are in milliseconds. Fields are -1 if not available
diff --git a/java/com/google/gerrit/sshd/BaseCommand.java b/java/com/google/gerrit/sshd/BaseCommand.java
index 0ce6766f86..48a55125d1 100644
--- a/java/com/google/gerrit/sshd/BaseCommand.java
+++ b/java/com/google/gerrit/sshd/BaseCommand.java
@@ -36,7 +36,6 @@ import com.google.gerrit.server.permissions.PermissionBackend;
 import com.google.gerrit.server.permissions.PermissionBackendException;
 import com.google.gerrit.server.project.NoSuchChangeException;
 import com.google.gerrit.server.project.NoSuchProjectException;
-import com.google.gerrit.server.util.time.TimeUtil;
 import com.google.gerrit.sshd.SshScope.Context;
 import com.google.gerrit.util.cli.CmdLineParser;
 import com.google.gerrit.util.cli.EndOfOptionsHandler;
@@ -480,7 +479,7 @@ public abstract class BaseCommand implements Command {
         context.getSession().setAccessPath(accessPath);
         final Context old = sshScope.set(context);
         try {
-          context.started = TimeUtil.nowMs();
+          context.start();
           thisThread.setName("SSH " + taskName);
 
           try {
diff --git a/java/com/google/gerrit/sshd/SshLog.java b/java/com/google/gerrit/sshd/SshLog.java
index 2b3052c8f9..411cdde5ef 100644
--- a/java/com/google/gerrit/sshd/SshLog.java
+++ b/java/com/google/gerrit/sshd/SshLog.java
@@ -57,6 +57,8 @@ class SshLog implements LifecycleListener, GerritConfigListener {
   protected static final String P_STATUS = "status";
   protected static final String P_AGENT = "agent";
   protected static final String P_MESSAGE = "message";
+  protected static final String P_TOTAL_CPU = "totalCpu";
+  protected static final String P_USER_CPU = "userCpu";
 
   private final Provider<SshSession> session;
   private final Provider<Context> context;
@@ -171,13 +173,15 @@ class SshLog implements LifecycleListener, GerritConfigListener {
 
   void onExecute(DispatchCommand dcmd, int exitValue, SshSession sshSession, String message) {
     final Context ctx = context.get();
-    ctx.finished = TimeUtil.nowMs();
+    ctx.finish();
 
     String cmd = extractWhat(dcmd);
 
     final LoggingEvent event = log(cmd);
-    event.setProperty(P_WAIT, (ctx.started - ctx.created) + "ms");
-    event.setProperty(P_EXEC, (ctx.finished - ctx.started) + "ms");
+    event.setProperty(P_WAIT, ctx.getWait() + "ms");
+    event.setProperty(P_EXEC, ctx.getExec() + "ms");
+    event.setProperty(P_TOTAL_CPU, ctx.getTotalCpu() + "ms");
+    event.setProperty(P_USER_CPU, ctx.getUserCpu() + "ms");
 
     final String status;
     switch (exitValue) {
@@ -328,7 +332,7 @@ class SshLog implements LifecycleListener, GerritConfigListener {
       SshSession session = ctx.getSession();
       sessionId = HexFormat.fromInt(session.getSessionId());
       currentUser = session.getUser();
-      created = ctx.created;
+      created = ctx.getCreated();
     }
     auditService.dispatch(new SshAuditEvent(sessionId, currentUser, cmd, created, params, result));
   }
diff --git a/java/com/google/gerrit/sshd/SshLogJsonLayout.java b/java/com/google/gerrit/sshd/SshLogJsonLayout.java
index 488a4c5dd2..7bc22e87f7 100644
--- a/java/com/google/gerrit/sshd/SshLogJsonLayout.java
+++ b/java/com/google/gerrit/sshd/SshLogJsonLayout.java
@@ -20,6 +20,8 @@ import static com.google.gerrit.sshd.SshLog.P_EXEC;
 import static com.google.gerrit.sshd.SshLog.P_MESSAGE;
 import static com.google.gerrit.sshd.SshLog.P_SESSION;
 import static com.google.gerrit.sshd.SshLog.P_STATUS;
+import static com.google.gerrit.sshd.SshLog.P_TOTAL_CPU;
+import static com.google.gerrit.sshd.SshLog.P_USER_CPU;
 import static com.google.gerrit.sshd.SshLog.P_USER_NAME;
 import static com.google.gerrit.sshd.SshLog.P_WAIT;
 
@@ -44,6 +46,8 @@ public class SshLogJsonLayout extends JsonLayout {
     public String message;
     public String waitTime;
     public String execTime;
+    public String totalCpu;
+    public String userCpu;
     public String status;
     public String agent;
     public String timeNegotiating;
@@ -67,6 +71,8 @@ public class SshLogJsonLayout extends JsonLayout {
       this.message = (String) event.getMessage();
       this.waitTime = getMdcString(event, P_WAIT);
       this.execTime = getMdcString(event, P_EXEC);
+      this.totalCpu = getMdcString(event, P_TOTAL_CPU);
+      this.userCpu = getMdcString(event, P_USER_CPU);
       this.status = getMdcString(event, P_STATUS);
       this.agent = getMdcString(event, P_AGENT);
 
diff --git a/java/com/google/gerrit/sshd/SshLogLayout.java b/java/com/google/gerrit/sshd/SshLogLayout.java
index 1dda0686b8..558efa26ee 100644
--- a/java/com/google/gerrit/sshd/SshLogLayout.java
+++ b/java/com/google/gerrit/sshd/SshLogLayout.java
@@ -20,6 +20,8 @@ import static com.google.gerrit.sshd.SshLog.P_EXEC;
 import static com.google.gerrit.sshd.SshLog.P_MESSAGE;
 import static com.google.gerrit.sshd.SshLog.P_SESSION;
 import static com.google.gerrit.sshd.SshLog.P_STATUS;
+import static com.google.gerrit.sshd.SshLog.P_TOTAL_CPU;
+import static com.google.gerrit.sshd.SshLog.P_USER_CPU;
 import static com.google.gerrit.sshd.SshLog.P_USER_NAME;
 import static com.google.gerrit.sshd.SshLog.P_WAIT;
 
@@ -56,11 +58,16 @@ public final class SshLogLayout extends Layout {
     buf.append(' ');
     buf.append(event.getMessage());
 
-    opt(P_WAIT, buf, event);
-    opt(P_EXEC, buf, event);
-    opt(P_MESSAGE, buf, event);
-    opt(P_STATUS, buf, event);
-    opt(P_AGENT, buf, event);
+    String msg = (String) event.getMessage();
+    if (!(msg.startsWith("LOGIN") || msg.equals("LOGOUT"))) {
+      req(P_WAIT, buf, event);
+      req(P_EXEC, buf, event);
+      req(P_MESSAGE, buf, event);
+      req(P_STATUS, buf, event);
+      req(P_AGENT, buf, event);
+      req(P_TOTAL_CPU, buf, event);
+      req(P_USER_CPU, buf, event);
+    }
 
     buf.append('\n');
     return buf.toString();
@@ -81,14 +88,6 @@ public final class SshLogLayout extends Layout {
     }
   }
 
-  private void opt(String key, StringBuffer buf, LoggingEvent event) {
-    Object val = event.getMDC(key);
-    if (val != null) {
-      buf.append(' ');
-      buf.append(val);
-    }
-  }
-
   @Override
   public boolean ignoresThrowable() {
     return true;
diff --git a/java/com/google/gerrit/sshd/SshScope.java b/java/com/google/gerrit/sshd/SshScope.java
index 340b910c59..61f6070ab1 100644
--- a/java/com/google/gerrit/sshd/SshScope.java
+++ b/java/com/google/gerrit/sshd/SshScope.java
@@ -26,27 +26,37 @@ import com.google.inject.Key;
 import com.google.inject.OutOfScopeException;
 import com.google.inject.Provider;
 import com.google.inject.Scope;
+import java.lang.management.ManagementFactory;
+import java.lang.management.ThreadMXBean;
 import java.util.HashMap;
 import java.util.Map;
 
 /** Guice scopes for state during an SSH connection. */
 public class SshScope {
   private static final Key<RequestCleanup> RC_KEY = Key.get(RequestCleanup.class);
+  private static final ThreadMXBean threadMxBean = ManagementFactory.getThreadMXBean();
 
   class Context implements RequestContext {
+
     private final RequestCleanup cleanup = new RequestCleanup();
     private final Map<Key<?>, Object> map = new HashMap<>();
     private final SshSession session;
     private final String commandLine;
 
-    final long created;
-    volatile long started;
-    volatile long finished;
+    private final long created;
+    private volatile long started;
+    private volatile long finished;
+    private volatile long startedTotalCpu;
+    private volatile long finishedTotalCpu;
+    private volatile long startedUserCpu;
+    private volatile long finishedUserCpu;
 
     private Context(SshSession s, String c, long at) {
       session = s;
       commandLine = c;
       created = started = finished = at;
+      startedTotalCpu = threadMxBean.getCurrentThreadCpuTime();
+      startedUserCpu = threadMxBean.getCurrentThreadUserTime();
       map.put(RC_KEY, cleanup);
     }
 
@@ -54,6 +64,42 @@ public class SshScope {
       this(s, c, p.created);
       started = p.started;
       finished = p.finished;
+      startedTotalCpu = p.startedTotalCpu;
+      finishedTotalCpu = p.finishedTotalCpu;
+      startedUserCpu = p.startedUserCpu;
+      finishedUserCpu = p.finishedUserCpu;
+    }
+
+    void start() {
+      started = TimeUtil.nowMs();
+      startedTotalCpu = threadMxBean.getCurrentThreadCpuTime();
+      startedUserCpu = threadMxBean.getCurrentThreadUserTime();
+    }
+
+    void finish() {
+      finished = TimeUtil.nowMs();
+      finishedTotalCpu = threadMxBean.getCurrentThreadCpuTime();
+      finishedUserCpu = threadMxBean.getCurrentThreadUserTime();
+    }
+
+    public long getCreated() {
+      return created;
+    }
+
+    public long getWait() {
+      return started - created;
+    }
+
+    public long getExec() {
+      return finished - started;
+    }
+
+    public long getTotalCpu() {
+      return (finishedTotalCpu - startedTotalCpu) / 1_000_000;
+    }
+
+    public long getUserCpu() {
+      return (finishedUserCpu - startedUserCpu) / 1_000_000;
     }
 
     String getCommandLine() {