diff --git a/Documentation/dev-plugins.txt b/Documentation/dev-plugins.txt index ada208a68e..72b92a72a6 100644 --- a/Documentation/dev-plugins.txt +++ b/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 diff --git a/java/com/google/gerrit/httpd/restapi/RestApiServlet.java b/java/com/google/gerrit/httpd/restapi/RestApiServlet.java index 33daf46b16..efdf5badba 100644 --- a/java/com/google/gerrit/httpd/restapi/RestApiServlet.java +++ b/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 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 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( - "Received REST request: %s %s (parameters: %s)", - req.getMethod(), req.getRequestURI(), getParameterNames(req)); - logger.atFinest().log("Calling user: %s", globals.currentUser.get().getLoggableName()); + // It's important that the PerformanceLogContext is closed before the response is sent to + // the client. Only this way it is ensured that the invocation of the PerformanceLogger + // plugins happens before the client sees the response. This is needed for being able to + // 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)) { - doCorsPreflight(req, res); - return; - } - - qp = ParameterParser.getQueryParams(req); - checkCors(req, res, qp.hasXdOverride()); - if (qp.hasXdOverride()) { - req = applyXdOverrides(req, qp); - } - checkUserSession(req); - - List path = splitPath(req); - RestCollection 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 (isCorsPreflight(req)) { + doCorsPreflight(req, res); + return; } - if (isRead(req)) { - viewData = new ViewData(null, rc.list()); - } else if (isPost(req)) { - RestView restCollectionView = - rc.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./"); - if (restCollectionView != null) { - viewData = new ViewData(null, restCollectionView); + qp = ParameterParser.getQueryParams(req); + checkCors(req, res, qp.hasXdOverride()); + if (qp.hasXdOverride()) { + req = applyXdOverrides(req, qp); + } + checkUserSession(req); + + List path = splitPath(req); + RestCollection 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 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 - throw methodNotAllowed(req); - } - } else { - IdString id = path.remove(0); - try { - rsrc = rc.parse(rsrc, id); - globals.quotaChecker.enforce(rsrc, req); - if (path.isEmpty()) { - checkPreconditions(req); - } - } catch (ResourceNotFoundException e) { - if (!path.isEmpty()) { - throw e; - } - globals.quotaChecker.enforce(req); + IdString id = path.remove(0); + try { + rsrc = rc.parse(rsrc, id); + globals.quotaChecker.enforce(rsrc, req); + if (path.isEmpty()) { + checkPreconditions(req); + } + } catch (ResourceNotFoundException e) { + if (!path.isEmpty()) { + throw e; + } + globals.quotaChecker.enforce(req); - if (isPost(req) || isPut(req)) { - RestView createView = rc.views().get(PluginName.GERRIT, "CREATE./"); - if (createView != null) { - viewData = new ViewData(null, createView); - status = SC_CREATED; - path.add(id); + if (isPost(req) || isPut(req)) { + RestView createView = rc.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 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 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) { - viewData = view(rc, req.getMethod(), path); - } - } - checkRequiresCapability(viewData); - - while (viewData.view instanceof RestCollection) { - @SuppressWarnings("unchecked") - RestCollection c = - (RestCollection) 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 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 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); + if (viewData.view == null) { + viewData = view(rc, req.getMethod(), path); } - 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 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 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)) { - logger.atFinest().log("REST call succeeded: %d", SC_NOT_MODIFIED); - res.sendError(SC_NOT_MODIFIED); - return; - } + while (viewData.view instanceof RestCollection) { + @SuppressWarnings("unchecked") + RestCollection c = + (RestCollection) viewData.view; - if (!globals.paramParser.get().parse(viewData.view, qp.params(), req, res)) { - return; - } - - if (viewData.view instanceof RestReadView && isRead(req)) { - result = ((RestReadView) viewData.view).apply(rsrc); - } else if (viewData.view instanceof RestModifyView) { - @SuppressWarnings("unchecked") - RestModifyView m = - (RestModifyView) 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); + 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 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 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; } - } - } else if (viewData.view instanceof RestCollectionCreateView) { - @SuppressWarnings("unchecked") - RestCollectionCreateView m = - (RestCollectionCreateView) viewData.view; + 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; + } - 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); + if (isPost(req) || isPut(req)) { + RestView 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 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 m = - (RestCollectionDeleteMissingView) 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); - } + if (notModified(req, rsrc, viewData.view)) { + logger.atFinest().log("REST call succeeded: %d", SC_NOT_MODIFIED); + res.sendError(SC_NOT_MODIFIED); + return; } - } else if (viewData.view instanceof RestCollectionModifyView) { - @SuppressWarnings("unchecked") - RestCollectionModifyView m = - (RestCollectionModifyView) 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); - } + if (!globals.paramParser.get().parse(viewData.view, qp.params(), req, res)) { + return; } - } else { - throw new ResourceNotFoundException(); + + if (viewData.view instanceof RestReadView && isRead(req)) { + result = ((RestReadView) viewData.view).apply(rsrc); + } else if (viewData.view instanceof RestModifyView) { + @SuppressWarnings("unchecked") + RestModifyView m = + (RestModifyView) 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 m = + (RestCollectionCreateView) 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 m = + (RestCollectionDeleteMissingView) 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 m = + (RestCollectionModifyView) 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) { diff --git a/java/com/google/gerrit/metrics/BUILD b/java/com/google/gerrit/metrics/BUILD index b7b99811f7..29b0a92205 100644 --- a/java/com/google/gerrit/metrics/BUILD +++ b/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", diff --git a/java/com/google/gerrit/metrics/Timer0.java b/java/com/google/gerrit/metrics/Timer0.java index 21344884cf..d0033a41f4 100644 --- a/java/com/google/gerrit/metrics/Timer0.java +++ b/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); } diff --git a/java/com/google/gerrit/metrics/Timer1.java b/java/com/google/gerrit/metrics/Timer1.java index 16c151ebde..01ca768eef 100644 --- a/java/com/google/gerrit/metrics/Timer1.java +++ b/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 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); } diff --git a/java/com/google/gerrit/metrics/Timer2.java b/java/com/google/gerrit/metrics/Timer2.java index bf19448d70..bacbcdff86 100644 --- a/java/com/google/gerrit/metrics/Timer2.java +++ b/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 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); } diff --git a/java/com/google/gerrit/metrics/Timer3.java b/java/com/google/gerrit/metrics/Timer3.java index c910eb0c85..27e224b67a 100644 --- a/java/com/google/gerrit/metrics/Timer3.java +++ b/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 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( - "%s (%s, %s, %s) took %dms", name, field1, field2, field3, 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, "field3", field3)); + + logger.atFinest().log("%s (%s, %s, %s) took %dms", name, field1, field2, field3, durationMs); doRecord(field1, field2, field3, value, unit); } diff --git a/java/com/google/gerrit/server/BUILD b/java/com/google/gerrit/server/BUILD index 736e786afe..2cc4fb2280 100644 --- a/java/com/google/gerrit/server/BUILD +++ b/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", diff --git a/java/com/google/gerrit/server/StarredChangesUtil.java b/java/com/google/gerrit/server/StarredChangesUtil.java index d092ac8551..9b43724c68 100644 --- a/java/com/google/gerrit/server/StarredChangesUtil.java +++ b/java/com/google/gerrit/server/StarredChangesUtil.java @@ -376,7 +376,7 @@ public class StarredChangesUtil { } public static StarRef readLabels(Repository repo, String refName) throws IOException { - try (TraceTimer traceTimer = TraceContext.newTimer("Read star labels from %s", refName)) { + try (TraceTimer traceTimer = TraceContext.newTimer("Read star labels", "ref", refName)) { Ref ref = repo.exactRef(refName); if (ref == null) { return StarRef.MISSING; @@ -450,7 +450,7 @@ public class StarredChangesUtil { Repository repo, String refName, ObjectId oldObjectId, Collection labels) throws IOException, InvalidLabelsException { try (TraceTimer traceTimer = - TraceContext.newTimer("Update star labels in %s (labels=%s)", refName, labels); + TraceContext.newTimer("Update star labels", "ref", refName, "labels", labels); RevWalk rw = new RevWalk(repo)) { RefUpdate u = repo.updateRef(refName); u.setExpectedOldObjectId(oldObjectId); @@ -487,7 +487,7 @@ public class StarredChangesUtil { return; } - try (TraceTimer traceTimer = TraceContext.newTimer("Delete star labels in %s", refName)) { + try (TraceTimer traceTimer = TraceContext.newTimer("Delete star labels", "ref", refName)) { RefUpdate u = repo.updateRef(refName); u.setForceUpdate(true); u.setExpectedOldObjectId(oldObjectId); diff --git a/java/com/google/gerrit/server/account/AccountCacheImpl.java b/java/com/google/gerrit/server/account/AccountCacheImpl.java index fd48fa7e67..3f3f27db82 100644 --- a/java/com/google/gerrit/server/account/AccountCacheImpl.java +++ b/java/com/google/gerrit/server/account/AccountCacheImpl.java @@ -183,7 +183,7 @@ public class AccountCacheImpl implements AccountCache { @Override public Optional load(Account.Id who) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading account %s", who)) { + try (TraceTimer timer = TraceContext.newTimer("Loading account", "accountId", who)) { return accounts.get(who); } } diff --git a/java/com/google/gerrit/server/account/GroupCacheImpl.java b/java/com/google/gerrit/server/account/GroupCacheImpl.java index b9cfb61e4f..7ed7ebc1c9 100644 --- a/java/com/google/gerrit/server/account/GroupCacheImpl.java +++ b/java/com/google/gerrit/server/account/GroupCacheImpl.java @@ -149,7 +149,7 @@ public class GroupCacheImpl implements GroupCache { @Override public Optional load(AccountGroup.Id key) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading group %s by ID", key)) { + try (TraceTimer timer = TraceContext.newTimer("Loading group by ID", "groupId", key)) { return groupQueryProvider.get().byId(key); } } @@ -165,7 +165,7 @@ public class GroupCacheImpl implements GroupCache { @Override public Optional load(String name) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading group '%s' by name", name)) { + try (TraceTimer timer = TraceContext.newTimer("Loading group by name", "groupName", name)) { return groupQueryProvider.get().byName(AccountGroup.nameKey(name)); } } @@ -181,7 +181,7 @@ public class GroupCacheImpl implements GroupCache { @Override public Optional load(String uuid) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading group %s by UUID", uuid)) { + try (TraceTimer timer = TraceContext.newTimer("Loading group by UUID", "groupUuid", uuid)) { return groups.getGroup(AccountGroup.uuid(uuid)); } } diff --git a/java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java b/java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java index c27d6c30c5..3507ba269e 100644 --- a/java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java +++ b/java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java @@ -152,7 +152,8 @@ public class GroupIncludeCacheImpl implements GroupIncludeCache { @Override public ImmutableSet load(Account.Id memberId) { - try (TraceTimer timer = TraceContext.newTimer("Loading groups with member %s", memberId)) { + try (TraceTimer timer = + TraceContext.newTimer("Loading groups with member", "memberId", memberId)) { return groupQueryProvider.get().byMember(memberId).stream() .map(InternalGroup::getGroupUUID) .collect(toImmutableSet()); @@ -171,7 +172,7 @@ public class GroupIncludeCacheImpl implements GroupIncludeCache { @Override public ImmutableList load(AccountGroup.UUID key) { - try (TraceTimer timer = TraceContext.newTimer("Loading parent groups of %s", key)) { + try (TraceTimer timer = TraceContext.newTimer("Loading parent groups", "groupUuid", key)) { return groupQueryProvider.get().bySubgroup(key).stream() .map(InternalGroup::getGroupUUID) .collect(toImmutableList()); diff --git a/java/com/google/gerrit/server/account/externalids/ExternalIdCacheImpl.java b/java/com/google/gerrit/server/account/externalids/ExternalIdCacheImpl.java index 5aa19d88f5..ad861c0e93 100644 --- a/java/com/google/gerrit/server/account/externalids/ExternalIdCacheImpl.java +++ b/java/com/google/gerrit/server/account/externalids/ExternalIdCacheImpl.java @@ -157,8 +157,7 @@ class ExternalIdCacheImpl implements ExternalIdCache { @Override public AllExternalIds load(ObjectId notesRev) throws Exception { - try (TraceTimer timer = - TraceContext.newTimer("Loading external IDs (revision=%s)", notesRev)) { + try (TraceTimer timer = TraceContext.newTimer("Loading external IDs", "revision", notesRev)) { ImmutableSet externalIds = externalIdReader.all(notesRev); externalIds.forEach(ExternalId::checkThatBlobIdIsSet); return AllExternalIds.create(externalIds); diff --git a/java/com/google/gerrit/server/auth/ldap/LdapRealm.java b/java/com/google/gerrit/server/auth/ldap/LdapRealm.java index ed446f218a..c12aaf50bf 100644 --- a/java/com/google/gerrit/server/auth/ldap/LdapRealm.java +++ b/java/com/google/gerrit/server/auth/ldap/LdapRealm.java @@ -353,7 +353,8 @@ class LdapRealm extends AbstractRealm { @Override public Optional load(String username) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading account for username %s", username)) { + try (TraceTimer timer = + TraceContext.newTimer("Loading account for username", "username", username)) { return externalIds .get(ExternalId.Key.create(SCHEME_GERRIT, username)) .map(ExternalId::accountId); @@ -372,7 +373,7 @@ class LdapRealm extends AbstractRealm { @Override public Set load(String username) throws Exception { try (TraceTimer timer = - TraceContext.newTimer("Loading group for member with username %s", username)) { + TraceContext.newTimer("Loading group for member with username", "username", username)) { final DirContext ctx = helper.open(); try { return helper.queryForGroups(ctx, username, null); @@ -393,7 +394,7 @@ class LdapRealm extends AbstractRealm { @Override public Boolean load(String groupDn) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading groupDn %s", groupDn)) { + try (TraceTimer timer = TraceContext.newTimer("Loading groupDn", "groupDn", groupDn)) { final DirContext ctx = helper.open(); try { Name compositeGroupName = new CompositeName().add(groupDn); diff --git a/java/com/google/gerrit/server/cache/h2/H2CacheImpl.java b/java/com/google/gerrit/server/cache/h2/H2CacheImpl.java index 3732e37e19..2b440194e7 100644 --- a/java/com/google/gerrit/server/cache/h2/H2CacheImpl.java +++ b/java/com/google/gerrit/server/cache/h2/H2CacheImpl.java @@ -237,7 +237,7 @@ public class H2CacheImpl extends AbstractLoadingCache implements Per @Override public ValueHolder load(K key) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading value for %s from cache", key)) { + try (TraceTimer timer = TraceContext.newTimer("Loading value from cache", "key", key)) { if (store.mightContain(key)) { ValueHolder h = store.getIfPresent(key); if (h != null) { diff --git a/java/com/google/gerrit/server/config/GerritGlobalModule.java b/java/com/google/gerrit/server/config/GerritGlobalModule.java index 59a55ab2e7..14747e598d 100644 --- a/java/com/google/gerrit/server/config/GerritGlobalModule.java +++ b/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); diff --git a/java/com/google/gerrit/server/git/PureRevertCache.java b/java/com/google/gerrit/server/git/PureRevertCache.java index 2faa0bb5ad..49377132f9 100644 --- a/java/com/google/gerrit/server/git/PureRevertCache.java +++ b/java/com/google/gerrit/server/git/PureRevertCache.java @@ -151,7 +151,7 @@ public class PureRevertCache { @Override public Boolean load(PureRevertKeyProto key) throws BadRequestException, IOException { try (TraceContext.TraceTimer ignored = - TraceContext.newTimer("Loading pure revert for %s", key)) { + TraceContext.newTimer("Loading pure revert", "key", key)) { ObjectId original = ObjectIdConverter.create().fromByteString(key.getClaimedOriginal()); ObjectId revert = ObjectIdConverter.create().fromByteString(key.getClaimedRevert()); Project.NameKey project = Project.nameKey(key.getProject()); diff --git a/java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java b/java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java index fb7756f55f..15284fe350 100644 --- a/java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java +++ b/java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java @@ -152,7 +152,8 @@ public class SearchingChangeCacheImpl implements GitReferenceUpdatedListener { @Override public List load(Project.NameKey key) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading changes of project %s", key); + try (TraceTimer timer = + TraceContext.newTimer("Loading changes of project", "projectName", key); ManualRequestContext ctx = requestContext.open()) { List cds = queryProvider diff --git a/java/com/google/gerrit/server/git/meta/VersionedMetaData.java b/java/com/google/gerrit/server/git/meta/VersionedMetaData.java index 9506efca1e..63560688ac 100644 --- a/java/com/google/gerrit/server/git/meta/VersionedMetaData.java +++ b/java/com/google/gerrit/server/git/meta/VersionedMetaData.java @@ -499,8 +499,15 @@ public abstract class VersionedMetaData { try (TraceTimer timer = TraceContext.newTimer( - "Read file '%s' from ref '%s' of project '%s' from revision '%s'", - fileName, getRefName(), projectName, revision.name()); + "Read file", + "fileName", + fileName, + "ref", + getRefName(), + "projectName", + projectName, + "revision", + revision.name()); TreeWalk tw = TreeWalk.forPath(reader, fileName, revision.getTree())) { if (tw != null) { ObjectLoader obj = reader.open(tw.getObjectId(0), Constants.OBJ_BLOB); @@ -575,7 +582,7 @@ public abstract class VersionedMetaData { protected void saveFile(String fileName, byte[] raw) throws IOException { try (TraceTimer timer = TraceContext.newTimer( - "Save file '%s' in ref '%s' of project '%s'", fileName, getRefName(), projectName)) { + "Save file", "fileName", fileName, "ref", getRefName(), "projectName", projectName)) { DirCacheEditor editor = newTree.editor(); if (raw != null && 0 < raw.length) { final ObjectId blobId = inserter.insert(Constants.OBJ_BLOB, raw); diff --git a/java/com/google/gerrit/server/git/receive/ReceiveCommits.java b/java/com/google/gerrit/server/git/receive/ReceiveCommits.java index 73e0b1c319..98ed97ac07 100644 --- a/java/com/google/gerrit/server/git/receive/ReceiveCommits.java +++ b/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 performanceLoggers; private final PermissionBackend permissionBackend; private final ProjectCache projectCache; private final Provider queryProvider; @@ -382,6 +386,7 @@ class ReceiveCommits { MergedByPushOp.Factory mergedByPushOpFactory, PatchSetInfoFactory patchSetInfoFactory, PatchSetUtil psUtil, + DynamicSet performanceLoggers, PermissionBackend permissionBackend, ProjectCache projectCache, Provider 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; @@ -506,117 +512,120 @@ class ReceiveCommits { } void processCommands(Collection commands, MultiProgressMonitor progress) { - Task commandProgress = progress.beginSubTask("refs", UNKNOWN); - commands = commands.stream().map(c -> wrapReceiveCommand(c, commandProgress)).collect(toList()); - processCommandsUnsafe(commands, progress); - rejectRemaining(commands, "internal server error"); - - // This sends error messages before the 'done' string of the progress monitor is sent. - // Currently, the test framework relies on this ordering to understand if pushes completed - // successfully. - sendErrorMessages(); - - commandProgress.end(); - progress.end(); - } - - // Process as many commands as possible, but may leave some commands in state NOT_ATTEMPTED. - private void processCommandsUnsafe( - Collection commands, MultiProgressMonitor progress) { parsePushOptions(); try (TraceContext traceContext = - TraceContext.newTrace( - tracePushOption.isPresent(), - tracePushOption.orElse(null), - (tagName, traceId) -> addMessage(tagName + ": " + traceId))) { + TraceContext.newTrace( + tracePushOption.isPresent(), + tracePushOption.orElse(null), + (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()); - // Log the push options here, rather than in parsePushOptions(), so that they are included // into the trace if tracing is enabled. logger.atFine().log("push options: %s", receivePack.getPushOptions()); - if (!projectState.getProject().getState().permitsWrite()) { - for (ReceiveCommand cmd : commands) { - reject(cmd, "prohibited by Gerrit: project state does not permit write"); - } - return; - } + Task commandProgress = progress.beginSubTask("refs", UNKNOWN); + commands = + commands.stream().map(c -> wrapReceiveCommand(c, commandProgress)).collect(toList()); + processCommandsUnsafe(commands, progress); + rejectRemaining(commands, "internal server error"); - logger.atFine().log("Parsing %d commands", commands.size()); + // This sends error messages before the 'done' string of the progress monitor is sent. + // Currently, the test framework relies on this ordering to understand if pushes completed + // successfully. + sendErrorMessages(); - List magicCommands = new ArrayList<>(); - List directPatchSetPushCommands = new ArrayList<>(); - List regularCommands = new ArrayList<>(); - - for (ReceiveCommand cmd : commands) { - if (MagicBranch.isMagicBranch(cmd.getRefName())) { - magicCommands.add(cmd); - } else if (isDirectChangesPush(cmd.getRefName())) { - directPatchSetPushCommands.add(cmd); - } else { - regularCommands.add(cmd); - } - } - - int commandTypes = - (magicCommands.isEmpty() ? 0 : 1) - + (directPatchSetPushCommands.isEmpty() ? 0 : 1) - + (regularCommands.isEmpty() ? 0 : 1); - - if (commandTypes > 1) { - rejectRemaining(commands, "cannot combine normal pushes and magic pushes"); - return; - } - - try { - if (!regularCommands.isEmpty()) { - handleRegularCommands(regularCommands, progress); - return; - } - - for (ReceiveCommand cmd : directPatchSetPushCommands) { - parseDirectChangesPush(cmd); - } - - boolean first = true; - for (ReceiveCommand cmd : magicCommands) { - if (first) { - parseMagicBranch(cmd); - first = false; - } else { - reject(cmd, "duplicate request"); - } - } - } catch (PermissionBackendException | NoSuchProjectException | IOException err) { - logger.atSevere().withCause(err).log("Failed to process refs in %s", project.getName()); - return; - } - - Task newProgress = progress.beginSubTask("new", UNKNOWN); - Task replaceProgress = progress.beginSubTask("updated", UNKNOWN); - - List newChanges = Collections.emptyList(); - if (magicBranch != null && magicBranch.cmd.getResult() == NOT_ATTEMPTED) { - newChanges = selectNewAndReplacedChangesFromMagicBranch(newProgress); - } - - // Commit validation has already happened, so any changes without Change-Id are for the - // deprecated feature. - warnAboutMissingChangeId(newChanges); - preparePatchSetsForReplace(newChanges); - insertChangesAndPatchSets(newChanges, replaceProgress); - newProgress.end(); - replaceProgress.end(); - queueSuccessMessages(newChanges); - - logger.atFine().log( - "Command results: %s", - lazy(() -> commands.stream().map(ReceiveCommits::commandToString).collect(joining(",")))); + commandProgress.end(); + progress.end(); } } + // Process as many commands as possible, but may leave some commands in state NOT_ATTEMPTED. + private void processCommandsUnsafe( + Collection commands, MultiProgressMonitor progress) { + logger.atFinest().log("Calling user: %s", user.getLoggableName()); + + if (!projectState.getProject().getState().permitsWrite()) { + for (ReceiveCommand cmd : commands) { + reject(cmd, "prohibited by Gerrit: project state does not permit write"); + } + return; + } + + logger.atFine().log("Parsing %d commands", commands.size()); + + List magicCommands = new ArrayList<>(); + List directPatchSetPushCommands = new ArrayList<>(); + List regularCommands = new ArrayList<>(); + + for (ReceiveCommand cmd : commands) { + if (MagicBranch.isMagicBranch(cmd.getRefName())) { + magicCommands.add(cmd); + } else if (isDirectChangesPush(cmd.getRefName())) { + directPatchSetPushCommands.add(cmd); + } else { + regularCommands.add(cmd); + } + } + + int commandTypes = + (magicCommands.isEmpty() ? 0 : 1) + + (directPatchSetPushCommands.isEmpty() ? 0 : 1) + + (regularCommands.isEmpty() ? 0 : 1); + + if (commandTypes > 1) { + rejectRemaining(commands, "cannot combine normal pushes and magic pushes"); + return; + } + + try { + if (!regularCommands.isEmpty()) { + handleRegularCommands(regularCommands, progress); + return; + } + + for (ReceiveCommand cmd : directPatchSetPushCommands) { + parseDirectChangesPush(cmd); + } + + boolean first = true; + for (ReceiveCommand cmd : magicCommands) { + if (first) { + parseMagicBranch(cmd); + first = false; + } else { + reject(cmd, "duplicate request"); + } + } + } catch (PermissionBackendException | NoSuchProjectException | IOException err) { + logger.atSevere().withCause(err).log("Failed to process refs in %s", project.getName()); + return; + } + + Task newProgress = progress.beginSubTask("new", UNKNOWN); + Task replaceProgress = progress.beginSubTask("updated", UNKNOWN); + + List newChanges = Collections.emptyList(); + if (magicBranch != null && magicBranch.cmd.getResult() == NOT_ATTEMPTED) { + newChanges = selectNewAndReplacedChangesFromMagicBranch(newProgress); + } + + // Commit validation has already happened, so any changes without Change-Id are for the + // deprecated feature. + warnAboutMissingChangeId(newChanges); + preparePatchSetsForReplace(newChanges); + insertChangesAndPatchSets(newChanges, replaceProgress); + newProgress.end(); + replaceProgress.end(); + queueSuccessMessages(newChanges); + + logger.atFine().log( + "Command results: %s", + lazy(() -> commands.stream().map(ReceiveCommits::commandToString).collect(joining(",")))); + } + private void sendErrorMessages() { if (!errors.isEmpty()) { logger.atFine().log("Handling error conditions: %s", errors.keySet()); diff --git a/java/com/google/gerrit/server/group/db/GroupsUpdate.java b/java/com/google/gerrit/server/group/db/GroupsUpdate.java index b450ab856e..2f9ce011e4 100644 --- a/java/com/google/gerrit/server/group/db/GroupsUpdate.java +++ b/java/com/google/gerrit/server/group/db/GroupsUpdate.java @@ -265,7 +265,9 @@ public class GroupsUpdate { throws DuplicateKeyException, IOException, ConfigInvalidException { try (TraceTimer timer = TraceContext.newTimer( - "Creating group '%s'", groupUpdate.getName().orElseGet(groupCreation::getNameKey))) { + "Creating group", + "groupName", + groupUpdate.getName().orElseGet(groupCreation::getNameKey))) { InternalGroup createdGroup = createGroupInNoteDbWithRetry(groupCreation, groupUpdate); evictCachesOnGroupCreation(createdGroup); dispatchAuditEventsOnGroupCreation(createdGroup); @@ -285,7 +287,7 @@ public class GroupsUpdate { */ public void updateGroup(AccountGroup.UUID groupUuid, InternalGroupUpdate groupUpdate) throws DuplicateKeyException, IOException, NoSuchGroupException, ConfigInvalidException { - try (TraceTimer timer = TraceContext.newTimer("Updating group %s", groupUuid)) { + try (TraceTimer timer = TraceContext.newTimer("Updating group", "groupUuid", groupUuid)) { Optional updatedOn = groupUpdate.getUpdatedOn(); if (!updatedOn.isPresent()) { updatedOn = Optional.of(TimeUtil.nowTs()); diff --git a/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java b/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java index 1eaac7a652..da22eac700 100644 --- a/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java +++ b/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java @@ -90,13 +90,21 @@ public class AccountIndexerImpl implements AccountIndexer { if (accountState.isPresent()) { try (TraceTimer traceTimer = TraceContext.newTimer( - "Replacing account %d in index version %d", id.get(), i.getSchema().getVersion())) { + "Replacing account in index", + "accountId", + id.get(), + "indexVersion", + i.getSchema().getVersion())) { i.replace(accountState.get()); } } else { try (TraceTimer traceTimer = TraceContext.newTimer( - "Deleteing account %d in index version %d", id.get(), i.getSchema().getVersion())) { + "Deleting account in index", + "accountId", + id.get(), + "indexVersion", + i.getSchema().getVersion())) { i.delete(id); } } diff --git a/java/com/google/gerrit/server/index/change/ChangeIndexer.java b/java/com/google/gerrit/server/index/change/ChangeIndexer.java index 348e0cec75..e1c7dc984c 100644 --- a/java/com/google/gerrit/server/index/change/ChangeIndexer.java +++ b/java/com/google/gerrit/server/index/change/ChangeIndexer.java @@ -174,8 +174,11 @@ public class ChangeIndexer { for (Index i : getWriteIndexes()) { try (TraceTimer traceTimer = TraceContext.newTimer( - "Replacing change %d in index version %d", - cd.getId().get(), i.getSchema().getVersion())) { + "Replacing change in index", + "changeId", + cd.getId().get(), + "indexVersion", + i.getSchema().getVersion())) { i.replace(cd); } } @@ -336,7 +339,11 @@ public class ChangeIndexer { for (ChangeIndex i : getWriteIndexes()) { try (TraceTimer traceTimer = TraceContext.newTimer( - "Deleteing change %d in index version %d", id.get(), i.getSchema().getVersion())) { + "Deleting change in index", + "changeId", + id.get(), + "indexVersion", + i.getSchema().getVersion())) { i.delete(id); } } diff --git a/java/com/google/gerrit/server/logging/BUILD b/java/com/google/gerrit/server/logging/BUILD index cf8e9db58f..5ab8e69138 100644 --- a/java/com/google/gerrit/server/logging/BUILD +++ b/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", ], ) diff --git a/java/com/google/gerrit/server/logging/LoggingContext.java b/java/com/google/gerrit/server/logging/LoggingContext.java index 1e81c29bd6..7f5cee3a2b 100644 --- a/java/com/google/gerrit/server/logging/LoggingContext.java +++ b/java/com/google/gerrit/server/logging/LoggingContext.java @@ -14,8 +14,14 @@ package com.google.gerrit.server.logging; +import static java.util.Objects.requireNonNull; + +import com.google.common.base.MoreObjects; +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 +41,9 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log private static final ThreadLocal tags = new ThreadLocal<>(); private static final ThreadLocal forceLogging = new ThreadLocal<>(); + private static final ThreadLocal performanceLogging = new ThreadLocal<>(); + private static final ThreadLocal performanceLogRecords = + new ThreadLocal<>(); private LoggingContext() {} @@ -47,14 +56,42 @@ 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 Callable copy(Callable 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()); + } + + public boolean isEmpty() { + return tags.get() == null + && forceLogging.get() == null + && performanceLogging.get() == null + && performanceLogRecords == null; + } + + public void clear() { + tags.remove(); + forceLogging.remove(); + performanceLogging.remove(); + performanceLogRecords.remove(); } @Override @@ -120,4 +157,113 @@ 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. + * + *

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 recordProvider) { + if (!isPerformanceLogging()) { + // return early and avoid the creation of a PerformanceLogRecord + return; + } + + getMutablePerformanceLogRecords().add(recordProvider.get()); + } + + ImmutableList 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. + * + *

This method makes a defensive copy of the passed in list. + * + * @param newPerformanceLogRecords performance log records that should be set + */ + void setPerformanceLogRecords(List newPerformanceLogRecords) { + if (newPerformanceLogRecords.isEmpty()) { + performanceLogRecords.remove(); + return; + } + + getMutablePerformanceLogRecords().set(newPerformanceLogRecords); + } + + /** + * Sets a {@link MutablePerformanceLogRecords} instance for storing performance log records. + * + *

Attention: The passed in {@link MutablePerformanceLogRecords} instance is + * directly stored in the logging context. + * + *

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; + } + + @Override + public String toString() { + return MoreObjects.toStringHelper(this) + .add("tags", tags.get()) + .add("forceLogging", forceLogging.get()) + .add("performanceLogging", performanceLogging.get()) + .add("performanceLogRecords", performanceLogRecords.get()) + .toString(); + } } diff --git a/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java b/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java index 6aff5c4b32..d2701d7416 100644 --- a/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java +++ b/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java @@ -15,6 +15,7 @@ package com.google.gerrit.server.logging; import com.google.common.collect.ImmutableSetMultimap; +import com.google.common.flogger.FluentLogger; import java.util.concurrent.Callable; /** @@ -31,16 +32,30 @@ import java.util.concurrent.Callable; * @see LoggingContextAwareRunnable */ class LoggingContextAwareCallable implements Callable { + private static final FluentLogger logger = FluentLogger.forEnclosingClass(); + private final Callable callable; private final Thread callingThread; private final ImmutableSetMultimap tags; private final boolean forceLogging; + private final boolean performanceLogging; + private final MutablePerformanceLogRecords mutablePerformanceLogRecords; - LoggingContextAwareCallable(Callable 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 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 @@ -50,17 +65,29 @@ class LoggingContextAwareCallable implements Callable { return callable.call(); } - // propagate logging context LoggingContext loggingCtx = LoggingContext.getInstance(); - ImmutableSetMultimap oldTags = loggingCtx.getTagsAsMap(); - boolean oldForceLogging = loggingCtx.isLoggingForced(); + + if (!loggingCtx.isEmpty()) { + logger.atWarning().log("Logging context is not empty: %s", loggingCtx); + } + + // propagate logging context 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); + // Cleanup logging context. This is important if the thread is pooled and reused. + loggingCtx.clear(); } } } diff --git a/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java b/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java index 0bd7d007ad..23162b10e4 100644 --- a/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java +++ b/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java @@ -15,6 +15,7 @@ package com.google.gerrit.server.logging; import com.google.common.collect.ImmutableSetMultimap; +import com.google.common.flogger.FluentLogger; /** * Wrapper for a {@link Runnable} that copies the {@link LoggingContext} from the current thread to @@ -49,16 +50,30 @@ import com.google.common.collect.ImmutableSetMultimap; * @see LoggingContextAwareCallable */ public class LoggingContextAwareRunnable implements Runnable { + private static final FluentLogger logger = FluentLogger.forEnclosingClass(); + private final Runnable runnable; private final Thread callingThread; private final ImmutableSetMultimap 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() { @@ -73,17 +88,29 @@ public class LoggingContextAwareRunnable implements Runnable { return; } - // propagate logging context LoggingContext loggingCtx = LoggingContext.getInstance(); - ImmutableSetMultimap oldTags = loggingCtx.getTagsAsMap(); - boolean oldForceLogging = loggingCtx.isLoggingForced(); + + if (!loggingCtx.isEmpty()) { + logger.atWarning().log("Logging context is not empty: %s", loggingCtx); + } + + // propagate logging context 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); + // Cleanup logging context. This is important if the thread is pooled and reused. + loggingCtx.clear(); } } } diff --git a/java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java b/java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java new file mode 100644 index 0000000000..4ee70d7c19 --- /dev/null +++ b/java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java @@ -0,0 +1,55 @@ +// 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.base.MoreObjects; +import com.google.common.collect.ImmutableList; +import java.util.ArrayList; +import java.util.List; + +/** + * Thread-safe store for performance log records. + * + *

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 performanceLogRecords = new ArrayList<>(); + + public synchronized void add(PerformanceLogRecord record) { + performanceLogRecords.add(record); + } + + public synchronized void set(List records) { + performanceLogRecords.clear(); + performanceLogRecords.addAll(records); + } + + public synchronized ImmutableList list() { + return ImmutableList.copyOf(performanceLogRecords); + } + + @Override + public String toString() { + return MoreObjects.toStringHelper(this) + .add("performanceLogRecords", performanceLogRecords) + .toString(); + } +} diff --git a/java/com/google/gerrit/server/logging/MutableTags.java b/java/com/google/gerrit/server/logging/MutableTags.java index f70a8dbf1d..83009a6ae4 100644 --- a/java/com/google/gerrit/server/logging/MutableTags.java +++ b/java/com/google/gerrit/server/logging/MutableTags.java @@ -16,6 +16,7 @@ package com.google.gerrit.server.logging; import static java.util.Objects.requireNonNull; +import com.google.common.base.MoreObjects; import com.google.common.collect.ImmutableSetMultimap; import com.google.common.collect.MultimapBuilder; import com.google.common.collect.SetMultimap; @@ -110,4 +111,10 @@ public class MutableTags { tagMap.forEach(tagsBuilder::addTag); tags = tagsBuilder.build(); } + + @Override + public String toString() { + buildTags(); + return MoreObjects.toStringHelper(this).add("tags", tags).toString(); + } } diff --git a/java/com/google/gerrit/server/logging/PerformanceLogContext.java b/java/com/google/gerrit/server/logging/PerformanceLogContext.java new file mode 100644 index 0000000000..2f5c789d43 --- /dev/null +++ b/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. + * + *

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). + * + *

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 performanceLoggers; + + private final boolean oldPerformanceLogging; + private final ImmutableList oldPerformanceLogRecords; + + public PerformanceLogContext(DynamicSet 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. + * + *

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 performanceLoggers, + ImmutableList 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}. + * + *

Basically the same as {@code + * com.google.gerrit.server.plugincontext.PluginContext#newTrace(Extension)}. 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 extension) { + return TraceContext.open().addPluginTag(extension.getPluginName()); + } +} diff --git a/java/com/google/gerrit/server/logging/PerformanceLogRecord.java b/java/com/google/gerrit/server/logging/PerformanceLogRecord.java new file mode 100644 index 0000000000..d30f862208 --- /dev/null +++ b/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. + * + *

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()); + } + } +} diff --git a/java/com/google/gerrit/server/logging/PerformanceLogger.java b/java/com/google/gerrit/server/logging/PerformanceLogger.java new file mode 100644 index 0000000000..3e33a3aba2 --- /dev/null +++ b/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. + * + *

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. + * + *

For optimal performance implementors should overwrite the default log 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. + * + *

For small numbers of meta data entries the instantiation of a map should avoided by using + * one of the log 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> metaData); +} diff --git a/java/com/google/gerrit/server/logging/TraceContext.java b/java/com/google/gerrit/server/logging/TraceContext.java index 5c0406ddd1..b018da4e8a 100644 --- a/java/com/google/gerrit/server/logging/TraceContext.java +++ b/java/com/google/gerrit/server/logging/TraceContext.java @@ -155,72 +155,116 @@ public class TraceContext implements AutoCloseable { /** * Opens a new timer that logs the time for an operation if request tracing is enabled. * - *

If request tracing is not enabled this is a no-op. - * - * @param message the message + * @param operation the name of operation the is being performed * @return the trace timer */ - public static TraceTimer newTimer(String message) { - return new TraceTimer(message); + public static TraceTimer newTimer(String operation) { + return new TraceTimer(requireNonNull(operation, "operation is required")); } /** * Opens a new timer that logs the time for an operation if request tracing is enabled. * - *

If request tracing is not enabled this is a no-op. - * - * @param format the message format string - * @param arg argument for the message + * @param operation the name of operation the is being performed + * @param key meta data key + * @param value meta data value * @return the trace timer */ - public static TraceTimer newTimer(String format, Object arg) { - return new TraceTimer(format, arg); + public static TraceTimer newTimer(String operation, String key, @Nullable Object 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. * - *

If request tracing is not enabled this is a no-op. - * - * @param format the message format string - * @param arg1 first argument for the message - * @param arg2 second argument for the message - * @return the trace timer - */ - public static TraceTimer newTimer(String format, Object arg1, Object arg2) { - return new TraceTimer(format, arg1, arg2); - } - - /** - * Opens a new timer that logs the time for an operation if request tracing is enabled. - * - *

If request tracing is not enabled this is a no-op. - * - * @param format the message format string - * @param arg1 first argument for the message - * @param arg2 second argument for the message - * @param arg3 third argument for the message - * @return the trace timer - */ - public static TraceTimer newTimer(String format, Object arg1, Object arg2, Object arg3) { - return new TraceTimer(format, arg1, arg2, arg3); - } - - /** - * Opens a new timer that logs the time for an operation if request tracing is enabled. - * - *

If request tracing is not enabled this is a no-op. - * - * @param format the message format string - * @param arg1 first argument for the message - * @param arg2 second argument for the message - * @param arg3 third argument for the message - * @param arg4 fourth argument for the message + * @param operation the name of operation the is being performed + * @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 trace timer */ public static TraceTimer newTimer( - String format, Object arg1, Object arg2, Object arg3, Object arg4) { - return new TraceTimer(format, arg1, arg2, arg3, arg4); + String operation, + 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. + * + * @param operation the name of operation the is being performed + * @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 trace timer + */ + public static TraceTimer newTimer( + String operation, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2, + String key3, + @Nullable Object value3) { + return new TraceTimer( + 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. + * + * @param operation the name of operation the is being performed + * @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 + * @return the trace timer + */ + public static TraceTimer newTimer( + String operation, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2, + String key3, + @Nullable Object value3, + String key4, + @Nullable Object value4) { + return new TraceTimer( + requireNonNull(operation, "operation is required"), + requireNonNull(key1, "key1 is required"), + value1, + requireNonNull(key2, "key2 is required"), + value2, + requireNonNull(key3, "key3 is required"), + value3, + requireNonNull(key4, "key4 is required"), + value4); } public static class TraceTimer implements AutoCloseable { @@ -229,31 +273,86 @@ public class TraceContext implements AutoCloseable { private final Consumer logFn; private final Stopwatch stopwatch; - private TraceTimer(String message) { - this(elapsedMs -> logger.atFine().log(message + " (%d ms)", elapsedMs)); - } - - private TraceTimer(String format, @Nullable Object arg) { - this(elapsedMs -> logger.atFine().log(format + " (%d ms)", arg, elapsedMs)); - } - - private TraceTimer(String format, @Nullable Object arg1, @Nullable Object arg2) { - this(elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, elapsedMs)); - } - - private TraceTimer( - String format, @Nullable Object arg1, @Nullable Object arg2, @Nullable Object arg3) { - this(elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, arg3, elapsedMs)); - } - - private TraceTimer( - String format, - @Nullable Object arg1, - @Nullable Object arg2, - @Nullable Object arg3, - @Nullable Object arg4) { + private TraceTimer(String operation) { this( - elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, arg3, arg4, elapsedMs)); + elapsedMs -> { + LoggingContext.getInstance() + .addPerformanceLogRecord(() -> PerformanceLogRecord.create(operation, elapsedMs)); + logger.atFine().log("%s (%d ms)", operation, elapsedMs); + }); + } + + private TraceTimer(String operation, String key, @Nullable Object value) { + 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 operation, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2) { + this( + 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 operation, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2, + String key3, + @Nullable Object value3) { + this( + elapsedMs -> { + LoggingContext.getInstance() + .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 operation, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2, + String key3, + @Nullable Object value3, + String key4, + @Nullable Object value4) { + this( + elapsedMs -> { + LoggingContext.getInstance() + .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 logFn) { diff --git a/java/com/google/gerrit/server/project/ProjectCacheImpl.java b/java/com/google/gerrit/server/project/ProjectCacheImpl.java index 3542187316..3fc634d5f9 100644 --- a/java/com/google/gerrit/server/project/ProjectCacheImpl.java +++ b/java/com/google/gerrit/server/project/ProjectCacheImpl.java @@ -293,7 +293,8 @@ public class ProjectCacheImpl implements ProjectCache { @Override public ProjectState load(String projectName) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading project %s", projectName)) { + try (TraceTimer timer = + TraceContext.newTimer("Loading project", "projectName", projectName)) { long now = clock.read(); Project.NameKey key = Project.nameKey(projectName); try (Repository git = mgr.openRepository(key)) { diff --git a/java/com/google/gerrit/sshd/SshCommand.java b/java/com/google/gerrit/sshd/SshCommand.java index 98289570b4..6c08c1e634 100644 --- a/java/com/google/gerrit/sshd/SshCommand.java +++ b/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 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(); diff --git a/java/com/google/gerrit/sshd/SshKeyCacheImpl.java b/java/com/google/gerrit/sshd/SshKeyCacheImpl.java index fb0b8f6f15..94e7f1b59b 100644 --- a/java/com/google/gerrit/sshd/SshKeyCacheImpl.java +++ b/java/com/google/gerrit/sshd/SshKeyCacheImpl.java @@ -106,7 +106,8 @@ public class SshKeyCacheImpl implements SshKeyCache { @Override public Iterable load(String username) throws Exception { try (TraceTimer timer = - TraceContext.newTimer("Loading SSH keys for account with username %s", username)) { + TraceContext.newTimer( + "Loading SSH keys for account with username", "username", username)) { Optional user = externalIds.get(ExternalId.Key.create(SCHEME_USERNAME, username)); if (!user.isPresent()) { diff --git a/javatests/com/google/gerrit/acceptance/rest/TraceIT.java b/javatests/com/google/gerrit/acceptance/rest/TraceIT.java index b30dc41290..0251a740e8 100644 --- a/javatests/com/google/gerrit/acceptance/rest/TraceIT.java +++ b/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 projectCreationValidationListeners; @Inject private DynamicSet commitValidationListeners; + @Inject private DynamicSet 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 logEntries = new ArrayList<>(); + + @Override + public void log(String operation, long durationMs, Map> metaData) { + logEntries.add(PerformanceLogEntry.create(operation, metaData)); + } + + ImmutableList logEntries() { + return ImmutableList.copyOf(logEntries); + } + } + + @AutoValue + abstract static class PerformanceLogEntry { + static PerformanceLogEntry create(String operation, Map> metaData) { + return new AutoValue_TraceIT_PerformanceLogEntry(operation, ImmutableMap.copyOf(metaData)); + } + + abstract String operation(); + + abstract ImmutableMap metaData(); + } } diff --git a/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java b/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java index 9c1e23d0a8..5dd07c0f70 100644 --- a/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java +++ b/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 projectCreationValidationListeners; + @Inject private DynamicSet 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 logEntries = new ArrayList<>(); + + @Override + public void log(String operation, long durationMs, Map> metaData) { + logEntries.add(PerformanceLogEntry.create(operation, metaData)); + } + + ImmutableList logEntries() { + return ImmutableList.copyOf(logEntries); + } + } + + @AutoValue + abstract static class PerformanceLogEntry { + static PerformanceLogEntry create(String operation, Map> metaData) { + return new AutoValue_SshTraceIT_PerformanceLogEntry(operation, ImmutableMap.copyOf(metaData)); + } + + abstract String operation(); + + abstract ImmutableMap metaData(); + } } diff --git a/javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java b/javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java index 5117c01971..c495cd8363 100644 --- a/javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java +++ b/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 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> 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> 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) { diff --git a/javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java b/javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java new file mode 100644 index 0000000000..4d0b1f05f2 --- /dev/null +++ b/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 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 timer1 = + metricMaker.newTimer( + "test2/latency", + new Description("Latency metric for testing"), + Field.ofString("foo")); + timer1.start("value1").close(); + + Timer2 timer2 = + metricMaker.newTimer( + "test3/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar")); + timer2.start("value1", "value2").close(); + + Timer3 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 timer1 = + metricMaker.newTimer( + "test1/latency", + new Description("Latency metric for testing"), + Field.ofString("foo")); + timer1.start(null).close(); + + Timer2 timer2 = + metricMaker.newTimer( + "test2/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar")); + timer2.start(null, null).close(); + + Timer3 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 timer1 = + metricMaker.newTimer( + "test2/latency", new Description("Latency metric for testing"), Field.ofString("foo")); + timer1.start("value1").close(); + + Timer2 timer2 = + metricMaker.newTimer( + "test3/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar")); + timer2.start("value1", "value2").close(); + + Timer3 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 timer1 = + metricMaker.newTimer( + "test2/latency", + new Description("Latency metric for testing"), + Field.ofString("foo")); + timer1.start("value1").close(); + + Timer2 timer2 = + metricMaker.newTimer( + "test3/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar")); + timer2.start("value1", "value2").close(); + + Timer3 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 logEntries = new ArrayList<>(); + + @Override + public void log(String operation, long durationMs, Map> metaData) { + logEntries.add(PerformanceLogEntry.create(operation, metaData)); + } + + ImmutableList logEntries() { + return ImmutableList.copyOf(logEntries); + } + } + + @AutoValue + abstract static class PerformanceLogEntry { + static PerformanceLogEntry create(String operation, Map> metaData) { + return new AutoValue_PerformanceLogContextTest_PerformanceLogEntry( + operation, ImmutableMap.copyOf(metaData)); + } + + abstract String operation(); + + abstract ImmutableMap metaData(); + } +} diff --git a/javatests/com/google/gerrit/server/logging/TraceContextTest.java b/javatests/com/google/gerrit/server/logging/TraceContextTest.java index 044d2378e3..fedbe8b7a5 100644 --- a/javatests/com/google/gerrit/server/logging/TraceContextTest.java +++ b/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> expectedTagMap) { SortedMap> actualTagMap = LoggingContext.getInstance().getTags().asMap();