Add extension point to record execution times in a performance log

Add a new extension point that is invoked for all operations for which
the execution time is measured. The invocation of the extension point
does not happen immediately, but only at the end of a request (REST
call, SSH call, git push). Implementors can write the execution times
into a performance log for further analysis.

In Gerrit there are 2 possibilities to measure and record the execution
time of an operation:

1. TraceTimer:
   Opens an autocloseable context to execute an operation. On close the
   execution time is written to the server logs, but only if the request
   is traced (or if log level was set to fine).
2. Timer Metrics:
   Record execution times as a metric.
   In addition this writes the execution time to the server logs, but
   only if the request is traced (or if log level was set to fine).

These are the 2 places where performance log entries must be captured.

Performance log entries are stored in the LoggingContext which is based
on ThreadLocals. LoggingContextAwareRunnable and
LoggingContextAwareCallable which are used by all executors ensure that
captured performance log entries are properly copied between threads.

At the end of a request (supported are REST call, SSH call and git push)
the captured performance log entries are handed over to the
PerformanceLogger implementations.

If no PerformanceLogger is registered, or if execution times of
operations outside of request scope are measured, performance log
entries are not captured because nobody would consume them.

Storing the performance log records in the LoggingContext and invoking
the PerformanceLogger plugins only at the end of a request has some
advantages and disadvantages:

1. [advantage] Users of TraceTimer can continue to use the static
   methods calls to create a TraceTimer (TraceContext.newTimer(...)). To
   invoke the plugins immediately we would need to get them injected
   into TraceTimer, hence callers would need a factory to create a
   TraceTimer. That would result in quite some boilerplate code and in
   addition some places that use TraceTimer (in VersionedMetaData)
   cannot use injection.
2. [advantage] The metric system is setup very early in the injector
   chain (in the DB injector, see SiteProgram#createDbInjector(boolean)).
   To invoke the plugins directly from the timer metrics we would need
   to have the PerformanceLogger plugins already available on this
   injector level, which is difficult.
3. [disadvantage] The captured performance log records are kept in
   memory while a request is processed. This leads to higher memory
   foodprint, but we think this is OK.

To keep the performance and memory overhead for recording performance as
low as possible we did some optimizations:

1. Performance log entries are only created if there is a consumer (at
   least one PerformanceLogger plugin + time measured inside request
   context)
2. Performance log entries avoid the instantiation of a Map to record
   meta data (instead we have dedicated fields for meta data keys and
   values).

For the timer metrics we use generic names for the meta data keys
("field1", "field2", "field3"). This is because the actual field names
are not available at this place. We may make them available, but that's
outside the scope of this change and may be done in a follow-up change.

To be able to write stable acceptance tests that verify that the
PerformanceLogger plugins are invoked, it is important that the server
calls the plugins before the response is sent back to the client. This
is why the scope of the PerformanceLogContext in RestApiServlet is a
little smaller than the scope of the TraceContext.

Change-Id: I699db01609a1b4a88cee8959bdd9f1dfbb8dc74e
Signed-off-by: Edwin Kempin <ekempin@google.com>

Documentation/dev-plugins.txt

@@ -2801,6 +2801,15 @@ class ApiQpsEnforcer implements QuotaEnforcer {
 }
 ----
 
+[[performance-logger]]
+== Performance Logger
+
+`com.google.gerrit.server.logging.PerformanceLogger` is an extension point that
+is invoked for all operations for which the execution time is measured. The
+invocation of the extension point does not happen immediately, but only at the
+end of a request (REST call, SSH call, git push). Implementors can write the
+execution times into a performance log for further analysis.
+
 [[plugins_hosting]]
 == Plugins source code hosting
 

java/com/google/gerrit/httpd/restapi/RestApiServlet.java

@@ -69,6 +69,7 @@ import com.google.gerrit.common.Nullable;
 import com.google.gerrit.common.RawInputUtil;
 import com.google.gerrit.extensions.registration.DynamicItem;
 import com.google.gerrit.extensions.registration.DynamicMap;
+import com.google.gerrit.extensions.registration.DynamicSet;
 import com.google.gerrit.extensions.registration.PluginName;
 import com.google.gerrit.extensions.restapi.AuthException;
 import com.google.gerrit.extensions.restapi.BadRequestException;
@@ -109,6 +110,8 @@ import com.google.gerrit.server.audit.ExtendedHttpAuditEvent;
 import com.google.gerrit.server.cache.PerThreadCache;
 import com.google.gerrit.server.config.GerritServerConfig;
 import com.google.gerrit.server.group.GroupAuditService;
+import com.google.gerrit.server.logging.PerformanceLogContext;
+import com.google.gerrit.server.logging.PerformanceLogger;
 import com.google.gerrit.server.logging.RequestId;
 import com.google.gerrit.server.logging.TraceContext;
 import com.google.gerrit.server.permissions.GlobalPermission;
@@ -229,6 +232,7 @@ public class RestApiServlet extends HttpServlet {
     final RestApiMetrics metrics;
     final Pattern allowOrigin;
     final RestApiQuotaEnforcer quotaChecker;
+    final DynamicSet<PerformanceLogger> performanceLoggers;
 
     @Inject
     Globals(
@@ -239,7 +243,8 @@ public class RestApiServlet extends HttpServlet {
         GroupAuditService auditService,
         RestApiMetrics metrics,
         RestApiQuotaEnforcer quotaChecker,
-        @GerritServerConfig Config cfg) {
+        @GerritServerConfig Config cfg,
+        DynamicSet<PerformanceLogger> performanceLoggers) {
       this.currentUser = currentUser;
       this.webSession = webSession;
       this.paramParser = paramParser;
@@ -247,6 +252,7 @@ public class RestApiServlet extends HttpServlet {
       this.auditService = auditService;
       this.metrics = metrics;
       this.quotaChecker = quotaChecker;
+      this.performanceLoggers = performanceLoggers;
       allowOrigin = makeAllowOrigin(cfg);
     }
 
@@ -294,258 +300,266 @@ public class RestApiServlet extends HttpServlet {
 
     try (TraceContext traceContext = enableTracing(req, res)) {
       try (PerThreadCache ignored = PerThreadCache.create()) {
-        logger.atFinest().log(
+        // It's important that the PerformanceLogContext is closed before the response is sent to
-            "Received REST request: %s %s (parameters: %s)",
+        // the client. Only this way it is ensured that the invocation of the PerformanceLogger
-            req.getMethod(), req.getRequestURI(), getParameterNames(req));
+        // plugins happens before the client sees the response. This is needed for being able to
-        logger.atFinest().log("Calling user: %s", globals.currentUser.get().getLoggableName());
+        // test performance logging from an acceptance test (see
+        // TraceIT#performanceLoggingForRestCall()).
+        try (PerformanceLogContext performanceLogContext =
+            new PerformanceLogContext(globals.performanceLoggers)) {
+          logger.atFinest().log(
+              "Received REST request: %s %s (parameters: %s)",
+              req.getMethod(), req.getRequestURI(), getParameterNames(req));
+          logger.atFinest().log("Calling user: %s", globals.currentUser.get().getLoggableName());
 
-        if (isCorsPreflight(req)) {
+          if (isCorsPreflight(req)) {
-          doCorsPreflight(req, res);
+            doCorsPreflight(req, res);
-          return;
+            return;
-        }
-
-        qp = ParameterParser.getQueryParams(req);
-        checkCors(req, res, qp.hasXdOverride());
-        if (qp.hasXdOverride()) {
-          req = applyXdOverrides(req, qp);
-        }
-        checkUserSession(req);
-
-        List<IdString> path = splitPath(req);
-        RestCollection<RestResource, RestResource> rc = members.get();
-        globals
-            .permissionBackend
-            .currentUser()
-            .checkAny(GlobalPermission.fromAnnotation(rc.getClass()));
-
-        viewData = new ViewData(null, null);
-
-        if (path.isEmpty()) {
-          globals.quotaChecker.enforce(req);
-          if (rc instanceof NeedsParams) {
-            ((NeedsParams) rc).setParams(qp.params());
           }
 
-          if (isRead(req)) {
+          qp = ParameterParser.getQueryParams(req);
-            viewData = new ViewData(null, rc.list());
+          checkCors(req, res, qp.hasXdOverride());
-          } else if (isPost(req)) {
+          if (qp.hasXdOverride()) {
-            RestView<RestResource> restCollectionView =
+            req = applyXdOverrides(req, qp);
-                rc.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./");
+          }
-            if (restCollectionView != null) {
+          checkUserSession(req);
-              viewData = new ViewData(null, restCollectionView);
+
+          List<IdString> path = splitPath(req);
+          RestCollection<RestResource, RestResource> rc = members.get();
+          globals
+              .permissionBackend
+              .currentUser()
+              .checkAny(GlobalPermission.fromAnnotation(rc.getClass()));
+
+          viewData = new ViewData(null, null);
+
+          if (path.isEmpty()) {
+            globals.quotaChecker.enforce(req);
+            if (rc instanceof NeedsParams) {
+              ((NeedsParams) rc).setParams(qp.params());
+            }
+
+            if (isRead(req)) {
+              viewData = new ViewData(null, rc.list());
+            } else if (isPost(req)) {
+              RestView<RestResource> restCollectionView =
+                  rc.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./");
+              if (restCollectionView != null) {
+                viewData = new ViewData(null, restCollectionView);
+              } else {
+                throw methodNotAllowed(req);
+              }
             } else {
+              // DELETE on root collections is not supported
               throw methodNotAllowed(req);
             }
           } else {
-            // DELETE on root collections is not supported
+            IdString id = path.remove(0);
-            throw methodNotAllowed(req);
+            try {
-          }
+              rsrc = rc.parse(rsrc, id);
-        } else {
+              globals.quotaChecker.enforce(rsrc, req);
-          IdString id = path.remove(0);
+              if (path.isEmpty()) {
-          try {
+                checkPreconditions(req);
-            rsrc = rc.parse(rsrc, id);
+              }
-            globals.quotaChecker.enforce(rsrc, req);
+            } catch (ResourceNotFoundException e) {
-            if (path.isEmpty()) {
+              if (!path.isEmpty()) {
-              checkPreconditions(req);
+                throw e;
-            }
+              }
-          } catch (ResourceNotFoundException e) {
+              globals.quotaChecker.enforce(req);
-            if (!path.isEmpty()) {
-              throw e;
-            }
-            globals.quotaChecker.enforce(req);
 
-            if (isPost(req) || isPut(req)) {
+              if (isPost(req) || isPut(req)) {
-              RestView<RestResource> createView = rc.views().get(PluginName.GERRIT, "CREATE./");
+                RestView<RestResource> createView = rc.views().get(PluginName.GERRIT, "CREATE./");
-              if (createView != null) {
+                if (createView != null) {
-                viewData = new ViewData(null, createView);
+                  viewData = new ViewData(null, createView);
-                status = SC_CREATED;
+                  status = SC_CREATED;
-                path.add(id);
+                  path.add(id);
+                } else {
+                  throw e;
+                }
+              } else if (isDelete(req)) {
+                RestView<RestResource> deleteView =
+                    rc.views().get(PluginName.GERRIT, "DELETE_MISSING./");
+                if (deleteView != null) {
+                  viewData = new ViewData(null, deleteView);
+                  status = SC_NO_CONTENT;
+                  path.add(id);
+                } else {
+                  throw e;
+                }
               } else {
                 throw e;
               }
-            } else if (isDelete(req)) {
-              RestView<RestResource> deleteView =
-                  rc.views().get(PluginName.GERRIT, "DELETE_MISSING./");
-              if (deleteView != null) {
-                viewData = new ViewData(null, deleteView);
-                status = SC_NO_CONTENT;
-                path.add(id);
-              } else {
-                throw e;
-              }
-            } else {
-              throw e;
             }
-          }
+            if (viewData.view == null) {
-          if (viewData.view == null) {
+              viewData = view(rc, req.getMethod(), path);
-            viewData = view(rc, req.getMethod(), path);
-          }
-        }
-        checkRequiresCapability(viewData);
-
-        while (viewData.view instanceof RestCollection<?, ?>) {
-          @SuppressWarnings("unchecked")
-          RestCollection<RestResource, RestResource> c =
-              (RestCollection<RestResource, RestResource>) viewData.view;
-
-          if (path.isEmpty()) {
-            if (isRead(req)) {
-              viewData = new ViewData(null, c.list());
-            } else if (isPost(req)) {
-              // TODO: Here and on other collection methods: There is a bug that binds child views
-              // with pluginName="gerrit" instead of the real plugin name. This has never worked
-              // correctly and should be fixed where the binding gets created (DynamicMapProvider)
-              // and here.
-              RestView<RestResource> restCollectionView =
-                  c.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./");
-              if (restCollectionView != null) {
-                viewData = new ViewData(null, restCollectionView);
-              } else {
-                throw methodNotAllowed(req);
-              }
-            } else if (isDelete(req)) {
-              RestView<RestResource> restCollectionView =
-                  c.views().get(PluginName.GERRIT, "DELETE_ON_COLLECTION./");
-              if (restCollectionView != null) {
-                viewData = new ViewData(null, restCollectionView);
-              } else {
-                throw methodNotAllowed(req);
-              }
-            } else {
-              throw methodNotAllowed(req);
             }
-            break;
-          }
-          IdString id = path.remove(0);
-          try {
-            rsrc = c.parse(rsrc, id);
-            checkPreconditions(req);
-            viewData = new ViewData(null, null);
-          } catch (ResourceNotFoundException e) {
-            if (!path.isEmpty()) {
-              throw e;
-            }
-
-            if (isPost(req) || isPut(req)) {
-              RestView<RestResource> createView = c.views().get(PluginName.GERRIT, "CREATE./");
-              if (createView != null) {
-                viewData = new ViewData(null, createView);
-                status = SC_CREATED;
-                path.add(id);
-              } else {
-                throw e;
-              }
-            } else if (isDelete(req)) {
-              RestView<RestResource> deleteView =
-                  c.views().get(PluginName.GERRIT, "DELETE_MISSING./");
-              if (deleteView != null) {
-                viewData = new ViewData(null, deleteView);
-                status = SC_NO_CONTENT;
-                path.add(id);
-              } else {
-                throw e;
-              }
-            } else {
-              throw e;
-            }
-          }
-          if (viewData.view == null) {
-            viewData = view(c, req.getMethod(), path);
           }
           checkRequiresCapability(viewData);
-        }
 
-        if (notModified(req, rsrc, viewData.view)) {
+          while (viewData.view instanceof RestCollection<?, ?>) {
-          logger.atFinest().log("REST call succeeded: %d", SC_NOT_MODIFIED);
+            @SuppressWarnings("unchecked")
-          res.sendError(SC_NOT_MODIFIED);
+            RestCollection<RestResource, RestResource> c =
-          return;
+                (RestCollection<RestResource, RestResource>) viewData.view;
-        }
 
-        if (!globals.paramParser.get().parse(viewData.view, qp.params(), req, res)) {
+            if (path.isEmpty()) {
-          return;
+              if (isRead(req)) {
-        }
+                viewData = new ViewData(null, c.list());
-
+              } else if (isPost(req)) {
-        if (viewData.view instanceof RestReadView<?> && isRead(req)) {
+                // TODO: Here and on other collection methods: There is a bug that binds child views
-          result = ((RestReadView<RestResource>) viewData.view).apply(rsrc);
+                // with pluginName="gerrit" instead of the real plugin name. This has never worked
-        } else if (viewData.view instanceof RestModifyView<?, ?>) {
+                // correctly and should be fixed where the binding gets created (DynamicMapProvider)
-          @SuppressWarnings("unchecked")
+                // and here.
-          RestModifyView<RestResource, Object> m =
+                RestView<RestResource> restCollectionView =
-              (RestModifyView<RestResource, Object>) viewData.view;
+                    c.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./");
-
+                if (restCollectionView != null) {
-          Type type = inputType(m);
+                  viewData = new ViewData(null, restCollectionView);
-          inputRequestBody = parseRequest(req, type);
+                } else {
-          result = m.apply(rsrc, inputRequestBody);
+                  throw methodNotAllowed(req);
-          if (inputRequestBody instanceof RawInput) {
+                }
-            try (InputStream is = req.getInputStream()) {
+              } else if (isDelete(req)) {
-              ServletUtils.consumeRequestBody(is);
+                RestView<RestResource> restCollectionView =
+                    c.views().get(PluginName.GERRIT, "DELETE_ON_COLLECTION./");
+                if (restCollectionView != null) {
+                  viewData = new ViewData(null, restCollectionView);
+                } else {
+                  throw methodNotAllowed(req);
+                }
+              } else {
+                throw methodNotAllowed(req);
+              }
+              break;
             }
-          }
+            IdString id = path.remove(0);
-        } else if (viewData.view instanceof RestCollectionCreateView<?, ?, ?>) {
+            try {
-          @SuppressWarnings("unchecked")
+              rsrc = c.parse(rsrc, id);
-          RestCollectionCreateView<RestResource, RestResource, Object> m =
+              checkPreconditions(req);
-              (RestCollectionCreateView<RestResource, RestResource, Object>) viewData.view;
+              viewData = new ViewData(null, null);
+            } catch (ResourceNotFoundException e) {
+              if (!path.isEmpty()) {
+                throw e;
+              }
 
-          Type type = inputType(m);
+              if (isPost(req) || isPut(req)) {
-          inputRequestBody = parseRequest(req, type);
+                RestView<RestResource> createView = c.views().get(PluginName.GERRIT, "CREATE./");
-          result = m.apply(rsrc, path.get(0), inputRequestBody);
+                if (createView != null) {
-          if (inputRequestBody instanceof RawInput) {
+                  viewData = new ViewData(null, createView);
-            try (InputStream is = req.getInputStream()) {
+                  status = SC_CREATED;
-              ServletUtils.consumeRequestBody(is);
+                  path.add(id);
+                } else {
+                  throw e;
+                }
+              } else if (isDelete(req)) {
+                RestView<RestResource> deleteView =
+                    c.views().get(PluginName.GERRIT, "DELETE_MISSING./");
+                if (deleteView != null) {
+                  viewData = new ViewData(null, deleteView);
+                  status = SC_NO_CONTENT;
+                  path.add(id);
+                } else {
+                  throw e;
+                }
+              } else {
+                throw e;
+              }
             }
+            if (viewData.view == null) {
+              viewData = view(c, req.getMethod(), path);
+            }
+            checkRequiresCapability(viewData);
           }
-        } else if (viewData.view instanceof RestCollectionDeleteMissingView<?, ?, ?>) {
-          @SuppressWarnings("unchecked")
-          RestCollectionDeleteMissingView<RestResource, RestResource, Object> m =
-              (RestCollectionDeleteMissingView<RestResource, RestResource, Object>) viewData.view;
 
-          Type type = inputType(m);
+          if (notModified(req, rsrc, viewData.view)) {
-          inputRequestBody = parseRequest(req, type);
+            logger.atFinest().log("REST call succeeded: %d", SC_NOT_MODIFIED);
-          result = m.apply(rsrc, path.get(0), inputRequestBody);
+            res.sendError(SC_NOT_MODIFIED);
-          if (inputRequestBody instanceof RawInput) {
+            return;
-            try (InputStream is = req.getInputStream()) {
-              ServletUtils.consumeRequestBody(is);
-            }
           }
-        } else if (viewData.view instanceof RestCollectionModifyView<?, ?, ?>) {
-          @SuppressWarnings("unchecked")
-          RestCollectionModifyView<RestResource, RestResource, Object> m =
-              (RestCollectionModifyView<RestResource, RestResource, Object>) viewData.view;
 
-          Type type = inputType(m);
+          if (!globals.paramParser.get().parse(viewData.view, qp.params(), req, res)) {
-          inputRequestBody = parseRequest(req, type);
+            return;
-          result = m.apply(rsrc, inputRequestBody);
-          if (inputRequestBody instanceof RawInput) {
-            try (InputStream is = req.getInputStream()) {
-              ServletUtils.consumeRequestBody(is);
-            }
           }
-        } else {
+
-          throw new ResourceNotFoundException();
+          if (viewData.view instanceof RestReadView<?> && isRead(req)) {
+            result = ((RestReadView<RestResource>) viewData.view).apply(rsrc);
+          } else if (viewData.view instanceof RestModifyView<?, ?>) {
+            @SuppressWarnings("unchecked")
+            RestModifyView<RestResource, Object> m =
+                (RestModifyView<RestResource, Object>) viewData.view;
+
+            Type type = inputType(m);
+            inputRequestBody = parseRequest(req, type);
+            result = m.apply(rsrc, inputRequestBody);
+            if (inputRequestBody instanceof RawInput) {
+              try (InputStream is = req.getInputStream()) {
+                ServletUtils.consumeRequestBody(is);
+              }
+            }
+          } else if (viewData.view instanceof RestCollectionCreateView<?, ?, ?>) {
+            @SuppressWarnings("unchecked")
+            RestCollectionCreateView<RestResource, RestResource, Object> m =
+                (RestCollectionCreateView<RestResource, RestResource, Object>) viewData.view;
+
+            Type type = inputType(m);
+            inputRequestBody = parseRequest(req, type);
+            result = m.apply(rsrc, path.get(0), inputRequestBody);
+            if (inputRequestBody instanceof RawInput) {
+              try (InputStream is = req.getInputStream()) {
+                ServletUtils.consumeRequestBody(is);
+              }
+            }
+          } else if (viewData.view instanceof RestCollectionDeleteMissingView<?, ?, ?>) {
+            @SuppressWarnings("unchecked")
+            RestCollectionDeleteMissingView<RestResource, RestResource, Object> m =
+                (RestCollectionDeleteMissingView<RestResource, RestResource, Object>) viewData.view;
+
+            Type type = inputType(m);
+            inputRequestBody = parseRequest(req, type);
+            result = m.apply(rsrc, path.get(0), inputRequestBody);
+            if (inputRequestBody instanceof RawInput) {
+              try (InputStream is = req.getInputStream()) {
+                ServletUtils.consumeRequestBody(is);
+              }
+            }
+          } else if (viewData.view instanceof RestCollectionModifyView<?, ?, ?>) {
+            @SuppressWarnings("unchecked")
+            RestCollectionModifyView<RestResource, RestResource, Object> m =
+                (RestCollectionModifyView<RestResource, RestResource, Object>) viewData.view;
+
+            Type type = inputType(m);
+            inputRequestBody = parseRequest(req, type);
+            result = m.apply(rsrc, inputRequestBody);
+            if (inputRequestBody instanceof RawInput) {
+              try (InputStream is = req.getInputStream()) {
+                ServletUtils.consumeRequestBody(is);
+              }
+            }
+          } else {
+            throw new ResourceNotFoundException();
+          }
+
+          if (result instanceof Response) {
+            @SuppressWarnings("rawtypes")
+            Response<?> r = (Response) result;
+            status = r.statusCode();
+            configureCaching(req, res, rsrc, viewData.view, r.caching());
+          } else if (result instanceof Response.Redirect) {
+            CacheHeaders.setNotCacheable(res);
+            String location = ((Response.Redirect) result).location();
+            res.sendRedirect(location);
+            logger.atFinest().log("REST call redirected to: %s", location);
+            return;
+          } else if (result instanceof Response.Accepted) {
+            CacheHeaders.setNotCacheable(res);
+            res.setStatus(SC_ACCEPTED);
+            res.setHeader(HttpHeaders.LOCATION, ((Response.Accepted) result).location());
+            logger.atFinest().log("REST call succeeded: %d", SC_ACCEPTED);
+            return;
+          } else {
+            CacheHeaders.setNotCacheable(res);
+          }
+          res.setStatus(status);
+          logger.atFinest().log("REST call succeeded: %d", status);
         }
 
-        if (result instanceof Response) {
-          @SuppressWarnings("rawtypes")
-          Response<?> r = (Response) result;
-          status = r.statusCode();
-          configureCaching(req, res, rsrc, viewData.view, r.caching());
-        } else if (result instanceof Response.Redirect) {
-          CacheHeaders.setNotCacheable(res);
-          String location = ((Response.Redirect) result).location();
-          res.sendRedirect(location);
-          logger.atFinest().log("REST call redirected to: %s", location);
-          return;
-        } else if (result instanceof Response.Accepted) {
-          CacheHeaders.setNotCacheable(res);
-          res.setStatus(SC_ACCEPTED);
-          res.setHeader(HttpHeaders.LOCATION, ((Response.Accepted) result).location());
-          logger.atFinest().log("REST call succeeded: %d", SC_ACCEPTED);
-          return;
-        } else {
-          CacheHeaders.setNotCacheable(res);
-        }
-        res.setStatus(status);
-        logger.atFinest().log("REST call succeeded: %d", status);
-
         if (result != Response.none()) {
           result = Response.unwrap(result);
           if (result instanceof BinaryResult) {

java/com/google/gerrit/metrics/BUILD

@@ -6,6 +6,7 @@ java_library(
         "//java/com/google/gerrit/common:server",
         "//java/com/google/gerrit/extensions:api",
         "//java/com/google/gerrit/lifecycle",
+        "//java/com/google/gerrit/server/logging",
         "//lib:guava",
         "//lib/flogger:api",
         "//lib/guice",

java/com/google/gerrit/metrics/Timer0.java

@@ -18,6 +18,8 @@ import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
 import com.google.common.flogger.FluentLogger;
 import com.google.gerrit.extensions.registration.RegistrationHandle;
+import com.google.gerrit.server.logging.LoggingContext;
+import com.google.gerrit.server.logging.PerformanceLogRecord;
 import java.util.concurrent.TimeUnit;
 
 /**
@@ -68,7 +70,10 @@ public abstract class Timer0 implements RegistrationHandle {
    * @param unit time unit of the value
    */
   public final void record(long value, TimeUnit unit) {
-    logger.atFinest().log("%s took %dms", name, unit.toMillis(value));
+    long durationMs = unit.toMillis(value);
+    LoggingContext.getInstance()
+        .addPerformanceLogRecord(() -> PerformanceLogRecord.create(name, durationMs));
+    logger.atFinest().log("%s took %dms", name, durationMs);
     doRecord(value, unit);
   }
 

java/com/google/gerrit/metrics/Timer1.java

@@ -18,6 +18,8 @@ import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
 import com.google.common.flogger.FluentLogger;
 import com.google.gerrit.extensions.registration.RegistrationHandle;
+import com.google.gerrit.server.logging.LoggingContext;
+import com.google.gerrit.server.logging.PerformanceLogRecord;
 import java.util.concurrent.TimeUnit;
 
 /**
@@ -75,7 +77,14 @@ public abstract class Timer1<F1> implements RegistrationHandle {
    * @param unit time unit of the value
    */
   public final void record(F1 field1, long value, TimeUnit unit) {
-    logger.atFinest().log("%s (%s) took %dms", name, field1, unit.toMillis(value));
+    long durationMs = unit.toMillis(value);
+
+    // TODO(ekempin): We don't know the field name here. Check whether we can make it available.
+    LoggingContext.getInstance()
+        .addPerformanceLogRecord(
+            () -> PerformanceLogRecord.create(name, durationMs, "field1", field1));
+
+    logger.atFinest().log("%s (%s) took %dms", name, field1, durationMs);
     doRecord(field1, value, unit);
   }
 

java/com/google/gerrit/metrics/Timer2.java

@@ -18,6 +18,8 @@ import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
 import com.google.common.flogger.FluentLogger;
 import com.google.gerrit.extensions.registration.RegistrationHandle;
+import com.google.gerrit.server.logging.LoggingContext;
+import com.google.gerrit.server.logging.PerformanceLogRecord;
 import java.util.concurrent.TimeUnit;
 
 /**
@@ -80,7 +82,15 @@ public abstract class Timer2<F1, F2> implements RegistrationHandle {
    * @param unit time unit of the value
    */
   public final void record(F1 field1, F2 field2, long value, TimeUnit unit) {
-    logger.atFinest().log("%s (%s, %s) took %dms", name, field1, field2, unit.toMillis(value));
+    long durationMs = unit.toMillis(value);
+
+    // TODO(ekempin): We don't know the field names here. Check whether we can make them available.
+    LoggingContext.getInstance()
+        .addPerformanceLogRecord(
+            () ->
+                PerformanceLogRecord.create(name, durationMs, "field1", field1, "field2", field2));
+
+    logger.atFinest().log("%s (%s, %s) took %dms", name, field1, field2, durationMs);
     doRecord(field1, field2, value, unit);
   }
 

java/com/google/gerrit/metrics/Timer3.java

@@ -18,6 +18,8 @@ import static java.util.concurrent.TimeUnit.NANOSECONDS;
 
 import com.google.common.flogger.FluentLogger;
 import com.google.gerrit.extensions.registration.RegistrationHandle;
+import com.google.gerrit.server.logging.LoggingContext;
+import com.google.gerrit.server.logging.PerformanceLogRecord;
 import java.util.concurrent.TimeUnit;
 
 /**
@@ -85,8 +87,16 @@ public abstract class Timer3<F1, F2, F3> implements RegistrationHandle {
    * @param unit time unit of the value
    */
   public final void record(F1 field1, F2 field2, F3 field3, long value, TimeUnit unit) {
-    logger.atFinest().log(
+    long durationMs = unit.toMillis(value);
-        "%s (%s, %s, %s) took %dms", name, field1, field2, field3, unit.toMillis(value));
+
+    // TODO(ekempin): We don't know the field names here. Check whether we can make them available.
+    LoggingContext.getInstance()
+        .addPerformanceLogRecord(
+            () ->
+                PerformanceLogRecord.create(
+                    name, durationMs, "field1", field1, "field2", field2, "field3", field3));
+
+    logger.atFinest().log("%s (%s, %s, %s) took %dms", name, field1, field2, field3, durationMs);
     doRecord(field1, field2, field3, value, unit);
   }
 

java/com/google/gerrit/server/BUILD

@@ -136,6 +136,7 @@ java_library(
         ":server",
         "//java/com/google/gerrit/extensions:api",
         "//java/com/google/gerrit/server/git/receive",
+        "//java/com/google/gerrit/server/logging",
         "//java/com/google/gerrit/server/restapi",
         "//lib:blame-cache",
         "//lib:guava",

java/com/google/gerrit/server/config/GerritGlobalModule.java

@@ -136,6 +136,7 @@ import com.google.gerrit.server.git.validators.UploadValidationListener;
 import com.google.gerrit.server.git.validators.UploadValidators;
 import com.google.gerrit.server.group.db.GroupDbModule;
 import com.google.gerrit.server.index.change.ReindexAfterRefUpdate;
+import com.google.gerrit.server.logging.PerformanceLogger;
 import com.google.gerrit.server.mail.AutoReplyMailFilter;
 import com.google.gerrit.server.mail.EmailModule;
 import com.google.gerrit.server.mail.ListMailFilter;
@@ -380,6 +381,7 @@ public class GerritGlobalModule extends FactoryModule {
     DynamicItem.itemOf(binder(), ProjectNameLockManager.class);
     DynamicSet.setOf(binder(), SubmitRule.class);
     DynamicSet.setOf(binder(), QuotaEnforcer.class);
+    DynamicSet.setOf(binder(), PerformanceLogger.class);
 
     DynamicMap.mapOf(binder(), MailFilter.class);
     bind(MailFilter.class).annotatedWith(Exports.named("ListMailFilter")).to(ListMailFilter.class);

java/com/google/gerrit/server/git/receive/ReceiveCommits.java

@@ -74,6 +74,7 @@ import com.google.gerrit.extensions.api.projects.ProjectConfigEntryType;
 import com.google.gerrit.extensions.client.GeneralPreferencesInfo;
 import com.google.gerrit.extensions.registration.DynamicItem;
 import com.google.gerrit.extensions.registration.DynamicMap;
+import com.google.gerrit.extensions.registration.DynamicSet;
 import com.google.gerrit.extensions.registration.Extension;
 import com.google.gerrit.extensions.restapi.AuthException;
 import com.google.gerrit.extensions.restapi.BadRequestException;
@@ -118,6 +119,8 @@ import com.google.gerrit.server.git.validators.RefOperationValidationException;
 import com.google.gerrit.server.git.validators.RefOperationValidators;
 import com.google.gerrit.server.git.validators.ValidationMessage;
 import com.google.gerrit.server.index.change.ChangeIndexer;
+import com.google.gerrit.server.logging.PerformanceLogContext;
+import com.google.gerrit.server.logging.PerformanceLogger;
 import com.google.gerrit.server.logging.RequestId;
 import com.google.gerrit.server.logging.TraceContext;
 import com.google.gerrit.server.mail.MailUtil.MailRecipients;
@@ -306,6 +309,7 @@ class ReceiveCommits {
   private final MergedByPushOp.Factory mergedByPushOpFactory;
   private final PatchSetInfoFactory patchSetInfoFactory;
   private final PatchSetUtil psUtil;
+  private final DynamicSet<PerformanceLogger> performanceLoggers;
   private final PermissionBackend permissionBackend;
   private final ProjectCache projectCache;
   private final Provider<InternalChangeQuery> queryProvider;
@@ -382,6 +386,7 @@ class ReceiveCommits {
       MergedByPushOp.Factory mergedByPushOpFactory,
       PatchSetInfoFactory patchSetInfoFactory,
       PatchSetUtil psUtil,
+      DynamicSet<PerformanceLogger> performanceLoggers,
       PermissionBackend permissionBackend,
       ProjectCache projectCache,
       Provider<InternalChangeQuery> queryProvider,
@@ -427,6 +432,7 @@ class ReceiveCommits {
     this.pluginConfigEntries = pluginConfigEntries;
     this.projectCache = projectCache;
     this.psUtil = psUtil;
+    this.performanceLoggers = performanceLoggers;
     this.queryProvider = queryProvider;
     this.receiveConfig = receiveConfig;
     this.refValidatorsFactory = refValidatorsFactory;
@@ -525,10 +531,12 @@ class ReceiveCommits {
       Collection<ReceiveCommand> commands, MultiProgressMonitor progress) {
     parsePushOptions();
     try (TraceContext traceContext =
-        TraceContext.newTrace(
+            TraceContext.newTrace(
-            tracePushOption.isPresent(),
+                tracePushOption.isPresent(),
-            tracePushOption.orElse(null),
+                tracePushOption.orElse(null),
-            (tagName, traceId) -> addMessage(tagName + ": " + traceId))) {
+                (tagName, traceId) -> addMessage(tagName + ": " + traceId));
+        PerformanceLogContext performanceLogContext =
+            new PerformanceLogContext(performanceLoggers)) {
       traceContext.addTag(RequestId.Type.RECEIVE_ID, new RequestId(project.getNameKey().get()));
 
       logger.atFinest().log("Calling user: %s", user.getLoggableName());

java/com/google/gerrit/server/logging/BUILD

@@ -6,10 +6,12 @@ java_library(
     visibility = ["//visibility:public"],
     deps = [
         "//java/com/google/gerrit/common:annotations",
+        "//java/com/google/gerrit/extensions:api",
         "//java/com/google/gerrit/server/util/time",
         "//lib:guava",
         "//lib/auto:auto-value",
         "//lib/auto:auto-value-annotations",
         "//lib/flogger:api",
+        "//lib/guice",
     ],
 )

java/com/google/gerrit/server/logging/LoggingContext.java

@@ -14,8 +14,13 @@
 
 package com.google.gerrit.server.logging;
 
+import static java.util.Objects.requireNonNull;
+
+import com.google.common.collect.ImmutableList;
 import com.google.common.collect.ImmutableSetMultimap;
 import com.google.common.flogger.backend.Tags;
+import com.google.inject.Provider;
+import java.util.List;
 import java.util.concurrent.Callable;
 import java.util.logging.Level;
 
@@ -35,6 +40,9 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log
 
   private static final ThreadLocal<MutableTags> tags = new ThreadLocal<>();
   private static final ThreadLocal<Boolean> forceLogging = new ThreadLocal<>();
+  private static final ThreadLocal<Boolean> performanceLogging = new ThreadLocal<>();
+  private static final ThreadLocal<MutablePerformanceLogRecords> performanceLogRecords =
+      new ThreadLocal<>();
 
   private LoggingContext() {}
 
@@ -47,14 +55,28 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log
     if (runnable instanceof LoggingContextAwareRunnable) {
       return runnable;
     }
-    return new LoggingContextAwareRunnable(runnable);
+
+    // Pass the MutablePerformanceLogRecords instance into the LoggingContextAwareRunnable
+    // constructor so that performance log records that are created in the wrapped runnable are
+    // added to this MutablePerformanceLogRecords instance. This is important since performance
+    // log records are processed only at the end of the request and performance log records that
+    // are created in another thread should not get lost.
+    return new LoggingContextAwareRunnable(
+        runnable, getInstance().getMutablePerformanceLogRecords());
   }
 
   public static <T> Callable<T> copy(Callable<T> callable) {
     if (callable instanceof LoggingContextAwareCallable) {
       return callable;
     }
-    return new LoggingContextAwareCallable<>(callable);
+
+    // Pass the MutablePerformanceLogRecords instance into the LoggingContextAwareCallable
+    // constructor so that performance log records that are created in the wrapped runnable are
+    // added to this MutablePerformanceLogRecords instance. This is important since performance
+    // log records are processed only at the end of the request and performance log records that
+    // are created in another thread should not get lost.
+    return new LoggingContextAwareCallable<>(
+        callable, getInstance().getMutablePerformanceLogRecords());
   }
 
   @Override
@@ -120,4 +142,103 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log
     }
     return oldValue != null ? oldValue : false;
   }
+
+  boolean isPerformanceLogging() {
+    Boolean isPerformanceLogging = performanceLogging.get();
+    return isPerformanceLogging != null ? isPerformanceLogging : false;
+  }
+
+  /**
+   * Enables performance logging.
+   *
+   * <p>It's important to enable performance logging only in a context that ensures to consume the
+   * captured performance log records. Otherwise captured performance log records might leak into
+   * other requests that are executed by the same thread (if a thread pool is used to process
+   * requests).
+   *
+   * @param enable whether performance logging should be enabled.
+   * @return whether performance logging was be enabled before invoking this method (old value).
+   */
+  boolean performanceLogging(boolean enable) {
+    Boolean oldValue = performanceLogging.get();
+    if (enable) {
+      performanceLogging.set(true);
+    } else {
+      performanceLogging.remove();
+    }
+    return oldValue != null ? oldValue : false;
+  }
+
+  /**
+   * Adds a performance log record, if performance logging is enabled.
+   *
+   * @param recordProvider Provider for the performance log record. This provider is only invoked if
+   *     performance logging is enabled. This means if performance logging is disabled, we avoid the
+   *     creation of a {@link PerformanceLogRecord}.
+   */
+  public void addPerformanceLogRecord(Provider<PerformanceLogRecord> recordProvider) {
+    if (!isPerformanceLogging()) {
+      // return early and avoid the creation of a PerformanceLogRecord
+      return;
+    }
+
+    getMutablePerformanceLogRecords().add(recordProvider.get());
+  }
+
+  ImmutableList<PerformanceLogRecord> getPerformanceLogRecords() {
+    MutablePerformanceLogRecords records = performanceLogRecords.get();
+    if (records != null) {
+      return records.list();
+    }
+    return ImmutableList.of();
+  }
+
+  void clearPerformanceLogEntries() {
+    performanceLogRecords.remove();
+  }
+
+  /**
+   * Set the performance log records in this logging context. Existing log records are overwritten.
+   *
+   * <p>This method makes a defensive copy of the passed in list.
+   *
+   * @param newPerformanceLogRecords performance log records that should be set
+   */
+  void setPerformanceLogRecords(List<PerformanceLogRecord> newPerformanceLogRecords) {
+    if (newPerformanceLogRecords.isEmpty()) {
+      performanceLogRecords.remove();
+      return;
+    }
+
+    getMutablePerformanceLogRecords().set(newPerformanceLogRecords);
+  }
+
+  /**
+   * Sets a {@link MutablePerformanceLogRecords} instance for storing performance log records.
+   *
+   * <p><strong>Attention:</strong> The passed in {@link MutablePerformanceLogRecords} instance is
+   * directly stored in the logging context.
+   *
+   * <p>This method is intended to be only used when the logging context is copied to a new thread
+   * to ensure that the performance log records that are added in the new thread are added to the
+   * same {@link MutablePerformanceLogRecords} instance (see {@link LoggingContextAwareRunnable} and
+   * {@link LoggingContextAwareCallable}). This is important since performance log records are
+   * processed only at the end of the request and performance log records that are created in
+   * another thread should not get lost.
+   *
+   * @param mutablePerformanceLogRecords the {@link MutablePerformanceLogRecords} instance in which
+   *     performance log records should be stored
+   */
+  void setMutablePerformanceLogRecords(MutablePerformanceLogRecords mutablePerformanceLogRecords) {
+    performanceLogRecords.set(requireNonNull(mutablePerformanceLogRecords));
+  }
+
+  private MutablePerformanceLogRecords getMutablePerformanceLogRecords() {
+    MutablePerformanceLogRecords records = performanceLogRecords.get();
+    if (records == null) {
+      records = new MutablePerformanceLogRecords();
+      performanceLogRecords.set(records);
+    }
+    return records;
+  }
 }

java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java

@@ -14,6 +14,7 @@
 
 package com.google.gerrit.server.logging;
 
+import com.google.common.collect.ImmutableList;
 import com.google.common.collect.ImmutableSetMultimap;
 import java.util.concurrent.Callable;
 
@@ -35,12 +36,24 @@ class LoggingContextAwareCallable<T> implements Callable<T> {
   private final Thread callingThread;
   private final ImmutableSetMultimap<String, String> tags;
   private final boolean forceLogging;
+  private final boolean performanceLogging;
+  private final MutablePerformanceLogRecords mutablePerformanceLogRecords;
 
-  LoggingContextAwareCallable(Callable<T> callable) {
+  /**
+   * Creates a LoggingContextAwareCallable that wraps the given {@link Callable}.
+   *
+   * @param callable Callable that should be wrapped.
+   * @param mutablePerformanceLogRecords instance of {@link MutablePerformanceLogRecords} to which
+   *     performance log records that are created from the runnable are added
+   */
+  LoggingContextAwareCallable(
+      Callable<T> callable, MutablePerformanceLogRecords mutablePerformanceLogRecords) {
     this.callable = callable;
     this.callingThread = Thread.currentThread();
     this.tags = LoggingContext.getInstance().getTagsAsMap();
     this.forceLogging = LoggingContext.getInstance().isLoggingForced();
+    this.performanceLogging = LoggingContext.getInstance().isPerformanceLogging();
+    this.mutablePerformanceLogRecords = mutablePerformanceLogRecords;
   }
 
   @Override
@@ -54,13 +67,27 @@ class LoggingContextAwareCallable<T> implements Callable<T> {
     LoggingContext loggingCtx = LoggingContext.getInstance();
     ImmutableSetMultimap<String, String> oldTags = loggingCtx.getTagsAsMap();
     boolean oldForceLogging = loggingCtx.isLoggingForced();
+    boolean oldPerformanceLogging = loggingCtx.isPerformanceLogging();
+    ImmutableList<PerformanceLogRecord> oldPerformanceLogRecords =
+        loggingCtx.getPerformanceLogRecords();
     loggingCtx.setTags(tags);
     loggingCtx.forceLogging(forceLogging);
+    loggingCtx.performanceLogging(performanceLogging);
+
+    // For the performance log records use the {@link MutablePerformanceLogRecords} instance from
+    // the logging context of the calling thread in the logging context of the new thread. This way
+    // performance log records that are created from the new thread are available from the logging
+    // context of the calling thread. This is important since performance log records are processed
+    // only at the end of the request and performance log records that are created in another thread
+    // should not get lost.
+    loggingCtx.setMutablePerformanceLogRecords(mutablePerformanceLogRecords);
     try {
       return callable.call();
     } finally {
       loggingCtx.setTags(oldTags);
       loggingCtx.forceLogging(oldForceLogging);
+      loggingCtx.performanceLogging(oldPerformanceLogging);
+      loggingCtx.setPerformanceLogRecords(oldPerformanceLogRecords);
     }
   }
 }

java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java

@@ -14,6 +14,7 @@
 
 package com.google.gerrit.server.logging;
 
+import com.google.common.collect.ImmutableList;
 import com.google.common.collect.ImmutableSetMultimap;
 
 /**
@@ -53,12 +54,24 @@ public class LoggingContextAwareRunnable implements Runnable {
   private final Thread callingThread;
   private final ImmutableSetMultimap<String, String> tags;
   private final boolean forceLogging;
+  private final boolean performanceLogging;
+  private final MutablePerformanceLogRecords mutablePerformanceLogRecords;
 
-  LoggingContextAwareRunnable(Runnable runnable) {
+  /**
+   * Creates a LoggingContextAwareRunnable that wraps the given {@link Runnable}.
+   *
+   * @param runnable Runnable that should be wrapped.
+   * @param mutablePerformanceLogRecords instance of {@link MutablePerformanceLogRecords} to which
+   *     performance log records that are created from the runnable are added
+   */
+  LoggingContextAwareRunnable(
+      Runnable runnable, MutablePerformanceLogRecords mutablePerformanceLogRecords) {
     this.runnable = runnable;
     this.callingThread = Thread.currentThread();
     this.tags = LoggingContext.getInstance().getTagsAsMap();
     this.forceLogging = LoggingContext.getInstance().isLoggingForced();
+    this.performanceLogging = LoggingContext.getInstance().isPerformanceLogging();
+    this.mutablePerformanceLogRecords = mutablePerformanceLogRecords;
   }
 
   public Runnable unwrap() {
@@ -77,13 +90,27 @@ public class LoggingContextAwareRunnable implements Runnable {
     LoggingContext loggingCtx = LoggingContext.getInstance();
     ImmutableSetMultimap<String, String> oldTags = loggingCtx.getTagsAsMap();
     boolean oldForceLogging = loggingCtx.isLoggingForced();
+    boolean oldPerformanceLogging = loggingCtx.isPerformanceLogging();
+    ImmutableList<PerformanceLogRecord> oldPerformanceLogRecords =
+        loggingCtx.getPerformanceLogRecords();
     loggingCtx.setTags(tags);
     loggingCtx.forceLogging(forceLogging);
+    loggingCtx.performanceLogging(performanceLogging);
+
+    // For the performance log records use the {@link MutablePerformanceLogRecords} instance from
+    // the logging context of the calling thread in the logging context of the new thread. This way
+    // performance log records that are created from the new thread are available from the logging
+    // context of the calling thread. This is important since performance log records are processed
+    // only at the end of the request and performance log records that are created in another thread
+    // should not get lost.
+    loggingCtx.setMutablePerformanceLogRecords(mutablePerformanceLogRecords);
     try {
       runnable.run();
     } finally {
       loggingCtx.setTags(oldTags);
       loggingCtx.forceLogging(oldForceLogging);
+      loggingCtx.performanceLogging(oldPerformanceLogging);
+      loggingCtx.setPerformanceLogRecords(oldPerformanceLogRecords);
     }
   }
 }

java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java

@@ -0,0 +1,47 @@
+// Copyright (C) 2018 The Android Open Source Project
+//
+// 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.google.gerrit.server.logging;
+
+import com.google.common.collect.ImmutableList;
+import java.util.ArrayList;
+import java.util.List;
+
+/**
+ * Thread-safe store for performance log records.
+ *
+ * <p>This class is intended to keep track of performance log records in {@link LoggingContext}. It
+ * needs to be thread-safe because it gets shared between threads when the logging context is copied
+ * to another thread (see {@link LoggingContextAwareRunnable} and {@link
+ * LoggingContextAwareCallable}. In this case the logging contexts of both threads share the same
+ * instance of this class. This is important since performance log records are processed only at the
+ * end of a request and performance log records that are created in another thread should not get
+ * lost.
+ */
+public class MutablePerformanceLogRecords {
+  private final ArrayList<PerformanceLogRecord> performanceLogRecords = new ArrayList<>();
+
+  public synchronized void add(PerformanceLogRecord record) {
+    performanceLogRecords.add(record);
+  }
+
+  public synchronized void set(List<PerformanceLogRecord> records) {
+    performanceLogRecords.clear();
+    performanceLogRecords.addAll(records);
+  }
+
+  public synchronized ImmutableList<PerformanceLogRecord> list() {
+    return ImmutableList.copyOf(performanceLogRecords);
+  }
+}

java/com/google/gerrit/server/logging/PerformanceLogContext.java

@@ -0,0 +1,111 @@
+// Copyright (C) 2019 The Android Open Source Project
+//
+// 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.google.gerrit.server.logging;
+
+import com.google.common.collect.ImmutableList;
+import com.google.common.collect.Iterables;
+import com.google.common.flogger.FluentLogger;
+import com.google.gerrit.extensions.registration.DynamicSet;
+import com.google.gerrit.extensions.registration.Extension;
+
+/**
+ * Context for capturing performance log records. When the context is closed the performance log
+ * records are handed over to the registered {@link PerformanceLogger}s.
+ *
+ * <p>Capturing performance log records is disabled if there are no {@link PerformanceLogger}
+ * registered (in this case the captured performance log records would never be used).
+ *
+ * <p>It's important to enable capturing of performance log records in a context that ensures to
+ * consume the captured performance log records. Otherwise captured performance log records might
+ * leak into other requests that are executed by the same thread (if a thread pool is used to
+ * process requests).
+ */
+public class PerformanceLogContext implements AutoCloseable {
+  private static final FluentLogger logger = FluentLogger.forEnclosingClass();
+
+  // Do not use PluginSetContext. PluginSetContext traces the plugin latency with a timer metric
+  // which would result in a performance log and we don't want to log the performance of writing
+  // a performance log in the performance log (endless loop).
+  private final DynamicSet<PerformanceLogger> performanceLoggers;
+
+  private final boolean oldPerformanceLogging;
+  private final ImmutableList<PerformanceLogRecord> oldPerformanceLogRecords;
+
+  public PerformanceLogContext(DynamicSet<PerformanceLogger> performanceLoggers) {
+    this.performanceLoggers = performanceLoggers;
+
+    // Just in case remember the old state and reset performance log entries.
+    this.oldPerformanceLogging = LoggingContext.getInstance().isPerformanceLogging();
+    this.oldPerformanceLogRecords = LoggingContext.getInstance().getPerformanceLogRecords();
+    LoggingContext.getInstance().clearPerformanceLogEntries();
+
+    // Do not create performance log entries if no PerformanceLogger is registered.
+    LoggingContext.getInstance()
+        .performanceLogging(!Iterables.isEmpty(performanceLoggers.entries()));
+  }
+
+  @Override
+  public void close() {
+    if (LoggingContext.getInstance().isPerformanceLogging()) {
+      runEach(performanceLoggers, LoggingContext.getInstance().getPerformanceLogRecords());
+    }
+
+    // Restore old state. Required to support nesting of PerformanceLogContext's.
+    LoggingContext.getInstance().performanceLogging(oldPerformanceLogging);
+    LoggingContext.getInstance().setPerformanceLogRecords(oldPerformanceLogRecords);
+  }
+
+  /**
+   * Invokes all performance loggers.
+   *
+   * <p>Similar to how {@code com.google.gerrit.server.plugincontext.PluginContext} invokes plugins
+   * but without recording metrics for invoking {@link PerformanceLogger}s.
+   *
+   * @param performanceLoggers the performance loggers that should be invoked
+   * @param performanceLogRecords the performance log records that should be handed over to the
+   *     performance loggers
+   */
+  private static void runEach(
+      DynamicSet<PerformanceLogger> performanceLoggers,
+      ImmutableList<PerformanceLogRecord> performanceLogRecords) {
+    performanceLoggers
+        .entries()
+        .forEach(
+            p -> {
+              try (TraceContext traceContext = newPluginTrace(p)) {
+                performanceLogRecords.forEach(r -> r.writeTo(p.get()));
+              } catch (Throwable e) {
+                logger.atWarning().withCause(e).log(
+                    "Failure in %s of plugin %s", p.get().getClass(), p.getPluginName());
+              }
+            });
+  }
+
+  /**
+   * Opens a trace context for a plugin that implements {@link PerformanceLogger}.
+   *
+   * <p>Basically the same as {@code
+   * com.google.gerrit.server.plugincontext.PluginContext#newTrace(Extension<T>)}. We have this
+   * method here to avoid a dependency on PluginContext which lives in
+   * "//java/com/google/gerrit/server". This package ("//java/com/google/gerrit/server/logging")
+   * should have as few dependencies as possible.
+   *
+   * @param extension performance logger extension
+   * @return the trace context
+   */
+  private static TraceContext newPluginTrace(Extension<PerformanceLogger> extension) {
+    return TraceContext.open().addPluginTag(extension.getPluginName());
+  }
+}

java/com/google/gerrit/server/logging/PerformanceLogRecord.java

@@ -0,0 +1,220 @@
+// Copyright (C) 2019 The Android Open Source Project
+//
+// 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.google.gerrit.server.logging;
+
+import static java.util.Objects.requireNonNull;
+
+import com.google.auto.value.AutoValue;
+import com.google.gerrit.common.Nullable;
+
+/**
+ * The record of an operation for which the execution time was measured.
+ *
+ * <p>Meta data is stored in separate key/value fields to avoid expensive instantiations of Map
+ * objects.
+ */
+@AutoValue
+public abstract class PerformanceLogRecord {
+  /**
+   * Creates a performance log record without meta data.
+   *
+   * @param operation the name of operation the is was performed
+   * @param durationMs the execution time in milliseconds
+   * @return the performance log record
+   */
+  public static PerformanceLogRecord create(String operation, long durationMs) {
+    return new AutoValue_PerformanceLogRecord(
+        operation, durationMs, null, null, null, null, null, null, null, null);
+  }
+
+  /**
+   * Creates a performance log record with meta data.
+   *
+   * @param operation the name of operation the is was performed
+   * @param durationMs the execution time in milliseconds
+   * @param key meta data key
+   * @param value meta data value
+   * @return the performance log record
+   */
+  public static PerformanceLogRecord create(
+      String operation, long durationMs, String key, @Nullable Object value) {
+    return new AutoValue_PerformanceLogRecord(
+        operation, durationMs, requireNonNull(key), value, null, null, null, null, null, null);
+  }
+
+  /**
+   * Creates a performance log record with meta data.
+   *
+   * @param operation the name of operation the is was performed
+   * @param durationMs the execution time in milliseconds
+   * @param key1 first meta data key
+   * @param value1 first meta data value
+   * @param key2 second meta data key
+   * @param value2 second meta data value
+   * @return the performance log record
+   */
+  public static PerformanceLogRecord create(
+      String operation,
+      long durationMs,
+      String key1,
+      @Nullable Object value1,
+      String key2,
+      @Nullable Object value2) {
+    return new AutoValue_PerformanceLogRecord(
+        operation,
+        durationMs,
+        requireNonNull(key1),
+        value1,
+        requireNonNull(key2),
+        value2,
+        null,
+        null,
+        null,
+        null);
+  }
+
+  /**
+   * Creates a performance log record with meta data.
+   *
+   * @param operation the name of operation the is was performed
+   * @param durationMs the execution time in milliseconds
+   * @param key1 first meta data key
+   * @param value1 first meta data value
+   * @param key2 second meta data key
+   * @param value2 second meta data value
+   * @param key3 third meta data key
+   * @param value3 third meta data value
+   * @return the performance log record
+   */
+  public static PerformanceLogRecord create(
+      String operation,
+      long durationMs,
+      String key1,
+      @Nullable Object value1,
+      String key2,
+      @Nullable Object value2,
+      String key3,
+      @Nullable Object value3) {
+    return new AutoValue_PerformanceLogRecord(
+        operation,
+        durationMs,
+        requireNonNull(key1),
+        value1,
+        requireNonNull(key2),
+        value2,
+        requireNonNull(key3),
+        value3,
+        null,
+        null);
+  }
+
+  /**
+   * Creates a performance log record with meta data.
+   *
+   * @param operation the name of operation the is was performed
+   * @param durationMs the execution time in milliseconds
+   * @param key1 first meta data key
+   * @param value1 first meta data value
+   * @param key2 second meta data key
+   * @param value2 second meta data value
+   * @param key3 third meta data key
+   * @param value3 third meta data value
+   * @param key4 forth meta data key
+   * @param value4 forth meta data value
+   * @return the performance log record
+   */
+  public static PerformanceLogRecord create(
+      String operation,
+      long durationMs,
+      String key1,
+      @Nullable Object value1,
+      String key2,
+      @Nullable Object value2,
+      String key3,
+      @Nullable Object value3,
+      String key4,
+      @Nullable Object value4) {
+    return new AutoValue_PerformanceLogRecord(
+        operation,
+        durationMs,
+        requireNonNull(key1),
+        value1,
+        requireNonNull(key2),
+        value2,
+        requireNonNull(key3),
+        value3,
+        requireNonNull(key4),
+        value4);
+  }
+
+  public abstract String operation();
+
+  public abstract long durationMs();
+
+  @Nullable
+  public abstract String key1();
+
+  @Nullable
+  public abstract Object value1();
+
+  @Nullable
+  public abstract String key2();
+
+  @Nullable
+  public abstract Object value2();
+
+  @Nullable
+  public abstract String key3();
+
+  @Nullable
+  public abstract Object value3();
+
+  @Nullable
+  public abstract String key4();
+
+  @Nullable
+  public abstract Object value4();
+
+  void writeTo(PerformanceLogger performanceLogger) {
+    if (key4() != null) {
+      requireNonNull(key1());
+      requireNonNull(key2());
+      requireNonNull(key3());
+      performanceLogger.log(
+          operation(),
+          durationMs(),
+          key1(),
+          value1(),
+          key2(),
+          value2(),
+          key3(),
+          value3(),
+          key4(),
+          value4());
+    } else if (key3() != null) {
+      requireNonNull(key1());
+      requireNonNull(key2());
+      performanceLogger.log(
+          operation(), durationMs(), key1(), value1(), key2(), value2(), key3(), value3());
+    } else if (key2() != null) {
+      requireNonNull(key1());
+      performanceLogger.log(operation(), durationMs(), key1(), value1(), key2(), value2());
+    } else if (key1() != null) {
+      performanceLogger.log(operation(), durationMs(), key1(), value1());
+    } else {
+      performanceLogger.log(operation(), durationMs());
+    }
+  }
+}

java/com/google/gerrit/server/logging/PerformanceLogger.java

@@ -0,0 +1,164 @@
+// Copyright (C) 2019 The Android Open Source Project
+//
+// 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.google.gerrit.server.logging;
+
+import com.google.common.collect.ImmutableMap;
+import com.google.gerrit.common.Nullable;
+import com.google.gerrit.extensions.annotations.ExtensionPoint;
+import java.util.Map;
+import java.util.Optional;
+
+/**
+ * Extension point for logging performance records.
+ *
+ * <p>This extension point is invoked for all operations for which the execution time is measured.
+ * The invocation of the extension point does not happen immediately, but only at the end of a
+ * request (REST call, SSH call, git push). Implementors can write the execution times into a
+ * performance log for further analysis.
+ *
+ * <p>For optimal performance implementors should overwrite the default <code>log</code> methods to
+ * avoid unneeded instantiation of Map objects.
+ */
+@ExtensionPoint
+public interface PerformanceLogger {
+  /**
+   * Record the execution time of an operation in a performance log.
+   *
+   * @param operation operation that was performed
+   * @param durationMs time that the execution of the operation took (in milliseconds)
+   */
+  default void log(String operation, long durationMs) {
+    log(operation, durationMs, ImmutableMap.of());
+  }
+
+  /**
+   * Record the execution time of an operation in a performance log.
+   *
+   * @param operation operation that was performed
+   * @param durationMs time that the execution of the operation took (in milliseconds)
+   * @param key meta data key
+   * @param value meta data value
+   */
+  default void log(String operation, long durationMs, String key, @Nullable Object value) {
+    log(operation, durationMs, ImmutableMap.of(key, Optional.ofNullable(value)));
+  }
+
+  /**
+   * Record the execution time of an operation in a performance log.
+   *
+   * @param operation operation that was performed
+   * @param durationMs time that the execution of the operation took (in milliseconds)
+   * @param key1 first meta data key
+   * @param value1 first meta data value
+   * @param key2 second meta data key
+   * @param value2 second meta data value
+   */
+  default void log(
+      String operation,
+      long durationMs,
+      String key1,
+      @Nullable Object value1,
+      String key2,
+      @Nullable Object value2) {
+    log(
+        operation,
+        durationMs,
+        ImmutableMap.of(key1, Optional.ofNullable(value1), key2, Optional.ofNullable(value2)));
+  }
+
+  /**
+   * Record the execution time of an operation in a performance log.
+   *
+   * @param operation operation that was performed
+   * @param durationMs time that the execution of the operation took (in milliseconds)
+   * @param key1 first meta data key
+   * @param value1 first meta data value
+   * @param key2 second meta data key
+   * @param value2 second meta data value
+   * @param key3 third meta data key
+   * @param value3 third meta data value
+   */
+  default void log(
+      String operation,
+      long durationMs,
+      String key1,
+      @Nullable Object value1,
+      String key2,
+      @Nullable Object value2,
+      String key3,
+      @Nullable Object value3) {
+    log(
+        operation,
+        durationMs,
+        ImmutableMap.of(
+            key1,
+            Optional.ofNullable(value1),
+            key2,
+            Optional.ofNullable(value2),
+            key3,
+            Optional.ofNullable(value3)));
+  }
+
+  /**
+   * Record the execution time of an operation in a performance log.
+   *
+   * @param operation operation that was performed
+   * @param durationMs time that the execution of the operation took (in milliseconds)
+   * @param key1 first meta data key
+   * @param value1 first meta data value
+   * @param key2 second meta data key
+   * @param value2 second meta data value
+   * @param key3 third meta data key
+   * @param value3 third meta data value
+   * @param key4 fourth meta data key
+   * @param value4 fourth meta data value
+   */
+  default void log(
+      String operation,
+      long durationMs,
+      String key1,
+      @Nullable Object value1,
+      String key2,
+      @Nullable Object value2,
+      String key3,
+      @Nullable Object value3,
+      String key4,
+      @Nullable Object value4) {
+    log(
+        operation,
+        durationMs,
+        ImmutableMap.of(
+            key1,
+            Optional.ofNullable(value1),
+            key2,
+            Optional.ofNullable(value2),
+            key3,
+            Optional.ofNullable(value3),
+            key4,
+            Optional.ofNullable(value4)));
+  }
+
+  /**
+   * Record the execution time of an operation in a performance log.
+   *
+   * <p>For small numbers of meta data entries the instantiation of a map should avoided by using
+   * one of the <code>log</code> methods that allows to pass in meta data entries directly.
+   *
+   * @param operation operation that was performed
+   * @param durationMs time that the execution of the operation took (in milliseconds)
+   * @param metaData key-value map with meta data
+   */
+  void log(String operation, long durationMs, Map<String, Optional<Object>> metaData);
+}

java/com/google/gerrit/server/logging/TraceContext.java

@@ -155,35 +155,32 @@ public class TraceContext implements AutoCloseable {
   /**
    * Opens a new timer that logs the time for an operation if request tracing is enabled.
    *
-   * <p>If request tracing is not enabled this is a no-op.
+   * @param operation the name of operation the is being performed
-   *
-   * @param message the message
    * @return the trace timer
    */
-  public static TraceTimer newTimer(String message) {
+  public static TraceTimer newTimer(String operation) {
-    return new TraceTimer(message);
+    return new TraceTimer(requireNonNull(operation, "operation is required"));
   }
 
   /**
    * Opens a new timer that logs the time for an operation if request tracing is enabled.
    *
-   * <p>If request tracing is not enabled this is a no-op.
+   * @param operation the name of operation the is being performed
-   *
-   * @param message the message
    * @param key meta data key
    * @param value meta data value
    * @return the trace timer
    */
-  public static TraceTimer newTimer(String message, String key, Object value) {
+  public static TraceTimer newTimer(String operation, String key, @Nullable Object value) {
-    return new TraceTimer(message + " (%s=%s)", key, value);
+    return new TraceTimer(
+        requireNonNull(operation, "operation is required"),
+        requireNonNull(key, "key is required"),
+        value);
   }
 
   /**
    * Opens a new timer that logs the time for an operation if request tracing is enabled.
    *
-   * <p>If request tracing is not enabled this is a no-op.
+   * @param operation the name of operation the is being performed
-   *
-   * @param message the message
    * @param key1 first meta data key
    * @param value1 first meta data value
    * @param key2 second meta data key
@@ -191,16 +188,23 @@ public class TraceContext implements AutoCloseable {
    * @return the trace timer
    */
   public static TraceTimer newTimer(
-      String message, String key1, Object value1, String key2, Object value2) {
+      String operation,
-    return new TraceTimer(message + " (%s=%s, %s=%s)", key1, value1, key2, value2);
+      String key1,
+      @Nullable Object value1,
+      String key2,
+      @Nullable Object value2) {
+    return new TraceTimer(
+        requireNonNull(operation, "operation is required"),
+        requireNonNull(key1, "key1 is required"),
+        value1,
+        requireNonNull(key2, "key2 is required"),
+        value2);
   }
 
   /**
    * Opens a new timer that logs the time for an operation if request tracing is enabled.
    *
-   * <p>If request tracing is not enabled this is a no-op.
+   * @param operation the name of operation the is being performed
-   *
-   * @param message the message
    * @param key1 first meta data key
    * @param value1 first meta data value
    * @param key2 second meta data key
@@ -210,23 +214,27 @@ public class TraceContext implements AutoCloseable {
    * @return the trace timer
    */
   public static TraceTimer newTimer(
-      String message,
+      String operation,
       String key1,
-      Object value1,
+      @Nullable Object value1,
       String key2,
-      Object value2,
+      @Nullable Object value2,
       String key3,
-      Object value3) {
+      @Nullable Object value3) {
     return new TraceTimer(
-        message + " (%s=%s, %s=%s, %s=%s)", key1, value1, key2, value2, key3, value3);
+        requireNonNull(operation, "operation is required"),
+        requireNonNull(key1, "key1 is required"),
+        value1,
+        requireNonNull(key2, "key2 is required"),
+        value2,
+        requireNonNull(key3, "key3 is required"),
+        value3);
   }
 
   /**
    * Opens a new timer that logs the time for an operation if request tracing is enabled.
    *
-   * <p>If request tracing is not enabled this is a no-op.
+   * @param operation the name of operation the is being performed
-   *
-   * @param message the message
    * @param key1 first meta data key
    * @param value1 first meta data value
    * @param key2 second meta data key
@@ -238,24 +246,24 @@ public class TraceContext implements AutoCloseable {
    * @return the trace timer
    */
   public static TraceTimer newTimer(
-      String message,
+      String operation,
       String key1,
-      Object value1,
+      @Nullable Object value1,
       String key2,
-      Object value2,
+      @Nullable Object value2,
       String key3,
-      Object value3,
+      @Nullable Object value3,
       String key4,
-      Object value4) {
+      @Nullable Object value4) {
     return new TraceTimer(
-        message + " (%s=%s, %s=%s, %s=%s, %s=%s)",
+        requireNonNull(operation, "operation is required"),
-        key1,
+        requireNonNull(key1, "key1 is required"),
         value1,
-        key2,
+        requireNonNull(key2, "key2 is required"),
         value2,
-        key3,
+        requireNonNull(key3, "key3 is required"),
         value3,
-        key4,
+        requireNonNull(key4, "key4 is required"),
         value4);
   }
 
@@ -265,52 +273,86 @@ public class TraceContext implements AutoCloseable {
     private final Consumer<Long> logFn;
     private final Stopwatch stopwatch;
 
-    private TraceTimer(String message) {
+    private TraceTimer(String operation) {
-      this(elapsedMs -> logger.atFine().log(message + " (%d ms)", elapsedMs));
+      this(
+          elapsedMs -> {
+            LoggingContext.getInstance()
+                .addPerformanceLogRecord(() -> PerformanceLogRecord.create(operation, elapsedMs));
+            logger.atFine().log("%s (%d ms)", operation, elapsedMs);
+          });
     }
 
-    private TraceTimer(String format, @Nullable Object arg1, @Nullable Object arg2) {
+    private TraceTimer(String operation, String key, @Nullable Object value) {
-      this(elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, elapsedMs));
+      this(
+          elapsedMs -> {
+            LoggingContext.getInstance()
+                .addPerformanceLogRecord(
+                    () -> PerformanceLogRecord.create(operation, elapsedMs, key, value));
+            logger.atFine().log("%s (%s=%s) (%d ms)", operation, key, value, elapsedMs);
+          });
     }
 
     private TraceTimer(
-        String format,
+        String operation,
-        @Nullable Object arg1,
+        String key1,
-        @Nullable Object arg2,
+        @Nullable Object value1,
-        @Nullable Object arg3,
+        String key2,
-        @Nullable Object arg4) {
+        @Nullable Object value2) {
       this(
-          elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, arg3, arg4, elapsedMs));
+          elapsedMs -> {
+            LoggingContext.getInstance()
+                .addPerformanceLogRecord(
+                    () ->
+                        PerformanceLogRecord.create(
+                            operation, elapsedMs, key1, value1, key2, value2));
+            logger.atFine().log(
+                "%s (%s=%s, %s=%s) (%d ms)", operation, key1, value1, key2, value2, elapsedMs);
+          });
     }
 
     private TraceTimer(
-        String format,
+        String operation,
-        @Nullable Object arg1,
+        String key1,
-        @Nullable Object arg2,
+        @Nullable Object value1,
-        @Nullable Object arg3,
+        String key2,
-        @Nullable Object arg4,
+        @Nullable Object value2,
-        @Nullable Object arg5,
+        String key3,
-        @Nullable Object arg6) {
+        @Nullable Object value3) {
       this(
-          elapsedMs ->
+          elapsedMs -> {
-              logger.atFine().log(
+            LoggingContext.getInstance()
-                  format + " (%d ms)", arg1, arg2, arg3, arg4, arg5, arg6, elapsedMs));
+                .addPerformanceLogRecord(
+                    () ->
+                        PerformanceLogRecord.create(
+                            operation, elapsedMs, key1, value1, key2, value2, key3, value3));
+            logger.atFine().log(
+                "%s (%s=%s, %s=%s, %s=%s) (%d ms)",
+                operation, key1, value1, key2, value2, key3, value3, elapsedMs);
+          });
     }
 
     private TraceTimer(
-        String format,
+        String operation,
-        @Nullable Object arg1,
+        String key1,
-        @Nullable Object arg2,
+        @Nullable Object value1,
-        @Nullable Object arg3,
+        String key2,
-        @Nullable Object arg4,
+        @Nullable Object value2,
-        @Nullable Object arg5,
+        String key3,
-        @Nullable Object arg6,
+        @Nullable Object value3,
-        @Nullable Object arg7,
+        String key4,
-        @Nullable Object arg8) {
+        @Nullable Object value4) {
       this(
-          elapsedMs ->
+          elapsedMs -> {
-              logger.atFine().log(
+            LoggingContext.getInstance()
-                  format + " (%d ms)", arg1, arg2, arg3, arg4, arg5, arg6, arg7, arg8, elapsedMs));
+                .addPerformanceLogRecord(
+                    () ->
+                        PerformanceLogRecord.create(
+                            operation, elapsedMs, key1, value1, key2, value2, key3, value3, key4,
+                            value4));
+            logger.atFine().log(
+                "%s (%s=%s, %s=%s, %s=%s, %s=%s) (%d ms)",
+                operation, key1, value1, key2, value2, key3, value3, key4, value4, elapsedMs);
+          });
     }
 
     private TraceTimer(Consumer<Long> logFn) {

java/com/google/gerrit/sshd/SshCommand.java

@@ -14,14 +14,20 @@
 
 package com.google.gerrit.sshd;
 
+import com.google.gerrit.extensions.registration.DynamicSet;
 import com.google.gerrit.server.AccessPath;
+import com.google.gerrit.server.logging.PerformanceLogContext;
+import com.google.gerrit.server.logging.PerformanceLogger;
 import com.google.gerrit.server.logging.TraceContext;
+import com.google.inject.Inject;
 import java.io.IOException;
 import java.io.PrintWriter;
 import org.apache.sshd.server.Environment;
 import org.kohsuke.args4j.Option;
 
 public abstract class SshCommand extends BaseCommand {
+  @Inject private DynamicSet<PerformanceLogger> performanceLoggers;
+
   @Option(name = "--trace", usage = "enable request tracing")
   private boolean trace;
 
@@ -38,7 +44,9 @@ public abstract class SshCommand extends BaseCommand {
           parseCommandLine();
           stdout = toPrintWriter(out);
           stderr = toPrintWriter(err);
-          try (TraceContext traceContext = enableTracing()) {
+          try (TraceContext traceContext = enableTracing();
+              PerformanceLogContext performanceLogContext =
+                  new PerformanceLogContext(performanceLoggers)) {
             SshCommand.this.run();
           } finally {
             stdout.flush();

javatests/com/google/gerrit/acceptance/rest/TraceIT.java

@@ -17,7 +17,9 @@ package com.google.gerrit.acceptance.rest;
 import static com.google.common.truth.Truth.assertThat;
 import static org.apache.http.HttpStatus.SC_CREATED;
 
+import com.google.auto.value.AutoValue;
 import com.google.common.collect.ImmutableList;
+import com.google.common.collect.ImmutableMap;
 import com.google.common.collect.ImmutableSet;
 import com.google.common.collect.Iterables;
 import com.google.common.truth.Expect;
@@ -34,12 +36,16 @@ import com.google.gerrit.server.git.validators.CommitValidationException;
 import com.google.gerrit.server.git.validators.CommitValidationListener;
 import com.google.gerrit.server.git.validators.CommitValidationMessage;
 import com.google.gerrit.server.logging.LoggingContext;
+import com.google.gerrit.server.logging.PerformanceLogger;
 import com.google.gerrit.server.logging.TraceContext;
 import com.google.gerrit.server.project.CreateProjectArgs;
 import com.google.gerrit.server.validators.ProjectCreationValidationListener;
 import com.google.gerrit.server.validators.ValidationException;
 import com.google.inject.Inject;
+import java.util.ArrayList;
 import java.util.List;
+import java.util.Map;
+import java.util.Optional;
 import java.util.SortedMap;
 import java.util.SortedSet;
 import org.apache.http.message.BasicHeader;
@@ -53,12 +59,15 @@ public class TraceIT extends AbstractDaemonTest {
 
   @Inject private DynamicSet<ProjectCreationValidationListener> projectCreationValidationListeners;
   @Inject private DynamicSet<CommitValidationListener> commitValidationListeners;
+  @Inject private DynamicSet<PerformanceLogger> performanceLoggers;
   @Inject private WorkQueue workQueue;
 
   private TraceValidatingProjectCreationValidationListener projectCreationListener;
   private RegistrationHandle projectCreationListenerRegistrationHandle;
   private TraceValidatingCommitValidationListener commitValidationListener;
   private RegistrationHandle commitValidationRegistrationHandle;
+  private TestPerformanceLogger testPerformanceLogger;
+  private RegistrationHandle performanceLoggerRegistrationHandle;
 
   @Before
   public void setup() {
@@ -68,12 +77,15 @@ public class TraceIT extends AbstractDaemonTest {
     commitValidationListener = new TraceValidatingCommitValidationListener();
     commitValidationRegistrationHandle =
         commitValidationListeners.add("gerrit", commitValidationListener);
+    testPerformanceLogger = new TestPerformanceLogger();
+    performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger);
   }
 
   @After
   public void cleanup() {
     projectCreationListenerRegistrationHandle.remove();
     commitValidationRegistrationHandle.remove();
+    performanceLoggerRegistrationHandle.remove();
   }
 
   @Test
@@ -263,6 +275,25 @@ public class TraceIT extends AbstractDaemonTest {
     assertForceLogging(false);
   }
 
+  @Test
+  public void performanceLoggingForRestCall() throws Exception {
+    RestResponse response = adminRestSession.put("/projects/new10");
+    assertThat(response.getStatusCode()).isEqualTo(SC_CREATED);
+
+    // This assertion assumes that the server invokes the PerformanceLogger plugins before it sends
+    // the response to the client. If this assertion gets flaky it's likely that this got changed on
+    // server-side.
+    assertThat(testPerformanceLogger.logEntries()).isNotEmpty();
+  }
+
+  @Test
+  public void performanceLoggingForPush() throws Exception {
+    PushOneCommit push = pushFactory.create(admin.newIdent(), testRepo);
+    PushOneCommit.Result r = push.to("refs/heads/master");
+    r.assertOkStatus();
+    assertThat(testPerformanceLogger.logEntries()).isNotEmpty();
+  }
+
   private void assertForceLogging(boolean expected) {
     assertThat(LoggingContext.getInstance().shouldForceLogging(null, null, false))
         .isEqualTo(expected);
@@ -296,4 +327,28 @@ public class TraceIT extends AbstractDaemonTest {
       return ImmutableList.of();
     }
   }
+
+  private static class TestPerformanceLogger implements PerformanceLogger {
+    private List<PerformanceLogEntry> logEntries = new ArrayList<>();
+
+    @Override
+    public void log(String operation, long durationMs, Map<String, Optional<Object>> metaData) {
+      logEntries.add(PerformanceLogEntry.create(operation, metaData));
+    }
+
+    ImmutableList<PerformanceLogEntry> logEntries() {
+      return ImmutableList.copyOf(logEntries);
+    }
+  }
+
+  @AutoValue
+  abstract static class PerformanceLogEntry {
+    static PerformanceLogEntry create(String operation, Map<String, Optional<Object>> metaData) {
+      return new AutoValue_TraceIT_PerformanceLogEntry(operation, ImmutableMap.copyOf(metaData));
+    }
+
+    abstract String operation();
+
+    abstract ImmutableMap<String, Object> metaData();
+  }
 }

javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java

@@ -16,17 +16,25 @@ package com.google.gerrit.acceptance.ssh;
 
 import static com.google.common.truth.Truth.assertThat;
 
+import com.google.auto.value.AutoValue;
+import com.google.common.collect.ImmutableList;
+import com.google.common.collect.ImmutableMap;
 import com.google.common.collect.Iterables;
 import com.google.gerrit.acceptance.AbstractDaemonTest;
 import com.google.gerrit.acceptance.UseSsh;
 import com.google.gerrit.extensions.registration.DynamicSet;
 import com.google.gerrit.extensions.registration.RegistrationHandle;
 import com.google.gerrit.server.logging.LoggingContext;
+import com.google.gerrit.server.logging.PerformanceLogger;
 import com.google.gerrit.server.logging.RequestId;
 import com.google.gerrit.server.project.CreateProjectArgs;
 import com.google.gerrit.server.validators.ProjectCreationValidationListener;
 import com.google.gerrit.server.validators.ValidationException;
 import com.google.inject.Inject;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.Map;
+import java.util.Optional;
 import org.junit.After;
 import org.junit.Before;
 import org.junit.Test;
@@ -34,20 +42,26 @@ import org.junit.Test;
 @UseSsh
 public class SshTraceIT extends AbstractDaemonTest {
   @Inject private DynamicSet<ProjectCreationValidationListener> projectCreationValidationListeners;
+  @Inject private DynamicSet<PerformanceLogger> performanceLoggers;
 
   private TraceValidatingProjectCreationValidationListener projectCreationListener;
   private RegistrationHandle projectCreationListenerRegistrationHandle;
+  private TestPerformanceLogger testPerformanceLogger;
+  private RegistrationHandle performanceLoggerRegistrationHandle;
 
   @Before
   public void setup() {
     projectCreationListener = new TraceValidatingProjectCreationValidationListener();
     projectCreationListenerRegistrationHandle =
         projectCreationValidationListeners.add("gerrit", projectCreationListener);
+    testPerformanceLogger = new TestPerformanceLogger();
+    performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger);
   }
 
   @After
   public void cleanup() {
     projectCreationListenerRegistrationHandle.remove();
+    performanceLoggerRegistrationHandle.remove();
   }
 
   @Test
@@ -85,10 +99,17 @@ public class SshTraceIT extends AbstractDaemonTest {
 
   @Test
   public void sshCallWithTraceIdAndWithoutTraceFails() throws Exception {
-    adminSshSession.exec("gerrit create-project --trace-id issue/123 new3");
+    adminSshSession.exec("gerrit create-project --trace-id issue/123 new4");
     adminSshSession.assertFailure("A trace ID can only be set if --trace was specified.");
   }
 
+  @Test
+  public void performanceLoggingForSshCall() throws Exception {
+    adminSshSession.exec("gerrit create-project new5");
+    adminSshSession.assertSuccess();
+    assertThat(testPerformanceLogger.logEntries()).isNotEmpty();
+  }
+
   private static class TraceValidatingProjectCreationValidationListener
       implements ProjectCreationValidationListener {
     String traceId;
@@ -103,4 +124,28 @@ public class SshTraceIT extends AbstractDaemonTest {
       this.isLoggingForced = LoggingContext.getInstance().shouldForceLogging(null, null, false);
     }
   }
+
+  private static class TestPerformanceLogger implements PerformanceLogger {
+    private List<PerformanceLogEntry> logEntries = new ArrayList<>();
+
+    @Override
+    public void log(String operation, long durationMs, Map<String, Optional<Object>> metaData) {
+      logEntries.add(PerformanceLogEntry.create(operation, metaData));
+    }
+
+    ImmutableList<PerformanceLogEntry> logEntries() {
+      return ImmutableList.copyOf(logEntries);
+    }
+  }
+
+  @AutoValue
+  abstract static class PerformanceLogEntry {
+    static PerformanceLogEntry create(String operation, Map<String, Optional<Object>> metaData) {
+      return new AutoValue_SshTraceIT_PerformanceLogEntry(operation, ImmutableMap.copyOf(metaData));
+    }
+
+    abstract String operation();
+
+    abstract ImmutableMap<String, Object> metaData();
+  }
 }

javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java

@@ -17,25 +17,71 @@ package com.google.gerrit.server.logging;
 import static com.google.common.truth.Truth.assertThat;
 
 import com.google.common.truth.Expect;
+import com.google.gerrit.extensions.registration.DynamicSet;
+import com.google.gerrit.extensions.registration.RegistrationHandle;
+import com.google.gerrit.testing.InMemoryModule;
+import com.google.inject.Guice;
+import com.google.inject.Inject;
+import com.google.inject.Injector;
+import java.util.Map;
+import java.util.Optional;
 import java.util.SortedMap;
 import java.util.SortedSet;
 import java.util.concurrent.ExecutorService;
 import java.util.concurrent.Executors;
+import org.junit.After;
+import org.junit.Before;
 import org.junit.Rule;
 import org.junit.Test;
 
 public class LoggingContextAwareExecutorServiceTest {
   @Rule public final Expect expect = Expect.create();
 
+  @Inject private DynamicSet<PerformanceLogger> performanceLoggers;
+
+  private PerformanceLogger testPerformanceLogger;
+  private RegistrationHandle performanceLoggerRegistrationHandle;
+
+  @Before
+  public void setup() {
+    Injector injector = Guice.createInjector(new InMemoryModule());
+    injector.injectMembers(this);
+
+    testPerformanceLogger =
+        new PerformanceLogger() {
+          @Override
+          public void log(
+              String operation, long durationMs, Map<String, Optional<Object>> metaData) {
+            // do nothing
+          }
+        };
+    performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger);
+  }
+
+  @After
+  public void cleanup() {
+    performanceLoggerRegistrationHandle.remove();
+  }
+
   @Test
   public void loggingContextPropagationToBackgroundThread() throws Exception {
     assertThat(LoggingContext.getInstance().getTags().isEmpty()).isTrue();
     assertForceLogging(false);
-    try (TraceContext traceContext = TraceContext.open().forceLogging().addTag("foo", "bar")) {
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+    try (TraceContext traceContext = TraceContext.open().forceLogging().addTag("foo", "bar");
+        PerformanceLogContext performanceLogContext =
+            new PerformanceLogContext(performanceLoggers)) {
+      // Create a performance log record.
+      TraceContext.newTimer("test").close();
+
       SortedMap<String, SortedSet<Object>> tagMap = LoggingContext.getInstance().getTags().asMap();
       assertThat(tagMap.keySet()).containsExactly("foo");
       assertThat(tagMap.get("foo")).containsExactly("bar");
       assertForceLogging(true);
+      assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+      assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1);
 
       ExecutorService executor =
           new LoggingContextAwareExecutorService(Executors.newFixedThreadPool(1));
@@ -51,17 +97,32 @@ public class LoggingContextAwareExecutorServiceTest {
                 expect
                     .that(LoggingContext.getInstance().shouldForceLogging(null, null, false))
                     .isTrue();
+                expect.that(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+                expect.that(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1);
+
+                // Create another performance log record. We expect this to be visible in the outer
+                // thread.
+                TraceContext.newTimer("test2").close();
+                expect.that(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(2);
               })
           .get();
 
-      // Verify that tags and force logging flag in the outer thread are still set.
+      // Verify that logging context values in the outer thread are still set.
       tagMap = LoggingContext.getInstance().getTags().asMap();
       assertThat(tagMap.keySet()).containsExactly("foo");
       assertThat(tagMap.get("foo")).containsExactly("bar");
       assertForceLogging(true);
+      assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+      // The performance log record that was added in the inner thread is available in addition to
+      // the performance log record that was created in the outer thread.
+      assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(2);
     }
+
     assertThat(LoggingContext.getInstance().getTags().isEmpty()).isTrue();
     assertForceLogging(false);
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
   }
 
   private void assertForceLogging(boolean expected) {

javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java

@@ -0,0 +1,467 @@
+// Copyright (C) 2019 The Android Open Source Project
+//
+// 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.google.gerrit.server.logging;
+
+import static com.google.common.truth.Truth.assertThat;
+
+import com.google.auto.value.AutoValue;
+import com.google.common.collect.ImmutableList;
+import com.google.common.collect.ImmutableMap;
+import com.google.gerrit.extensions.registration.DynamicSet;
+import com.google.gerrit.extensions.registration.RegistrationHandle;
+import com.google.gerrit.metrics.Description;
+import com.google.gerrit.metrics.Field;
+import com.google.gerrit.metrics.MetricMaker;
+import com.google.gerrit.metrics.Timer0;
+import com.google.gerrit.metrics.Timer1;
+import com.google.gerrit.metrics.Timer2;
+import com.google.gerrit.metrics.Timer3;
+import com.google.gerrit.testing.InMemoryModule;
+import com.google.inject.Guice;
+import com.google.inject.Inject;
+import com.google.inject.Injector;
+import java.util.ArrayList;
+import java.util.List;
+import java.util.Map;
+import java.util.Optional;
+import org.junit.After;
+import org.junit.Before;
+import org.junit.Test;
+
+public class PerformanceLogContextTest {
+  @Inject private DynamicSet<PerformanceLogger> performanceLoggers;
+
+  // In this test setup this gets the DisabledMetricMaker injected. This means it doesn't record any
+  // metric, but performance log records are still created.
+  @Inject private MetricMaker metricMaker;
+
+  private TestPerformanceLogger testPerformanceLogger;
+  private RegistrationHandle performanceLoggerRegistrationHandle;
+
+  @Before
+  public void setup() {
+    Injector injector = Guice.createInjector(new InMemoryModule());
+    injector.injectMembers(this);
+
+    testPerformanceLogger = new TestPerformanceLogger();
+    performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger);
+  }
+
+  @After
+  public void cleanup() {
+    performanceLoggerRegistrationHandle.remove();
+
+    LoggingContext.getInstance().clearPerformanceLogEntries();
+    LoggingContext.getInstance().performanceLogging(false);
+  }
+
+  @Test
+  public void traceTimersInsidePerformanceLogContextCreatePerformanceLog() {
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+    try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+      assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+      TraceContext.newTimer("test1").close();
+      TraceContext.newTimer("test2", "foo", "bar").close();
+      TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close();
+      TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close();
+      TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4")
+          .close();
+
+      assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(5);
+    }
+
+    assertThat(testPerformanceLogger.logEntries())
+        .containsExactly(
+            PerformanceLogEntry.create("test1", ImmutableMap.of()),
+            PerformanceLogEntry.create("test2", ImmutableMap.of("foo", Optional.of("bar"))),
+            PerformanceLogEntry.create(
+                "test3", ImmutableMap.of("foo1", Optional.of("bar1"), "foo2", Optional.of("bar2"))),
+            PerformanceLogEntry.create(
+                "test4",
+                ImmutableMap.of(
+                    "foo1",
+                    Optional.of("bar1"),
+                    "foo2",
+                    Optional.of("bar2"),
+                    "foo3",
+                    Optional.of("bar3"))),
+            PerformanceLogEntry.create(
+                "test5",
+                ImmutableMap.of(
+                    "foo1",
+                    Optional.of("bar1"),
+                    "foo2",
+                    Optional.of("bar2"),
+                    "foo3",
+                    Optional.of("bar3"),
+                    "foo4",
+                    Optional.of("bar4"))))
+        .inOrder();
+
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+  }
+
+  @Test
+  public void traceTimersInsidePerformanceLogContextCreatePerformanceLogNullValuesAllowed() {
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+    try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+      assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+      TraceContext.newTimer("test1").close();
+      TraceContext.newTimer("test2", "foo", null).close();
+      TraceContext.newTimer("test3", "foo1", null, "foo2", null).close();
+      TraceContext.newTimer("test4", "foo1", null, "foo2", null, "foo3", null).close();
+      TraceContext.newTimer("test5", "foo1", null, "foo2", null, "foo3", null, "foo4", null)
+          .close();
+
+      assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(5);
+    }
+
+    assertThat(testPerformanceLogger.logEntries())
+        .containsExactly(
+            PerformanceLogEntry.create("test1", ImmutableMap.of()),
+            PerformanceLogEntry.create("test2", ImmutableMap.of("foo", Optional.empty())),
+            PerformanceLogEntry.create(
+                "test3", ImmutableMap.of("foo1", Optional.empty(), "foo2", Optional.empty())),
+            PerformanceLogEntry.create(
+                "test4",
+                ImmutableMap.of(
+                    "foo1", Optional.empty(), "foo2", Optional.empty(), "foo3", Optional.empty())),
+            PerformanceLogEntry.create(
+                "test5",
+                ImmutableMap.of(
+                    "foo1",
+                    Optional.empty(),
+                    "foo2",
+                    Optional.empty(),
+                    "foo3",
+                    Optional.empty(),
+                    "foo4",
+                    Optional.empty())))
+        .inOrder();
+
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+  }
+
+  @Test
+  public void traceTimersOutsidePerformanceLogContextDoNotCreatePerformanceLog() {
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+    TraceContext.newTimer("test1").close();
+    TraceContext.newTimer("test2", "foo", "bar").close();
+    TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close();
+    TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close();
+    TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4")
+        .close();
+
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+    assertThat(testPerformanceLogger.logEntries()).isEmpty();
+  }
+
+  @Test
+  public void
+      traceTimersInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers() {
+    // Remove test performance logger so that there are no registered performance loggers.
+    performanceLoggerRegistrationHandle.remove();
+
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+    try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+      assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+
+      TraceContext.newTimer("test1").close();
+      TraceContext.newTimer("test2", "foo", "bar").close();
+      TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close();
+      TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close();
+      TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4")
+          .close();
+
+      assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+    }
+
+    assertThat(testPerformanceLogger.logEntries()).isEmpty();
+
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+  }
+
+  @Test
+  public void timerMetricsInsidePerformanceLogContextCreatePerformanceLog() {
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+    try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+      assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+      Timer0 timer0 =
+          metricMaker.newTimer("test1/latency", new Description("Latency metric for testing"));
+      timer0.start().close();
+
+      Timer1<String> timer1 =
+          metricMaker.newTimer(
+              "test2/latency",
+              new Description("Latency metric for testing"),
+              Field.ofString("foo"));
+      timer1.start("value1").close();
+
+      Timer2<String, String> timer2 =
+          metricMaker.newTimer(
+              "test3/latency",
+              new Description("Latency metric for testing"),
+              Field.ofString("foo"),
+              Field.ofString("bar"));
+      timer2.start("value1", "value2").close();
+
+      Timer3<String, String, String> timer3 =
+          metricMaker.newTimer(
+              "test4/latency",
+              new Description("Latency metric for testing"),
+              Field.ofString("foo"),
+              Field.ofString("bar"),
+              Field.ofString("baz"));
+      timer3.start("value1", "value2", "value3").close();
+
+      assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(4);
+    }
+
+    assertThat(testPerformanceLogger.logEntries())
+        .containsExactly(
+            PerformanceLogEntry.create("test1/latency", ImmutableMap.of()),
+            PerformanceLogEntry.create(
+                "test2/latency", ImmutableMap.of("field1", Optional.of("value1"))),
+            PerformanceLogEntry.create(
+                "test3/latency",
+                ImmutableMap.of("field1", Optional.of("value1"), "field2", Optional.of("value2"))),
+            PerformanceLogEntry.create(
+                "test4/latency",
+                ImmutableMap.of(
+                    "field1",
+                    Optional.of("value1"),
+                    "field2",
+                    Optional.of("value2"),
+                    "field3",
+                    Optional.of("value3"))))
+        .inOrder();
+
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+  }
+
+  @Test
+  public void timerMetricsInsidePerformanceLogContextCreatePerformanceLogNullValuesAllowed() {
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+    try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+      assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+      Timer1<String> timer1 =
+          metricMaker.newTimer(
+              "test1/latency",
+              new Description("Latency metric for testing"),
+              Field.ofString("foo"));
+      timer1.start(null).close();
+
+      Timer2<String, String> timer2 =
+          metricMaker.newTimer(
+              "test2/latency",
+              new Description("Latency metric for testing"),
+              Field.ofString("foo"),
+              Field.ofString("bar"));
+      timer2.start(null, null).close();
+
+      Timer3<String, String, String> timer3 =
+          metricMaker.newTimer(
+              "test3/latency",
+              new Description("Latency metric for testing"),
+              Field.ofString("foo"),
+              Field.ofString("bar"),
+              Field.ofString("baz"));
+      timer3.start(null, null, null).close();
+
+      assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(3);
+    }
+
+    assertThat(testPerformanceLogger.logEntries())
+        .containsExactly(
+            PerformanceLogEntry.create(
+                "test1/latency", ImmutableMap.of("field1", Optional.empty())),
+            PerformanceLogEntry.create(
+                "test2/latency",
+                ImmutableMap.of("field1", Optional.empty(), "field2", Optional.empty())),
+            PerformanceLogEntry.create(
+                "test3/latency",
+                ImmutableMap.of(
+                    "field1",
+                    Optional.empty(),
+                    "field2",
+                    Optional.empty(),
+                    "field3",
+                    Optional.empty())))
+        .inOrder();
+
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+  }
+
+  @Test
+  public void timerMetricsOutsidePerformanceLogContextDoNotCreatePerformanceLog() {
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+    Timer0 timer0 =
+        metricMaker.newTimer("test1/latency", new Description("Latency metric for testing"));
+    timer0.start().close();
+
+    Timer1<String> timer1 =
+        metricMaker.newTimer(
+            "test2/latency", new Description("Latency metric for testing"), Field.ofString("foo"));
+    timer1.start("value1").close();
+
+    Timer2<String, String> timer2 =
+        metricMaker.newTimer(
+            "test3/latency",
+            new Description("Latency metric for testing"),
+            Field.ofString("foo"),
+            Field.ofString("bar"));
+    timer2.start("value1", "value2").close();
+
+    Timer3<String, String, String> timer3 =
+        metricMaker.newTimer(
+            "test4/latency",
+            new Description("Latency metric for testing"),
+            Field.ofString("foo"),
+            Field.ofString("bar"),
+            Field.ofString("baz"));
+    timer3.start("value1", "value2", "value3").close();
+
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+    assertThat(testPerformanceLogger.logEntries()).isEmpty();
+  }
+
+  @Test
+  public void
+      timerMetricssInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers() {
+    // Remove test performance logger so that there are no registered performance loggers.
+    performanceLoggerRegistrationHandle.remove();
+
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+    try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+      assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+
+      Timer0 timer0 =
+          metricMaker.newTimer("test1/latency", new Description("Latency metric for testing"));
+      timer0.start().close();
+
+      Timer1<String> timer1 =
+          metricMaker.newTimer(
+              "test2/latency",
+              new Description("Latency metric for testing"),
+              Field.ofString("foo"));
+      timer1.start("value1").close();
+
+      Timer2<String, String> timer2 =
+          metricMaker.newTimer(
+              "test3/latency",
+              new Description("Latency metric for testing"),
+              Field.ofString("foo"),
+              Field.ofString("bar"));
+      timer2.start("value1", "value2").close();
+
+      Timer3<String, String, String> timer3 =
+          metricMaker.newTimer(
+              "test4/latency",
+              new Description("Latency metric for testing"),
+              Field.ofString("foo"),
+              Field.ofString("bar"),
+              Field.ofString("baz"));
+      timer3.start("value1", "value2", "value3").close();
+
+      assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+    }
+
+    assertThat(testPerformanceLogger.logEntries()).isEmpty();
+
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+  }
+
+  @Test
+  public void nestingPerformanceLogContextsIsPossible() {
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+    try (PerformanceLogContext traceContext1 = new PerformanceLogContext(performanceLoggers)) {
+      assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+      TraceContext.newTimer("test1").close();
+
+      assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1);
+
+      try (PerformanceLogContext traceContext2 = new PerformanceLogContext(performanceLoggers)) {
+        assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+        assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+        TraceContext.newTimer("test2").close();
+        TraceContext.newTimer("test3").close();
+
+        assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(2);
+      }
+
+      assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+      assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1);
+    }
+    assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+    assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+  }
+
+  private static class TestPerformanceLogger implements PerformanceLogger {
+    private List<PerformanceLogEntry> logEntries = new ArrayList<>();
+
+    @Override
+    public void log(String operation, long durationMs, Map<String, Optional<Object>> metaData) {
+      logEntries.add(PerformanceLogEntry.create(operation, metaData));
+    }
+
+    ImmutableList<PerformanceLogEntry> logEntries() {
+      return ImmutableList.copyOf(logEntries);
+    }
+  }
+
+  @AutoValue
+  abstract static class PerformanceLogEntry {
+    static PerformanceLogEntry create(String operation, Map<String, Optional<Object>> metaData) {
+      return new AutoValue_PerformanceLogContextTest_PerformanceLogEntry(
+          operation, ImmutableMap.copyOf(metaData));
+    }
+
+    abstract String operation();
+
+    abstract ImmutableMap<String, Object> metaData();
+  }
+}

javatests/com/google/gerrit/server/logging/TraceContextTest.java

@@ -15,6 +15,7 @@
 package com.google.gerrit.server.logging;
 
 import static com.google.common.truth.Truth.assertThat;
+import static com.google.gerrit.testing.GerritJUnit.assertThrows;
 
 import com.google.common.collect.ImmutableMap;
 import com.google.common.collect.ImmutableSet;
@@ -236,6 +237,63 @@ public class TraceContextTest {
     }
   }
 
+  @Test
+  public void operationForTraceTimerCannotBeNull() throws Exception {
+    assertThrows(NullPointerException.class, () -> TraceContext.newTimer(null));
+    assertThrows(NullPointerException.class, () -> TraceContext.newTimer(null, "foo", "bar"));
+    assertThrows(
+        NullPointerException.class,
+        () -> TraceContext.newTimer(null, "foo1", "bar1", "foo2", "bar2"));
+    assertThrows(
+        NullPointerException.class,
+        () -> TraceContext.newTimer(null, "foo1", "bar1", "foo2", "bar2", "foo3", "bar3"));
+    assertThrows(
+        NullPointerException.class,
+        () ->
+            TraceContext.newTimer(
+                null, "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4"));
+  }
+
+  @Test
+  public void keysForTraceTimerCannotBeNull() throws Exception {
+    assertThrows(NullPointerException.class, () -> TraceContext.newTimer("test", null, "bar"));
+    assertThrows(
+        NullPointerException.class,
+        () -> TraceContext.newTimer("test", null, "bar1", "foo2", "bar2"));
+    assertThrows(
+        NullPointerException.class,
+        () -> TraceContext.newTimer("test", "foo1", "bar1", null, "bar2"));
+    assertThrows(
+        NullPointerException.class,
+        () -> TraceContext.newTimer("test", null, "bar1", "foo2", "bar2", "foo3", "bar3"));
+    assertThrows(
+        NullPointerException.class,
+        () -> TraceContext.newTimer("test", "foo1", "bar1", null, "bar2", "foo3", "bar3"));
+    assertThrows(
+        NullPointerException.class,
+        () -> TraceContext.newTimer("test", "foo1", "bar1", "foo2", "bar2", null, "bar3"));
+    assertThrows(
+        NullPointerException.class,
+        () ->
+            TraceContext.newTimer(
+                "test", null, "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4"));
+    assertThrows(
+        NullPointerException.class,
+        () ->
+            TraceContext.newTimer(
+                "test", "foo1", "bar1", null, "bar2", "foo3", "bar3", "foo4", "bar4"));
+    assertThrows(
+        NullPointerException.class,
+        () ->
+            TraceContext.newTimer(
+                "test", "foo1", "bar1", "foo2", "bar2", null, "bar3", "foo4", "bar4"));
+    assertThrows(
+        NullPointerException.class,
+        () ->
+            TraceContext.newTimer(
+                "test", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", null, "bar4"));
+  }
+
   private void assertTags(ImmutableMap<String, ImmutableSet<String>> expectedTagMap) {
     SortedMap<String, SortedSet<Object>> actualTagMap =
         LoggingContext.getInstance().getTags().asMap();