Merge changes from topic "new-TraceContext-newTimer-signature"
* changes:
ReceiveCommits: Pull up trace context from processCommandsUnsafe into processCommands
Log warning when LoggingContext of background thread is not initially empty
Unset logging context before returning a thread back to the thread pool
Add extension point to record execution times in a performance log
TraceContext#newTimer: Separate message from arguments
diff --git a/Documentation/dev-plugins.txt b/Documentation/dev-plugins.txt
index ada208a..72b92a7 100644
--- a/Documentation/dev-plugins.txt
+++ b/Documentation/dev-plugins.txt
@@ -2801,6 +2801,15 @@
}
----
+[[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 33daf46..efdf5ba 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.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.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 @@
final RestApiMetrics metrics;
final Pattern allowOrigin;
final RestApiQuotaEnforcer quotaChecker;
+ final DynamicSet<PerformanceLogger> performanceLoggers;
@Inject
Globals(
@@ -239,7 +243,8 @@
GroupAuditService auditService,
RestApiMetrics metrics,
RestApiQuotaEnforcer quotaChecker,
- @GerritServerConfig Config cfg) {
+ @GerritServerConfig Config cfg,
+ DynamicSet<PerformanceLogger> performanceLoggers) {
this.currentUser = currentUser;
this.webSession = webSession;
this.paramParser = paramParser;
@@ -247,6 +252,7 @@
this.auditService = auditService;
this.metrics = metrics;
this.quotaChecker = quotaChecker;
+ this.performanceLoggers = performanceLoggers;
allowOrigin = makeAllowOrigin(cfg);
}
@@ -294,258 +300,266 @@
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<IdString> path = splitPath(req);
- RestCollection<RestResource, RestResource> rc = members.get();
- globals
- .permissionBackend
- .currentUser()
- .checkAny(GlobalPermission.fromAnnotation(rc.getClass()));
-
- viewData = new ViewData(null, null);
-
- if (path.isEmpty()) {
- globals.quotaChecker.enforce(req);
- if (rc instanceof NeedsParams) {
- ((NeedsParams) rc).setParams(qp.params());
+ if (isCorsPreflight(req)) {
+ doCorsPreflight(req, res);
+ return;
}
- if (isRead(req)) {
- viewData = new ViewData(null, rc.list());
- } else if (isPost(req)) {
- RestView<RestResource> restCollectionView =
- rc.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./");
- if (restCollectionView != null) {
- viewData = new ViewData(null, restCollectionView);
+ qp = ParameterParser.getQueryParams(req);
+ checkCors(req, res, qp.hasXdOverride());
+ if (qp.hasXdOverride()) {
+ req = applyXdOverrides(req, qp);
+ }
+ checkUserSession(req);
+
+ List<IdString> path = splitPath(req);
+ RestCollection<RestResource, RestResource> rc = members.get();
+ globals
+ .permissionBackend
+ .currentUser()
+ .checkAny(GlobalPermission.fromAnnotation(rc.getClass()));
+
+ viewData = new ViewData(null, null);
+
+ if (path.isEmpty()) {
+ globals.quotaChecker.enforce(req);
+ if (rc instanceof NeedsParams) {
+ ((NeedsParams) rc).setParams(qp.params());
+ }
+
+ if (isRead(req)) {
+ viewData = new ViewData(null, rc.list());
+ } else if (isPost(req)) {
+ RestView<RestResource> restCollectionView =
+ rc.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./");
+ if (restCollectionView != null) {
+ viewData = new ViewData(null, restCollectionView);
+ } else {
+ throw methodNotAllowed(req);
+ }
} else {
+ // DELETE on root collections is not supported
throw methodNotAllowed(req);
}
} else {
- // DELETE on root collections is not supported
- 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<RestResource> 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<RestResource> 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<RestResource> deleteView =
+ rc.views().get(PluginName.GERRIT, "DELETE_MISSING./");
+ if (deleteView != null) {
+ viewData = new ViewData(null, deleteView);
+ status = SC_NO_CONTENT;
+ path.add(id);
+ } else {
+ throw e;
+ }
} else {
throw e;
}
- } else if (isDelete(req)) {
- RestView<RestResource> deleteView =
- rc.views().get(PluginName.GERRIT, "DELETE_MISSING./");
- if (deleteView != null) {
- viewData = new ViewData(null, deleteView);
- status = SC_NO_CONTENT;
- path.add(id);
- } else {
- throw e;
- }
- } else {
- throw e;
}
- }
- if (viewData.view == null) {
- viewData = view(rc, req.getMethod(), path);
- }
- }
- checkRequiresCapability(viewData);
-
- while (viewData.view instanceof RestCollection<?, ?>) {
- @SuppressWarnings("unchecked")
- RestCollection<RestResource, RestResource> c =
- (RestCollection<RestResource, RestResource>) viewData.view;
-
- if (path.isEmpty()) {
- if (isRead(req)) {
- viewData = new ViewData(null, c.list());
- } else if (isPost(req)) {
- // TODO: Here and on other collection methods: There is a bug that binds child views
- // with pluginName="gerrit" instead of the real plugin name. This has never worked
- // correctly and should be fixed where the binding gets created (DynamicMapProvider)
- // and here.
- RestView<RestResource> restCollectionView =
- c.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./");
- if (restCollectionView != null) {
- viewData = new ViewData(null, restCollectionView);
- } else {
- throw methodNotAllowed(req);
- }
- } else if (isDelete(req)) {
- RestView<RestResource> restCollectionView =
- c.views().get(PluginName.GERRIT, "DELETE_ON_COLLECTION./");
- if (restCollectionView != null) {
- viewData = new ViewData(null, restCollectionView);
- } else {
- throw methodNotAllowed(req);
- }
- } else {
- throw methodNotAllowed(req);
+ 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<RestResource> createView = c.views().get(PluginName.GERRIT, "CREATE./");
- if (createView != null) {
- viewData = new ViewData(null, createView);
- status = SC_CREATED;
- path.add(id);
- } else {
- throw e;
- }
- } else if (isDelete(req)) {
- RestView<RestResource> deleteView =
- c.views().get(PluginName.GERRIT, "DELETE_MISSING./");
- if (deleteView != null) {
- viewData = new ViewData(null, deleteView);
- status = SC_NO_CONTENT;
- path.add(id);
- } else {
- throw e;
- }
- } else {
- throw e;
- }
- }
- if (viewData.view == null) {
- viewData = view(c, req.getMethod(), path);
}
checkRequiresCapability(viewData);
- }
- if (notModified(req, rsrc, viewData.view)) {
- logger.atFinest().log("REST call succeeded: %d", SC_NOT_MODIFIED);
- res.sendError(SC_NOT_MODIFIED);
- return;
- }
+ while (viewData.view instanceof RestCollection<?, ?>) {
+ @SuppressWarnings("unchecked")
+ RestCollection<RestResource, RestResource> c =
+ (RestCollection<RestResource, RestResource>) viewData.view;
- if (!globals.paramParser.get().parse(viewData.view, qp.params(), req, res)) {
- return;
- }
-
- if (viewData.view instanceof RestReadView<?> && isRead(req)) {
- result = ((RestReadView<RestResource>) viewData.view).apply(rsrc);
- } else if (viewData.view instanceof RestModifyView<?, ?>) {
- @SuppressWarnings("unchecked")
- RestModifyView<RestResource, Object> m =
- (RestModifyView<RestResource, Object>) viewData.view;
-
- Type type = inputType(m);
- inputRequestBody = parseRequest(req, type);
- result = m.apply(rsrc, inputRequestBody);
- if (inputRequestBody instanceof RawInput) {
- try (InputStream is = req.getInputStream()) {
- ServletUtils.consumeRequestBody(is);
+ if (path.isEmpty()) {
+ if (isRead(req)) {
+ viewData = new ViewData(null, c.list());
+ } else if (isPost(req)) {
+ // TODO: Here and on other collection methods: There is a bug that binds child views
+ // with pluginName="gerrit" instead of the real plugin name. This has never worked
+ // correctly and should be fixed where the binding gets created (DynamicMapProvider)
+ // and here.
+ RestView<RestResource> restCollectionView =
+ c.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./");
+ if (restCollectionView != null) {
+ viewData = new ViewData(null, restCollectionView);
+ } else {
+ throw methodNotAllowed(req);
+ }
+ } else if (isDelete(req)) {
+ RestView<RestResource> restCollectionView =
+ c.views().get(PluginName.GERRIT, "DELETE_ON_COLLECTION./");
+ if (restCollectionView != null) {
+ viewData = new ViewData(null, restCollectionView);
+ } else {
+ throw methodNotAllowed(req);
+ }
+ } else {
+ throw methodNotAllowed(req);
+ }
+ break;
}
- }
- } else if (viewData.view instanceof RestCollectionCreateView<?, ?, ?>) {
- @SuppressWarnings("unchecked")
- RestCollectionCreateView<RestResource, RestResource, Object> m =
- (RestCollectionCreateView<RestResource, RestResource, Object>) 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<RestResource> createView = c.views().get(PluginName.GERRIT, "CREATE./");
+ if (createView != null) {
+ viewData = new ViewData(null, createView);
+ status = SC_CREATED;
+ path.add(id);
+ } else {
+ throw e;
+ }
+ } else if (isDelete(req)) {
+ RestView<RestResource> deleteView =
+ c.views().get(PluginName.GERRIT, "DELETE_MISSING./");
+ if (deleteView != null) {
+ viewData = new ViewData(null, deleteView);
+ status = SC_NO_CONTENT;
+ path.add(id);
+ } else {
+ throw e;
+ }
+ } else {
+ throw e;
+ }
}
+ if (viewData.view == null) {
+ viewData = view(c, req.getMethod(), path);
+ }
+ checkRequiresCapability(viewData);
}
- } else if (viewData.view instanceof RestCollectionDeleteMissingView<?, ?, ?>) {
- @SuppressWarnings("unchecked")
- RestCollectionDeleteMissingView<RestResource, RestResource, Object> m =
- (RestCollectionDeleteMissingView<RestResource, RestResource, Object>) viewData.view;
- Type type = inputType(m);
- inputRequestBody = parseRequest(req, type);
- result = m.apply(rsrc, path.get(0), inputRequestBody);
- if (inputRequestBody instanceof RawInput) {
- try (InputStream is = req.getInputStream()) {
- ServletUtils.consumeRequestBody(is);
- }
+ 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<RestResource, RestResource, Object> m =
- (RestCollectionModifyView<RestResource, RestResource, Object>) viewData.view;
- Type type = inputType(m);
- inputRequestBody = parseRequest(req, type);
- result = m.apply(rsrc, inputRequestBody);
- if (inputRequestBody instanceof RawInput) {
- try (InputStream is = req.getInputStream()) {
- ServletUtils.consumeRequestBody(is);
- }
+ 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<RestResource>) viewData.view).apply(rsrc);
+ } else if (viewData.view instanceof RestModifyView<?, ?>) {
+ @SuppressWarnings("unchecked")
+ RestModifyView<RestResource, Object> m =
+ (RestModifyView<RestResource, Object>) viewData.view;
+
+ Type type = inputType(m);
+ inputRequestBody = parseRequest(req, type);
+ result = m.apply(rsrc, inputRequestBody);
+ if (inputRequestBody instanceof RawInput) {
+ try (InputStream is = req.getInputStream()) {
+ ServletUtils.consumeRequestBody(is);
+ }
+ }
+ } else if (viewData.view instanceof RestCollectionCreateView<?, ?, ?>) {
+ @SuppressWarnings("unchecked")
+ RestCollectionCreateView<RestResource, RestResource, Object> m =
+ (RestCollectionCreateView<RestResource, RestResource, Object>) viewData.view;
+
+ Type type = inputType(m);
+ inputRequestBody = parseRequest(req, type);
+ result = m.apply(rsrc, path.get(0), inputRequestBody);
+ if (inputRequestBody instanceof RawInput) {
+ try (InputStream is = req.getInputStream()) {
+ ServletUtils.consumeRequestBody(is);
+ }
+ }
+ } else if (viewData.view instanceof RestCollectionDeleteMissingView<?, ?, ?>) {
+ @SuppressWarnings("unchecked")
+ RestCollectionDeleteMissingView<RestResource, RestResource, Object> m =
+ (RestCollectionDeleteMissingView<RestResource, RestResource, Object>) viewData.view;
+
+ Type type = inputType(m);
+ inputRequestBody = parseRequest(req, type);
+ result = m.apply(rsrc, path.get(0), inputRequestBody);
+ if (inputRequestBody instanceof RawInput) {
+ try (InputStream is = req.getInputStream()) {
+ ServletUtils.consumeRequestBody(is);
+ }
+ }
+ } else if (viewData.view instanceof RestCollectionModifyView<?, ?, ?>) {
+ @SuppressWarnings("unchecked")
+ RestCollectionModifyView<RestResource, RestResource, Object> m =
+ (RestCollectionModifyView<RestResource, RestResource, Object>) viewData.view;
+
+ Type type = inputType(m);
+ inputRequestBody = parseRequest(req, type);
+ result = m.apply(rsrc, inputRequestBody);
+ if (inputRequestBody instanceof RawInput) {
+ try (InputStream is = req.getInputStream()) {
+ ServletUtils.consumeRequestBody(is);
+ }
+ }
+ } else {
+ throw new ResourceNotFoundException();
+ }
+
+ if (result instanceof Response) {
+ @SuppressWarnings("rawtypes")
+ Response<?> r = (Response) result;
+ status = r.statusCode();
+ configureCaching(req, res, rsrc, viewData.view, r.caching());
+ } else if (result instanceof Response.Redirect) {
+ CacheHeaders.setNotCacheable(res);
+ String location = ((Response.Redirect) result).location();
+ res.sendRedirect(location);
+ logger.atFinest().log("REST call redirected to: %s", location);
+ return;
+ } else if (result instanceof Response.Accepted) {
+ CacheHeaders.setNotCacheable(res);
+ res.setStatus(SC_ACCEPTED);
+ res.setHeader(HttpHeaders.LOCATION, ((Response.Accepted) result).location());
+ logger.atFinest().log("REST call succeeded: %d", SC_ACCEPTED);
+ return;
+ } else {
+ CacheHeaders.setNotCacheable(res);
+ }
+ res.setStatus(status);
+ logger.atFinest().log("REST call succeeded: %d", status);
}
- if (result instanceof Response) {
- @SuppressWarnings("rawtypes")
- Response<?> r = (Response) result;
- status = r.statusCode();
- configureCaching(req, res, rsrc, viewData.view, r.caching());
- } else if (result instanceof Response.Redirect) {
- CacheHeaders.setNotCacheable(res);
- String location = ((Response.Redirect) result).location();
- res.sendRedirect(location);
- logger.atFinest().log("REST call redirected to: %s", location);
- return;
- } else if (result instanceof Response.Accepted) {
- CacheHeaders.setNotCacheable(res);
- res.setStatus(SC_ACCEPTED);
- res.setHeader(HttpHeaders.LOCATION, ((Response.Accepted) result).location());
- logger.atFinest().log("REST call succeeded: %d", SC_ACCEPTED);
- return;
- } else {
- CacheHeaders.setNotCacheable(res);
- }
- res.setStatus(status);
- logger.atFinest().log("REST call succeeded: %d", status);
-
if (result != Response.none()) {
result = Response.unwrap(result);
if (result instanceof BinaryResult) {
diff --git a/java/com/google/gerrit/metrics/BUILD b/java/com/google/gerrit/metrics/BUILD
index b7b9981..29b0a92 100644
--- a/java/com/google/gerrit/metrics/BUILD
+++ b/java/com/google/gerrit/metrics/BUILD
@@ -6,6 +6,7 @@
"//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 2134488..d0033a4 100644
--- a/java/com/google/gerrit/metrics/Timer0.java
+++ b/java/com/google/gerrit/metrics/Timer0.java
@@ -18,6 +18,8 @@
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 @@
* @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 16c151e..01ca768 100644
--- a/java/com/google/gerrit/metrics/Timer1.java
+++ b/java/com/google/gerrit/metrics/Timer1.java
@@ -18,6 +18,8 @@
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 @@
* @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 bf19448..bacbcdf 100644
--- a/java/com/google/gerrit/metrics/Timer2.java
+++ b/java/com/google/gerrit/metrics/Timer2.java
@@ -18,6 +18,8 @@
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 @@
* @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 c910eb0..27e224b 100644
--- a/java/com/google/gerrit/metrics/Timer3.java
+++ b/java/com/google/gerrit/metrics/Timer3.java
@@ -18,6 +18,8 @@
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 @@
* @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 736e786..2cc4fb2 100644
--- a/java/com/google/gerrit/server/BUILD
+++ b/java/com/google/gerrit/server/BUILD
@@ -136,6 +136,7 @@
":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 d092ac8..9b43724 100644
--- a/java/com/google/gerrit/server/StarredChangesUtil.java
+++ b/java/com/google/gerrit/server/StarredChangesUtil.java
@@ -376,7 +376,7 @@
}
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 @@
Repository repo, String refName, ObjectId oldObjectId, Collection<String> 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 @@
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 fd48fa7..3f3f27d 100644
--- a/java/com/google/gerrit/server/account/AccountCacheImpl.java
+++ b/java/com/google/gerrit/server/account/AccountCacheImpl.java
@@ -183,7 +183,7 @@
@Override
public Optional<AccountState> 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 b9cfb61..7ed7ebc 100644
--- a/java/com/google/gerrit/server/account/GroupCacheImpl.java
+++ b/java/com/google/gerrit/server/account/GroupCacheImpl.java
@@ -149,7 +149,7 @@
@Override
public Optional<InternalGroup> 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 @@
@Override
public Optional<InternalGroup> 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 @@
@Override
public Optional<InternalGroup> 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 c27d6c3..3507ba2 100644
--- a/java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java
+++ b/java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java
@@ -152,7 +152,8 @@
@Override
public ImmutableSet<AccountGroup.UUID> 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 @@
@Override
public ImmutableList<AccountGroup.UUID> 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 5aa19d8..ad861c0 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 @@
@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<ExternalId> 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 ed446f2..c12aaf5 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 @@
@Override
public Optional<Account.Id> 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 @@
@Override
public Set<AccountGroup.UUID> 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 @@
@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 3732e37..2b44019 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 @@
@Override
public ValueHolder<V> 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<V> 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 59a55ab..14747e5 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.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 @@
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 2faa0bb..4937713 100644
--- a/java/com/google/gerrit/server/git/PureRevertCache.java
+++ b/java/com/google/gerrit/server/git/PureRevertCache.java
@@ -151,7 +151,7 @@
@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 fb7756f..15284fe 100644
--- a/java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java
+++ b/java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java
@@ -152,7 +152,8 @@
@Override
public List<CachedChange> 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<ChangeData> 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 9506efc..6356068 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 @@
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 @@
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 73e0b1c..98ed97a 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.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.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 @@
private final MergedByPushOp.Factory mergedByPushOpFactory;
private final PatchSetInfoFactory patchSetInfoFactory;
private final PatchSetUtil psUtil;
+ private final DynamicSet<PerformanceLogger> performanceLoggers;
private final PermissionBackend permissionBackend;
private final ProjectCache projectCache;
private final Provider<InternalChangeQuery> queryProvider;
@@ -382,6 +386,7 @@
MergedByPushOp.Factory mergedByPushOpFactory,
PatchSetInfoFactory patchSetInfoFactory,
PatchSetUtil psUtil,
+ DynamicSet<PerformanceLogger> performanceLoggers,
PermissionBackend permissionBackend,
ProjectCache projectCache,
Provider<InternalChangeQuery> queryProvider,
@@ -427,6 +432,7 @@
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 @@
}
void processCommands(Collection<ReceiveCommand> 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<ReceiveCommand> 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<ReceiveCommand> magicCommands = new ArrayList<>();
- List<ReceiveCommand> directPatchSetPushCommands = new ArrayList<>();
- List<ReceiveCommand> 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<CreateRequest> 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<ReceiveCommand> 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<ReceiveCommand> magicCommands = new ArrayList<>();
+ List<ReceiveCommand> directPatchSetPushCommands = new ArrayList<>();
+ List<ReceiveCommand> 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<CreateRequest> 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 b450ab8..2f9ce01 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 @@
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 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<Timestamp> 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 1eaac7a..da22eac 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 @@
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 348e0ce..e1c7dc9 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 @@
for (Index<?, ChangeData> 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 @@
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 cf8e9db..5ab8e69 100644
--- a/java/com/google/gerrit/server/logging/BUILD
+++ b/java/com/google/gerrit/server/logging/BUILD
@@ -6,10 +6,12 @@
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 1e81c29..7f5cee3 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 @@
private static final ThreadLocal<MutableTags> tags = new ThreadLocal<>();
private static final ThreadLocal<Boolean> forceLogging = new ThreadLocal<>();
+ private static final ThreadLocal<Boolean> performanceLogging = new ThreadLocal<>();
+ private static final ThreadLocal<MutablePerformanceLogRecords> performanceLogRecords =
+ new ThreadLocal<>();
private LoggingContext() {}
@@ -47,14 +56,42 @@
if (runnable instanceof LoggingContextAwareRunnable) {
return runnable;
}
- return new LoggingContextAwareRunnable(runnable);
+
+ // Pass the MutablePerformanceLogRecords instance into the LoggingContextAwareRunnable
+ // constructor so that performance log records that are created in the wrapped runnable are
+ // added to this MutablePerformanceLogRecords instance. This is important since performance
+ // log records are processed only at the end of the request and performance log records that
+ // are created in another thread should not get lost.
+ return new LoggingContextAwareRunnable(
+ runnable, getInstance().getMutablePerformanceLogRecords());
}
public static <T> Callable<T> copy(Callable<T> callable) {
if (callable instanceof LoggingContextAwareCallable) {
return callable;
}
- return new LoggingContextAwareCallable<>(callable);
+
+ // Pass the MutablePerformanceLogRecords instance into the LoggingContextAwareCallable
+ // constructor so that performance log records that are created in the wrapped runnable are
+ // added to this MutablePerformanceLogRecords instance. This is important since performance
+ // log records are processed only at the end of the request and performance log records that
+ // are created in another thread should not get lost.
+ return new LoggingContextAwareCallable<>(
+ callable, getInstance().getMutablePerformanceLogRecords());
+ }
+
+ 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 @@
}
return oldValue != null ? oldValue : false;
}
+
+ boolean isPerformanceLogging() {
+ Boolean isPerformanceLogging = performanceLogging.get();
+ return isPerformanceLogging != null ? isPerformanceLogging : false;
+ }
+
+ /**
+ * Enables performance logging.
+ *
+ * <p>It's important to enable performance logging only in a context that ensures to consume the
+ * captured performance log records. Otherwise captured performance log records might leak into
+ * other requests that are executed by the same thread (if a thread pool is used to process
+ * requests).
+ *
+ * @param enable whether performance logging should be enabled.
+ * @return whether performance logging was be enabled before invoking this method (old value).
+ */
+ boolean performanceLogging(boolean enable) {
+ Boolean oldValue = performanceLogging.get();
+ if (enable) {
+ performanceLogging.set(true);
+ } else {
+ performanceLogging.remove();
+ }
+ return oldValue != null ? oldValue : false;
+ }
+
+ /**
+ * Adds a performance log record, if performance logging is enabled.
+ *
+ * @param recordProvider Provider for the performance log record. This provider is only invoked if
+ * performance logging is enabled. This means if performance logging is disabled, we avoid the
+ * creation of a {@link PerformanceLogRecord}.
+ */
+ public void addPerformanceLogRecord(Provider<PerformanceLogRecord> recordProvider) {
+ if (!isPerformanceLogging()) {
+ // return early and avoid the creation of a PerformanceLogRecord
+ return;
+ }
+
+ getMutablePerformanceLogRecords().add(recordProvider.get());
+ }
+
+ ImmutableList<PerformanceLogRecord> getPerformanceLogRecords() {
+ MutablePerformanceLogRecords records = performanceLogRecords.get();
+ if (records != null) {
+ return records.list();
+ }
+ return ImmutableList.of();
+ }
+
+ void clearPerformanceLogEntries() {
+ performanceLogRecords.remove();
+ }
+
+ /**
+ * Set the performance log records in this logging context. Existing log records are overwritten.
+ *
+ * <p>This method makes a defensive copy of the passed in list.
+ *
+ * @param newPerformanceLogRecords performance log records that should be set
+ */
+ void setPerformanceLogRecords(List<PerformanceLogRecord> newPerformanceLogRecords) {
+ if (newPerformanceLogRecords.isEmpty()) {
+ performanceLogRecords.remove();
+ return;
+ }
+
+ getMutablePerformanceLogRecords().set(newPerformanceLogRecords);
+ }
+
+ /**
+ * Sets a {@link MutablePerformanceLogRecords} instance for storing performance log records.
+ *
+ * <p><strong>Attention:</strong> The passed in {@link MutablePerformanceLogRecords} instance is
+ * directly stored in the logging context.
+ *
+ * <p>This method is intended to be only used when the logging context is copied to a new thread
+ * to ensure that the performance log records that are added in the new thread are added to the
+ * same {@link MutablePerformanceLogRecords} instance (see {@link LoggingContextAwareRunnable} and
+ * {@link LoggingContextAwareCallable}). This is important since performance log records are
+ * processed only at the end of the request and performance log records that are created in
+ * another thread should not get lost.
+ *
+ * @param mutablePerformanceLogRecords the {@link MutablePerformanceLogRecords} instance in which
+ * performance log records should be stored
+ */
+ void setMutablePerformanceLogRecords(MutablePerformanceLogRecords mutablePerformanceLogRecords) {
+ performanceLogRecords.set(requireNonNull(mutablePerformanceLogRecords));
+ }
+
+ private MutablePerformanceLogRecords getMutablePerformanceLogRecords() {
+ MutablePerformanceLogRecords records = performanceLogRecords.get();
+ if (records == null) {
+ records = new MutablePerformanceLogRecords();
+ performanceLogRecords.set(records);
+ }
+ return records;
+ }
+
+ @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 6aff5c4..d2701d7 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 @@
* @see LoggingContextAwareRunnable
*/
class LoggingContextAwareCallable<T> implements Callable<T> {
+ private static final FluentLogger logger = FluentLogger.forEnclosingClass();
+
private final Callable<T> callable;
private final Thread callingThread;
private final ImmutableSetMultimap<String, String> tags;
private final boolean forceLogging;
+ private final boolean performanceLogging;
+ private final MutablePerformanceLogRecords mutablePerformanceLogRecords;
- LoggingContextAwareCallable(Callable<T> callable) {
+ /**
+ * Creates a LoggingContextAwareCallable that wraps the given {@link Callable}.
+ *
+ * @param callable Callable that should be wrapped.
+ * @param mutablePerformanceLogRecords instance of {@link MutablePerformanceLogRecords} to which
+ * performance log records that are created from the runnable are added
+ */
+ LoggingContextAwareCallable(
+ Callable<T> callable, MutablePerformanceLogRecords mutablePerformanceLogRecords) {
this.callable = callable;
this.callingThread = Thread.currentThread();
this.tags = LoggingContext.getInstance().getTagsAsMap();
this.forceLogging = LoggingContext.getInstance().isLoggingForced();
+ this.performanceLogging = LoggingContext.getInstance().isPerformanceLogging();
+ this.mutablePerformanceLogRecords = mutablePerformanceLogRecords;
}
@Override
@@ -50,17 +65,29 @@
return callable.call();
}
- // propagate logging context
LoggingContext loggingCtx = LoggingContext.getInstance();
- ImmutableSetMultimap<String, String> 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 0bd7d00..23162b1 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 @@
* @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<String, String> tags;
private final boolean forceLogging;
+ private final boolean performanceLogging;
+ private final MutablePerformanceLogRecords mutablePerformanceLogRecords;
- LoggingContextAwareRunnable(Runnable runnable) {
+ /**
+ * Creates a LoggingContextAwareRunnable that wraps the given {@link Runnable}.
+ *
+ * @param runnable Runnable that should be wrapped.
+ * @param mutablePerformanceLogRecords instance of {@link MutablePerformanceLogRecords} to which
+ * performance log records that are created from the runnable are added
+ */
+ LoggingContextAwareRunnable(
+ Runnable runnable, MutablePerformanceLogRecords mutablePerformanceLogRecords) {
this.runnable = runnable;
this.callingThread = Thread.currentThread();
this.tags = LoggingContext.getInstance().getTagsAsMap();
this.forceLogging = LoggingContext.getInstance().isLoggingForced();
+ this.performanceLogging = LoggingContext.getInstance().isPerformanceLogging();
+ this.mutablePerformanceLogRecords = mutablePerformanceLogRecords;
}
public Runnable unwrap() {
@@ -73,17 +88,29 @@
return;
}
- // propagate logging context
LoggingContext loggingCtx = LoggingContext.getInstance();
- ImmutableSetMultimap<String, String> 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 0000000..4ee70d7
--- /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.
+ *
+ * <p>This class is intended to keep track of performance log records in {@link LoggingContext}. It
+ * needs to be thread-safe because it gets shared between threads when the logging context is copied
+ * to another thread (see {@link LoggingContextAwareRunnable} and {@link
+ * LoggingContextAwareCallable}. In this case the logging contexts of both threads share the same
+ * instance of this class. This is important since performance log records are processed only at the
+ * end of a request and performance log records that are created in another thread should not get
+ * lost.
+ */
+public class MutablePerformanceLogRecords {
+ private final ArrayList<PerformanceLogRecord> performanceLogRecords = new ArrayList<>();
+
+ public synchronized void add(PerformanceLogRecord record) {
+ performanceLogRecords.add(record);
+ }
+
+ public synchronized void set(List<PerformanceLogRecord> records) {
+ performanceLogRecords.clear();
+ performanceLogRecords.addAll(records);
+ }
+
+ public synchronized ImmutableList<PerformanceLogRecord> list() {
+ return ImmutableList.copyOf(performanceLogRecords);
+ }
+
+ @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 f70a8db..83009a6 100644
--- a/java/com/google/gerrit/server/logging/MutableTags.java
+++ b/java/com/google/gerrit/server/logging/MutableTags.java
@@ -16,6 +16,7 @@
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 @@
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 0000000..2f5c789
--- /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.
+ *
+ * <p>Capturing performance log records is disabled if there are no {@link PerformanceLogger}
+ * registered (in this case the captured performance log records would never be used).
+ *
+ * <p>It's important to enable capturing of performance log records in a context that ensures to
+ * consume the captured performance log records. Otherwise captured performance log records might
+ * leak into other requests that are executed by the same thread (if a thread pool is used to
+ * process requests).
+ */
+public class PerformanceLogContext implements AutoCloseable {
+ private static final FluentLogger logger = FluentLogger.forEnclosingClass();
+
+ // Do not use PluginSetContext. PluginSetContext traces the plugin latency with a timer metric
+ // which would result in a performance log and we don't want to log the performance of writing
+ // a performance log in the performance log (endless loop).
+ private final DynamicSet<PerformanceLogger> performanceLoggers;
+
+ private final boolean oldPerformanceLogging;
+ private final ImmutableList<PerformanceLogRecord> oldPerformanceLogRecords;
+
+ public PerformanceLogContext(DynamicSet<PerformanceLogger> performanceLoggers) {
+ this.performanceLoggers = performanceLoggers;
+
+ // Just in case remember the old state and reset performance log entries.
+ this.oldPerformanceLogging = LoggingContext.getInstance().isPerformanceLogging();
+ this.oldPerformanceLogRecords = LoggingContext.getInstance().getPerformanceLogRecords();
+ LoggingContext.getInstance().clearPerformanceLogEntries();
+
+ // Do not create performance log entries if no PerformanceLogger is registered.
+ LoggingContext.getInstance()
+ .performanceLogging(!Iterables.isEmpty(performanceLoggers.entries()));
+ }
+
+ @Override
+ public void close() {
+ if (LoggingContext.getInstance().isPerformanceLogging()) {
+ runEach(performanceLoggers, LoggingContext.getInstance().getPerformanceLogRecords());
+ }
+
+ // Restore old state. Required to support nesting of PerformanceLogContext's.
+ LoggingContext.getInstance().performanceLogging(oldPerformanceLogging);
+ LoggingContext.getInstance().setPerformanceLogRecords(oldPerformanceLogRecords);
+ }
+
+ /**
+ * Invokes all performance loggers.
+ *
+ * <p>Similar to how {@code com.google.gerrit.server.plugincontext.PluginContext} invokes plugins
+ * but without recording metrics for invoking {@link PerformanceLogger}s.
+ *
+ * @param performanceLoggers the performance loggers that should be invoked
+ * @param performanceLogRecords the performance log records that should be handed over to the
+ * performance loggers
+ */
+ private static void runEach(
+ DynamicSet<PerformanceLogger> performanceLoggers,
+ ImmutableList<PerformanceLogRecord> performanceLogRecords) {
+ performanceLoggers
+ .entries()
+ .forEach(
+ p -> {
+ try (TraceContext traceContext = newPluginTrace(p)) {
+ performanceLogRecords.forEach(r -> r.writeTo(p.get()));
+ } catch (Throwable e) {
+ logger.atWarning().withCause(e).log(
+ "Failure in %s of plugin %s", p.get().getClass(), p.getPluginName());
+ }
+ });
+ }
+
+ /**
+ * Opens a trace context for a plugin that implements {@link PerformanceLogger}.
+ *
+ * <p>Basically the same as {@code
+ * com.google.gerrit.server.plugincontext.PluginContext#newTrace(Extension<T>)}. We have this
+ * method here to avoid a dependency on PluginContext which lives in
+ * "//java/com/google/gerrit/server". This package ("//java/com/google/gerrit/server/logging")
+ * should have as few dependencies as possible.
+ *
+ * @param extension performance logger extension
+ * @return the trace context
+ */
+ private static TraceContext newPluginTrace(Extension<PerformanceLogger> extension) {
+ return TraceContext.open().addPluginTag(extension.getPluginName());
+ }
+}
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 0000000..d30f862
--- /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.
+ *
+ * <p>Meta data is stored in separate key/value fields to avoid expensive instantiations of Map
+ * objects.
+ */
+@AutoValue
+public abstract class PerformanceLogRecord {
+ /**
+ * Creates a performance log record without meta data.
+ *
+ * @param operation the name of operation the is was performed
+ * @param durationMs the execution time in milliseconds
+ * @return the performance log record
+ */
+ public static PerformanceLogRecord create(String operation, long durationMs) {
+ return new AutoValue_PerformanceLogRecord(
+ operation, durationMs, null, null, null, null, null, null, null, null);
+ }
+
+ /**
+ * Creates a performance log record with meta data.
+ *
+ * @param operation the name of operation the is was performed
+ * @param durationMs the execution time in milliseconds
+ * @param key meta data key
+ * @param value meta data value
+ * @return the performance log record
+ */
+ public static PerformanceLogRecord create(
+ String operation, long durationMs, String key, @Nullable Object value) {
+ return new AutoValue_PerformanceLogRecord(
+ operation, durationMs, requireNonNull(key), value, null, null, null, null, null, null);
+ }
+
+ /**
+ * Creates a performance log record with meta data.
+ *
+ * @param operation the name of operation the is was performed
+ * @param durationMs the execution time in milliseconds
+ * @param key1 first meta data key
+ * @param value1 first meta data value
+ * @param key2 second meta data key
+ * @param value2 second meta data value
+ * @return the performance log record
+ */
+ public static PerformanceLogRecord create(
+ String operation,
+ long durationMs,
+ String key1,
+ @Nullable Object value1,
+ String key2,
+ @Nullable Object value2) {
+ return new AutoValue_PerformanceLogRecord(
+ operation,
+ durationMs,
+ requireNonNull(key1),
+ value1,
+ requireNonNull(key2),
+ value2,
+ null,
+ null,
+ null,
+ null);
+ }
+
+ /**
+ * Creates a performance log record with meta data.
+ *
+ * @param operation the name of operation the is was performed
+ * @param durationMs the execution time in milliseconds
+ * @param key1 first meta data key
+ * @param value1 first meta data value
+ * @param key2 second meta data key
+ * @param value2 second meta data value
+ * @param key3 third meta data key
+ * @param value3 third meta data value
+ * @return the performance log record
+ */
+ public static PerformanceLogRecord create(
+ String operation,
+ long durationMs,
+ String key1,
+ @Nullable Object value1,
+ String key2,
+ @Nullable Object value2,
+ String key3,
+ @Nullable Object value3) {
+ return new AutoValue_PerformanceLogRecord(
+ operation,
+ durationMs,
+ requireNonNull(key1),
+ value1,
+ requireNonNull(key2),
+ value2,
+ requireNonNull(key3),
+ value3,
+ null,
+ null);
+ }
+
+ /**
+ * Creates a performance log record with meta data.
+ *
+ * @param operation the name of operation the is was performed
+ * @param durationMs the execution time in milliseconds
+ * @param key1 first meta data key
+ * @param value1 first meta data value
+ * @param key2 second meta data key
+ * @param value2 second meta data value
+ * @param key3 third meta data key
+ * @param value3 third meta data value
+ * @param key4 forth meta data key
+ * @param value4 forth meta data value
+ * @return the performance log record
+ */
+ public static PerformanceLogRecord create(
+ String operation,
+ long durationMs,
+ String key1,
+ @Nullable Object value1,
+ String key2,
+ @Nullable Object value2,
+ String key3,
+ @Nullable Object value3,
+ String key4,
+ @Nullable Object value4) {
+ return new AutoValue_PerformanceLogRecord(
+ operation,
+ durationMs,
+ requireNonNull(key1),
+ value1,
+ requireNonNull(key2),
+ value2,
+ requireNonNull(key3),
+ value3,
+ requireNonNull(key4),
+ value4);
+ }
+
+ public abstract String operation();
+
+ public abstract long durationMs();
+
+ @Nullable
+ public abstract String key1();
+
+ @Nullable
+ public abstract Object value1();
+
+ @Nullable
+ public abstract String key2();
+
+ @Nullable
+ public abstract Object value2();
+
+ @Nullable
+ public abstract String key3();
+
+ @Nullable
+ public abstract Object value3();
+
+ @Nullable
+ public abstract String key4();
+
+ @Nullable
+ public abstract Object value4();
+
+ void writeTo(PerformanceLogger performanceLogger) {
+ if (key4() != null) {
+ requireNonNull(key1());
+ requireNonNull(key2());
+ requireNonNull(key3());
+ performanceLogger.log(
+ operation(),
+ durationMs(),
+ key1(),
+ value1(),
+ key2(),
+ value2(),
+ key3(),
+ value3(),
+ key4(),
+ value4());
+ } else if (key3() != null) {
+ requireNonNull(key1());
+ requireNonNull(key2());
+ performanceLogger.log(
+ operation(), durationMs(), key1(), value1(), key2(), value2(), key3(), value3());
+ } else if (key2() != null) {
+ requireNonNull(key1());
+ performanceLogger.log(operation(), durationMs(), key1(), value1(), key2(), value2());
+ } else if (key1() != null) {
+ performanceLogger.log(operation(), durationMs(), key1(), value1());
+ } else {
+ performanceLogger.log(operation(), durationMs());
+ }
+ }
+}
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 0000000..3e33a3a
--- /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.
+ *
+ * <p>This extension point is invoked for all operations for which the execution time is measured.
+ * The invocation of the extension point does not happen immediately, but only at the end of a
+ * request (REST call, SSH call, git push). Implementors can write the execution times into a
+ * performance log for further analysis.
+ *
+ * <p>For optimal performance implementors should overwrite the default <code>log</code> methods to
+ * avoid unneeded instantiation of Map objects.
+ */
+@ExtensionPoint
+public interface PerformanceLogger {
+ /**
+ * Record the execution time of an operation in a performance log.
+ *
+ * @param operation operation that was performed
+ * @param durationMs time that the execution of the operation took (in milliseconds)
+ */
+ default void log(String operation, long durationMs) {
+ log(operation, durationMs, ImmutableMap.of());
+ }
+
+ /**
+ * Record the execution time of an operation in a performance log.
+ *
+ * @param operation operation that was performed
+ * @param durationMs time that the execution of the operation took (in milliseconds)
+ * @param key meta data key
+ * @param value meta data value
+ */
+ default void log(String operation, long durationMs, String key, @Nullable Object value) {
+ log(operation, durationMs, ImmutableMap.of(key, Optional.ofNullable(value)));
+ }
+
+ /**
+ * Record the execution time of an operation in a performance log.
+ *
+ * @param operation operation that was performed
+ * @param durationMs time that the execution of the operation took (in milliseconds)
+ * @param key1 first meta data key
+ * @param value1 first meta data value
+ * @param key2 second meta data key
+ * @param value2 second meta data value
+ */
+ default void log(
+ String operation,
+ long durationMs,
+ String key1,
+ @Nullable Object value1,
+ String key2,
+ @Nullable Object value2) {
+ log(
+ operation,
+ durationMs,
+ ImmutableMap.of(key1, Optional.ofNullable(value1), key2, Optional.ofNullable(value2)));
+ }
+
+ /**
+ * Record the execution time of an operation in a performance log.
+ *
+ * @param operation operation that was performed
+ * @param durationMs time that the execution of the operation took (in milliseconds)
+ * @param key1 first meta data key
+ * @param value1 first meta data value
+ * @param key2 second meta data key
+ * @param value2 second meta data value
+ * @param key3 third meta data key
+ * @param value3 third meta data value
+ */
+ default void log(
+ String operation,
+ long durationMs,
+ String key1,
+ @Nullable Object value1,
+ String key2,
+ @Nullable Object value2,
+ String key3,
+ @Nullable Object value3) {
+ log(
+ operation,
+ durationMs,
+ ImmutableMap.of(
+ key1,
+ Optional.ofNullable(value1),
+ key2,
+ Optional.ofNullable(value2),
+ key3,
+ Optional.ofNullable(value3)));
+ }
+
+ /**
+ * Record the execution time of an operation in a performance log.
+ *
+ * @param operation operation that was performed
+ * @param durationMs time that the execution of the operation took (in milliseconds)
+ * @param key1 first meta data key
+ * @param value1 first meta data value
+ * @param key2 second meta data key
+ * @param value2 second meta data value
+ * @param key3 third meta data key
+ * @param value3 third meta data value
+ * @param key4 fourth meta data key
+ * @param value4 fourth meta data value
+ */
+ default void log(
+ String operation,
+ long durationMs,
+ String key1,
+ @Nullable Object value1,
+ String key2,
+ @Nullable Object value2,
+ String key3,
+ @Nullable Object value3,
+ String key4,
+ @Nullable Object value4) {
+ log(
+ operation,
+ durationMs,
+ ImmutableMap.of(
+ key1,
+ Optional.ofNullable(value1),
+ key2,
+ Optional.ofNullable(value2),
+ key3,
+ Optional.ofNullable(value3),
+ key4,
+ Optional.ofNullable(value4)));
+ }
+
+ /**
+ * Record the execution time of an operation in a performance log.
+ *
+ * <p>For small numbers of meta data entries the instantiation of a map should avoided by using
+ * one of the <code>log</code> methods that allows to pass in meta data entries directly.
+ *
+ * @param operation operation that was performed
+ * @param durationMs time that the execution of the operation took (in milliseconds)
+ * @param metaData key-value map with meta data
+ */
+ void log(String operation, long durationMs, Map<String, Optional<Object>> metaData);
+}
diff --git a/java/com/google/gerrit/server/logging/TraceContext.java b/java/com/google/gerrit/server/logging/TraceContext.java
index 5c0406d..b018da4 100644
--- a/java/com/google/gerrit/server/logging/TraceContext.java
+++ b/java/com/google/gerrit/server/logging/TraceContext.java
@@ -155,72 +155,116 @@
/**
* Opens a new timer that logs the time for an operation if request tracing is enabled.
*
- * <p>If request tracing is not enabled this is a no-op.
- *
- * @param 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.
*
- * <p>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.
*
- * <p>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.
- *
- * <p>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.
- *
- * <p>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 @@
private final Consumer<Long> 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<Long> logFn) {
diff --git a/java/com/google/gerrit/server/project/ProjectCacheImpl.java b/java/com/google/gerrit/server/project/ProjectCacheImpl.java
index 3542187..3fc634d 100644
--- a/java/com/google/gerrit/server/project/ProjectCacheImpl.java
+++ b/java/com/google/gerrit/server/project/ProjectCacheImpl.java
@@ -293,7 +293,8 @@
@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 9828957..6c08c1e 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<PerformanceLogger> performanceLoggers;
+
@Option(name = "--trace", usage = "enable request tracing")
private boolean trace;
@@ -38,7 +44,9 @@
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 fb0b8f6..94e7f1b 100644
--- a/java/com/google/gerrit/sshd/SshKeyCacheImpl.java
+++ b/java/com/google/gerrit/sshd/SshKeyCacheImpl.java
@@ -106,7 +106,8 @@
@Override
public Iterable<SshKeyCacheEntry> 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<ExternalId> 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 b30dc41..0251a74 100644
--- a/javatests/com/google/gerrit/acceptance/rest/TraceIT.java
+++ b/javatests/com/google/gerrit/acceptance/rest/TraceIT.java
@@ -17,7 +17,9 @@
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.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 @@
@Inject private DynamicSet<ProjectCreationValidationListener> projectCreationValidationListeners;
@Inject private DynamicSet<CommitValidationListener> commitValidationListeners;
+ @Inject private DynamicSet<PerformanceLogger> performanceLoggers;
@Inject private WorkQueue workQueue;
private TraceValidatingProjectCreationValidationListener projectCreationListener;
private RegistrationHandle projectCreationListenerRegistrationHandle;
private TraceValidatingCommitValidationListener commitValidationListener;
private RegistrationHandle commitValidationRegistrationHandle;
+ private TestPerformanceLogger testPerformanceLogger;
+ private RegistrationHandle performanceLoggerRegistrationHandle;
@Before
public void setup() {
@@ -68,12 +77,15 @@
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 @@
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 @@
return ImmutableList.of();
}
}
+
+ private static class TestPerformanceLogger implements PerformanceLogger {
+ private List<PerformanceLogEntry> logEntries = new ArrayList<>();
+
+ @Override
+ public void log(String operation, long durationMs, Map<String, Optional<Object>> metaData) {
+ logEntries.add(PerformanceLogEntry.create(operation, metaData));
+ }
+
+ ImmutableList<PerformanceLogEntry> logEntries() {
+ return ImmutableList.copyOf(logEntries);
+ }
+ }
+
+ @AutoValue
+ abstract static class PerformanceLogEntry {
+ static PerformanceLogEntry create(String operation, Map<String, Optional<Object>> metaData) {
+ return new AutoValue_TraceIT_PerformanceLogEntry(operation, ImmutableMap.copyOf(metaData));
+ }
+
+ abstract String operation();
+
+ abstract ImmutableMap<String, Object> metaData();
+ }
}
diff --git a/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java b/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java
index 9c1e23d..5dd07c0 100644
--- a/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java
+++ b/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java
@@ -16,17 +16,25 @@
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 @@
@UseSsh
public class SshTraceIT extends AbstractDaemonTest {
@Inject private DynamicSet<ProjectCreationValidationListener> projectCreationValidationListeners;
+ @Inject private DynamicSet<PerformanceLogger> performanceLoggers;
private TraceValidatingProjectCreationValidationListener projectCreationListener;
private RegistrationHandle projectCreationListenerRegistrationHandle;
+ private TestPerformanceLogger testPerformanceLogger;
+ private RegistrationHandle performanceLoggerRegistrationHandle;
@Before
public void setup() {
projectCreationListener = new TraceValidatingProjectCreationValidationListener();
projectCreationListenerRegistrationHandle =
projectCreationValidationListeners.add("gerrit", projectCreationListener);
+ testPerformanceLogger = new TestPerformanceLogger();
+ performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger);
}
@After
public void cleanup() {
projectCreationListenerRegistrationHandle.remove();
+ performanceLoggerRegistrationHandle.remove();
}
@Test
@@ -85,10 +99,17 @@
@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 @@
this.isLoggingForced = LoggingContext.getInstance().shouldForceLogging(null, null, false);
}
}
+
+ private static class TestPerformanceLogger implements PerformanceLogger {
+ private List<PerformanceLogEntry> logEntries = new ArrayList<>();
+
+ @Override
+ public void log(String operation, long durationMs, Map<String, Optional<Object>> metaData) {
+ logEntries.add(PerformanceLogEntry.create(operation, metaData));
+ }
+
+ ImmutableList<PerformanceLogEntry> logEntries() {
+ return ImmutableList.copyOf(logEntries);
+ }
+ }
+
+ @AutoValue
+ abstract static class PerformanceLogEntry {
+ static PerformanceLogEntry create(String operation, Map<String, Optional<Object>> metaData) {
+ return new AutoValue_SshTraceIT_PerformanceLogEntry(operation, ImmutableMap.copyOf(metaData));
+ }
+
+ abstract String operation();
+
+ abstract ImmutableMap<String, Object> metaData();
+ }
}
diff --git a/javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java b/javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java
index 5117c01..c495cd8 100644
--- a/javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java
+++ b/javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java
@@ -17,25 +17,71 @@
import static com.google.common.truth.Truth.assertThat;
import com.google.common.truth.Expect;
+import com.google.gerrit.extensions.registration.DynamicSet;
+import com.google.gerrit.extensions.registration.RegistrationHandle;
+import com.google.gerrit.testing.InMemoryModule;
+import com.google.inject.Guice;
+import com.google.inject.Inject;
+import com.google.inject.Injector;
+import java.util.Map;
+import java.util.Optional;
import java.util.SortedMap;
import java.util.SortedSet;
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
+import org.junit.After;
+import org.junit.Before;
import org.junit.Rule;
import org.junit.Test;
public class LoggingContextAwareExecutorServiceTest {
@Rule public final Expect expect = Expect.create();
+ @Inject private DynamicSet<PerformanceLogger> performanceLoggers;
+
+ private PerformanceLogger testPerformanceLogger;
+ private RegistrationHandle performanceLoggerRegistrationHandle;
+
+ @Before
+ public void setup() {
+ Injector injector = Guice.createInjector(new InMemoryModule());
+ injector.injectMembers(this);
+
+ testPerformanceLogger =
+ new PerformanceLogger() {
+ @Override
+ public void log(
+ String operation, long durationMs, Map<String, Optional<Object>> metaData) {
+ // do nothing
+ }
+ };
+ performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger);
+ }
+
+ @After
+ public void cleanup() {
+ performanceLoggerRegistrationHandle.remove();
+ }
+
@Test
public void loggingContextPropagationToBackgroundThread() throws Exception {
assertThat(LoggingContext.getInstance().getTags().isEmpty()).isTrue();
assertForceLogging(false);
- try (TraceContext traceContext = TraceContext.open().forceLogging().addTag("foo", "bar")) {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+ try (TraceContext traceContext = TraceContext.open().forceLogging().addTag("foo", "bar");
+ PerformanceLogContext performanceLogContext =
+ new PerformanceLogContext(performanceLoggers)) {
+ // Create a performance log record.
+ TraceContext.newTimer("test").close();
+
SortedMap<String, SortedSet<Object>> tagMap = LoggingContext.getInstance().getTags().asMap();
assertThat(tagMap.keySet()).containsExactly("foo");
assertThat(tagMap.get("foo")).containsExactly("bar");
assertForceLogging(true);
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1);
ExecutorService executor =
new LoggingContextAwareExecutorService(Executors.newFixedThreadPool(1));
@@ -51,17 +97,32 @@
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 0000000..4d0b1f0
--- /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<PerformanceLogger> performanceLoggers;
+
+ // In this test setup this gets the DisabledMetricMaker injected. This means it doesn't record any
+ // metric, but performance log records are still created.
+ @Inject private MetricMaker metricMaker;
+
+ private TestPerformanceLogger testPerformanceLogger;
+ private RegistrationHandle performanceLoggerRegistrationHandle;
+
+ @Before
+ public void setup() {
+ Injector injector = Guice.createInjector(new InMemoryModule());
+ injector.injectMembers(this);
+
+ testPerformanceLogger = new TestPerformanceLogger();
+ performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger);
+ }
+
+ @After
+ public void cleanup() {
+ performanceLoggerRegistrationHandle.remove();
+
+ LoggingContext.getInstance().clearPerformanceLogEntries();
+ LoggingContext.getInstance().performanceLogging(false);
+ }
+
+ @Test
+ public void traceTimersInsidePerformanceLogContextCreatePerformanceLog() {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+ try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+ TraceContext.newTimer("test1").close();
+ TraceContext.newTimer("test2", "foo", "bar").close();
+ TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close();
+ TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close();
+ TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4")
+ .close();
+
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(5);
+ }
+
+ assertThat(testPerformanceLogger.logEntries())
+ .containsExactly(
+ PerformanceLogEntry.create("test1", ImmutableMap.of()),
+ PerformanceLogEntry.create("test2", ImmutableMap.of("foo", Optional.of("bar"))),
+ PerformanceLogEntry.create(
+ "test3", ImmutableMap.of("foo1", Optional.of("bar1"), "foo2", Optional.of("bar2"))),
+ PerformanceLogEntry.create(
+ "test4",
+ ImmutableMap.of(
+ "foo1",
+ Optional.of("bar1"),
+ "foo2",
+ Optional.of("bar2"),
+ "foo3",
+ Optional.of("bar3"))),
+ PerformanceLogEntry.create(
+ "test5",
+ ImmutableMap.of(
+ "foo1",
+ Optional.of("bar1"),
+ "foo2",
+ Optional.of("bar2"),
+ "foo3",
+ Optional.of("bar3"),
+ "foo4",
+ Optional.of("bar4"))))
+ .inOrder();
+
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ }
+
+ @Test
+ public void traceTimersInsidePerformanceLogContextCreatePerformanceLogNullValuesAllowed() {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+ try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+ TraceContext.newTimer("test1").close();
+ TraceContext.newTimer("test2", "foo", null).close();
+ TraceContext.newTimer("test3", "foo1", null, "foo2", null).close();
+ TraceContext.newTimer("test4", "foo1", null, "foo2", null, "foo3", null).close();
+ TraceContext.newTimer("test5", "foo1", null, "foo2", null, "foo3", null, "foo4", null)
+ .close();
+
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(5);
+ }
+
+ assertThat(testPerformanceLogger.logEntries())
+ .containsExactly(
+ PerformanceLogEntry.create("test1", ImmutableMap.of()),
+ PerformanceLogEntry.create("test2", ImmutableMap.of("foo", Optional.empty())),
+ PerformanceLogEntry.create(
+ "test3", ImmutableMap.of("foo1", Optional.empty(), "foo2", Optional.empty())),
+ PerformanceLogEntry.create(
+ "test4",
+ ImmutableMap.of(
+ "foo1", Optional.empty(), "foo2", Optional.empty(), "foo3", Optional.empty())),
+ PerformanceLogEntry.create(
+ "test5",
+ ImmutableMap.of(
+ "foo1",
+ Optional.empty(),
+ "foo2",
+ Optional.empty(),
+ "foo3",
+ Optional.empty(),
+ "foo4",
+ Optional.empty())))
+ .inOrder();
+
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ }
+
+ @Test
+ public void traceTimersOutsidePerformanceLogContextDoNotCreatePerformanceLog() {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+ TraceContext.newTimer("test1").close();
+ TraceContext.newTimer("test2", "foo", "bar").close();
+ TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close();
+ TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close();
+ TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4")
+ .close();
+
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ assertThat(testPerformanceLogger.logEntries()).isEmpty();
+ }
+
+ @Test
+ public void
+ traceTimersInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers() {
+ // Remove test performance logger so that there are no registered performance loggers.
+ performanceLoggerRegistrationHandle.remove();
+
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+ try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+
+ TraceContext.newTimer("test1").close();
+ TraceContext.newTimer("test2", "foo", "bar").close();
+ TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close();
+ TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close();
+ TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4")
+ .close();
+
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ }
+
+ assertThat(testPerformanceLogger.logEntries()).isEmpty();
+
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ }
+
+ @Test
+ public void timerMetricsInsidePerformanceLogContextCreatePerformanceLog() {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+ try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+ Timer0 timer0 =
+ metricMaker.newTimer("test1/latency", new Description("Latency metric for testing"));
+ timer0.start().close();
+
+ Timer1<String> timer1 =
+ metricMaker.newTimer(
+ "test2/latency",
+ new Description("Latency metric for testing"),
+ Field.ofString("foo"));
+ timer1.start("value1").close();
+
+ Timer2<String, String> timer2 =
+ metricMaker.newTimer(
+ "test3/latency",
+ new Description("Latency metric for testing"),
+ Field.ofString("foo"),
+ Field.ofString("bar"));
+ timer2.start("value1", "value2").close();
+
+ Timer3<String, String, String> timer3 =
+ metricMaker.newTimer(
+ "test4/latency",
+ new Description("Latency metric for testing"),
+ Field.ofString("foo"),
+ Field.ofString("bar"),
+ Field.ofString("baz"));
+ timer3.start("value1", "value2", "value3").close();
+
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(4);
+ }
+
+ assertThat(testPerformanceLogger.logEntries())
+ .containsExactly(
+ PerformanceLogEntry.create("test1/latency", ImmutableMap.of()),
+ PerformanceLogEntry.create(
+ "test2/latency", ImmutableMap.of("field1", Optional.of("value1"))),
+ PerformanceLogEntry.create(
+ "test3/latency",
+ ImmutableMap.of("field1", Optional.of("value1"), "field2", Optional.of("value2"))),
+ PerformanceLogEntry.create(
+ "test4/latency",
+ ImmutableMap.of(
+ "field1",
+ Optional.of("value1"),
+ "field2",
+ Optional.of("value2"),
+ "field3",
+ Optional.of("value3"))))
+ .inOrder();
+
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ }
+
+ @Test
+ public void timerMetricsInsidePerformanceLogContextCreatePerformanceLogNullValuesAllowed() {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+ try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+ Timer1<String> timer1 =
+ metricMaker.newTimer(
+ "test1/latency",
+ new Description("Latency metric for testing"),
+ Field.ofString("foo"));
+ timer1.start(null).close();
+
+ Timer2<String, String> timer2 =
+ metricMaker.newTimer(
+ "test2/latency",
+ new Description("Latency metric for testing"),
+ Field.ofString("foo"),
+ Field.ofString("bar"));
+ timer2.start(null, null).close();
+
+ Timer3<String, String, String> timer3 =
+ metricMaker.newTimer(
+ "test3/latency",
+ new Description("Latency metric for testing"),
+ Field.ofString("foo"),
+ Field.ofString("bar"),
+ Field.ofString("baz"));
+ timer3.start(null, null, null).close();
+
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(3);
+ }
+
+ assertThat(testPerformanceLogger.logEntries())
+ .containsExactly(
+ PerformanceLogEntry.create(
+ "test1/latency", ImmutableMap.of("field1", Optional.empty())),
+ PerformanceLogEntry.create(
+ "test2/latency",
+ ImmutableMap.of("field1", Optional.empty(), "field2", Optional.empty())),
+ PerformanceLogEntry.create(
+ "test3/latency",
+ ImmutableMap.of(
+ "field1",
+ Optional.empty(),
+ "field2",
+ Optional.empty(),
+ "field3",
+ Optional.empty())))
+ .inOrder();
+
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ }
+
+ @Test
+ public void timerMetricsOutsidePerformanceLogContextDoNotCreatePerformanceLog() {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+ Timer0 timer0 =
+ metricMaker.newTimer("test1/latency", new Description("Latency metric for testing"));
+ timer0.start().close();
+
+ Timer1<String> timer1 =
+ metricMaker.newTimer(
+ "test2/latency", new Description("Latency metric for testing"), Field.ofString("foo"));
+ timer1.start("value1").close();
+
+ Timer2<String, String> timer2 =
+ metricMaker.newTimer(
+ "test3/latency",
+ new Description("Latency metric for testing"),
+ Field.ofString("foo"),
+ Field.ofString("bar"));
+ timer2.start("value1", "value2").close();
+
+ Timer3<String, String, String> timer3 =
+ metricMaker.newTimer(
+ "test4/latency",
+ new Description("Latency metric for testing"),
+ Field.ofString("foo"),
+ Field.ofString("bar"),
+ Field.ofString("baz"));
+ timer3.start("value1", "value2", "value3").close();
+
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ assertThat(testPerformanceLogger.logEntries()).isEmpty();
+ }
+
+ @Test
+ public void
+ timerMetricssInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers() {
+ // Remove test performance logger so that there are no registered performance loggers.
+ performanceLoggerRegistrationHandle.remove();
+
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+ try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+
+ Timer0 timer0 =
+ metricMaker.newTimer("test1/latency", new Description("Latency metric for testing"));
+ timer0.start().close();
+
+ Timer1<String> timer1 =
+ metricMaker.newTimer(
+ "test2/latency",
+ new Description("Latency metric for testing"),
+ Field.ofString("foo"));
+ timer1.start("value1").close();
+
+ Timer2<String, String> timer2 =
+ metricMaker.newTimer(
+ "test3/latency",
+ new Description("Latency metric for testing"),
+ Field.ofString("foo"),
+ Field.ofString("bar"));
+ timer2.start("value1", "value2").close();
+
+ Timer3<String, String, String> timer3 =
+ metricMaker.newTimer(
+ "test4/latency",
+ new Description("Latency metric for testing"),
+ Field.ofString("foo"),
+ Field.ofString("bar"),
+ Field.ofString("baz"));
+ timer3.start("value1", "value2", "value3").close();
+
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ }
+
+ assertThat(testPerformanceLogger.logEntries()).isEmpty();
+
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ }
+
+ @Test
+ public void nestingPerformanceLogContextsIsPossible() {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+
+ try (PerformanceLogContext traceContext1 = new PerformanceLogContext(performanceLoggers)) {
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+ TraceContext.newTimer("test1").close();
+
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1);
+
+ try (PerformanceLogContext traceContext2 = new PerformanceLogContext(performanceLoggers)) {
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+
+ TraceContext.newTimer("test2").close();
+ TraceContext.newTimer("test3").close();
+
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(2);
+ }
+
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1);
+ }
+ assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse();
+ assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty();
+ }
+
+ private static class TestPerformanceLogger implements PerformanceLogger {
+ private List<PerformanceLogEntry> logEntries = new ArrayList<>();
+
+ @Override
+ public void log(String operation, long durationMs, Map<String, Optional<Object>> metaData) {
+ logEntries.add(PerformanceLogEntry.create(operation, metaData));
+ }
+
+ ImmutableList<PerformanceLogEntry> logEntries() {
+ return ImmutableList.copyOf(logEntries);
+ }
+ }
+
+ @AutoValue
+ abstract static class PerformanceLogEntry {
+ static PerformanceLogEntry create(String operation, Map<String, Optional<Object>> metaData) {
+ return new AutoValue_PerformanceLogContextTest_PerformanceLogEntry(
+ operation, ImmutableMap.copyOf(metaData));
+ }
+
+ abstract String operation();
+
+ abstract ImmutableMap<String, Object> metaData();
+ }
+}
diff --git a/javatests/com/google/gerrit/server/logging/TraceContextTest.java b/javatests/com/google/gerrit/server/logging/TraceContextTest.java
index 044d237..fedbe8b 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 @@
}
}
+ @Test
+ public void operationForTraceTimerCannotBeNull() throws Exception {
+ assertThrows(NullPointerException.class, () -> TraceContext.newTimer(null));
+ assertThrows(NullPointerException.class, () -> TraceContext.newTimer(null, "foo", "bar"));
+ assertThrows(
+ NullPointerException.class,
+ () -> TraceContext.newTimer(null, "foo1", "bar1", "foo2", "bar2"));
+ assertThrows(
+ NullPointerException.class,
+ () -> TraceContext.newTimer(null, "foo1", "bar1", "foo2", "bar2", "foo3", "bar3"));
+ assertThrows(
+ NullPointerException.class,
+ () ->
+ TraceContext.newTimer(
+ null, "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4"));
+ }
+
+ @Test
+ public void keysForTraceTimerCannotBeNull() throws Exception {
+ assertThrows(NullPointerException.class, () -> TraceContext.newTimer("test", null, "bar"));
+ assertThrows(
+ NullPointerException.class,
+ () -> TraceContext.newTimer("test", null, "bar1", "foo2", "bar2"));
+ assertThrows(
+ NullPointerException.class,
+ () -> TraceContext.newTimer("test", "foo1", "bar1", null, "bar2"));
+ assertThrows(
+ NullPointerException.class,
+ () -> TraceContext.newTimer("test", null, "bar1", "foo2", "bar2", "foo3", "bar3"));
+ assertThrows(
+ NullPointerException.class,
+ () -> TraceContext.newTimer("test", "foo1", "bar1", null, "bar2", "foo3", "bar3"));
+ assertThrows(
+ NullPointerException.class,
+ () -> TraceContext.newTimer("test", "foo1", "bar1", "foo2", "bar2", null, "bar3"));
+ assertThrows(
+ NullPointerException.class,
+ () ->
+ TraceContext.newTimer(
+ "test", null, "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4"));
+ assertThrows(
+ NullPointerException.class,
+ () ->
+ TraceContext.newTimer(
+ "test", "foo1", "bar1", null, "bar2", "foo3", "bar3", "foo4", "bar4"));
+ assertThrows(
+ NullPointerException.class,
+ () ->
+ TraceContext.newTimer(
+ "test", "foo1", "bar1", "foo2", "bar2", null, "bar3", "foo4", "bar4"));
+ assertThrows(
+ NullPointerException.class,
+ () ->
+ TraceContext.newTimer(
+ "test", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", null, "bar4"));
+ }
+
private void assertTags(ImmutableMap<String, ImmutableSet<String>> expectedTagMap) {
SortedMap<String, SortedSet<Object>> actualTagMap =
LoggingContext.getInstance().getTags().asMap();
