opendev/gerrit
Code Issues Proposed changes

Merge changes from topic "new-TraceContext-newTimer-signature"

Browse Source 
* changes:
  ReceiveCommits: Pull up trace context from processCommandsUnsafe into processCommands
  Log warning when LoggingContext of background thread is not initially empty
  Unset logging context before returning a thread back to the thread pool
  Add extension point to record execution times in a performance log
  TraceContext#newTimer: Separate message from arguments
This commit is contained in:
Edwin Kempin
2019-06-13 11:39:35 +00:00
committed by Gerrit Code Review
parent ce7fea34da 2f6a8ffd27
commit b277edfe60
41 changed files with 2099 additions and 449 deletions
Download Patch File Download Diff File Expand all files Collapse all files

9
Documentation/dev-plugins.txt
View File

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

466
java/com/google/gerrit/httpd/restapi/RestApiServlet.java
View File

@@ -69,6 +69,7 @@ import com.google.gerrit.common.Nullable;
import com.google.gerrit.common.RawInputUtil;
import com.google.gerrit.extensions.registration.DynamicItem;
import com.google.gerrit.extensions.registration.DynamicMap;
import com.google.gerrit.extensions.registration.DynamicSet;
import com.google.gerrit.extensions.registration.PluginName;
import com.google.gerrit.extensions.restapi.AuthException;
import com.google.gerrit.extensions.restapi.BadRequestException;
@@ -109,6 +110,8 @@ import com.google.gerrit.server.audit.ExtendedHttpAuditEvent;
import com.google.gerrit.server.cache.PerThreadCache;
import com.google.gerrit.server.config.GerritServerConfig;
import com.google.gerrit.server.group.GroupAuditService;
import com.google.gerrit.server.logging.PerformanceLogContext;
import com.google.gerrit.server.logging.PerformanceLogger;
import com.google.gerrit.server.logging.RequestId;
import com.google.gerrit.server.logging.TraceContext;
import com.google.gerrit.server.permissions.GlobalPermission;
@@ -229,6 +232,7 @@ public class RestApiServlet extends HttpServlet {
final RestApiMetrics metrics;
final Pattern allowOrigin;
final RestApiQuotaEnforcer quotaChecker;
final DynamicSet<PerformanceLogger> performanceLoggers;
@Inject
Globals(
@@ -239,7 +243,8 @@ public class RestApiServlet extends HttpServlet {
GroupAuditService auditService,
RestApiMetrics metrics,
RestApiQuotaEnforcer quotaChecker,
@GerritServerConfig Config cfg) {
@GerritServerConfig Config cfg,
DynamicSet<PerformanceLogger> performanceLoggers) {
this.currentUser = currentUser;
this.webSession = webSession;
this.paramParser = paramParser;
@@ -247,6 +252,7 @@ public class RestApiServlet extends HttpServlet {
this.auditService = auditService;
this.metrics = metrics;
this.quotaChecker = quotaChecker;
this.performanceLoggers = performanceLoggers;
allowOrigin = makeAllowOrigin(cfg);
}
@@ -294,258 +300,266 @@ public class RestApiServlet extends HttpServlet {
try (TraceContext traceContext = enableTracing(req, res)) {
try (PerThreadCache ignored = PerThreadCache.create()) {
logger.atFinest().log(
"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) {

1
java/com/google/gerrit/metrics/BUILD
View File

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

7
java/com/google/gerrit/metrics/Timer0.java
View File

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

11
java/com/google/gerrit/metrics/Timer1.java
View File

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

12
java/com/google/gerrit/metrics/Timer2.java
View File

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

14
java/com/google/gerrit/metrics/Timer3.java
View File

@@ -18,6 +18,8 @@ import static java.util.concurrent.TimeUnit.NANOSECONDS;
import com.google.common.flogger.FluentLogger;
import com.google.gerrit.extensions.registration.RegistrationHandle;
import com.google.gerrit.server.logging.LoggingContext;
import com.google.gerrit.server.logging.PerformanceLogRecord;
import java.util.concurrent.TimeUnit;
/**
@@ -85,8 +87,16 @@ public abstract class Timer3<F1, F2, F3> implements RegistrationHandle {
* @param unit time unit of the value
*/
public final void record(F1 field1, F2 field2, F3 field3, long value, TimeUnit unit) {
logger.atFinest().log(
"%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);
}

1
java/com/google/gerrit/server/BUILD
View File

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

6
java/com/google/gerrit/server/StarredChangesUtil.java
View File

@@ -376,7 +376,7 @@ public class StarredChangesUtil {
}
public static StarRef readLabels(Repository repo, String refName) throws IOException {
try (TraceTimer traceTimer = TraceContext.newTimer("Read star labels from %s", refName)) {
try (TraceTimer traceTimer = TraceContext.newTimer("Read star labels", "ref", refName)) {
Ref ref = repo.exactRef(refName);
if (ref == null) {
return StarRef.MISSING;
@@ -450,7 +450,7 @@ public class StarredChangesUtil {
Repository repo, String refName, ObjectId oldObjectId, Collection<String> labels)
throws IOException, InvalidLabelsException {
try (TraceTimer traceTimer =
TraceContext.newTimer("Update star labels in %s (labels=%s)", refName, labels);
TraceContext.newTimer("Update star labels", "ref", refName, "labels", labels);
RevWalk rw = new RevWalk(repo)) {
RefUpdate u = repo.updateRef(refName);
u.setExpectedOldObjectId(oldObjectId);
@@ -487,7 +487,7 @@ public class StarredChangesUtil {
return;
}
try (TraceTimer traceTimer = TraceContext.newTimer("Delete star labels in %s", refName)) {
try (TraceTimer traceTimer = TraceContext.newTimer("Delete star labels", "ref", refName)) {
RefUpdate u = repo.updateRef(refName);
u.setForceUpdate(true);
u.setExpectedOldObjectId(oldObjectId);

2
java/com/google/gerrit/server/account/AccountCacheImpl.java
View File

@@ -183,7 +183,7 @@ public class AccountCacheImpl implements AccountCache {
@Override
public Optional<AccountState> load(Account.Id who) throws Exception {
try (TraceTimer timer = TraceContext.newTimer("Loading account %s", who)) {
try (TraceTimer timer = TraceContext.newTimer("Loading account", "accountId", who)) {
return accounts.get(who);
}
}

6
java/com/google/gerrit/server/account/GroupCacheImpl.java
View File

@@ -149,7 +149,7 @@ public class GroupCacheImpl implements GroupCache {
@Override
public Optional<InternalGroup> load(AccountGroup.Id key) throws Exception {
try (TraceTimer timer = TraceContext.newTimer("Loading group %s by ID", key)) {
try (TraceTimer timer = TraceContext.newTimer("Loading group by ID", "groupId", key)) {
return groupQueryProvider.get().byId(key);
}
}
@@ -165,7 +165,7 @@ public class GroupCacheImpl implements GroupCache {
@Override
public Optional<InternalGroup> load(String name) throws Exception {
try (TraceTimer timer = TraceContext.newTimer("Loading group '%s' by name", name)) {
try (TraceTimer timer = TraceContext.newTimer("Loading group by name", "groupName", name)) {
return groupQueryProvider.get().byName(AccountGroup.nameKey(name));
}
}
@@ -181,7 +181,7 @@ public class GroupCacheImpl implements GroupCache {
@Override
public Optional<InternalGroup> load(String uuid) throws Exception {
try (TraceTimer timer = TraceContext.newTimer("Loading group %s by UUID", uuid)) {
try (TraceTimer timer = TraceContext.newTimer("Loading group by UUID", "groupUuid", uuid)) {
return groups.getGroup(AccountGroup.uuid(uuid));
}
}

5
java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java
View File

@@ -152,7 +152,8 @@ public class GroupIncludeCacheImpl implements GroupIncludeCache {
@Override
public ImmutableSet<AccountGroup.UUID> load(Account.Id memberId) {
try (TraceTimer timer = TraceContext.newTimer("Loading groups with member %s", memberId)) {
try (TraceTimer timer =
TraceContext.newTimer("Loading groups with member", "memberId", memberId)) {
return groupQueryProvider.get().byMember(memberId).stream()
.map(InternalGroup::getGroupUUID)
.collect(toImmutableSet());
@@ -171,7 +172,7 @@ public class GroupIncludeCacheImpl implements GroupIncludeCache {
@Override
public ImmutableList<AccountGroup.UUID> load(AccountGroup.UUID key) {
try (TraceTimer timer = TraceContext.newTimer("Loading parent groups of %s", key)) {
try (TraceTimer timer = TraceContext.newTimer("Loading parent groups", "groupUuid", key)) {
return groupQueryProvider.get().bySubgroup(key).stream()
.map(InternalGroup::getGroupUUID)
.collect(toImmutableList());

3
java/com/google/gerrit/server/account/externalids/ExternalIdCacheImpl.java
View File

@@ -157,8 +157,7 @@ class ExternalIdCacheImpl implements ExternalIdCache {
@Override
public AllExternalIds load(ObjectId notesRev) throws Exception {
try (TraceTimer timer =
TraceContext.newTimer("Loading external IDs (revision=%s)", notesRev)) {
try (TraceTimer timer = TraceContext.newTimer("Loading external IDs", "revision", notesRev)) {
ImmutableSet<ExternalId> externalIds = externalIdReader.all(notesRev);
externalIds.forEach(ExternalId::checkThatBlobIdIsSet);
return AllExternalIds.create(externalIds);

7
java/com/google/gerrit/server/auth/ldap/LdapRealm.java
View File

@@ -353,7 +353,8 @@ class LdapRealm extends AbstractRealm {
@Override
public Optional<Account.Id> load(String username) throws Exception {
try (TraceTimer timer = TraceContext.newTimer("Loading account for username %s", username)) {
try (TraceTimer timer =
TraceContext.newTimer("Loading account for username", "username", username)) {
return externalIds
.get(ExternalId.Key.create(SCHEME_GERRIT, username))
.map(ExternalId::accountId);
@@ -372,7 +373,7 @@ class LdapRealm extends AbstractRealm {
@Override
public Set<AccountGroup.UUID> load(String username) throws Exception {
try (TraceTimer timer =
TraceContext.newTimer("Loading group for member with username %s", username)) {
TraceContext.newTimer("Loading group for member with username", "username", username)) {
final DirContext ctx = helper.open();
try {
return helper.queryForGroups(ctx, username, null);
@@ -393,7 +394,7 @@ class LdapRealm extends AbstractRealm {
@Override
public Boolean load(String groupDn) throws Exception {
try (TraceTimer timer = TraceContext.newTimer("Loading groupDn %s", groupDn)) {
try (TraceTimer timer = TraceContext.newTimer("Loading groupDn", "groupDn", groupDn)) {
final DirContext ctx = helper.open();
try {
Name compositeGroupName = new CompositeName().add(groupDn);

2
java/com/google/gerrit/server/cache/h2/H2CacheImpl.java vendored
View File

@@ -237,7 +237,7 @@ public class H2CacheImpl<K, V> extends AbstractLoadingCache<K, V> implements Per
@Override
public ValueHolder<V> load(K key) throws Exception {
try (TraceTimer timer = TraceContext.newTimer("Loading value for %s from cache", key)) {
try (TraceTimer timer = TraceContext.newTimer("Loading value from cache", "key", key)) {
if (store.mightContain(key)) {
ValueHolder<V> h = store.getIfPresent(key);
if (h != null) {

2
java/com/google/gerrit/server/config/GerritGlobalModule.java
View File

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

2
java/com/google/gerrit/server/git/PureRevertCache.java
View File

@@ -151,7 +151,7 @@ public class PureRevertCache {
@Override
public Boolean load(PureRevertKeyProto key) throws BadRequestException, IOException {
try (TraceContext.TraceTimer ignored =
TraceContext.newTimer("Loading pure revert for %s", key)) {
TraceContext.newTimer("Loading pure revert", "key", key)) {
ObjectId original = ObjectIdConverter.create().fromByteString(key.getClaimedOriginal());
ObjectId revert = ObjectIdConverter.create().fromByteString(key.getClaimedRevert());
Project.NameKey project = Project.nameKey(key.getProject());

3
java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java
View File

@@ -152,7 +152,8 @@ public class SearchingChangeCacheImpl implements GitReferenceUpdatedListener {
@Override
public List<CachedChange> load(Project.NameKey key) throws Exception {
try (TraceTimer timer = TraceContext.newTimer("Loading changes of project %s", key);
try (TraceTimer timer =
TraceContext.newTimer("Loading changes of project", "projectName", key);
ManualRequestContext ctx = requestContext.open()) {
List<ChangeData> cds =
queryProvider

13
java/com/google/gerrit/server/git/meta/VersionedMetaData.java
View File

@@ -499,8 +499,15 @@ public abstract class VersionedMetaData {
try (TraceTimer timer =
TraceContext.newTimer(
"Read file '%s' from ref '%s' of project '%s' from revision '%s'",
fileName, getRefName(), projectName, revision.name());
"Read file",
"fileName",
fileName,
"ref",
getRefName(),
"projectName",
projectName,
"revision",
revision.name());
TreeWalk tw = TreeWalk.forPath(reader, fileName, revision.getTree())) {
if (tw != null) {
ObjectLoader obj = reader.open(tw.getObjectId(0), Constants.OBJ_BLOB);
@@ -575,7 +582,7 @@ public abstract class VersionedMetaData {
protected void saveFile(String fileName, byte[] raw) throws IOException {
try (TraceTimer timer =
TraceContext.newTimer(
"Save file '%s' in ref '%s' of project '%s'", fileName, getRefName(), projectName)) {
"Save file", "fileName", fileName, "ref", getRefName(), "projectName", projectName)) {
DirCacheEditor editor = newTree.editor();
if (raw != null && 0 < raw.length) {
final ObjectId blobId = inserter.insert(Constants.OBJ_BLOB, raw);

205
java/com/google/gerrit/server/git/receive/ReceiveCommits.java
View File

@@ -74,6 +74,7 @@ import com.google.gerrit.extensions.api.projects.ProjectConfigEntryType;
import com.google.gerrit.extensions.client.GeneralPreferencesInfo;
import com.google.gerrit.extensions.registration.DynamicItem;
import com.google.gerrit.extensions.registration.DynamicMap;
import com.google.gerrit.extensions.registration.DynamicSet;
import com.google.gerrit.extensions.registration.Extension;
import com.google.gerrit.extensions.restapi.AuthException;
import com.google.gerrit.extensions.restapi.BadRequestException;
@@ -118,6 +119,8 @@ import com.google.gerrit.server.git.validators.RefOperationValidationException;
import com.google.gerrit.server.git.validators.RefOperationValidators;
import com.google.gerrit.server.git.validators.ValidationMessage;
import com.google.gerrit.server.index.change.ChangeIndexer;
import com.google.gerrit.server.logging.PerformanceLogContext;
import com.google.gerrit.server.logging.PerformanceLogger;
import com.google.gerrit.server.logging.RequestId;
import com.google.gerrit.server.logging.TraceContext;
import com.google.gerrit.server.mail.MailUtil.MailRecipients;
@@ -306,6 +309,7 @@ class ReceiveCommits {
private final MergedByPushOp.Factory mergedByPushOpFactory;
private final PatchSetInfoFactory patchSetInfoFactory;
private final PatchSetUtil psUtil;
private final DynamicSet<PerformanceLogger> performanceLoggers;
private final PermissionBackend permissionBackend;
private final ProjectCache projectCache;
private final Provider<InternalChangeQuery> queryProvider;
@@ -382,6 +386,7 @@ class ReceiveCommits {
MergedByPushOp.Factory mergedByPushOpFactory,
PatchSetInfoFactory patchSetInfoFactory,
PatchSetUtil psUtil,
DynamicSet<PerformanceLogger> performanceLoggers,
PermissionBackend permissionBackend,
ProjectCache projectCache,
Provider<InternalChangeQuery> queryProvider,
@@ -427,6 +432,7 @@ class ReceiveCommits {
this.pluginConfigEntries = pluginConfigEntries;
this.projectCache = projectCache;
this.psUtil = psUtil;
this.performanceLoggers = performanceLoggers;
this.queryProvider = queryProvider;
this.receiveConfig = receiveConfig;
this.refValidatorsFactory = refValidatorsFactory;
@@ -506,117 +512,120 @@ class ReceiveCommits {
}
void processCommands(Collection<ReceiveCommand> commands, MultiProgressMonitor progress) {
Task commandProgress = progress.beginSubTask("refs", UNKNOWN);
commands = commands.stream().map(c -> wrapReceiveCommand(c, commandProgress)).collect(toList());
processCommandsUnsafe(commands, progress);
rejectRemaining(commands, "internal server error");
// This sends error messages before the 'done' string of the progress monitor is sent.
// Currently, the test framework relies on this ordering to understand if pushes completed
// successfully.
sendErrorMessages();
commandProgress.end();
progress.end();
}
// Process as many commands as possible, but may leave some commands in state NOT_ATTEMPTED.
private void processCommandsUnsafe(
Collection<ReceiveCommand> commands, MultiProgressMonitor progress) {
parsePushOptions();
try (TraceContext traceContext =
TraceContext.newTrace(
tracePushOption.isPresent(),
tracePushOption.orElse(null),
(tagName, traceId) -> addMessage(tagName + ": " + traceId))) {
TraceContext.newTrace(
tracePushOption.isPresent(),
tracePushOption.orElse(null),
(tagName, traceId) -> addMessage(tagName + ": " + traceId));
PerformanceLogContext performanceLogContext =
new PerformanceLogContext(performanceLoggers)) {
traceContext.addTag(RequestId.Type.RECEIVE_ID, new RequestId(project.getNameKey().get()));
logger.atFinest().log("Calling user: %s", user.getLoggableName());
// Log the push options here, rather than in parsePushOptions(), so that they are included
// into the trace if tracing is enabled.
logger.atFine().log("push options: %s", receivePack.getPushOptions());
if (!projectState.getProject().getState().permitsWrite()) {
for (ReceiveCommand cmd : commands) {
reject(cmd, "prohibited by Gerrit: project state does not permit write");
}
return;
}
Task commandProgress = progress.beginSubTask("refs", UNKNOWN);
commands =
commands.stream().map(c -> wrapReceiveCommand(c, commandProgress)).collect(toList());
processCommandsUnsafe(commands, progress);
rejectRemaining(commands, "internal server error");
logger.atFine().log("Parsing %d commands", commands.size());
// This sends error messages before the 'done' string of the progress monitor is sent.
// Currently, the test framework relies on this ordering to understand if pushes completed
// successfully.
sendErrorMessages();
List<ReceiveCommand> magicCommands = new ArrayList<>();
List<ReceiveCommand> directPatchSetPushCommands = new ArrayList<>();
List<ReceiveCommand> regularCommands = new ArrayList<>();
for (ReceiveCommand cmd : commands) {
if (MagicBranch.isMagicBranch(cmd.getRefName())) {
magicCommands.add(cmd);
} else if (isDirectChangesPush(cmd.getRefName())) {
directPatchSetPushCommands.add(cmd);
} else {
regularCommands.add(cmd);
}
}
int commandTypes =
(magicCommands.isEmpty() ? 0 : 1)
+ (directPatchSetPushCommands.isEmpty() ? 0 : 1)
+ (regularCommands.isEmpty() ? 0 : 1);
if (commandTypes > 1) {
rejectRemaining(commands, "cannot combine normal pushes and magic pushes");
return;
}
try {
if (!regularCommands.isEmpty()) {
handleRegularCommands(regularCommands, progress);
return;
}
for (ReceiveCommand cmd : directPatchSetPushCommands) {
parseDirectChangesPush(cmd);
}
boolean first = true;
for (ReceiveCommand cmd : magicCommands) {
if (first) {
parseMagicBranch(cmd);
first = false;
} else {
reject(cmd, "duplicate request");
}
}
} catch (PermissionBackendException | NoSuchProjectException | IOException err) {
logger.atSevere().withCause(err).log("Failed to process refs in %s", project.getName());
return;
}
Task newProgress = progress.beginSubTask("new", UNKNOWN);
Task replaceProgress = progress.beginSubTask("updated", UNKNOWN);
List<CreateRequest> newChanges = Collections.emptyList();
if (magicBranch != null && magicBranch.cmd.getResult() == NOT_ATTEMPTED) {
newChanges = selectNewAndReplacedChangesFromMagicBranch(newProgress);
}
// Commit validation has already happened, so any changes without Change-Id are for the
// deprecated feature.
warnAboutMissingChangeId(newChanges);
preparePatchSetsForReplace(newChanges);
insertChangesAndPatchSets(newChanges, replaceProgress);
newProgress.end();
replaceProgress.end();
queueSuccessMessages(newChanges);
logger.atFine().log(
"Command results: %s",
lazy(() -> commands.stream().map(ReceiveCommits::commandToString).collect(joining(","))));
commandProgress.end();
progress.end();
}
}
// Process as many commands as possible, but may leave some commands in state NOT_ATTEMPTED.
private void processCommandsUnsafe(
Collection<ReceiveCommand> commands, MultiProgressMonitor progress) {
logger.atFinest().log("Calling user: %s", user.getLoggableName());
if (!projectState.getProject().getState().permitsWrite()) {
for (ReceiveCommand cmd : commands) {
reject(cmd, "prohibited by Gerrit: project state does not permit write");
}
return;
}
logger.atFine().log("Parsing %d commands", commands.size());
List<ReceiveCommand> magicCommands = new ArrayList<>();
List<ReceiveCommand> directPatchSetPushCommands = new ArrayList<>();
List<ReceiveCommand> regularCommands = new ArrayList<>();
for (ReceiveCommand cmd : commands) {
if (MagicBranch.isMagicBranch(cmd.getRefName())) {
magicCommands.add(cmd);
} else if (isDirectChangesPush(cmd.getRefName())) {
directPatchSetPushCommands.add(cmd);
} else {
regularCommands.add(cmd);
}
}
int commandTypes =
(magicCommands.isEmpty() ? 0 : 1)
+ (directPatchSetPushCommands.isEmpty() ? 0 : 1)
+ (regularCommands.isEmpty() ? 0 : 1);
if (commandTypes > 1) {
rejectRemaining(commands, "cannot combine normal pushes and magic pushes");
return;
}
try {
if (!regularCommands.isEmpty()) {
handleRegularCommands(regularCommands, progress);
return;
}
for (ReceiveCommand cmd : directPatchSetPushCommands) {
parseDirectChangesPush(cmd);
}
boolean first = true;
for (ReceiveCommand cmd : magicCommands) {
if (first) {
parseMagicBranch(cmd);
first = false;
} else {
reject(cmd, "duplicate request");
}
}
} catch (PermissionBackendException | NoSuchProjectException | IOException err) {
logger.atSevere().withCause(err).log("Failed to process refs in %s", project.getName());
return;
}
Task newProgress = progress.beginSubTask("new", UNKNOWN);
Task replaceProgress = progress.beginSubTask("updated", UNKNOWN);
List<CreateRequest> newChanges = Collections.emptyList();
if (magicBranch != null && magicBranch.cmd.getResult() == NOT_ATTEMPTED) {
newChanges = selectNewAndReplacedChangesFromMagicBranch(newProgress);
}
// Commit validation has already happened, so any changes without Change-Id are for the
// deprecated feature.
warnAboutMissingChangeId(newChanges);
preparePatchSetsForReplace(newChanges);
insertChangesAndPatchSets(newChanges, replaceProgress);
newProgress.end();
replaceProgress.end();
queueSuccessMessages(newChanges);
logger.atFine().log(
"Command results: %s",
lazy(() -> commands.stream().map(ReceiveCommits::commandToString).collect(joining(","))));
}
private void sendErrorMessages() {
if (!errors.isEmpty()) {
logger.atFine().log("Handling error conditions: %s", errors.keySet());

6
java/com/google/gerrit/server/group/db/GroupsUpdate.java
View File

@@ -265,7 +265,9 @@ public class GroupsUpdate {
throws DuplicateKeyException, IOException, ConfigInvalidException {
try (TraceTimer timer =
TraceContext.newTimer(
"Creating group '%s'", groupUpdate.getName().orElseGet(groupCreation::getNameKey))) {
"Creating group",
"groupName",
groupUpdate.getName().orElseGet(groupCreation::getNameKey))) {
InternalGroup createdGroup = createGroupInNoteDbWithRetry(groupCreation, groupUpdate);
evictCachesOnGroupCreation(createdGroup);
dispatchAuditEventsOnGroupCreation(createdGroup);
@@ -285,7 +287,7 @@ public class GroupsUpdate {
*/
public void updateGroup(AccountGroup.UUID groupUuid, InternalGroupUpdate groupUpdate)
throws DuplicateKeyException, IOException, NoSuchGroupException, ConfigInvalidException {
try (TraceTimer timer = TraceContext.newTimer("Updating group %s", groupUuid)) {
try (TraceTimer timer = TraceContext.newTimer("Updating group", "groupUuid", groupUuid)) {
Optional<Timestamp> updatedOn = groupUpdate.getUpdatedOn();
if (!updatedOn.isPresent()) {
updatedOn = Optional.of(TimeUtil.nowTs());

12
java/com/google/gerrit/server/index/account/AccountIndexerImpl.java
View File

@@ -90,13 +90,21 @@ public class AccountIndexerImpl implements AccountIndexer {
if (accountState.isPresent()) {
try (TraceTimer traceTimer =
TraceContext.newTimer(
"Replacing account %d in index version %d", id.get(), i.getSchema().getVersion())) {
"Replacing account in index",
"accountId",
id.get(),
"indexVersion",
i.getSchema().getVersion())) {
i.replace(accountState.get());
}
} else {
try (TraceTimer traceTimer =
TraceContext.newTimer(
"Deleteing account %d in index version %d", id.get(), i.getSchema().getVersion())) {
"Deleting account in index",
"accountId",
id.get(),
"indexVersion",
i.getSchema().getVersion())) {
i.delete(id);
}
}

13
java/com/google/gerrit/server/index/change/ChangeIndexer.java
View File

@@ -174,8 +174,11 @@ public class ChangeIndexer {
for (Index<?, ChangeData> i : getWriteIndexes()) {
try (TraceTimer traceTimer =
TraceContext.newTimer(
"Replacing change %d in index version %d",
cd.getId().get(), i.getSchema().getVersion())) {
"Replacing change in index",
"changeId",
cd.getId().get(),
"indexVersion",
i.getSchema().getVersion())) {
i.replace(cd);
}
}
@@ -336,7 +339,11 @@ public class ChangeIndexer {
for (ChangeIndex i : getWriteIndexes()) {
try (TraceTimer traceTimer =
TraceContext.newTimer(
"Deleteing change %d in index version %d", id.get(), i.getSchema().getVersion())) {
"Deleting change in index",
"changeId",
id.get(),
"indexVersion",
i.getSchema().getVersion())) {
i.delete(id);
}
}

2
java/com/google/gerrit/server/logging/BUILD
View File

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

150
java/com/google/gerrit/server/logging/LoggingContext.java
View File

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

39
java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java
View File

@@ -15,6 +15,7 @@
package com.google.gerrit.server.logging;
import com.google.common.collect.ImmutableSetMultimap;
import com.google.common.flogger.FluentLogger;
import java.util.concurrent.Callable;
/**
@@ -31,16 +32,30 @@ import java.util.concurrent.Callable;
* @see LoggingContextAwareRunnable
*/
class LoggingContextAwareCallable<T> implements Callable<T> {
private static final FluentLogger logger = FluentLogger.forEnclosingClass();
private final Callable<T> callable;
private final Thread callingThread;
private final ImmutableSetMultimap<String, String> tags;
private final boolean forceLogging;
private final boolean performanceLogging;
private final MutablePerformanceLogRecords mutablePerformanceLogRecords;
LoggingContextAwareCallable(Callable<T> callable) {
/**
* Creates a LoggingContextAwareCallable that wraps the given {@link Callable}.
*
* @param callable Callable that should be wrapped.
* @param mutablePerformanceLogRecords instance of {@link MutablePerformanceLogRecords} to which
* performance log records that are created from the runnable are added
*/
LoggingContextAwareCallable(
Callable<T> callable, MutablePerformanceLogRecords mutablePerformanceLogRecords) {
this.callable = callable;
this.callingThread = Thread.currentThread();
this.tags = LoggingContext.getInstance().getTagsAsMap();
this.forceLogging = LoggingContext.getInstance().isLoggingForced();
this.performanceLogging = LoggingContext.getInstance().isPerformanceLogging();
this.mutablePerformanceLogRecords = mutablePerformanceLogRecords;
}
@Override
@@ -50,17 +65,29 @@ class LoggingContextAwareCallable<T> implements Callable<T> {
return callable.call();
}
// propagate logging context
LoggingContext loggingCtx = LoggingContext.getInstance();
ImmutableSetMultimap<String, String> oldTags = loggingCtx.getTagsAsMap();
boolean oldForceLogging = loggingCtx.isLoggingForced();
if (!loggingCtx.isEmpty()) {
logger.atWarning().log("Logging context is not empty: %s", loggingCtx);
}
// propagate logging context
loggingCtx.setTags(tags);
loggingCtx.forceLogging(forceLogging);
loggingCtx.performanceLogging(performanceLogging);
// For the performance log records use the {@link MutablePerformanceLogRecords} instance from
// the logging context of the calling thread in the logging context of the new thread. This way
// performance log records that are created from the new thread are available from the logging
// context of the calling thread. This is important since performance log records are processed
// only at the end of the request and performance log records that are created in another thread
// should not get lost.
loggingCtx.setMutablePerformanceLogRecords(mutablePerformanceLogRecords);
try {
return callable.call();
} finally {
loggingCtx.setTags(oldTags);
loggingCtx.forceLogging(oldForceLogging);
// Cleanup logging context. This is important if the thread is pooled and reused.
loggingCtx.clear();
}
}
}

39
java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java
View File

@@ -15,6 +15,7 @@
package com.google.gerrit.server.logging;
import com.google.common.collect.ImmutableSetMultimap;
import com.google.common.flogger.FluentLogger;
/**
* Wrapper for a {@link Runnable} that copies the {@link LoggingContext} from the current thread to
@@ -49,16 +50,30 @@ import com.google.common.collect.ImmutableSetMultimap;
* @see LoggingContextAwareCallable
*/
public class LoggingContextAwareRunnable implements Runnable {
private static final FluentLogger logger = FluentLogger.forEnclosingClass();
private final Runnable runnable;
private final Thread callingThread;
private final ImmutableSetMultimap<String, String> tags;
private final boolean forceLogging;
private final boolean performanceLogging;
private final MutablePerformanceLogRecords mutablePerformanceLogRecords;
LoggingContextAwareRunnable(Runnable runnable) {
/**
* Creates a LoggingContextAwareRunnable that wraps the given {@link Runnable}.
*
* @param runnable Runnable that should be wrapped.
* @param mutablePerformanceLogRecords instance of {@link MutablePerformanceLogRecords} to which
* performance log records that are created from the runnable are added
*/
LoggingContextAwareRunnable(
Runnable runnable, MutablePerformanceLogRecords mutablePerformanceLogRecords) {
this.runnable = runnable;
this.callingThread = Thread.currentThread();
this.tags = LoggingContext.getInstance().getTagsAsMap();
this.forceLogging = LoggingContext.getInstance().isLoggingForced();
this.performanceLogging = LoggingContext.getInstance().isPerformanceLogging();
this.mutablePerformanceLogRecords = mutablePerformanceLogRecords;
}
public Runnable unwrap() {
@@ -73,17 +88,29 @@ public class LoggingContextAwareRunnable implements Runnable {
return;
}
// propagate logging context
LoggingContext loggingCtx = LoggingContext.getInstance();
ImmutableSetMultimap<String, String> oldTags = loggingCtx.getTagsAsMap();
boolean oldForceLogging = loggingCtx.isLoggingForced();
if (!loggingCtx.isEmpty()) {
logger.atWarning().log("Logging context is not empty: %s", loggingCtx);
}
// propagate logging context
loggingCtx.setTags(tags);
loggingCtx.forceLogging(forceLogging);
loggingCtx.performanceLogging(performanceLogging);
// For the performance log records use the {@link MutablePerformanceLogRecords} instance from
// the logging context of the calling thread in the logging context of the new thread. This way
// performance log records that are created from the new thread are available from the logging
// context of the calling thread. This is important since performance log records are processed
// only at the end of the request and performance log records that are created in another thread
// should not get lost.
loggingCtx.setMutablePerformanceLogRecords(mutablePerformanceLogRecords);
try {
runnable.run();
} finally {
loggingCtx.setTags(oldTags);
loggingCtx.forceLogging(oldForceLogging);
// Cleanup logging context. This is important if the thread is pooled and reused.
loggingCtx.clear();
}
}
}

55
java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java Normal file
View File

@@ -0,0 +1,55 @@
// Copyright (C) 2018 The Android Open Source Project
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
package com.google.gerrit.server.logging;
import com.google.common.base.MoreObjects;
import com.google.common.collect.ImmutableList;
import java.util.ArrayList;
import java.util.List;
/**
* Thread-safe store for performance log records.
*
* <p>This class is intended to keep track of performance log records in {@link LoggingContext}. It
* needs to be thread-safe because it gets shared between threads when the logging context is copied
* to another thread (see {@link LoggingContextAwareRunnable} and {@link
* LoggingContextAwareCallable}. In this case the logging contexts of both threads share the same
* instance of this class. This is important since performance log records are processed only at the
* end of a request and performance log records that are created in another thread should not get
* lost.
*/
public class MutablePerformanceLogRecords {
private final ArrayList<PerformanceLogRecord> performanceLogRecords = new ArrayList<>();
public synchronized void add(PerformanceLogRecord record) {
performanceLogRecords.add(record);
}
public synchronized void set(List<PerformanceLogRecord> records) {
performanceLogRecords.clear();
performanceLogRecords.addAll(records);
}
public synchronized ImmutableList<PerformanceLogRecord> list() {
return ImmutableList.copyOf(performanceLogRecords);
}
@Override
public String toString() {
return MoreObjects.toStringHelper(this)
.add("performanceLogRecords", performanceLogRecords)
.toString();
}
}

7
java/com/google/gerrit/server/logging/MutableTags.java
View File

@@ -16,6 +16,7 @@ package com.google.gerrit.server.logging;
import static java.util.Objects.requireNonNull;
import com.google.common.base.MoreObjects;
import com.google.common.collect.ImmutableSetMultimap;
import com.google.common.collect.MultimapBuilder;
import com.google.common.collect.SetMultimap;
@@ -110,4 +111,10 @@ public class MutableTags {
tagMap.forEach(tagsBuilder::addTag);
tags = tagsBuilder.build();
}
@Override
public String toString() {
buildTags();
return MoreObjects.toStringHelper(this).add("tags", tags).toString();
}
}

111
java/com/google/gerrit/server/logging/PerformanceLogContext.java Normal file
View File

@@ -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());
}
}

220
java/com/google/gerrit/server/logging/PerformanceLogRecord.java Normal file
View File

@@ -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());
}
}
}

164
java/com/google/gerrit/server/logging/PerformanceLogger.java Normal file
View File

@@ -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);
}

245
java/com/google/gerrit/server/logging/TraceContext.java
View File

@@ -155,72 +155,116 @@ public class TraceContext implements AutoCloseable {
/**
* Opens a new timer that logs the time for an operation if request tracing is enabled.
*
* <p>If request tracing is not enabled this is a no-op.
*
* @param message the message
* @param operation the name of operation the is being performed
* @return the trace timer
*/
public static TraceTimer newTimer(String message) {
return new TraceTimer(message);
public static TraceTimer newTimer(String operation) {
return new TraceTimer(requireNonNull(operation, "operation is required"));
}
/**
* Opens a new timer that logs the time for an operation if request tracing is enabled.
*
* <p>If request tracing is not enabled this is a no-op.
*
* @param format the message format string
* @param arg argument for the message
* @param operation the name of operation the is being performed
* @param key meta data key
* @param value meta data value
* @return the trace timer
*/
public static TraceTimer newTimer(String format, Object arg) {
return new TraceTimer(format, arg);
public static TraceTimer newTimer(String operation, String key, @Nullable Object value) {
return new TraceTimer(
requireNonNull(operation, "operation is required"),
requireNonNull(key, "key is required"),
value);
}
/**
* Opens a new timer that logs the time for an operation if request tracing is enabled.
*
* <p>If request tracing is not enabled this is a no-op.
*
* @param format the message format string
* @param arg1 first argument for the message
* @param arg2 second argument for the message
* @return the trace timer
*/
public static TraceTimer newTimer(String format, Object arg1, Object arg2) {
return new TraceTimer(format, arg1, arg2);
}
/**
* Opens a new timer that logs the time for an operation if request tracing is enabled.
*
* <p>If request tracing is not enabled this is a no-op.
*
* @param format the message format string
* @param arg1 first argument for the message
* @param arg2 second argument for the message
* @param arg3 third argument for the message
* @return the trace timer
*/
public static TraceTimer newTimer(String format, Object arg1, Object arg2, Object arg3) {
return new TraceTimer(format, arg1, arg2, arg3);
}
/**
* Opens a new timer that logs the time for an operation if request tracing is enabled.
*
* <p>If request tracing is not enabled this is a no-op.
*
* @param format the message format string
* @param arg1 first argument for the message
* @param arg2 second argument for the message
* @param arg3 third argument for the message
* @param arg4 fourth argument for the message
* @param operation the name of operation the is being performed
* @param key1 first meta data key
* @param value1 first meta data value
* @param key2 second meta data key
* @param value2 second meta data value
* @return the trace timer
*/
public static TraceTimer newTimer(
String format, Object arg1, Object arg2, Object arg3, Object arg4) {
return new TraceTimer(format, arg1, arg2, arg3, arg4);
String operation,
String key1,
@Nullable Object value1,
String key2,
@Nullable Object value2) {
return new TraceTimer(
requireNonNull(operation, "operation is required"),
requireNonNull(key1, "key1 is required"),
value1,
requireNonNull(key2, "key2 is required"),
value2);
}
/**
* Opens a new timer that logs the time for an operation if request tracing is enabled.
*
* @param operation the name of operation the is being performed
* @param key1 first meta data key
* @param value1 first meta data value
* @param key2 second meta data key
* @param value2 second meta data value
* @param key3 third meta data key
* @param value3 third meta data value
* @return the trace timer
*/
public static TraceTimer newTimer(
String operation,
String key1,
@Nullable Object value1,
String key2,
@Nullable Object value2,
String key3,
@Nullable Object value3) {
return new TraceTimer(
requireNonNull(operation, "operation is required"),
requireNonNull(key1, "key1 is required"),
value1,
requireNonNull(key2, "key2 is required"),
value2,
requireNonNull(key3, "key3 is required"),
value3);
}
/**
* Opens a new timer that logs the time for an operation if request tracing is enabled.
*
* @param operation the name of operation the is being performed
* @param key1 first meta data key
* @param value1 first meta data value
* @param key2 second meta data key
* @param value2 second meta data value
* @param key3 third meta data key
* @param value3 third meta data value
* @param key4 fourth meta data key
* @param value4 fourth meta data value
* @return the trace timer
*/
public static TraceTimer newTimer(
String operation,
String key1,
@Nullable Object value1,
String key2,
@Nullable Object value2,
String key3,
@Nullable Object value3,
String key4,
@Nullable Object value4) {
return new TraceTimer(
requireNonNull(operation, "operation is required"),
requireNonNull(key1, "key1 is required"),
value1,
requireNonNull(key2, "key2 is required"),
value2,
requireNonNull(key3, "key3 is required"),
value3,
requireNonNull(key4, "key4 is required"),
value4);
}
public static class TraceTimer implements AutoCloseable {
@@ -229,31 +273,86 @@ public class TraceContext implements AutoCloseable {
private final Consumer<Long> logFn;
private final Stopwatch stopwatch;
private TraceTimer(String message) {
this(elapsedMs -> logger.atFine().log(message + " (%d ms)", elapsedMs));
}
private TraceTimer(String format, @Nullable Object arg) {
this(elapsedMs -> logger.atFine().log(format + " (%d ms)", arg, elapsedMs));
}
private TraceTimer(String format, @Nullable Object arg1, @Nullable Object arg2) {
this(elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, elapsedMs));
}
private TraceTimer(
String format, @Nullable Object arg1, @Nullable Object arg2, @Nullable Object arg3) {
this(elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, arg3, elapsedMs));
}
private TraceTimer(
String format,
@Nullable Object arg1,
@Nullable Object arg2,
@Nullable Object arg3,
@Nullable Object arg4) {
private TraceTimer(String operation) {
this(
elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, arg3, arg4, elapsedMs));
elapsedMs -> {
LoggingContext.getInstance()
.addPerformanceLogRecord(() -> PerformanceLogRecord.create(operation, elapsedMs));
logger.atFine().log("%s (%d ms)", operation, elapsedMs);
});
}
private TraceTimer(String operation, String key, @Nullable Object value) {
this(
elapsedMs -> {
LoggingContext.getInstance()
.addPerformanceLogRecord(
() -> PerformanceLogRecord.create(operation, elapsedMs, key, value));
logger.atFine().log("%s (%s=%s) (%d ms)", operation, key, value, elapsedMs);
});
}
private TraceTimer(
String operation,
String key1,
@Nullable Object value1,
String key2,
@Nullable Object value2) {
this(
elapsedMs -> {
LoggingContext.getInstance()
.addPerformanceLogRecord(
() ->
PerformanceLogRecord.create(
operation, elapsedMs, key1, value1, key2, value2));
logger.atFine().log(
"%s (%s=%s, %s=%s) (%d ms)", operation, key1, value1, key2, value2, elapsedMs);
});
}
private TraceTimer(
String operation,
String key1,
@Nullable Object value1,
String key2,
@Nullable Object value2,
String key3,
@Nullable Object value3) {
this(
elapsedMs -> {
LoggingContext.getInstance()
.addPerformanceLogRecord(
() ->
PerformanceLogRecord.create(
operation, elapsedMs, key1, value1, key2, value2, key3, value3));
logger.atFine().log(
"%s (%s=%s, %s=%s, %s=%s) (%d ms)",
operation, key1, value1, key2, value2, key3, value3, elapsedMs);
});
}
private TraceTimer(
String operation,
String key1,
@Nullable Object value1,
String key2,
@Nullable Object value2,
String key3,
@Nullable Object value3,
String key4,
@Nullable Object value4) {
this(
elapsedMs -> {
LoggingContext.getInstance()
.addPerformanceLogRecord(
() ->
PerformanceLogRecord.create(
operation, elapsedMs, key1, value1, key2, value2, key3, value3, key4,
value4));
logger.atFine().log(
"%s (%s=%s, %s=%s, %s=%s, %s=%s) (%d ms)",
operation, key1, value1, key2, value2, key3, value3, key4, value4, elapsedMs);
});
}
private TraceTimer(Consumer<Long> logFn) {

3
java/com/google/gerrit/server/project/ProjectCacheImpl.java
View File

@@ -293,7 +293,8 @@ public class ProjectCacheImpl implements ProjectCache {
@Override
public ProjectState load(String projectName) throws Exception {
try (TraceTimer timer = TraceContext.newTimer("Loading project %s", projectName)) {
try (TraceTimer timer =
TraceContext.newTimer("Loading project", "projectName", projectName)) {
long now = clock.read();
Project.NameKey key = Project.nameKey(projectName);
try (Repository git = mgr.openRepository(key)) {

10
java/com/google/gerrit/sshd/SshCommand.java
View File

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

3
java/com/google/gerrit/sshd/SshKeyCacheImpl.java
View File

@@ -106,7 +106,8 @@ public class SshKeyCacheImpl implements SshKeyCache {
@Override
public Iterable<SshKeyCacheEntry> load(String username) throws Exception {
try (TraceTimer timer =
TraceContext.newTimer("Loading SSH keys for account with username %s", username)) {
TraceContext.newTimer(
"Loading SSH keys for account with username", "username", username)) {
Optional<ExternalId> user =
externalIds.get(ExternalId.Key.create(SCHEME_USERNAME, username));
if (!user.isPresent()) {

55
javatests/com/google/gerrit/acceptance/rest/TraceIT.java
View File

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

47
javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java
View File

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

65
javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java
View File

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

467
javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java Normal file
View File

@@ -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();
}
}

58
javatests/com/google/gerrit/server/logging/TraceContextTest.java
View File

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