Add extension point to record execution times in a performance log
Add a new extension point that is invoked for all operations for which
the execution time is measured. The invocation of the extension point
does not happen immediately, but only at the end of a request (REST
call, SSH call, git push). Implementors can write the execution times
into a performance log for further analysis.
In Gerrit there are 2 possibilities to measure and record the execution
time of an operation:
1. TraceTimer:
Opens an autocloseable context to execute an operation. On close the
execution time is written to the server logs, but only if the request
is traced (or if log level was set to fine).
2. Timer Metrics:
Record execution times as a metric.
In addition this writes the execution time to the server logs, but
only if the request is traced (or if log level was set to fine).
These are the 2 places where performance log entries must be captured.
Performance log entries are stored in the LoggingContext which is based
on ThreadLocals. LoggingContextAwareRunnable and
LoggingContextAwareCallable which are used by all executors ensure that
captured performance log entries are properly copied between threads.
At the end of a request (supported are REST call, SSH call and git push)
the captured performance log entries are handed over to the
PerformanceLogger implementations.
If no PerformanceLogger is registered, or if execution times of
operations outside of request scope are measured, performance log
entries are not captured because nobody would consume them.
Storing the performance log records in the LoggingContext and invoking
the PerformanceLogger plugins only at the end of a request has some
advantages and disadvantages:
1. [advantage] Users of TraceTimer can continue to use the static
methods calls to create a TraceTimer (TraceContext.newTimer(...)). To
invoke the plugins immediately we would need to get them injected
into TraceTimer, hence callers would need a factory to create a
TraceTimer. That would result in quite some boilerplate code and in
addition some places that use TraceTimer (in VersionedMetaData)
cannot use injection.
2. [advantage] The metric system is setup very early in the injector
chain (in the DB injector, see SiteProgram#createDbInjector(boolean)).
To invoke the plugins directly from the timer metrics we would need
to have the PerformanceLogger plugins already available on this
injector level, which is difficult.
3. [disadvantage] The captured performance log records are kept in
memory while a request is processed. This leads to higher memory
foodprint, but we think this is OK.
To keep the performance and memory overhead for recording performance as
low as possible we did some optimizations:
1. Performance log entries are only created if there is a consumer (at
least one PerformanceLogger plugin + time measured inside request
context)
2. Performance log entries avoid the instantiation of a Map to record
meta data (instead we have dedicated fields for meta data keys and
values).
For the timer metrics we use generic names for the meta data keys
("field1", "field2", "field3"). This is because the actual field names
are not available at this place. We may make them available, but that's
outside the scope of this change and may be done in a follow-up change.
To be able to write stable acceptance tests that verify that the
PerformanceLogger plugins are invoked, it is important that the server
calls the plugins before the response is sent back to the client. This
is why the scope of the PerformanceLogContext in RestApiServlet is a
little smaller than the scope of the TraceContext.
Change-Id: I699db01609a1b4a88cee8959bdd9f1dfbb8dc74e
Signed-off-by: Edwin Kempin <ekempin@google.com>
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/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/receive/ReceiveCommits.java b/java/com/google/gerrit/server/git/receive/ReceiveCommits.java
index 73e0b1c..7a0b56e 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;
@@ -525,10 +531,12 @@
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());
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..deb111a 100644
--- a/java/com/google/gerrit/server/logging/LoggingContext.java
+++ b/java/com/google/gerrit/server/logging/LoggingContext.java
@@ -14,8 +14,13 @@
package com.google.gerrit.server.logging;
+import static java.util.Objects.requireNonNull;
+
+import com.google.common.collect.ImmutableList;
import com.google.common.collect.ImmutableSetMultimap;
import com.google.common.flogger.backend.Tags;
+import com.google.inject.Provider;
+import java.util.List;
import java.util.concurrent.Callable;
import java.util.logging.Level;
@@ -35,6 +40,9 @@
private static final ThreadLocal<MutableTags> tags = new ThreadLocal<>();
private static final ThreadLocal<Boolean> forceLogging = new ThreadLocal<>();
+ private static final ThreadLocal<Boolean> performanceLogging = new ThreadLocal<>();
+ private static final ThreadLocal<MutablePerformanceLogRecords> performanceLogRecords =
+ new ThreadLocal<>();
private LoggingContext() {}
@@ -47,14 +55,28 @@
if (runnable instanceof LoggingContextAwareRunnable) {
return runnable;
}
- return new LoggingContextAwareRunnable(runnable);
+
+ // Pass the MutablePerformanceLogRecords instance into the LoggingContextAwareRunnable
+ // constructor so that performance log records that are created in the wrapped runnable are
+ // added to this MutablePerformanceLogRecords instance. This is important since performance
+ // log records are processed only at the end of the request and performance log records that
+ // are created in another thread should not get lost.
+ return new LoggingContextAwareRunnable(
+ runnable, getInstance().getMutablePerformanceLogRecords());
}
public static <T> Callable<T> copy(Callable<T> callable) {
if (callable instanceof LoggingContextAwareCallable) {
return callable;
}
- return new LoggingContextAwareCallable<>(callable);
+
+ // Pass the MutablePerformanceLogRecords instance into the LoggingContextAwareCallable
+ // constructor so that performance log records that are created in the wrapped runnable are
+ // added to this MutablePerformanceLogRecords instance. This is important since performance
+ // log records are processed only at the end of the request and performance log records that
+ // are created in another thread should not get lost.
+ return new LoggingContextAwareCallable<>(
+ callable, getInstance().getMutablePerformanceLogRecords());
}
@Override
@@ -120,4 +142,103 @@
}
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;
+ }
}
diff --git a/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java b/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java
index 6aff5c4..3906630 100644
--- a/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java
+++ b/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java
@@ -14,6 +14,7 @@
package com.google.gerrit.server.logging;
+import com.google.common.collect.ImmutableList;
import com.google.common.collect.ImmutableSetMultimap;
import java.util.concurrent.Callable;
@@ -35,12 +36,24 @@
private final Thread callingThread;
private final ImmutableSetMultimap<String, String> tags;
private final boolean forceLogging;
+ private final boolean performanceLogging;
+ private final MutablePerformanceLogRecords mutablePerformanceLogRecords;
- LoggingContextAwareCallable(Callable<T> callable) {
+ /**
+ * Creates a LoggingContextAwareCallable that wraps the given {@link Callable}.
+ *
+ * @param callable Callable that should be wrapped.
+ * @param mutablePerformanceLogRecords instance of {@link MutablePerformanceLogRecords} to which
+ * performance log records that are created from the runnable are added
+ */
+ LoggingContextAwareCallable(
+ Callable<T> callable, MutablePerformanceLogRecords mutablePerformanceLogRecords) {
this.callable = callable;
this.callingThread = Thread.currentThread();
this.tags = LoggingContext.getInstance().getTagsAsMap();
this.forceLogging = LoggingContext.getInstance().isLoggingForced();
+ this.performanceLogging = LoggingContext.getInstance().isPerformanceLogging();
+ this.mutablePerformanceLogRecords = mutablePerformanceLogRecords;
}
@Override
@@ -54,13 +67,27 @@
LoggingContext loggingCtx = LoggingContext.getInstance();
ImmutableSetMultimap<String, String> oldTags = loggingCtx.getTagsAsMap();
boolean oldForceLogging = loggingCtx.isLoggingForced();
+ boolean oldPerformanceLogging = loggingCtx.isPerformanceLogging();
+ ImmutableList<PerformanceLogRecord> oldPerformanceLogRecords =
+ loggingCtx.getPerformanceLogRecords();
loggingCtx.setTags(tags);
loggingCtx.forceLogging(forceLogging);
+ loggingCtx.performanceLogging(performanceLogging);
+
+ // For the performance log records use the {@link MutablePerformanceLogRecords} instance from
+ // the logging context of the calling thread in the logging context of the new thread. This way
+ // performance log records that are created from the new thread are available from the logging
+ // context of the calling thread. This is important since performance log records are processed
+ // only at the end of the request and performance log records that are created in another thread
+ // should not get lost.
+ loggingCtx.setMutablePerformanceLogRecords(mutablePerformanceLogRecords);
try {
return callable.call();
} finally {
loggingCtx.setTags(oldTags);
loggingCtx.forceLogging(oldForceLogging);
+ loggingCtx.performanceLogging(oldPerformanceLogging);
+ loggingCtx.setPerformanceLogRecords(oldPerformanceLogRecords);
}
}
}
diff --git a/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java b/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java
index 0bd7d00..712459b 100644
--- a/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java
+++ b/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java
@@ -14,6 +14,7 @@
package com.google.gerrit.server.logging;
+import com.google.common.collect.ImmutableList;
import com.google.common.collect.ImmutableSetMultimap;
/**
@@ -53,12 +54,24 @@
private final Thread callingThread;
private final ImmutableSetMultimap<String, String> tags;
private final boolean forceLogging;
+ private final boolean performanceLogging;
+ private final MutablePerformanceLogRecords mutablePerformanceLogRecords;
- LoggingContextAwareRunnable(Runnable runnable) {
+ /**
+ * Creates a LoggingContextAwareRunnable that wraps the given {@link Runnable}.
+ *
+ * @param runnable Runnable that should be wrapped.
+ * @param mutablePerformanceLogRecords instance of {@link MutablePerformanceLogRecords} to which
+ * performance log records that are created from the runnable are added
+ */
+ LoggingContextAwareRunnable(
+ Runnable runnable, MutablePerformanceLogRecords mutablePerformanceLogRecords) {
this.runnable = runnable;
this.callingThread = Thread.currentThread();
this.tags = LoggingContext.getInstance().getTagsAsMap();
this.forceLogging = LoggingContext.getInstance().isLoggingForced();
+ this.performanceLogging = LoggingContext.getInstance().isPerformanceLogging();
+ this.mutablePerformanceLogRecords = mutablePerformanceLogRecords;
}
public Runnable unwrap() {
@@ -77,13 +90,27 @@
LoggingContext loggingCtx = LoggingContext.getInstance();
ImmutableSetMultimap<String, String> oldTags = loggingCtx.getTagsAsMap();
boolean oldForceLogging = loggingCtx.isLoggingForced();
+ boolean oldPerformanceLogging = loggingCtx.isPerformanceLogging();
+ ImmutableList<PerformanceLogRecord> oldPerformanceLogRecords =
+ loggingCtx.getPerformanceLogRecords();
loggingCtx.setTags(tags);
loggingCtx.forceLogging(forceLogging);
+ loggingCtx.performanceLogging(performanceLogging);
+
+ // For the performance log records use the {@link MutablePerformanceLogRecords} instance from
+ // the logging context of the calling thread in the logging context of the new thread. This way
+ // performance log records that are created from the new thread are available from the logging
+ // context of the calling thread. This is important since performance log records are processed
+ // only at the end of the request and performance log records that are created in another thread
+ // should not get lost.
+ loggingCtx.setMutablePerformanceLogRecords(mutablePerformanceLogRecords);
try {
runnable.run();
} finally {
loggingCtx.setTags(oldTags);
loggingCtx.forceLogging(oldForceLogging);
+ loggingCtx.performanceLogging(oldPerformanceLogging);
+ loggingCtx.setPerformanceLogRecords(oldPerformanceLogRecords);
}
}
}
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..02143f0
--- /dev/null
+++ b/java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java
@@ -0,0 +1,47 @@
+// Copyright (C) 2018 The Android Open Source Project
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package com.google.gerrit.server.logging;
+
+import com.google.common.collect.ImmutableList;
+import java.util.ArrayList;
+import java.util.List;
+
+/**
+ * Thread-safe store for performance log records.
+ *
+ * <p>This class is intended to keep track of performance log records in {@link LoggingContext}. It
+ * needs to be thread-safe because it gets shared between threads when the logging context is copied
+ * to another thread (see {@link LoggingContextAwareRunnable} and {@link
+ * LoggingContextAwareCallable}. In this case the logging contexts of both threads share the same
+ * instance of this class. This is important since performance log records are processed only at the
+ * end of a request and performance log records that are created in another thread should not get
+ * lost.
+ */
+public class MutablePerformanceLogRecords {
+ private final ArrayList<PerformanceLogRecord> performanceLogRecords = new ArrayList<>();
+
+ public synchronized void add(PerformanceLogRecord record) {
+ performanceLogRecords.add(record);
+ }
+
+ public synchronized void set(List<PerformanceLogRecord> records) {
+ performanceLogRecords.clear();
+ performanceLogRecords.addAll(records);
+ }
+
+ public synchronized ImmutableList<PerformanceLogRecord> list() {
+ return ImmutableList.copyOf(performanceLogRecords);
+ }
+}
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 06fa302..b018da4 100644
--- a/java/com/google/gerrit/server/logging/TraceContext.java
+++ b/java/com/google/gerrit/server/logging/TraceContext.java
@@ -155,35 +155,32 @@
/**
* 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 message 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 message, String key, Object value) {
- return new TraceTimer(message + " (%s=%s)", key, value);
+ 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 message 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
@@ -191,16 +188,23 @@
* @return the trace timer
*/
public static TraceTimer newTimer(
- String message, String key1, Object value1, String key2, Object value2) {
- return new TraceTimer(message + " (%s=%s, %s=%s)", key1, value1, key2, value2);
+ 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.
*
- * <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
* @param key1 first meta data key
* @param value1 first meta data value
* @param key2 second meta data key
@@ -210,23 +214,27 @@
* @return the trace timer
*/
public static TraceTimer newTimer(
- String message,
+ String operation,
String key1,
- Object value1,
+ @Nullable Object value1,
String key2,
- Object value2,
+ @Nullable Object value2,
String key3,
- Object value3) {
+ @Nullable Object value3) {
return new TraceTimer(
- message + " (%s=%s, %s=%s, %s=%s)", key1, value1, key2, value2, key3, value3);
+ requireNonNull(operation, "operation is required"),
+ requireNonNull(key1, "key1 is required"),
+ value1,
+ requireNonNull(key2, "key2 is required"),
+ value2,
+ requireNonNull(key3, "key3 is required"),
+ value3);
}
/**
* Opens a new timer that logs the time for an operation if request tracing is enabled.
*
- * <p>If request tracing is not enabled this is a no-op.
- *
- * @param message 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
@@ -238,24 +246,24 @@
* @return the trace timer
*/
public static TraceTimer newTimer(
- String message,
+ String operation,
String key1,
- Object value1,
+ @Nullable Object value1,
String key2,
- Object value2,
+ @Nullable Object value2,
String key3,
- Object value3,
+ @Nullable Object value3,
String key4,
- Object value4) {
+ @Nullable Object value4) {
return new TraceTimer(
- message + " (%s=%s, %s=%s, %s=%s, %s=%s)",
- key1,
+ requireNonNull(operation, "operation is required"),
+ requireNonNull(key1, "key1 is required"),
value1,
- key2,
+ requireNonNull(key2, "key2 is required"),
value2,
- key3,
+ requireNonNull(key3, "key3 is required"),
value3,
- key4,
+ requireNonNull(key4, "key4 is required"),
value4);
}
@@ -265,52 +273,86 @@
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 operation) {
+ this(
+ elapsedMs -> {
+ LoggingContext.getInstance()
+ .addPerformanceLogRecord(() -> PerformanceLogRecord.create(operation, elapsedMs));
+ logger.atFine().log("%s (%d ms)", operation, elapsedMs);
+ });
}
- private TraceTimer(String format, @Nullable Object arg1, @Nullable Object arg2) {
- this(elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, 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 format,
- @Nullable Object arg1,
- @Nullable Object arg2,
- @Nullable Object arg3,
- @Nullable Object arg4) {
+ String operation,
+ String key1,
+ @Nullable Object value1,
+ String key2,
+ @Nullable Object value2) {
this(
- elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, arg3, arg4, elapsedMs));
+ elapsedMs -> {
+ LoggingContext.getInstance()
+ .addPerformanceLogRecord(
+ () ->
+ PerformanceLogRecord.create(
+ operation, elapsedMs, key1, value1, key2, value2));
+ logger.atFine().log(
+ "%s (%s=%s, %s=%s) (%d ms)", operation, key1, value1, key2, value2, elapsedMs);
+ });
}
private TraceTimer(
- String format,
- @Nullable Object arg1,
- @Nullable Object arg2,
- @Nullable Object arg3,
- @Nullable Object arg4,
- @Nullable Object arg5,
- @Nullable Object arg6) {
+ String operation,
+ String key1,
+ @Nullable Object value1,
+ String key2,
+ @Nullable Object value2,
+ String key3,
+ @Nullable Object value3) {
this(
- elapsedMs ->
- logger.atFine().log(
- format + " (%d ms)", arg1, arg2, arg3, arg4, arg5, arg6, elapsedMs));
+ 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 format,
- @Nullable Object arg1,
- @Nullable Object arg2,
- @Nullable Object arg3,
- @Nullable Object arg4,
- @Nullable Object arg5,
- @Nullable Object arg6,
- @Nullable Object arg7,
- @Nullable Object arg8) {
+ String operation,
+ String key1,
+ @Nullable Object value1,
+ String key2,
+ @Nullable Object value2,
+ String key3,
+ @Nullable Object value3,
+ String key4,
+ @Nullable Object value4) {
this(
- elapsedMs ->
- logger.atFine().log(
- format + " (%d ms)", arg1, arg2, arg3, arg4, arg5, arg6, arg7, arg8, elapsedMs));
+ 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/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/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();
