From 1b9244d7f3511756c29feb8db72992c39d598531 Mon Sep 17 00:00:00 2001 From: Edwin Kempin Date: Fri, 24 May 2019 10:23:12 +0200 Subject: [PATCH 1/5] TraceContext#newTimer: Separate message from arguments We plan to add a new extension point that allows to write recorded times into a dedicated performance log. To be able to aggregate data in the performance log by message, the message string should be constant (without parameters which differ for each invocation). Meta data that is specific to one invocation should be recorded in a separate field in the performance log. Signed-off-by: Edwin Kempin Change-Id: I6417d8ddc4755cc7bfb60f3e57f050c262c28f17 --- .../gerrit/server/StarredChangesUtil.java | 6 +- .../server/account/AccountCacheImpl.java | 2 +- .../gerrit/server/account/GroupCacheImpl.java | 6 +- .../server/account/GroupIncludeCacheImpl.java | 5 +- .../externalids/ExternalIdCacheImpl.java | 3 +- .../gerrit/server/auth/ldap/LdapRealm.java | 7 +- .../gerrit/server/cache/h2/H2CacheImpl.java | 2 +- .../gerrit/server/git/PureRevertCache.java | 2 +- .../server/git/SearchingChangeCacheImpl.java | 3 +- .../server/git/meta/VersionedMetaData.java | 13 +- .../gerrit/server/group/db/GroupsUpdate.java | 6 +- .../index/account/AccountIndexerImpl.java | 12 +- .../server/index/change/ChangeIndexer.java | 13 +- .../gerrit/server/logging/TraceContext.java | 155 ++++++++++++------ .../server/project/ProjectCacheImpl.java | 3 +- .../google/gerrit/sshd/SshKeyCacheImpl.java | 3 +- 16 files changed, 163 insertions(+), 78 deletions(-) diff --git a/java/com/google/gerrit/server/StarredChangesUtil.java b/java/com/google/gerrit/server/StarredChangesUtil.java index d092ac8551..9b43724c68 100644 --- a/java/com/google/gerrit/server/StarredChangesUtil.java +++ b/java/com/google/gerrit/server/StarredChangesUtil.java @@ -376,7 +376,7 @@ public class StarredChangesUtil { } public static StarRef readLabels(Repository repo, String refName) throws IOException { - try (TraceTimer traceTimer = TraceContext.newTimer("Read star labels from %s", refName)) { + try (TraceTimer traceTimer = TraceContext.newTimer("Read star labels", "ref", refName)) { Ref ref = repo.exactRef(refName); if (ref == null) { return StarRef.MISSING; @@ -450,7 +450,7 @@ public class StarredChangesUtil { Repository repo, String refName, ObjectId oldObjectId, Collection labels) throws IOException, InvalidLabelsException { try (TraceTimer traceTimer = - TraceContext.newTimer("Update star labels in %s (labels=%s)", refName, labels); + TraceContext.newTimer("Update star labels", "ref", refName, "labels", labels); RevWalk rw = new RevWalk(repo)) { RefUpdate u = repo.updateRef(refName); u.setExpectedOldObjectId(oldObjectId); @@ -487,7 +487,7 @@ public class StarredChangesUtil { return; } - try (TraceTimer traceTimer = TraceContext.newTimer("Delete star labels in %s", refName)) { + try (TraceTimer traceTimer = TraceContext.newTimer("Delete star labels", "ref", refName)) { RefUpdate u = repo.updateRef(refName); u.setForceUpdate(true); u.setExpectedOldObjectId(oldObjectId); diff --git a/java/com/google/gerrit/server/account/AccountCacheImpl.java b/java/com/google/gerrit/server/account/AccountCacheImpl.java index fd48fa7e67..3f3f27db82 100644 --- a/java/com/google/gerrit/server/account/AccountCacheImpl.java +++ b/java/com/google/gerrit/server/account/AccountCacheImpl.java @@ -183,7 +183,7 @@ public class AccountCacheImpl implements AccountCache { @Override public Optional load(Account.Id who) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading account %s", who)) { + try (TraceTimer timer = TraceContext.newTimer("Loading account", "accountId", who)) { return accounts.get(who); } } diff --git a/java/com/google/gerrit/server/account/GroupCacheImpl.java b/java/com/google/gerrit/server/account/GroupCacheImpl.java index b9cfb61e4f..7ed7ebc1c9 100644 --- a/java/com/google/gerrit/server/account/GroupCacheImpl.java +++ b/java/com/google/gerrit/server/account/GroupCacheImpl.java @@ -149,7 +149,7 @@ public class GroupCacheImpl implements GroupCache { @Override public Optional load(AccountGroup.Id key) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading group %s by ID", key)) { + try (TraceTimer timer = TraceContext.newTimer("Loading group by ID", "groupId", key)) { return groupQueryProvider.get().byId(key); } } @@ -165,7 +165,7 @@ public class GroupCacheImpl implements GroupCache { @Override public Optional load(String name) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading group '%s' by name", name)) { + try (TraceTimer timer = TraceContext.newTimer("Loading group by name", "groupName", name)) { return groupQueryProvider.get().byName(AccountGroup.nameKey(name)); } } @@ -181,7 +181,7 @@ public class GroupCacheImpl implements GroupCache { @Override public Optional load(String uuid) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading group %s by UUID", uuid)) { + try (TraceTimer timer = TraceContext.newTimer("Loading group by UUID", "groupUuid", uuid)) { return groups.getGroup(AccountGroup.uuid(uuid)); } } diff --git a/java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java b/java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java index c27d6c30c5..3507ba269e 100644 --- a/java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java +++ b/java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java @@ -152,7 +152,8 @@ public class GroupIncludeCacheImpl implements GroupIncludeCache { @Override public ImmutableSet load(Account.Id memberId) { - try (TraceTimer timer = TraceContext.newTimer("Loading groups with member %s", memberId)) { + try (TraceTimer timer = + TraceContext.newTimer("Loading groups with member", "memberId", memberId)) { return groupQueryProvider.get().byMember(memberId).stream() .map(InternalGroup::getGroupUUID) .collect(toImmutableSet()); @@ -171,7 +172,7 @@ public class GroupIncludeCacheImpl implements GroupIncludeCache { @Override public ImmutableList load(AccountGroup.UUID key) { - try (TraceTimer timer = TraceContext.newTimer("Loading parent groups of %s", key)) { + try (TraceTimer timer = TraceContext.newTimer("Loading parent groups", "groupUuid", key)) { return groupQueryProvider.get().bySubgroup(key).stream() .map(InternalGroup::getGroupUUID) .collect(toImmutableList()); diff --git a/java/com/google/gerrit/server/account/externalids/ExternalIdCacheImpl.java b/java/com/google/gerrit/server/account/externalids/ExternalIdCacheImpl.java index 5aa19d88f5..ad861c0e93 100644 --- a/java/com/google/gerrit/server/account/externalids/ExternalIdCacheImpl.java +++ b/java/com/google/gerrit/server/account/externalids/ExternalIdCacheImpl.java @@ -157,8 +157,7 @@ class ExternalIdCacheImpl implements ExternalIdCache { @Override public AllExternalIds load(ObjectId notesRev) throws Exception { - try (TraceTimer timer = - TraceContext.newTimer("Loading external IDs (revision=%s)", notesRev)) { + try (TraceTimer timer = TraceContext.newTimer("Loading external IDs", "revision", notesRev)) { ImmutableSet externalIds = externalIdReader.all(notesRev); externalIds.forEach(ExternalId::checkThatBlobIdIsSet); return AllExternalIds.create(externalIds); diff --git a/java/com/google/gerrit/server/auth/ldap/LdapRealm.java b/java/com/google/gerrit/server/auth/ldap/LdapRealm.java index ed446f218a..c12aaf50bf 100644 --- a/java/com/google/gerrit/server/auth/ldap/LdapRealm.java +++ b/java/com/google/gerrit/server/auth/ldap/LdapRealm.java @@ -353,7 +353,8 @@ class LdapRealm extends AbstractRealm { @Override public Optional load(String username) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading account for username %s", username)) { + try (TraceTimer timer = + TraceContext.newTimer("Loading account for username", "username", username)) { return externalIds .get(ExternalId.Key.create(SCHEME_GERRIT, username)) .map(ExternalId::accountId); @@ -372,7 +373,7 @@ class LdapRealm extends AbstractRealm { @Override public Set load(String username) throws Exception { try (TraceTimer timer = - TraceContext.newTimer("Loading group for member with username %s", username)) { + TraceContext.newTimer("Loading group for member with username", "username", username)) { final DirContext ctx = helper.open(); try { return helper.queryForGroups(ctx, username, null); @@ -393,7 +394,7 @@ class LdapRealm extends AbstractRealm { @Override public Boolean load(String groupDn) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading groupDn %s", groupDn)) { + try (TraceTimer timer = TraceContext.newTimer("Loading groupDn", "groupDn", groupDn)) { final DirContext ctx = helper.open(); try { Name compositeGroupName = new CompositeName().add(groupDn); diff --git a/java/com/google/gerrit/server/cache/h2/H2CacheImpl.java b/java/com/google/gerrit/server/cache/h2/H2CacheImpl.java index 3732e37e19..2b440194e7 100644 --- a/java/com/google/gerrit/server/cache/h2/H2CacheImpl.java +++ b/java/com/google/gerrit/server/cache/h2/H2CacheImpl.java @@ -237,7 +237,7 @@ public class H2CacheImpl extends AbstractLoadingCache implements Per @Override public ValueHolder load(K key) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading value for %s from cache", key)) { + try (TraceTimer timer = TraceContext.newTimer("Loading value from cache", "key", key)) { if (store.mightContain(key)) { ValueHolder h = store.getIfPresent(key); if (h != null) { diff --git a/java/com/google/gerrit/server/git/PureRevertCache.java b/java/com/google/gerrit/server/git/PureRevertCache.java index 2faa0bb5ad..49377132f9 100644 --- a/java/com/google/gerrit/server/git/PureRevertCache.java +++ b/java/com/google/gerrit/server/git/PureRevertCache.java @@ -151,7 +151,7 @@ public class PureRevertCache { @Override public Boolean load(PureRevertKeyProto key) throws BadRequestException, IOException { try (TraceContext.TraceTimer ignored = - TraceContext.newTimer("Loading pure revert for %s", key)) { + TraceContext.newTimer("Loading pure revert", "key", key)) { ObjectId original = ObjectIdConverter.create().fromByteString(key.getClaimedOriginal()); ObjectId revert = ObjectIdConverter.create().fromByteString(key.getClaimedRevert()); Project.NameKey project = Project.nameKey(key.getProject()); diff --git a/java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java b/java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java index fb7756f55f..15284fe350 100644 --- a/java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java +++ b/java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java @@ -152,7 +152,8 @@ public class SearchingChangeCacheImpl implements GitReferenceUpdatedListener { @Override public List load(Project.NameKey key) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading changes of project %s", key); + try (TraceTimer timer = + TraceContext.newTimer("Loading changes of project", "projectName", key); ManualRequestContext ctx = requestContext.open()) { List cds = queryProvider diff --git a/java/com/google/gerrit/server/git/meta/VersionedMetaData.java b/java/com/google/gerrit/server/git/meta/VersionedMetaData.java index 9506efca1e..63560688ac 100644 --- a/java/com/google/gerrit/server/git/meta/VersionedMetaData.java +++ b/java/com/google/gerrit/server/git/meta/VersionedMetaData.java @@ -499,8 +499,15 @@ public abstract class VersionedMetaData { try (TraceTimer timer = TraceContext.newTimer( - "Read file '%s' from ref '%s' of project '%s' from revision '%s'", - fileName, getRefName(), projectName, revision.name()); + "Read file", + "fileName", + fileName, + "ref", + getRefName(), + "projectName", + projectName, + "revision", + revision.name()); TreeWalk tw = TreeWalk.forPath(reader, fileName, revision.getTree())) { if (tw != null) { ObjectLoader obj = reader.open(tw.getObjectId(0), Constants.OBJ_BLOB); @@ -575,7 +582,7 @@ public abstract class VersionedMetaData { protected void saveFile(String fileName, byte[] raw) throws IOException { try (TraceTimer timer = TraceContext.newTimer( - "Save file '%s' in ref '%s' of project '%s'", fileName, getRefName(), projectName)) { + "Save file", "fileName", fileName, "ref", getRefName(), "projectName", projectName)) { DirCacheEditor editor = newTree.editor(); if (raw != null && 0 < raw.length) { final ObjectId blobId = inserter.insert(Constants.OBJ_BLOB, raw); diff --git a/java/com/google/gerrit/server/group/db/GroupsUpdate.java b/java/com/google/gerrit/server/group/db/GroupsUpdate.java index b450ab856e..2f9ce011e4 100644 --- a/java/com/google/gerrit/server/group/db/GroupsUpdate.java +++ b/java/com/google/gerrit/server/group/db/GroupsUpdate.java @@ -265,7 +265,9 @@ public class GroupsUpdate { throws DuplicateKeyException, IOException, ConfigInvalidException { try (TraceTimer timer = TraceContext.newTimer( - "Creating group '%s'", groupUpdate.getName().orElseGet(groupCreation::getNameKey))) { + "Creating group", + "groupName", + groupUpdate.getName().orElseGet(groupCreation::getNameKey))) { InternalGroup createdGroup = createGroupInNoteDbWithRetry(groupCreation, groupUpdate); evictCachesOnGroupCreation(createdGroup); dispatchAuditEventsOnGroupCreation(createdGroup); @@ -285,7 +287,7 @@ public class GroupsUpdate { */ public void updateGroup(AccountGroup.UUID groupUuid, InternalGroupUpdate groupUpdate) throws DuplicateKeyException, IOException, NoSuchGroupException, ConfigInvalidException { - try (TraceTimer timer = TraceContext.newTimer("Updating group %s", groupUuid)) { + try (TraceTimer timer = TraceContext.newTimer("Updating group", "groupUuid", groupUuid)) { Optional updatedOn = groupUpdate.getUpdatedOn(); if (!updatedOn.isPresent()) { updatedOn = Optional.of(TimeUtil.nowTs()); diff --git a/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java b/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java index 1eaac7a652..da22eac700 100644 --- a/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java +++ b/java/com/google/gerrit/server/index/account/AccountIndexerImpl.java @@ -90,13 +90,21 @@ public class AccountIndexerImpl implements AccountIndexer { if (accountState.isPresent()) { try (TraceTimer traceTimer = TraceContext.newTimer( - "Replacing account %d in index version %d", id.get(), i.getSchema().getVersion())) { + "Replacing account in index", + "accountId", + id.get(), + "indexVersion", + i.getSchema().getVersion())) { i.replace(accountState.get()); } } else { try (TraceTimer traceTimer = TraceContext.newTimer( - "Deleteing account %d in index version %d", id.get(), i.getSchema().getVersion())) { + "Deleting account in index", + "accountId", + id.get(), + "indexVersion", + i.getSchema().getVersion())) { i.delete(id); } } diff --git a/java/com/google/gerrit/server/index/change/ChangeIndexer.java b/java/com/google/gerrit/server/index/change/ChangeIndexer.java index 348e0cec75..e1c7dc984c 100644 --- a/java/com/google/gerrit/server/index/change/ChangeIndexer.java +++ b/java/com/google/gerrit/server/index/change/ChangeIndexer.java @@ -174,8 +174,11 @@ public class ChangeIndexer { for (Index i : getWriteIndexes()) { try (TraceTimer traceTimer = TraceContext.newTimer( - "Replacing change %d in index version %d", - cd.getId().get(), i.getSchema().getVersion())) { + "Replacing change in index", + "changeId", + cd.getId().get(), + "indexVersion", + i.getSchema().getVersion())) { i.replace(cd); } } @@ -336,7 +339,11 @@ public class ChangeIndexer { for (ChangeIndex i : getWriteIndexes()) { try (TraceTimer traceTimer = TraceContext.newTimer( - "Deleteing change %d in index version %d", id.get(), i.getSchema().getVersion())) { + "Deleting change in index", + "changeId", + id.get(), + "indexVersion", + i.getSchema().getVersion())) { i.delete(id); } } diff --git a/java/com/google/gerrit/server/logging/TraceContext.java b/java/com/google/gerrit/server/logging/TraceContext.java index 5c0406ddd1..06fa302f0a 100644 --- a/java/com/google/gerrit/server/logging/TraceContext.java +++ b/java/com/google/gerrit/server/logging/TraceContext.java @@ -169,12 +169,13 @@ public class TraceContext implements AutoCloseable { * *

If request tracing is not enabled this is a no-op. * - * @param format the message format string - * @param arg argument for the message + * @param message the message + * @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 message, String key, Object value) { + return new TraceTimer(message + " (%s=%s)", key, value); } /** @@ -182,45 +183,80 @@ public class TraceContext implements AutoCloseable { * *

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

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

If request tracing is not enabled this is a no-op. - * - * @param format the message format string - * @param arg1 first argument for the message - * @param arg2 second argument for the message - * @param arg3 third argument for the message - * @param arg4 fourth argument for the message + * @param message the message + * @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 message, String key1, Object value1, String key2, Object value2) { + return new TraceTimer(message + " (%s=%s, %s=%s)", key1, value1, key2, value2); + } + + /** + * Opens a new timer that logs the time for an operation if request tracing is enabled. + * + *

If request tracing is not enabled this is a no-op. + * + * @param message the message + * @param 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 message, + String key1, + Object value1, + String key2, + Object value2, + String key3, + Object value3) { + return new TraceTimer( + message + " (%s=%s, %s=%s, %s=%s)", key1, value1, key2, value2, key3, value3); + } + + /** + * Opens a new timer that logs the time for an operation if request tracing is enabled. + * + *

If request tracing is not enabled this is a no-op. + * + * @param message the message + * @param 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 message, + String key1, + Object value1, + String key2, + Object value2, + String key3, + Object value3, + String key4, + Object value4) { + return new TraceTimer( + message + " (%s=%s, %s=%s, %s=%s, %s=%s)", + key1, + value1, + key2, + value2, + key3, + value3, + key4, + value4); } public static class TraceTimer implements AutoCloseable { @@ -233,19 +269,10 @@ public class TraceContext implements AutoCloseable { 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, @@ -256,6 +283,36 @@ public class TraceContext implements AutoCloseable { elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, arg3, arg4, elapsedMs)); } + private TraceTimer( + String format, + @Nullable Object arg1, + @Nullable Object arg2, + @Nullable Object arg3, + @Nullable Object arg4, + @Nullable Object arg5, + @Nullable Object arg6) { + this( + elapsedMs -> + logger.atFine().log( + format + " (%d ms)", arg1, arg2, arg3, arg4, arg5, arg6, elapsedMs)); + } + + private TraceTimer( + String format, + @Nullable Object arg1, + @Nullable Object arg2, + @Nullable Object arg3, + @Nullable Object arg4, + @Nullable Object arg5, + @Nullable Object arg6, + @Nullable Object arg7, + @Nullable Object arg8) { + this( + elapsedMs -> + logger.atFine().log( + format + " (%d ms)", arg1, arg2, arg3, arg4, arg5, arg6, arg7, arg8, elapsedMs)); + } + private TraceTimer(Consumer logFn) { this.logFn = logFn; this.stopwatch = Stopwatch.createStarted(); diff --git a/java/com/google/gerrit/server/project/ProjectCacheImpl.java b/java/com/google/gerrit/server/project/ProjectCacheImpl.java index 3542187316..3fc634d5f9 100644 --- a/java/com/google/gerrit/server/project/ProjectCacheImpl.java +++ b/java/com/google/gerrit/server/project/ProjectCacheImpl.java @@ -293,7 +293,8 @@ public class ProjectCacheImpl implements ProjectCache { @Override public ProjectState load(String projectName) throws Exception { - try (TraceTimer timer = TraceContext.newTimer("Loading project %s", projectName)) { + try (TraceTimer timer = + TraceContext.newTimer("Loading project", "projectName", projectName)) { long now = clock.read(); Project.NameKey key = Project.nameKey(projectName); try (Repository git = mgr.openRepository(key)) { diff --git a/java/com/google/gerrit/sshd/SshKeyCacheImpl.java b/java/com/google/gerrit/sshd/SshKeyCacheImpl.java index fb0b8f6f15..94e7f1b59b 100644 --- a/java/com/google/gerrit/sshd/SshKeyCacheImpl.java +++ b/java/com/google/gerrit/sshd/SshKeyCacheImpl.java @@ -106,7 +106,8 @@ public class SshKeyCacheImpl implements SshKeyCache { @Override public Iterable load(String username) throws Exception { try (TraceTimer timer = - TraceContext.newTimer("Loading SSH keys for account with username %s", username)) { + TraceContext.newTimer( + "Loading SSH keys for account with username", "username", username)) { Optional user = externalIds.get(ExternalId.Key.create(SCHEME_USERNAME, username)); if (!user.isPresent()) { From f3e6cc7777245e8a3a8aeaf6ec48c1247a0136cf Mon Sep 17 00:00:00 2001 From: Edwin Kempin Date: Mon, 27 May 2019 17:33:16 +0200 Subject: [PATCH 2/5] Add extension point to record execution times in a performance log Add a new extension point that is invoked for all operations for which the execution time is measured. The invocation of the extension point does not happen immediately, but only at the end of a request (REST call, SSH call, git push). Implementors can write the execution times into a performance log for further analysis. In Gerrit there are 2 possibilities to measure and record the execution time of an operation: 1. TraceTimer: Opens an autocloseable context to execute an operation. On close the execution time is written to the server logs, but only if the request is traced (or if log level was set to fine). 2. Timer Metrics: Record execution times as a metric. In addition this writes the execution time to the server logs, but only if the request is traced (or if log level was set to fine). These are the 2 places where performance log entries must be captured. Performance log entries are stored in the LoggingContext which is based on ThreadLocals. LoggingContextAwareRunnable and LoggingContextAwareCallable which are used by all executors ensure that captured performance log entries are properly copied between threads. At the end of a request (supported are REST call, SSH call and git push) the captured performance log entries are handed over to the PerformanceLogger implementations. If no PerformanceLogger is registered, or if execution times of operations outside of request scope are measured, performance log entries are not captured because nobody would consume them. Storing the performance log records in the LoggingContext and invoking the PerformanceLogger plugins only at the end of a request has some advantages and disadvantages: 1. [advantage] Users of TraceTimer can continue to use the static methods calls to create a TraceTimer (TraceContext.newTimer(...)). To invoke the plugins immediately we would need to get them injected into TraceTimer, hence callers would need a factory to create a TraceTimer. That would result in quite some boilerplate code and in addition some places that use TraceTimer (in VersionedMetaData) cannot use injection. 2. [advantage] The metric system is setup very early in the injector chain (in the DB injector, see SiteProgram#createDbInjector(boolean)). To invoke the plugins directly from the timer metrics we would need to have the PerformanceLogger plugins already available on this injector level, which is difficult. 3. [disadvantage] The captured performance log records are kept in memory while a request is processed. This leads to higher memory foodprint, but we think this is OK. To keep the performance and memory overhead for recording performance as low as possible we did some optimizations: 1. Performance log entries are only created if there is a consumer (at least one PerformanceLogger plugin + time measured inside request context) 2. Performance log entries avoid the instantiation of a Map to record meta data (instead we have dedicated fields for meta data keys and values). For the timer metrics we use generic names for the meta data keys ("field1", "field2", "field3"). This is because the actual field names are not available at this place. We may make them available, but that's outside the scope of this change and may be done in a follow-up change. To be able to write stable acceptance tests that verify that the PerformanceLogger plugins are invoked, it is important that the server calls the plugins before the response is sent back to the client. This is why the scope of the PerformanceLogContext in RestApiServlet is a little smaller than the scope of the TraceContext. Change-Id: I699db01609a1b4a88cee8959bdd9f1dfbb8dc74e Signed-off-by: Edwin Kempin --- Documentation/dev-plugins.txt | 9 + .../gerrit/httpd/restapi/RestApiServlet.java | 466 ++++++++--------- java/com/google/gerrit/metrics/BUILD | 1 + java/com/google/gerrit/metrics/Timer0.java | 7 +- java/com/google/gerrit/metrics/Timer1.java | 11 +- java/com/google/gerrit/metrics/Timer2.java | 12 +- java/com/google/gerrit/metrics/Timer3.java | 14 +- java/com/google/gerrit/server/BUILD | 1 + .../server/config/GerritGlobalModule.java | 2 + .../server/git/receive/ReceiveCommits.java | 16 +- java/com/google/gerrit/server/logging/BUILD | 2 + .../gerrit/server/logging/LoggingContext.java | 125 ++++- .../logging/LoggingContextAwareCallable.java | 29 +- .../logging/LoggingContextAwareRunnable.java | 29 +- .../logging/MutablePerformanceLogRecords.java | 47 ++ .../server/logging/PerformanceLogContext.java | 111 +++++ .../server/logging/PerformanceLogRecord.java | 220 +++++++++ .../server/logging/PerformanceLogger.java | 164 ++++++ .../gerrit/server/logging/TraceContext.java | 178 ++++--- java/com/google/gerrit/sshd/SshCommand.java | 10 +- .../gerrit/acceptance/rest/TraceIT.java | 55 +++ .../gerrit/acceptance/ssh/SshTraceIT.java | 47 +- ...oggingContextAwareExecutorServiceTest.java | 65 ++- .../logging/PerformanceLogContextTest.java | 467 ++++++++++++++++++ .../server/logging/TraceContextTest.java | 58 +++ 25 files changed, 1835 insertions(+), 311 deletions(-) create mode 100644 java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java create mode 100644 java/com/google/gerrit/server/logging/PerformanceLogContext.java create mode 100644 java/com/google/gerrit/server/logging/PerformanceLogRecord.java create mode 100644 java/com/google/gerrit/server/logging/PerformanceLogger.java create mode 100644 javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java diff --git a/Documentation/dev-plugins.txt b/Documentation/dev-plugins.txt index ada208a68e..72b92a72a6 100644 --- a/Documentation/dev-plugins.txt +++ b/Documentation/dev-plugins.txt @@ -2801,6 +2801,15 @@ class ApiQpsEnforcer implements QuotaEnforcer { } ---- +[[performance-logger]] +== Performance Logger + +`com.google.gerrit.server.logging.PerformanceLogger` is an extension point that +is invoked for all operations for which the execution time is measured. The +invocation of the extension point does not happen immediately, but only at the +end of a request (REST call, SSH call, git push). Implementors can write the +execution times into a performance log for further analysis. + [[plugins_hosting]] == Plugins source code hosting diff --git a/java/com/google/gerrit/httpd/restapi/RestApiServlet.java b/java/com/google/gerrit/httpd/restapi/RestApiServlet.java index 33daf46b16..efdf5badba 100644 --- a/java/com/google/gerrit/httpd/restapi/RestApiServlet.java +++ b/java/com/google/gerrit/httpd/restapi/RestApiServlet.java @@ -69,6 +69,7 @@ import com.google.gerrit.common.Nullable; import com.google.gerrit.common.RawInputUtil; import com.google.gerrit.extensions.registration.DynamicItem; import com.google.gerrit.extensions.registration.DynamicMap; +import com.google.gerrit.extensions.registration.DynamicSet; import com.google.gerrit.extensions.registration.PluginName; import com.google.gerrit.extensions.restapi.AuthException; import com.google.gerrit.extensions.restapi.BadRequestException; @@ -109,6 +110,8 @@ import com.google.gerrit.server.audit.ExtendedHttpAuditEvent; import com.google.gerrit.server.cache.PerThreadCache; import com.google.gerrit.server.config.GerritServerConfig; import com.google.gerrit.server.group.GroupAuditService; +import com.google.gerrit.server.logging.PerformanceLogContext; +import com.google.gerrit.server.logging.PerformanceLogger; import com.google.gerrit.server.logging.RequestId; import com.google.gerrit.server.logging.TraceContext; import com.google.gerrit.server.permissions.GlobalPermission; @@ -229,6 +232,7 @@ public class RestApiServlet extends HttpServlet { final RestApiMetrics metrics; final Pattern allowOrigin; final RestApiQuotaEnforcer quotaChecker; + final DynamicSet performanceLoggers; @Inject Globals( @@ -239,7 +243,8 @@ public class RestApiServlet extends HttpServlet { GroupAuditService auditService, RestApiMetrics metrics, RestApiQuotaEnforcer quotaChecker, - @GerritServerConfig Config cfg) { + @GerritServerConfig Config cfg, + DynamicSet performanceLoggers) { this.currentUser = currentUser; this.webSession = webSession; this.paramParser = paramParser; @@ -247,6 +252,7 @@ public class RestApiServlet extends HttpServlet { this.auditService = auditService; this.metrics = metrics; this.quotaChecker = quotaChecker; + this.performanceLoggers = performanceLoggers; allowOrigin = makeAllowOrigin(cfg); } @@ -294,258 +300,266 @@ public class RestApiServlet extends HttpServlet { try (TraceContext traceContext = enableTracing(req, res)) { try (PerThreadCache ignored = PerThreadCache.create()) { - logger.atFinest().log( - "Received REST request: %s %s (parameters: %s)", - req.getMethod(), req.getRequestURI(), getParameterNames(req)); - logger.atFinest().log("Calling user: %s", globals.currentUser.get().getLoggableName()); + // It's important that the PerformanceLogContext is closed before the response is sent to + // the client. Only this way it is ensured that the invocation of the PerformanceLogger + // plugins happens before the client sees the response. This is needed for being able to + // test performance logging from an acceptance test (see + // TraceIT#performanceLoggingForRestCall()). + try (PerformanceLogContext performanceLogContext = + new PerformanceLogContext(globals.performanceLoggers)) { + logger.atFinest().log( + "Received REST request: %s %s (parameters: %s)", + req.getMethod(), req.getRequestURI(), getParameterNames(req)); + logger.atFinest().log("Calling user: %s", globals.currentUser.get().getLoggableName()); - if (isCorsPreflight(req)) { - doCorsPreflight(req, res); - return; - } - - qp = ParameterParser.getQueryParams(req); - checkCors(req, res, qp.hasXdOverride()); - if (qp.hasXdOverride()) { - req = applyXdOverrides(req, qp); - } - checkUserSession(req); - - List path = splitPath(req); - RestCollection rc = members.get(); - globals - .permissionBackend - .currentUser() - .checkAny(GlobalPermission.fromAnnotation(rc.getClass())); - - viewData = new ViewData(null, null); - - if (path.isEmpty()) { - globals.quotaChecker.enforce(req); - if (rc instanceof NeedsParams) { - ((NeedsParams) rc).setParams(qp.params()); + if (isCorsPreflight(req)) { + doCorsPreflight(req, res); + return; } - if (isRead(req)) { - viewData = new ViewData(null, rc.list()); - } else if (isPost(req)) { - RestView restCollectionView = - rc.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./"); - if (restCollectionView != null) { - viewData = new ViewData(null, restCollectionView); + qp = ParameterParser.getQueryParams(req); + checkCors(req, res, qp.hasXdOverride()); + if (qp.hasXdOverride()) { + req = applyXdOverrides(req, qp); + } + checkUserSession(req); + + List path = splitPath(req); + RestCollection rc = members.get(); + globals + .permissionBackend + .currentUser() + .checkAny(GlobalPermission.fromAnnotation(rc.getClass())); + + viewData = new ViewData(null, null); + + if (path.isEmpty()) { + globals.quotaChecker.enforce(req); + if (rc instanceof NeedsParams) { + ((NeedsParams) rc).setParams(qp.params()); + } + + if (isRead(req)) { + viewData = new ViewData(null, rc.list()); + } else if (isPost(req)) { + RestView restCollectionView = + rc.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./"); + if (restCollectionView != null) { + viewData = new ViewData(null, restCollectionView); + } else { + throw methodNotAllowed(req); + } } else { + // DELETE on root collections is not supported throw methodNotAllowed(req); } } else { - // DELETE on root collections is not supported - throw methodNotAllowed(req); - } - } else { - IdString id = path.remove(0); - try { - rsrc = rc.parse(rsrc, id); - globals.quotaChecker.enforce(rsrc, req); - if (path.isEmpty()) { - checkPreconditions(req); - } - } catch (ResourceNotFoundException e) { - if (!path.isEmpty()) { - throw e; - } - globals.quotaChecker.enforce(req); + IdString id = path.remove(0); + try { + rsrc = rc.parse(rsrc, id); + globals.quotaChecker.enforce(rsrc, req); + if (path.isEmpty()) { + checkPreconditions(req); + } + } catch (ResourceNotFoundException e) { + if (!path.isEmpty()) { + throw e; + } + globals.quotaChecker.enforce(req); - if (isPost(req) || isPut(req)) { - RestView createView = rc.views().get(PluginName.GERRIT, "CREATE./"); - if (createView != null) { - viewData = new ViewData(null, createView); - status = SC_CREATED; - path.add(id); + if (isPost(req) || isPut(req)) { + RestView createView = rc.views().get(PluginName.GERRIT, "CREATE./"); + if (createView != null) { + viewData = new ViewData(null, createView); + status = SC_CREATED; + path.add(id); + } else { + throw e; + } + } else if (isDelete(req)) { + RestView deleteView = + rc.views().get(PluginName.GERRIT, "DELETE_MISSING./"); + if (deleteView != null) { + viewData = new ViewData(null, deleteView); + status = SC_NO_CONTENT; + path.add(id); + } else { + throw e; + } } else { throw e; } - } else if (isDelete(req)) { - RestView deleteView = - rc.views().get(PluginName.GERRIT, "DELETE_MISSING./"); - if (deleteView != null) { - viewData = new ViewData(null, deleteView); - status = SC_NO_CONTENT; - path.add(id); - } else { - throw e; - } - } else { - throw e; } - } - if (viewData.view == null) { - viewData = view(rc, req.getMethod(), path); - } - } - checkRequiresCapability(viewData); - - while (viewData.view instanceof RestCollection) { - @SuppressWarnings("unchecked") - RestCollection c = - (RestCollection) viewData.view; - - if (path.isEmpty()) { - if (isRead(req)) { - viewData = new ViewData(null, c.list()); - } else if (isPost(req)) { - // TODO: Here and on other collection methods: There is a bug that binds child views - // with pluginName="gerrit" instead of the real plugin name. This has never worked - // correctly and should be fixed where the binding gets created (DynamicMapProvider) - // and here. - RestView restCollectionView = - c.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./"); - if (restCollectionView != null) { - viewData = new ViewData(null, restCollectionView); - } else { - throw methodNotAllowed(req); - } - } else if (isDelete(req)) { - RestView restCollectionView = - c.views().get(PluginName.GERRIT, "DELETE_ON_COLLECTION./"); - if (restCollectionView != null) { - viewData = new ViewData(null, restCollectionView); - } else { - throw methodNotAllowed(req); - } - } else { - throw methodNotAllowed(req); + if (viewData.view == null) { + viewData = view(rc, req.getMethod(), path); } - break; - } - IdString id = path.remove(0); - try { - rsrc = c.parse(rsrc, id); - checkPreconditions(req); - viewData = new ViewData(null, null); - } catch (ResourceNotFoundException e) { - if (!path.isEmpty()) { - throw e; - } - - if (isPost(req) || isPut(req)) { - RestView createView = c.views().get(PluginName.GERRIT, "CREATE./"); - if (createView != null) { - viewData = new ViewData(null, createView); - status = SC_CREATED; - path.add(id); - } else { - throw e; - } - } else if (isDelete(req)) { - RestView deleteView = - c.views().get(PluginName.GERRIT, "DELETE_MISSING./"); - if (deleteView != null) { - viewData = new ViewData(null, deleteView); - status = SC_NO_CONTENT; - path.add(id); - } else { - throw e; - } - } else { - throw e; - } - } - if (viewData.view == null) { - viewData = view(c, req.getMethod(), path); } checkRequiresCapability(viewData); - } - if (notModified(req, rsrc, viewData.view)) { - logger.atFinest().log("REST call succeeded: %d", SC_NOT_MODIFIED); - res.sendError(SC_NOT_MODIFIED); - return; - } + while (viewData.view instanceof RestCollection) { + @SuppressWarnings("unchecked") + RestCollection c = + (RestCollection) viewData.view; - if (!globals.paramParser.get().parse(viewData.view, qp.params(), req, res)) { - return; - } - - if (viewData.view instanceof RestReadView && isRead(req)) { - result = ((RestReadView) viewData.view).apply(rsrc); - } else if (viewData.view instanceof RestModifyView) { - @SuppressWarnings("unchecked") - RestModifyView m = - (RestModifyView) viewData.view; - - Type type = inputType(m); - inputRequestBody = parseRequest(req, type); - result = m.apply(rsrc, inputRequestBody); - if (inputRequestBody instanceof RawInput) { - try (InputStream is = req.getInputStream()) { - ServletUtils.consumeRequestBody(is); + if (path.isEmpty()) { + if (isRead(req)) { + viewData = new ViewData(null, c.list()); + } else if (isPost(req)) { + // TODO: Here and on other collection methods: There is a bug that binds child views + // with pluginName="gerrit" instead of the real plugin name. This has never worked + // correctly and should be fixed where the binding gets created (DynamicMapProvider) + // and here. + RestView restCollectionView = + c.views().get(PluginName.GERRIT, "POST_ON_COLLECTION./"); + if (restCollectionView != null) { + viewData = new ViewData(null, restCollectionView); + } else { + throw methodNotAllowed(req); + } + } else if (isDelete(req)) { + RestView restCollectionView = + c.views().get(PluginName.GERRIT, "DELETE_ON_COLLECTION./"); + if (restCollectionView != null) { + viewData = new ViewData(null, restCollectionView); + } else { + throw methodNotAllowed(req); + } + } else { + throw methodNotAllowed(req); + } + break; } - } - } else if (viewData.view instanceof RestCollectionCreateView) { - @SuppressWarnings("unchecked") - RestCollectionCreateView m = - (RestCollectionCreateView) viewData.view; + IdString id = path.remove(0); + try { + rsrc = c.parse(rsrc, id); + checkPreconditions(req); + viewData = new ViewData(null, null); + } catch (ResourceNotFoundException e) { + if (!path.isEmpty()) { + throw e; + } - Type type = inputType(m); - inputRequestBody = parseRequest(req, type); - result = m.apply(rsrc, path.get(0), inputRequestBody); - if (inputRequestBody instanceof RawInput) { - try (InputStream is = req.getInputStream()) { - ServletUtils.consumeRequestBody(is); + if (isPost(req) || isPut(req)) { + RestView createView = c.views().get(PluginName.GERRIT, "CREATE./"); + if (createView != null) { + viewData = new ViewData(null, createView); + status = SC_CREATED; + path.add(id); + } else { + throw e; + } + } else if (isDelete(req)) { + RestView deleteView = + c.views().get(PluginName.GERRIT, "DELETE_MISSING./"); + if (deleteView != null) { + viewData = new ViewData(null, deleteView); + status = SC_NO_CONTENT; + path.add(id); + } else { + throw e; + } + } else { + throw e; + } } + if (viewData.view == null) { + viewData = view(c, req.getMethod(), path); + } + checkRequiresCapability(viewData); } - } else if (viewData.view instanceof RestCollectionDeleteMissingView) { - @SuppressWarnings("unchecked") - RestCollectionDeleteMissingView m = - (RestCollectionDeleteMissingView) viewData.view; - Type type = inputType(m); - inputRequestBody = parseRequest(req, type); - result = m.apply(rsrc, path.get(0), inputRequestBody); - if (inputRequestBody instanceof RawInput) { - try (InputStream is = req.getInputStream()) { - ServletUtils.consumeRequestBody(is); - } + if (notModified(req, rsrc, viewData.view)) { + logger.atFinest().log("REST call succeeded: %d", SC_NOT_MODIFIED); + res.sendError(SC_NOT_MODIFIED); + return; } - } else if (viewData.view instanceof RestCollectionModifyView) { - @SuppressWarnings("unchecked") - RestCollectionModifyView m = - (RestCollectionModifyView) viewData.view; - Type type = inputType(m); - inputRequestBody = parseRequest(req, type); - result = m.apply(rsrc, inputRequestBody); - if (inputRequestBody instanceof RawInput) { - try (InputStream is = req.getInputStream()) { - ServletUtils.consumeRequestBody(is); - } + if (!globals.paramParser.get().parse(viewData.view, qp.params(), req, res)) { + return; } - } else { - throw new ResourceNotFoundException(); + + if (viewData.view instanceof RestReadView && isRead(req)) { + result = ((RestReadView) viewData.view).apply(rsrc); + } else if (viewData.view instanceof RestModifyView) { + @SuppressWarnings("unchecked") + RestModifyView m = + (RestModifyView) viewData.view; + + Type type = inputType(m); + inputRequestBody = parseRequest(req, type); + result = m.apply(rsrc, inputRequestBody); + if (inputRequestBody instanceof RawInput) { + try (InputStream is = req.getInputStream()) { + ServletUtils.consumeRequestBody(is); + } + } + } else if (viewData.view instanceof RestCollectionCreateView) { + @SuppressWarnings("unchecked") + RestCollectionCreateView m = + (RestCollectionCreateView) viewData.view; + + Type type = inputType(m); + inputRequestBody = parseRequest(req, type); + result = m.apply(rsrc, path.get(0), inputRequestBody); + if (inputRequestBody instanceof RawInput) { + try (InputStream is = req.getInputStream()) { + ServletUtils.consumeRequestBody(is); + } + } + } else if (viewData.view instanceof RestCollectionDeleteMissingView) { + @SuppressWarnings("unchecked") + RestCollectionDeleteMissingView m = + (RestCollectionDeleteMissingView) viewData.view; + + Type type = inputType(m); + inputRequestBody = parseRequest(req, type); + result = m.apply(rsrc, path.get(0), inputRequestBody); + if (inputRequestBody instanceof RawInput) { + try (InputStream is = req.getInputStream()) { + ServletUtils.consumeRequestBody(is); + } + } + } else if (viewData.view instanceof RestCollectionModifyView) { + @SuppressWarnings("unchecked") + RestCollectionModifyView m = + (RestCollectionModifyView) viewData.view; + + Type type = inputType(m); + inputRequestBody = parseRequest(req, type); + result = m.apply(rsrc, inputRequestBody); + if (inputRequestBody instanceof RawInput) { + try (InputStream is = req.getInputStream()) { + ServletUtils.consumeRequestBody(is); + } + } + } else { + throw new ResourceNotFoundException(); + } + + if (result instanceof Response) { + @SuppressWarnings("rawtypes") + Response r = (Response) result; + status = r.statusCode(); + configureCaching(req, res, rsrc, viewData.view, r.caching()); + } else if (result instanceof Response.Redirect) { + CacheHeaders.setNotCacheable(res); + String location = ((Response.Redirect) result).location(); + res.sendRedirect(location); + logger.atFinest().log("REST call redirected to: %s", location); + return; + } else if (result instanceof Response.Accepted) { + CacheHeaders.setNotCacheable(res); + res.setStatus(SC_ACCEPTED); + res.setHeader(HttpHeaders.LOCATION, ((Response.Accepted) result).location()); + logger.atFinest().log("REST call succeeded: %d", SC_ACCEPTED); + return; + } else { + CacheHeaders.setNotCacheable(res); + } + res.setStatus(status); + logger.atFinest().log("REST call succeeded: %d", status); } - if (result instanceof Response) { - @SuppressWarnings("rawtypes") - Response r = (Response) result; - status = r.statusCode(); - configureCaching(req, res, rsrc, viewData.view, r.caching()); - } else if (result instanceof Response.Redirect) { - CacheHeaders.setNotCacheable(res); - String location = ((Response.Redirect) result).location(); - res.sendRedirect(location); - logger.atFinest().log("REST call redirected to: %s", location); - return; - } else if (result instanceof Response.Accepted) { - CacheHeaders.setNotCacheable(res); - res.setStatus(SC_ACCEPTED); - res.setHeader(HttpHeaders.LOCATION, ((Response.Accepted) result).location()); - logger.atFinest().log("REST call succeeded: %d", SC_ACCEPTED); - return; - } else { - CacheHeaders.setNotCacheable(res); - } - res.setStatus(status); - logger.atFinest().log("REST call succeeded: %d", status); - if (result != Response.none()) { result = Response.unwrap(result); if (result instanceof BinaryResult) { diff --git a/java/com/google/gerrit/metrics/BUILD b/java/com/google/gerrit/metrics/BUILD index b7b99811f7..29b0a92205 100644 --- a/java/com/google/gerrit/metrics/BUILD +++ b/java/com/google/gerrit/metrics/BUILD @@ -6,6 +6,7 @@ java_library( "//java/com/google/gerrit/common:server", "//java/com/google/gerrit/extensions:api", "//java/com/google/gerrit/lifecycle", + "//java/com/google/gerrit/server/logging", "//lib:guava", "//lib/flogger:api", "//lib/guice", diff --git a/java/com/google/gerrit/metrics/Timer0.java b/java/com/google/gerrit/metrics/Timer0.java index 21344884cf..d0033a41f4 100644 --- a/java/com/google/gerrit/metrics/Timer0.java +++ b/java/com/google/gerrit/metrics/Timer0.java @@ -18,6 +18,8 @@ import static java.util.concurrent.TimeUnit.NANOSECONDS; import com.google.common.flogger.FluentLogger; import com.google.gerrit.extensions.registration.RegistrationHandle; +import com.google.gerrit.server.logging.LoggingContext; +import com.google.gerrit.server.logging.PerformanceLogRecord; import java.util.concurrent.TimeUnit; /** @@ -68,7 +70,10 @@ public abstract class Timer0 implements RegistrationHandle { * @param unit time unit of the value */ public final void record(long value, TimeUnit unit) { - logger.atFinest().log("%s took %dms", name, unit.toMillis(value)); + long durationMs = unit.toMillis(value); + LoggingContext.getInstance() + .addPerformanceLogRecord(() -> PerformanceLogRecord.create(name, durationMs)); + logger.atFinest().log("%s took %dms", name, durationMs); doRecord(value, unit); } diff --git a/java/com/google/gerrit/metrics/Timer1.java b/java/com/google/gerrit/metrics/Timer1.java index 16c151ebde..01ca768eef 100644 --- a/java/com/google/gerrit/metrics/Timer1.java +++ b/java/com/google/gerrit/metrics/Timer1.java @@ -18,6 +18,8 @@ import static java.util.concurrent.TimeUnit.NANOSECONDS; import com.google.common.flogger.FluentLogger; import com.google.gerrit.extensions.registration.RegistrationHandle; +import com.google.gerrit.server.logging.LoggingContext; +import com.google.gerrit.server.logging.PerformanceLogRecord; import java.util.concurrent.TimeUnit; /** @@ -75,7 +77,14 @@ public abstract class Timer1 implements RegistrationHandle { * @param unit time unit of the value */ public final void record(F1 field1, long value, TimeUnit unit) { - logger.atFinest().log("%s (%s) took %dms", name, field1, unit.toMillis(value)); + long durationMs = unit.toMillis(value); + + // TODO(ekempin): We don't know the field name here. Check whether we can make it available. + LoggingContext.getInstance() + .addPerformanceLogRecord( + () -> PerformanceLogRecord.create(name, durationMs, "field1", field1)); + + logger.atFinest().log("%s (%s) took %dms", name, field1, durationMs); doRecord(field1, value, unit); } diff --git a/java/com/google/gerrit/metrics/Timer2.java b/java/com/google/gerrit/metrics/Timer2.java index bf19448d70..bacbcdff86 100644 --- a/java/com/google/gerrit/metrics/Timer2.java +++ b/java/com/google/gerrit/metrics/Timer2.java @@ -18,6 +18,8 @@ import static java.util.concurrent.TimeUnit.NANOSECONDS; import com.google.common.flogger.FluentLogger; import com.google.gerrit.extensions.registration.RegistrationHandle; +import com.google.gerrit.server.logging.LoggingContext; +import com.google.gerrit.server.logging.PerformanceLogRecord; import java.util.concurrent.TimeUnit; /** @@ -80,7 +82,15 @@ public abstract class Timer2 implements RegistrationHandle { * @param unit time unit of the value */ public final void record(F1 field1, F2 field2, long value, TimeUnit unit) { - logger.atFinest().log("%s (%s, %s) took %dms", name, field1, field2, unit.toMillis(value)); + long durationMs = unit.toMillis(value); + + // TODO(ekempin): We don't know the field names here. Check whether we can make them available. + LoggingContext.getInstance() + .addPerformanceLogRecord( + () -> + PerformanceLogRecord.create(name, durationMs, "field1", field1, "field2", field2)); + + logger.atFinest().log("%s (%s, %s) took %dms", name, field1, field2, durationMs); doRecord(field1, field2, value, unit); } diff --git a/java/com/google/gerrit/metrics/Timer3.java b/java/com/google/gerrit/metrics/Timer3.java index c910eb0c85..27e224b67a 100644 --- a/java/com/google/gerrit/metrics/Timer3.java +++ b/java/com/google/gerrit/metrics/Timer3.java @@ -18,6 +18,8 @@ import static java.util.concurrent.TimeUnit.NANOSECONDS; import com.google.common.flogger.FluentLogger; import com.google.gerrit.extensions.registration.RegistrationHandle; +import com.google.gerrit.server.logging.LoggingContext; +import com.google.gerrit.server.logging.PerformanceLogRecord; import java.util.concurrent.TimeUnit; /** @@ -85,8 +87,16 @@ public abstract class Timer3 implements RegistrationHandle { * @param unit time unit of the value */ public final void record(F1 field1, F2 field2, F3 field3, long value, TimeUnit unit) { - logger.atFinest().log( - "%s (%s, %s, %s) took %dms", name, field1, field2, field3, unit.toMillis(value)); + long durationMs = unit.toMillis(value); + + // TODO(ekempin): We don't know the field names here. Check whether we can make them available. + LoggingContext.getInstance() + .addPerformanceLogRecord( + () -> + PerformanceLogRecord.create( + name, durationMs, "field1", field1, "field2", field2, "field3", field3)); + + logger.atFinest().log("%s (%s, %s, %s) took %dms", name, field1, field2, field3, durationMs); doRecord(field1, field2, field3, value, unit); } diff --git a/java/com/google/gerrit/server/BUILD b/java/com/google/gerrit/server/BUILD index 736e786afe..2cc4fb2280 100644 --- a/java/com/google/gerrit/server/BUILD +++ b/java/com/google/gerrit/server/BUILD @@ -136,6 +136,7 @@ java_library( ":server", "//java/com/google/gerrit/extensions:api", "//java/com/google/gerrit/server/git/receive", + "//java/com/google/gerrit/server/logging", "//java/com/google/gerrit/server/restapi", "//lib:blame-cache", "//lib:guava", diff --git a/java/com/google/gerrit/server/config/GerritGlobalModule.java b/java/com/google/gerrit/server/config/GerritGlobalModule.java index 59a55ab2e7..14747e598d 100644 --- a/java/com/google/gerrit/server/config/GerritGlobalModule.java +++ b/java/com/google/gerrit/server/config/GerritGlobalModule.java @@ -136,6 +136,7 @@ import com.google.gerrit.server.git.validators.UploadValidationListener; import com.google.gerrit.server.git.validators.UploadValidators; import com.google.gerrit.server.group.db.GroupDbModule; import com.google.gerrit.server.index.change.ReindexAfterRefUpdate; +import com.google.gerrit.server.logging.PerformanceLogger; import com.google.gerrit.server.mail.AutoReplyMailFilter; import com.google.gerrit.server.mail.EmailModule; import com.google.gerrit.server.mail.ListMailFilter; @@ -380,6 +381,7 @@ public class GerritGlobalModule extends FactoryModule { DynamicItem.itemOf(binder(), ProjectNameLockManager.class); DynamicSet.setOf(binder(), SubmitRule.class); DynamicSet.setOf(binder(), QuotaEnforcer.class); + DynamicSet.setOf(binder(), PerformanceLogger.class); DynamicMap.mapOf(binder(), MailFilter.class); bind(MailFilter.class).annotatedWith(Exports.named("ListMailFilter")).to(ListMailFilter.class); diff --git a/java/com/google/gerrit/server/git/receive/ReceiveCommits.java b/java/com/google/gerrit/server/git/receive/ReceiveCommits.java index 73e0b1c319..7a0b56eaa3 100644 --- a/java/com/google/gerrit/server/git/receive/ReceiveCommits.java +++ b/java/com/google/gerrit/server/git/receive/ReceiveCommits.java @@ -74,6 +74,7 @@ import com.google.gerrit.extensions.api.projects.ProjectConfigEntryType; import com.google.gerrit.extensions.client.GeneralPreferencesInfo; import com.google.gerrit.extensions.registration.DynamicItem; import com.google.gerrit.extensions.registration.DynamicMap; +import com.google.gerrit.extensions.registration.DynamicSet; import com.google.gerrit.extensions.registration.Extension; import com.google.gerrit.extensions.restapi.AuthException; import com.google.gerrit.extensions.restapi.BadRequestException; @@ -118,6 +119,8 @@ import com.google.gerrit.server.git.validators.RefOperationValidationException; import com.google.gerrit.server.git.validators.RefOperationValidators; import com.google.gerrit.server.git.validators.ValidationMessage; import com.google.gerrit.server.index.change.ChangeIndexer; +import com.google.gerrit.server.logging.PerformanceLogContext; +import com.google.gerrit.server.logging.PerformanceLogger; import com.google.gerrit.server.logging.RequestId; import com.google.gerrit.server.logging.TraceContext; import com.google.gerrit.server.mail.MailUtil.MailRecipients; @@ -306,6 +309,7 @@ class ReceiveCommits { private final MergedByPushOp.Factory mergedByPushOpFactory; private final PatchSetInfoFactory patchSetInfoFactory; private final PatchSetUtil psUtil; + private final DynamicSet performanceLoggers; private final PermissionBackend permissionBackend; private final ProjectCache projectCache; private final Provider queryProvider; @@ -382,6 +386,7 @@ class ReceiveCommits { MergedByPushOp.Factory mergedByPushOpFactory, PatchSetInfoFactory patchSetInfoFactory, PatchSetUtil psUtil, + DynamicSet performanceLoggers, PermissionBackend permissionBackend, ProjectCache projectCache, Provider queryProvider, @@ -427,6 +432,7 @@ class ReceiveCommits { this.pluginConfigEntries = pluginConfigEntries; this.projectCache = projectCache; this.psUtil = psUtil; + this.performanceLoggers = performanceLoggers; this.queryProvider = queryProvider; this.receiveConfig = receiveConfig; this.refValidatorsFactory = refValidatorsFactory; @@ -525,10 +531,12 @@ class ReceiveCommits { Collection commands, MultiProgressMonitor progress) { parsePushOptions(); try (TraceContext traceContext = - TraceContext.newTrace( - tracePushOption.isPresent(), - tracePushOption.orElse(null), - (tagName, traceId) -> addMessage(tagName + ": " + traceId))) { + TraceContext.newTrace( + tracePushOption.isPresent(), + tracePushOption.orElse(null), + (tagName, traceId) -> addMessage(tagName + ": " + traceId)); + PerformanceLogContext performanceLogContext = + new PerformanceLogContext(performanceLoggers)) { traceContext.addTag(RequestId.Type.RECEIVE_ID, new RequestId(project.getNameKey().get())); logger.atFinest().log("Calling user: %s", user.getLoggableName()); diff --git a/java/com/google/gerrit/server/logging/BUILD b/java/com/google/gerrit/server/logging/BUILD index cf8e9db58f..5ab8e69138 100644 --- a/java/com/google/gerrit/server/logging/BUILD +++ b/java/com/google/gerrit/server/logging/BUILD @@ -6,10 +6,12 @@ java_library( visibility = ["//visibility:public"], deps = [ "//java/com/google/gerrit/common:annotations", + "//java/com/google/gerrit/extensions:api", "//java/com/google/gerrit/server/util/time", "//lib:guava", "//lib/auto:auto-value", "//lib/auto:auto-value-annotations", "//lib/flogger:api", + "//lib/guice", ], ) diff --git a/java/com/google/gerrit/server/logging/LoggingContext.java b/java/com/google/gerrit/server/logging/LoggingContext.java index 1e81c29bd6..deb111a8b6 100644 --- a/java/com/google/gerrit/server/logging/LoggingContext.java +++ b/java/com/google/gerrit/server/logging/LoggingContext.java @@ -14,8 +14,13 @@ package com.google.gerrit.server.logging; +import static java.util.Objects.requireNonNull; + +import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableSetMultimap; import com.google.common.flogger.backend.Tags; +import com.google.inject.Provider; +import java.util.List; import java.util.concurrent.Callable; import java.util.logging.Level; @@ -35,6 +40,9 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log private static final ThreadLocal tags = new ThreadLocal<>(); private static final ThreadLocal forceLogging = new ThreadLocal<>(); + private static final ThreadLocal performanceLogging = new ThreadLocal<>(); + private static final ThreadLocal performanceLogRecords = + new ThreadLocal<>(); private LoggingContext() {} @@ -47,14 +55,28 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log if (runnable instanceof LoggingContextAwareRunnable) { return runnable; } - return new LoggingContextAwareRunnable(runnable); + + // Pass the MutablePerformanceLogRecords instance into the LoggingContextAwareRunnable + // constructor so that performance log records that are created in the wrapped runnable are + // added to this MutablePerformanceLogRecords instance. This is important since performance + // log records are processed only at the end of the request and performance log records that + // are created in another thread should not get lost. + return new LoggingContextAwareRunnable( + runnable, getInstance().getMutablePerformanceLogRecords()); } public static Callable copy(Callable callable) { if (callable instanceof LoggingContextAwareCallable) { return callable; } - return new LoggingContextAwareCallable<>(callable); + + // Pass the MutablePerformanceLogRecords instance into the LoggingContextAwareCallable + // constructor so that performance log records that are created in the wrapped runnable are + // added to this MutablePerformanceLogRecords instance. This is important since performance + // log records are processed only at the end of the request and performance log records that + // are created in another thread should not get lost. + return new LoggingContextAwareCallable<>( + callable, getInstance().getMutablePerformanceLogRecords()); } @Override @@ -120,4 +142,103 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log } return oldValue != null ? oldValue : false; } + + boolean isPerformanceLogging() { + Boolean isPerformanceLogging = performanceLogging.get(); + return isPerformanceLogging != null ? isPerformanceLogging : false; + } + + /** + * Enables performance logging. + * + *

It's important to enable performance logging only in a context that ensures to consume the + * captured performance log records. Otherwise captured performance log records might leak into + * other requests that are executed by the same thread (if a thread pool is used to process + * requests). + * + * @param enable whether performance logging should be enabled. + * @return whether performance logging was be enabled before invoking this method (old value). + */ + boolean performanceLogging(boolean enable) { + Boolean oldValue = performanceLogging.get(); + if (enable) { + performanceLogging.set(true); + } else { + performanceLogging.remove(); + } + return oldValue != null ? oldValue : false; + } + + /** + * Adds a performance log record, if performance logging is enabled. + * + * @param recordProvider Provider for the performance log record. This provider is only invoked if + * performance logging is enabled. This means if performance logging is disabled, we avoid the + * creation of a {@link PerformanceLogRecord}. + */ + public void addPerformanceLogRecord(Provider recordProvider) { + if (!isPerformanceLogging()) { + // return early and avoid the creation of a PerformanceLogRecord + return; + } + + getMutablePerformanceLogRecords().add(recordProvider.get()); + } + + ImmutableList getPerformanceLogRecords() { + MutablePerformanceLogRecords records = performanceLogRecords.get(); + if (records != null) { + return records.list(); + } + return ImmutableList.of(); + } + + void clearPerformanceLogEntries() { + performanceLogRecords.remove(); + } + + /** + * Set the performance log records in this logging context. Existing log records are overwritten. + * + *

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

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

This method is intended to be only used when the logging context is copied to a new thread + * to ensure that the performance log records that are added in the new thread are added to the + * same {@link MutablePerformanceLogRecords} instance (see {@link LoggingContextAwareRunnable} and + * {@link LoggingContextAwareCallable}). This is important since performance log records are + * processed only at the end of the request and performance log records that are created in + * another thread should not get lost. + * + * @param mutablePerformanceLogRecords the {@link MutablePerformanceLogRecords} instance in which + * performance log records should be stored + */ + void setMutablePerformanceLogRecords(MutablePerformanceLogRecords mutablePerformanceLogRecords) { + performanceLogRecords.set(requireNonNull(mutablePerformanceLogRecords)); + } + + private MutablePerformanceLogRecords getMutablePerformanceLogRecords() { + MutablePerformanceLogRecords records = performanceLogRecords.get(); + if (records == null) { + records = new MutablePerformanceLogRecords(); + performanceLogRecords.set(records); + } + return records; + } } diff --git a/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java b/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java index 6aff5c4b32..3906630d9e 100644 --- a/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java +++ b/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java @@ -14,6 +14,7 @@ package com.google.gerrit.server.logging; +import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableSetMultimap; import java.util.concurrent.Callable; @@ -35,12 +36,24 @@ class LoggingContextAwareCallable implements Callable { private final Thread callingThread; private final ImmutableSetMultimap tags; private final boolean forceLogging; + private final boolean performanceLogging; + private final MutablePerformanceLogRecords mutablePerformanceLogRecords; - LoggingContextAwareCallable(Callable callable) { + /** + * Creates a LoggingContextAwareCallable that wraps the given {@link Callable}. + * + * @param callable Callable that should be wrapped. + * @param mutablePerformanceLogRecords instance of {@link MutablePerformanceLogRecords} to which + * performance log records that are created from the runnable are added + */ + LoggingContextAwareCallable( + Callable callable, MutablePerformanceLogRecords mutablePerformanceLogRecords) { this.callable = callable; this.callingThread = Thread.currentThread(); this.tags = LoggingContext.getInstance().getTagsAsMap(); this.forceLogging = LoggingContext.getInstance().isLoggingForced(); + this.performanceLogging = LoggingContext.getInstance().isPerformanceLogging(); + this.mutablePerformanceLogRecords = mutablePerformanceLogRecords; } @Override @@ -54,13 +67,27 @@ class LoggingContextAwareCallable implements Callable { LoggingContext loggingCtx = LoggingContext.getInstance(); ImmutableSetMultimap oldTags = loggingCtx.getTagsAsMap(); boolean oldForceLogging = loggingCtx.isLoggingForced(); + boolean oldPerformanceLogging = loggingCtx.isPerformanceLogging(); + ImmutableList oldPerformanceLogRecords = + loggingCtx.getPerformanceLogRecords(); loggingCtx.setTags(tags); loggingCtx.forceLogging(forceLogging); + loggingCtx.performanceLogging(performanceLogging); + + // For the performance log records use the {@link MutablePerformanceLogRecords} instance from + // the logging context of the calling thread in the logging context of the new thread. This way + // performance log records that are created from the new thread are available from the logging + // context of the calling thread. This is important since performance log records are processed + // only at the end of the request and performance log records that are created in another thread + // should not get lost. + loggingCtx.setMutablePerformanceLogRecords(mutablePerformanceLogRecords); try { return callable.call(); } finally { loggingCtx.setTags(oldTags); loggingCtx.forceLogging(oldForceLogging); + loggingCtx.performanceLogging(oldPerformanceLogging); + loggingCtx.setPerformanceLogRecords(oldPerformanceLogRecords); } } } diff --git a/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java b/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java index 0bd7d007ad..712459b2c6 100644 --- a/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java +++ b/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java @@ -14,6 +14,7 @@ package com.google.gerrit.server.logging; +import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableSetMultimap; /** @@ -53,12 +54,24 @@ public class LoggingContextAwareRunnable implements Runnable { private final Thread callingThread; private final ImmutableSetMultimap tags; private final boolean forceLogging; + private final boolean performanceLogging; + private final MutablePerformanceLogRecords mutablePerformanceLogRecords; - LoggingContextAwareRunnable(Runnable runnable) { + /** + * Creates a LoggingContextAwareRunnable that wraps the given {@link Runnable}. + * + * @param runnable Runnable that should be wrapped. + * @param mutablePerformanceLogRecords instance of {@link MutablePerformanceLogRecords} to which + * performance log records that are created from the runnable are added + */ + LoggingContextAwareRunnable( + Runnable runnable, MutablePerformanceLogRecords mutablePerformanceLogRecords) { this.runnable = runnable; this.callingThread = Thread.currentThread(); this.tags = LoggingContext.getInstance().getTagsAsMap(); this.forceLogging = LoggingContext.getInstance().isLoggingForced(); + this.performanceLogging = LoggingContext.getInstance().isPerformanceLogging(); + this.mutablePerformanceLogRecords = mutablePerformanceLogRecords; } public Runnable unwrap() { @@ -77,13 +90,27 @@ public class LoggingContextAwareRunnable implements Runnable { LoggingContext loggingCtx = LoggingContext.getInstance(); ImmutableSetMultimap oldTags = loggingCtx.getTagsAsMap(); boolean oldForceLogging = loggingCtx.isLoggingForced(); + boolean oldPerformanceLogging = loggingCtx.isPerformanceLogging(); + ImmutableList oldPerformanceLogRecords = + loggingCtx.getPerformanceLogRecords(); loggingCtx.setTags(tags); loggingCtx.forceLogging(forceLogging); + loggingCtx.performanceLogging(performanceLogging); + + // For the performance log records use the {@link MutablePerformanceLogRecords} instance from + // the logging context of the calling thread in the logging context of the new thread. This way + // performance log records that are created from the new thread are available from the logging + // context of the calling thread. This is important since performance log records are processed + // only at the end of the request and performance log records that are created in another thread + // should not get lost. + loggingCtx.setMutablePerformanceLogRecords(mutablePerformanceLogRecords); try { runnable.run(); } finally { loggingCtx.setTags(oldTags); loggingCtx.forceLogging(oldForceLogging); + loggingCtx.performanceLogging(oldPerformanceLogging); + loggingCtx.setPerformanceLogRecords(oldPerformanceLogRecords); } } } diff --git a/java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java b/java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java new file mode 100644 index 0000000000..02143f0dfb --- /dev/null +++ b/java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java @@ -0,0 +1,47 @@ +// Copyright (C) 2018 The Android Open Source Project +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package com.google.gerrit.server.logging; + +import com.google.common.collect.ImmutableList; +import java.util.ArrayList; +import java.util.List; + +/** + * Thread-safe store for performance log records. + * + *

This class is intended to keep track of performance log records in {@link LoggingContext}. It + * needs to be thread-safe because it gets shared between threads when the logging context is copied + * to another thread (see {@link LoggingContextAwareRunnable} and {@link + * LoggingContextAwareCallable}. In this case the logging contexts of both threads share the same + * instance of this class. This is important since performance log records are processed only at the + * end of a request and performance log records that are created in another thread should not get + * lost. + */ +public class MutablePerformanceLogRecords { + private final ArrayList performanceLogRecords = new ArrayList<>(); + + public synchronized void add(PerformanceLogRecord record) { + performanceLogRecords.add(record); + } + + public synchronized void set(List records) { + performanceLogRecords.clear(); + performanceLogRecords.addAll(records); + } + + public synchronized ImmutableList list() { + return ImmutableList.copyOf(performanceLogRecords); + } +} diff --git a/java/com/google/gerrit/server/logging/PerformanceLogContext.java b/java/com/google/gerrit/server/logging/PerformanceLogContext.java new file mode 100644 index 0000000000..2f5c789d43 --- /dev/null +++ b/java/com/google/gerrit/server/logging/PerformanceLogContext.java @@ -0,0 +1,111 @@ +// Copyright (C) 2019 The Android Open Source Project +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package com.google.gerrit.server.logging; + +import com.google.common.collect.ImmutableList; +import com.google.common.collect.Iterables; +import com.google.common.flogger.FluentLogger; +import com.google.gerrit.extensions.registration.DynamicSet; +import com.google.gerrit.extensions.registration.Extension; + +/** + * Context for capturing performance log records. When the context is closed the performance log + * records are handed over to the registered {@link PerformanceLogger}s. + * + *

Capturing performance log records is disabled if there are no {@link PerformanceLogger} + * registered (in this case the captured performance log records would never be used). + * + *

It's important to enable capturing of performance log records in a context that ensures to + * consume the captured performance log records. Otherwise captured performance log records might + * leak into other requests that are executed by the same thread (if a thread pool is used to + * process requests). + */ +public class PerformanceLogContext implements AutoCloseable { + private static final FluentLogger logger = FluentLogger.forEnclosingClass(); + + // Do not use PluginSetContext. PluginSetContext traces the plugin latency with a timer metric + // which would result in a performance log and we don't want to log the performance of writing + // a performance log in the performance log (endless loop). + private final DynamicSet performanceLoggers; + + private final boolean oldPerformanceLogging; + private final ImmutableList oldPerformanceLogRecords; + + public PerformanceLogContext(DynamicSet performanceLoggers) { + this.performanceLoggers = performanceLoggers; + + // Just in case remember the old state and reset performance log entries. + this.oldPerformanceLogging = LoggingContext.getInstance().isPerformanceLogging(); + this.oldPerformanceLogRecords = LoggingContext.getInstance().getPerformanceLogRecords(); + LoggingContext.getInstance().clearPerformanceLogEntries(); + + // Do not create performance log entries if no PerformanceLogger is registered. + LoggingContext.getInstance() + .performanceLogging(!Iterables.isEmpty(performanceLoggers.entries())); + } + + @Override + public void close() { + if (LoggingContext.getInstance().isPerformanceLogging()) { + runEach(performanceLoggers, LoggingContext.getInstance().getPerformanceLogRecords()); + } + + // Restore old state. Required to support nesting of PerformanceLogContext's. + LoggingContext.getInstance().performanceLogging(oldPerformanceLogging); + LoggingContext.getInstance().setPerformanceLogRecords(oldPerformanceLogRecords); + } + + /** + * Invokes all performance loggers. + * + *

Similar to how {@code com.google.gerrit.server.plugincontext.PluginContext} invokes plugins + * but without recording metrics for invoking {@link PerformanceLogger}s. + * + * @param performanceLoggers the performance loggers that should be invoked + * @param performanceLogRecords the performance log records that should be handed over to the + * performance loggers + */ + private static void runEach( + DynamicSet performanceLoggers, + ImmutableList performanceLogRecords) { + performanceLoggers + .entries() + .forEach( + p -> { + try (TraceContext traceContext = newPluginTrace(p)) { + performanceLogRecords.forEach(r -> r.writeTo(p.get())); + } catch (Throwable e) { + logger.atWarning().withCause(e).log( + "Failure in %s of plugin %s", p.get().getClass(), p.getPluginName()); + } + }); + } + + /** + * Opens a trace context for a plugin that implements {@link PerformanceLogger}. + * + *

Basically the same as {@code + * com.google.gerrit.server.plugincontext.PluginContext#newTrace(Extension)}. We have this + * method here to avoid a dependency on PluginContext which lives in + * "//java/com/google/gerrit/server". This package ("//java/com/google/gerrit/server/logging") + * should have as few dependencies as possible. + * + * @param extension performance logger extension + * @return the trace context + */ + private static TraceContext newPluginTrace(Extension extension) { + return TraceContext.open().addPluginTag(extension.getPluginName()); + } +} diff --git a/java/com/google/gerrit/server/logging/PerformanceLogRecord.java b/java/com/google/gerrit/server/logging/PerformanceLogRecord.java new file mode 100644 index 0000000000..d30f862208 --- /dev/null +++ b/java/com/google/gerrit/server/logging/PerformanceLogRecord.java @@ -0,0 +1,220 @@ +// Copyright (C) 2019 The Android Open Source Project +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package com.google.gerrit.server.logging; + +import static java.util.Objects.requireNonNull; + +import com.google.auto.value.AutoValue; +import com.google.gerrit.common.Nullable; + +/** + * The record of an operation for which the execution time was measured. + * + *

Meta data is stored in separate key/value fields to avoid expensive instantiations of Map + * objects. + */ +@AutoValue +public abstract class PerformanceLogRecord { + /** + * Creates a performance log record without meta data. + * + * @param operation the name of operation the is was performed + * @param durationMs the execution time in milliseconds + * @return the performance log record + */ + public static PerformanceLogRecord create(String operation, long durationMs) { + return new AutoValue_PerformanceLogRecord( + operation, durationMs, null, null, null, null, null, null, null, null); + } + + /** + * Creates a performance log record with meta data. + * + * @param operation the name of operation the is was performed + * @param durationMs the execution time in milliseconds + * @param key meta data key + * @param value meta data value + * @return the performance log record + */ + public static PerformanceLogRecord create( + String operation, long durationMs, String key, @Nullable Object value) { + return new AutoValue_PerformanceLogRecord( + operation, durationMs, requireNonNull(key), value, null, null, null, null, null, null); + } + + /** + * Creates a performance log record with meta data. + * + * @param operation the name of operation the is was performed + * @param durationMs the execution time in milliseconds + * @param key1 first meta data key + * @param value1 first meta data value + * @param key2 second meta data key + * @param value2 second meta data value + * @return the performance log record + */ + public static PerformanceLogRecord create( + String operation, + long durationMs, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2) { + return new AutoValue_PerformanceLogRecord( + operation, + durationMs, + requireNonNull(key1), + value1, + requireNonNull(key2), + value2, + null, + null, + null, + null); + } + + /** + * Creates a performance log record with meta data. + * + * @param operation the name of operation the is was performed + * @param durationMs the execution time in milliseconds + * @param key1 first meta data key + * @param value1 first meta data value + * @param key2 second meta data key + * @param value2 second meta data value + * @param key3 third meta data key + * @param value3 third meta data value + * @return the performance log record + */ + public static PerformanceLogRecord create( + String operation, + long durationMs, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2, + String key3, + @Nullable Object value3) { + return new AutoValue_PerformanceLogRecord( + operation, + durationMs, + requireNonNull(key1), + value1, + requireNonNull(key2), + value2, + requireNonNull(key3), + value3, + null, + null); + } + + /** + * Creates a performance log record with meta data. + * + * @param operation the name of operation the is was performed + * @param durationMs the execution time in milliseconds + * @param key1 first meta data key + * @param value1 first meta data value + * @param key2 second meta data key + * @param value2 second meta data value + * @param key3 third meta data key + * @param value3 third meta data value + * @param key4 forth meta data key + * @param value4 forth meta data value + * @return the performance log record + */ + public static PerformanceLogRecord create( + String operation, + long durationMs, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2, + String key3, + @Nullable Object value3, + String key4, + @Nullable Object value4) { + return new AutoValue_PerformanceLogRecord( + operation, + durationMs, + requireNonNull(key1), + value1, + requireNonNull(key2), + value2, + requireNonNull(key3), + value3, + requireNonNull(key4), + value4); + } + + public abstract String operation(); + + public abstract long durationMs(); + + @Nullable + public abstract String key1(); + + @Nullable + public abstract Object value1(); + + @Nullable + public abstract String key2(); + + @Nullable + public abstract Object value2(); + + @Nullable + public abstract String key3(); + + @Nullable + public abstract Object value3(); + + @Nullable + public abstract String key4(); + + @Nullable + public abstract Object value4(); + + void writeTo(PerformanceLogger performanceLogger) { + if (key4() != null) { + requireNonNull(key1()); + requireNonNull(key2()); + requireNonNull(key3()); + performanceLogger.log( + operation(), + durationMs(), + key1(), + value1(), + key2(), + value2(), + key3(), + value3(), + key4(), + value4()); + } else if (key3() != null) { + requireNonNull(key1()); + requireNonNull(key2()); + performanceLogger.log( + operation(), durationMs(), key1(), value1(), key2(), value2(), key3(), value3()); + } else if (key2() != null) { + requireNonNull(key1()); + performanceLogger.log(operation(), durationMs(), key1(), value1(), key2(), value2()); + } else if (key1() != null) { + performanceLogger.log(operation(), durationMs(), key1(), value1()); + } else { + performanceLogger.log(operation(), durationMs()); + } + } +} diff --git a/java/com/google/gerrit/server/logging/PerformanceLogger.java b/java/com/google/gerrit/server/logging/PerformanceLogger.java new file mode 100644 index 0000000000..3e33a3aba2 --- /dev/null +++ b/java/com/google/gerrit/server/logging/PerformanceLogger.java @@ -0,0 +1,164 @@ +// Copyright (C) 2019 The Android Open Source Project +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package com.google.gerrit.server.logging; + +import com.google.common.collect.ImmutableMap; +import com.google.gerrit.common.Nullable; +import com.google.gerrit.extensions.annotations.ExtensionPoint; +import java.util.Map; +import java.util.Optional; + +/** + * Extension point for logging performance records. + * + *

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

For optimal performance implementors should overwrite the default log methods to + * avoid unneeded instantiation of Map objects. + */ +@ExtensionPoint +public interface PerformanceLogger { + /** + * Record the execution time of an operation in a performance log. + * + * @param operation operation that was performed + * @param durationMs time that the execution of the operation took (in milliseconds) + */ + default void log(String operation, long durationMs) { + log(operation, durationMs, ImmutableMap.of()); + } + + /** + * Record the execution time of an operation in a performance log. + * + * @param operation operation that was performed + * @param durationMs time that the execution of the operation took (in milliseconds) + * @param key meta data key + * @param value meta data value + */ + default void log(String operation, long durationMs, String key, @Nullable Object value) { + log(operation, durationMs, ImmutableMap.of(key, Optional.ofNullable(value))); + } + + /** + * Record the execution time of an operation in a performance log. + * + * @param operation operation that was performed + * @param durationMs time that the execution of the operation took (in milliseconds) + * @param key1 first meta data key + * @param value1 first meta data value + * @param key2 second meta data key + * @param value2 second meta data value + */ + default void log( + String operation, + long durationMs, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2) { + log( + operation, + durationMs, + ImmutableMap.of(key1, Optional.ofNullable(value1), key2, Optional.ofNullable(value2))); + } + + /** + * Record the execution time of an operation in a performance log. + * + * @param operation operation that was performed + * @param durationMs time that the execution of the operation took (in milliseconds) + * @param key1 first meta data key + * @param value1 first meta data value + * @param key2 second meta data key + * @param value2 second meta data value + * @param key3 third meta data key + * @param value3 third meta data value + */ + default void log( + String operation, + long durationMs, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2, + String key3, + @Nullable Object value3) { + log( + operation, + durationMs, + ImmutableMap.of( + key1, + Optional.ofNullable(value1), + key2, + Optional.ofNullable(value2), + key3, + Optional.ofNullable(value3))); + } + + /** + * Record the execution time of an operation in a performance log. + * + * @param operation operation that was performed + * @param durationMs time that the execution of the operation took (in milliseconds) + * @param key1 first meta data key + * @param value1 first meta data value + * @param key2 second meta data key + * @param value2 second meta data value + * @param key3 third meta data key + * @param value3 third meta data value + * @param key4 fourth meta data key + * @param value4 fourth meta data value + */ + default void log( + String operation, + long durationMs, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2, + String key3, + @Nullable Object value3, + String key4, + @Nullable Object value4) { + log( + operation, + durationMs, + ImmutableMap.of( + key1, + Optional.ofNullable(value1), + key2, + Optional.ofNullable(value2), + key3, + Optional.ofNullable(value3), + key4, + Optional.ofNullable(value4))); + } + + /** + * Record the execution time of an operation in a performance log. + * + *

For small numbers of meta data entries the instantiation of a map should avoided by using + * one of the log methods that allows to pass in meta data entries directly. + * + * @param operation operation that was performed + * @param durationMs time that the execution of the operation took (in milliseconds) + * @param metaData key-value map with meta data + */ + void log(String operation, long durationMs, Map> metaData); +} diff --git a/java/com/google/gerrit/server/logging/TraceContext.java b/java/com/google/gerrit/server/logging/TraceContext.java index 06fa302f0a..b018da4e8a 100644 --- a/java/com/google/gerrit/server/logging/TraceContext.java +++ b/java/com/google/gerrit/server/logging/TraceContext.java @@ -155,35 +155,32 @@ public class TraceContext implements AutoCloseable { /** * Opens a new timer that logs the time for an operation if request tracing is enabled. * - *

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

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

If request tracing is not enabled this is a no-op. - * - * @param message the message + * @param operation the name of operation the is being performed * @param key1 first meta data key * @param value1 first meta data value * @param key2 second meta data key @@ -191,16 +188,23 @@ public class TraceContext implements AutoCloseable { * @return the trace timer */ public static TraceTimer newTimer( - String message, String key1, Object value1, String key2, Object value2) { - return new TraceTimer(message + " (%s=%s, %s=%s)", key1, value1, key2, value2); + String operation, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2) { + return new TraceTimer( + requireNonNull(operation, "operation is required"), + requireNonNull(key1, "key1 is required"), + value1, + requireNonNull(key2, "key2 is required"), + value2); } /** * Opens a new timer that logs the time for an operation if request tracing is enabled. * - *

If request tracing is not enabled this is a no-op. - * - * @param message the message + * @param operation the name of operation the is being performed * @param key1 first meta data key * @param value1 first meta data value * @param key2 second meta data key @@ -210,23 +214,27 @@ public class TraceContext implements AutoCloseable { * @return the trace timer */ public static TraceTimer newTimer( - String message, + String operation, String key1, - Object value1, + @Nullable Object value1, String key2, - Object value2, + @Nullable Object value2, String key3, - Object value3) { + @Nullable Object value3) { return new TraceTimer( - message + " (%s=%s, %s=%s, %s=%s)", key1, value1, key2, value2, key3, value3); + requireNonNull(operation, "operation is required"), + requireNonNull(key1, "key1 is required"), + value1, + requireNonNull(key2, "key2 is required"), + value2, + requireNonNull(key3, "key3 is required"), + value3); } /** * Opens a new timer that logs the time for an operation if request tracing is enabled. * - *

If request tracing is not enabled this is a no-op. - * - * @param message the message + * @param operation the name of operation the is being performed * @param key1 first meta data key * @param value1 first meta data value * @param key2 second meta data key @@ -238,24 +246,24 @@ public class TraceContext implements AutoCloseable { * @return the trace timer */ public static TraceTimer newTimer( - String message, + String operation, String key1, - Object value1, + @Nullable Object value1, String key2, - Object value2, + @Nullable Object value2, String key3, - Object value3, + @Nullable Object value3, String key4, - Object value4) { + @Nullable Object value4) { return new TraceTimer( - message + " (%s=%s, %s=%s, %s=%s, %s=%s)", - key1, + requireNonNull(operation, "operation is required"), + requireNonNull(key1, "key1 is required"), value1, - key2, + requireNonNull(key2, "key2 is required"), value2, - key3, + requireNonNull(key3, "key3 is required"), value3, - key4, + requireNonNull(key4, "key4 is required"), value4); } @@ -265,52 +273,86 @@ public class TraceContext implements AutoCloseable { private final Consumer logFn; private final Stopwatch stopwatch; - private TraceTimer(String message) { - this(elapsedMs -> logger.atFine().log(message + " (%d ms)", elapsedMs)); + private TraceTimer(String operation) { + this( + elapsedMs -> { + LoggingContext.getInstance() + .addPerformanceLogRecord(() -> PerformanceLogRecord.create(operation, elapsedMs)); + logger.atFine().log("%s (%d ms)", operation, elapsedMs); + }); } - private TraceTimer(String format, @Nullable Object arg1, @Nullable Object arg2) { - this(elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, elapsedMs)); + private TraceTimer(String operation, String key, @Nullable Object value) { + this( + elapsedMs -> { + LoggingContext.getInstance() + .addPerformanceLogRecord( + () -> PerformanceLogRecord.create(operation, elapsedMs, key, value)); + logger.atFine().log("%s (%s=%s) (%d ms)", operation, key, value, elapsedMs); + }); } private TraceTimer( - String format, - @Nullable Object arg1, - @Nullable Object arg2, - @Nullable Object arg3, - @Nullable Object arg4) { + String operation, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2) { this( - elapsedMs -> logger.atFine().log(format + " (%d ms)", arg1, arg2, arg3, arg4, elapsedMs)); + elapsedMs -> { + LoggingContext.getInstance() + .addPerformanceLogRecord( + () -> + PerformanceLogRecord.create( + operation, elapsedMs, key1, value1, key2, value2)); + logger.atFine().log( + "%s (%s=%s, %s=%s) (%d ms)", operation, key1, value1, key2, value2, elapsedMs); + }); } private TraceTimer( - String format, - @Nullable Object arg1, - @Nullable Object arg2, - @Nullable Object arg3, - @Nullable Object arg4, - @Nullable Object arg5, - @Nullable Object arg6) { + String operation, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2, + String key3, + @Nullable Object value3) { this( - elapsedMs -> - logger.atFine().log( - format + " (%d ms)", arg1, arg2, arg3, arg4, arg5, arg6, elapsedMs)); + elapsedMs -> { + LoggingContext.getInstance() + .addPerformanceLogRecord( + () -> + PerformanceLogRecord.create( + operation, elapsedMs, key1, value1, key2, value2, key3, value3)); + logger.atFine().log( + "%s (%s=%s, %s=%s, %s=%s) (%d ms)", + operation, key1, value1, key2, value2, key3, value3, elapsedMs); + }); } private TraceTimer( - String format, - @Nullable Object arg1, - @Nullable Object arg2, - @Nullable Object arg3, - @Nullable Object arg4, - @Nullable Object arg5, - @Nullable Object arg6, - @Nullable Object arg7, - @Nullable Object arg8) { + String operation, + String key1, + @Nullable Object value1, + String key2, + @Nullable Object value2, + String key3, + @Nullable Object value3, + String key4, + @Nullable Object value4) { this( - elapsedMs -> - logger.atFine().log( - format + " (%d ms)", arg1, arg2, arg3, arg4, arg5, arg6, arg7, arg8, elapsedMs)); + elapsedMs -> { + LoggingContext.getInstance() + .addPerformanceLogRecord( + () -> + PerformanceLogRecord.create( + operation, elapsedMs, key1, value1, key2, value2, key3, value3, key4, + value4)); + logger.atFine().log( + "%s (%s=%s, %s=%s, %s=%s, %s=%s) (%d ms)", + operation, key1, value1, key2, value2, key3, value3, key4, value4, elapsedMs); + }); } private TraceTimer(Consumer logFn) { diff --git a/java/com/google/gerrit/sshd/SshCommand.java b/java/com/google/gerrit/sshd/SshCommand.java index 98289570b4..6c08c1e634 100644 --- a/java/com/google/gerrit/sshd/SshCommand.java +++ b/java/com/google/gerrit/sshd/SshCommand.java @@ -14,14 +14,20 @@ package com.google.gerrit.sshd; +import com.google.gerrit.extensions.registration.DynamicSet; import com.google.gerrit.server.AccessPath; +import com.google.gerrit.server.logging.PerformanceLogContext; +import com.google.gerrit.server.logging.PerformanceLogger; import com.google.gerrit.server.logging.TraceContext; +import com.google.inject.Inject; import java.io.IOException; import java.io.PrintWriter; import org.apache.sshd.server.Environment; import org.kohsuke.args4j.Option; public abstract class SshCommand extends BaseCommand { + @Inject private DynamicSet performanceLoggers; + @Option(name = "--trace", usage = "enable request tracing") private boolean trace; @@ -38,7 +44,9 @@ public abstract class SshCommand extends BaseCommand { parseCommandLine(); stdout = toPrintWriter(out); stderr = toPrintWriter(err); - try (TraceContext traceContext = enableTracing()) { + try (TraceContext traceContext = enableTracing(); + PerformanceLogContext performanceLogContext = + new PerformanceLogContext(performanceLoggers)) { SshCommand.this.run(); } finally { stdout.flush(); diff --git a/javatests/com/google/gerrit/acceptance/rest/TraceIT.java b/javatests/com/google/gerrit/acceptance/rest/TraceIT.java index b30dc41290..0251a740e8 100644 --- a/javatests/com/google/gerrit/acceptance/rest/TraceIT.java +++ b/javatests/com/google/gerrit/acceptance/rest/TraceIT.java @@ -17,7 +17,9 @@ package com.google.gerrit.acceptance.rest; import static com.google.common.truth.Truth.assertThat; import static org.apache.http.HttpStatus.SC_CREATED; +import com.google.auto.value.AutoValue; import com.google.common.collect.ImmutableList; +import com.google.common.collect.ImmutableMap; import com.google.common.collect.ImmutableSet; import com.google.common.collect.Iterables; import com.google.common.truth.Expect; @@ -34,12 +36,16 @@ import com.google.gerrit.server.git.validators.CommitValidationException; import com.google.gerrit.server.git.validators.CommitValidationListener; import com.google.gerrit.server.git.validators.CommitValidationMessage; import com.google.gerrit.server.logging.LoggingContext; +import com.google.gerrit.server.logging.PerformanceLogger; import com.google.gerrit.server.logging.TraceContext; import com.google.gerrit.server.project.CreateProjectArgs; import com.google.gerrit.server.validators.ProjectCreationValidationListener; import com.google.gerrit.server.validators.ValidationException; import com.google.inject.Inject; +import java.util.ArrayList; import java.util.List; +import java.util.Map; +import java.util.Optional; import java.util.SortedMap; import java.util.SortedSet; import org.apache.http.message.BasicHeader; @@ -53,12 +59,15 @@ public class TraceIT extends AbstractDaemonTest { @Inject private DynamicSet projectCreationValidationListeners; @Inject private DynamicSet commitValidationListeners; + @Inject private DynamicSet performanceLoggers; @Inject private WorkQueue workQueue; private TraceValidatingProjectCreationValidationListener projectCreationListener; private RegistrationHandle projectCreationListenerRegistrationHandle; private TraceValidatingCommitValidationListener commitValidationListener; private RegistrationHandle commitValidationRegistrationHandle; + private TestPerformanceLogger testPerformanceLogger; + private RegistrationHandle performanceLoggerRegistrationHandle; @Before public void setup() { @@ -68,12 +77,15 @@ public class TraceIT extends AbstractDaemonTest { commitValidationListener = new TraceValidatingCommitValidationListener(); commitValidationRegistrationHandle = commitValidationListeners.add("gerrit", commitValidationListener); + testPerformanceLogger = new TestPerformanceLogger(); + performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger); } @After public void cleanup() { projectCreationListenerRegistrationHandle.remove(); commitValidationRegistrationHandle.remove(); + performanceLoggerRegistrationHandle.remove(); } @Test @@ -263,6 +275,25 @@ public class TraceIT extends AbstractDaemonTest { assertForceLogging(false); } + @Test + public void performanceLoggingForRestCall() throws Exception { + RestResponse response = adminRestSession.put("/projects/new10"); + assertThat(response.getStatusCode()).isEqualTo(SC_CREATED); + + // This assertion assumes that the server invokes the PerformanceLogger plugins before it sends + // the response to the client. If this assertion gets flaky it's likely that this got changed on + // server-side. + assertThat(testPerformanceLogger.logEntries()).isNotEmpty(); + } + + @Test + public void performanceLoggingForPush() throws Exception { + PushOneCommit push = pushFactory.create(admin.newIdent(), testRepo); + PushOneCommit.Result r = push.to("refs/heads/master"); + r.assertOkStatus(); + assertThat(testPerformanceLogger.logEntries()).isNotEmpty(); + } + private void assertForceLogging(boolean expected) { assertThat(LoggingContext.getInstance().shouldForceLogging(null, null, false)) .isEqualTo(expected); @@ -296,4 +327,28 @@ public class TraceIT extends AbstractDaemonTest { return ImmutableList.of(); } } + + private static class TestPerformanceLogger implements PerformanceLogger { + private List logEntries = new ArrayList<>(); + + @Override + public void log(String operation, long durationMs, Map> metaData) { + logEntries.add(PerformanceLogEntry.create(operation, metaData)); + } + + ImmutableList logEntries() { + return ImmutableList.copyOf(logEntries); + } + } + + @AutoValue + abstract static class PerformanceLogEntry { + static PerformanceLogEntry create(String operation, Map> metaData) { + return new AutoValue_TraceIT_PerformanceLogEntry(operation, ImmutableMap.copyOf(metaData)); + } + + abstract String operation(); + + abstract ImmutableMap metaData(); + } } diff --git a/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java b/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java index 9c1e23d0a8..5dd07c0f70 100644 --- a/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java +++ b/javatests/com/google/gerrit/acceptance/ssh/SshTraceIT.java @@ -16,17 +16,25 @@ package com.google.gerrit.acceptance.ssh; import static com.google.common.truth.Truth.assertThat; +import com.google.auto.value.AutoValue; +import com.google.common.collect.ImmutableList; +import com.google.common.collect.ImmutableMap; import com.google.common.collect.Iterables; import com.google.gerrit.acceptance.AbstractDaemonTest; import com.google.gerrit.acceptance.UseSsh; import com.google.gerrit.extensions.registration.DynamicSet; import com.google.gerrit.extensions.registration.RegistrationHandle; import com.google.gerrit.server.logging.LoggingContext; +import com.google.gerrit.server.logging.PerformanceLogger; import com.google.gerrit.server.logging.RequestId; import com.google.gerrit.server.project.CreateProjectArgs; import com.google.gerrit.server.validators.ProjectCreationValidationListener; import com.google.gerrit.server.validators.ValidationException; import com.google.inject.Inject; +import java.util.ArrayList; +import java.util.List; +import java.util.Map; +import java.util.Optional; import org.junit.After; import org.junit.Before; import org.junit.Test; @@ -34,20 +42,26 @@ import org.junit.Test; @UseSsh public class SshTraceIT extends AbstractDaemonTest { @Inject private DynamicSet projectCreationValidationListeners; + @Inject private DynamicSet performanceLoggers; private TraceValidatingProjectCreationValidationListener projectCreationListener; private RegistrationHandle projectCreationListenerRegistrationHandle; + private TestPerformanceLogger testPerformanceLogger; + private RegistrationHandle performanceLoggerRegistrationHandle; @Before public void setup() { projectCreationListener = new TraceValidatingProjectCreationValidationListener(); projectCreationListenerRegistrationHandle = projectCreationValidationListeners.add("gerrit", projectCreationListener); + testPerformanceLogger = new TestPerformanceLogger(); + performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger); } @After public void cleanup() { projectCreationListenerRegistrationHandle.remove(); + performanceLoggerRegistrationHandle.remove(); } @Test @@ -85,10 +99,17 @@ public class SshTraceIT extends AbstractDaemonTest { @Test public void sshCallWithTraceIdAndWithoutTraceFails() throws Exception { - adminSshSession.exec("gerrit create-project --trace-id issue/123 new3"); + adminSshSession.exec("gerrit create-project --trace-id issue/123 new4"); adminSshSession.assertFailure("A trace ID can only be set if --trace was specified."); } + @Test + public void performanceLoggingForSshCall() throws Exception { + adminSshSession.exec("gerrit create-project new5"); + adminSshSession.assertSuccess(); + assertThat(testPerformanceLogger.logEntries()).isNotEmpty(); + } + private static class TraceValidatingProjectCreationValidationListener implements ProjectCreationValidationListener { String traceId; @@ -103,4 +124,28 @@ public class SshTraceIT extends AbstractDaemonTest { this.isLoggingForced = LoggingContext.getInstance().shouldForceLogging(null, null, false); } } + + private static class TestPerformanceLogger implements PerformanceLogger { + private List logEntries = new ArrayList<>(); + + @Override + public void log(String operation, long durationMs, Map> metaData) { + logEntries.add(PerformanceLogEntry.create(operation, metaData)); + } + + ImmutableList logEntries() { + return ImmutableList.copyOf(logEntries); + } + } + + @AutoValue + abstract static class PerformanceLogEntry { + static PerformanceLogEntry create(String operation, Map> metaData) { + return new AutoValue_SshTraceIT_PerformanceLogEntry(operation, ImmutableMap.copyOf(metaData)); + } + + abstract String operation(); + + abstract ImmutableMap metaData(); + } } diff --git a/javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java b/javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java index 5117c01971..c495cd8363 100644 --- a/javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java +++ b/javatests/com/google/gerrit/server/logging/LoggingContextAwareExecutorServiceTest.java @@ -17,25 +17,71 @@ package com.google.gerrit.server.logging; import static com.google.common.truth.Truth.assertThat; import com.google.common.truth.Expect; +import com.google.gerrit.extensions.registration.DynamicSet; +import com.google.gerrit.extensions.registration.RegistrationHandle; +import com.google.gerrit.testing.InMemoryModule; +import com.google.inject.Guice; +import com.google.inject.Inject; +import com.google.inject.Injector; +import java.util.Map; +import java.util.Optional; import java.util.SortedMap; import java.util.SortedSet; import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; +import org.junit.After; +import org.junit.Before; import org.junit.Rule; import org.junit.Test; public class LoggingContextAwareExecutorServiceTest { @Rule public final Expect expect = Expect.create(); + @Inject private DynamicSet performanceLoggers; + + private PerformanceLogger testPerformanceLogger; + private RegistrationHandle performanceLoggerRegistrationHandle; + + @Before + public void setup() { + Injector injector = Guice.createInjector(new InMemoryModule()); + injector.injectMembers(this); + + testPerformanceLogger = + new PerformanceLogger() { + @Override + public void log( + String operation, long durationMs, Map> metaData) { + // do nothing + } + }; + performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger); + } + + @After + public void cleanup() { + performanceLoggerRegistrationHandle.remove(); + } + @Test public void loggingContextPropagationToBackgroundThread() throws Exception { assertThat(LoggingContext.getInstance().getTags().isEmpty()).isTrue(); assertForceLogging(false); - try (TraceContext traceContext = TraceContext.open().forceLogging().addTag("foo", "bar")) { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + + try (TraceContext traceContext = TraceContext.open().forceLogging().addTag("foo", "bar"); + PerformanceLogContext performanceLogContext = + new PerformanceLogContext(performanceLoggers)) { + // Create a performance log record. + TraceContext.newTimer("test").close(); + SortedMap> tagMap = LoggingContext.getInstance().getTags().asMap(); assertThat(tagMap.keySet()).containsExactly("foo"); assertThat(tagMap.get("foo")).containsExactly("bar"); assertForceLogging(true); + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1); ExecutorService executor = new LoggingContextAwareExecutorService(Executors.newFixedThreadPool(1)); @@ -51,17 +97,32 @@ public class LoggingContextAwareExecutorServiceTest { expect .that(LoggingContext.getInstance().shouldForceLogging(null, null, false)) .isTrue(); + expect.that(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); + expect.that(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1); + + // Create another performance log record. We expect this to be visible in the outer + // thread. + TraceContext.newTimer("test2").close(); + expect.that(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(2); }) .get(); - // Verify that tags and force logging flag in the outer thread are still set. + // Verify that logging context values in the outer thread are still set. tagMap = LoggingContext.getInstance().getTags().asMap(); assertThat(tagMap.keySet()).containsExactly("foo"); assertThat(tagMap.get("foo")).containsExactly("bar"); assertForceLogging(true); + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); + + // The performance log record that was added in the inner thread is available in addition to + // the performance log record that was created in the outer thread. + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(2); } + assertThat(LoggingContext.getInstance().getTags().isEmpty()).isTrue(); assertForceLogging(false); + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); } private void assertForceLogging(boolean expected) { diff --git a/javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java b/javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java new file mode 100644 index 0000000000..4d0b1f05f2 --- /dev/null +++ b/javatests/com/google/gerrit/server/logging/PerformanceLogContextTest.java @@ -0,0 +1,467 @@ +// Copyright (C) 2019 The Android Open Source Project +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package com.google.gerrit.server.logging; + +import static com.google.common.truth.Truth.assertThat; + +import com.google.auto.value.AutoValue; +import com.google.common.collect.ImmutableList; +import com.google.common.collect.ImmutableMap; +import com.google.gerrit.extensions.registration.DynamicSet; +import com.google.gerrit.extensions.registration.RegistrationHandle; +import com.google.gerrit.metrics.Description; +import com.google.gerrit.metrics.Field; +import com.google.gerrit.metrics.MetricMaker; +import com.google.gerrit.metrics.Timer0; +import com.google.gerrit.metrics.Timer1; +import com.google.gerrit.metrics.Timer2; +import com.google.gerrit.metrics.Timer3; +import com.google.gerrit.testing.InMemoryModule; +import com.google.inject.Guice; +import com.google.inject.Inject; +import com.google.inject.Injector; +import java.util.ArrayList; +import java.util.List; +import java.util.Map; +import java.util.Optional; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; + +public class PerformanceLogContextTest { + @Inject private DynamicSet performanceLoggers; + + // In this test setup this gets the DisabledMetricMaker injected. This means it doesn't record any + // metric, but performance log records are still created. + @Inject private MetricMaker metricMaker; + + private TestPerformanceLogger testPerformanceLogger; + private RegistrationHandle performanceLoggerRegistrationHandle; + + @Before + public void setup() { + Injector injector = Guice.createInjector(new InMemoryModule()); + injector.injectMembers(this); + + testPerformanceLogger = new TestPerformanceLogger(); + performanceLoggerRegistrationHandle = performanceLoggers.add("gerrit", testPerformanceLogger); + } + + @After + public void cleanup() { + performanceLoggerRegistrationHandle.remove(); + + LoggingContext.getInstance().clearPerformanceLogEntries(); + LoggingContext.getInstance().performanceLogging(false); + } + + @Test + public void traceTimersInsidePerformanceLogContextCreatePerformanceLog() { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + + try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); + + TraceContext.newTimer("test1").close(); + TraceContext.newTimer("test2", "foo", "bar").close(); + TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close(); + TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close(); + TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4") + .close(); + + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(5); + } + + assertThat(testPerformanceLogger.logEntries()) + .containsExactly( + PerformanceLogEntry.create("test1", ImmutableMap.of()), + PerformanceLogEntry.create("test2", ImmutableMap.of("foo", Optional.of("bar"))), + PerformanceLogEntry.create( + "test3", ImmutableMap.of("foo1", Optional.of("bar1"), "foo2", Optional.of("bar2"))), + PerformanceLogEntry.create( + "test4", + ImmutableMap.of( + "foo1", + Optional.of("bar1"), + "foo2", + Optional.of("bar2"), + "foo3", + Optional.of("bar3"))), + PerformanceLogEntry.create( + "test5", + ImmutableMap.of( + "foo1", + Optional.of("bar1"), + "foo2", + Optional.of("bar2"), + "foo3", + Optional.of("bar3"), + "foo4", + Optional.of("bar4")))) + .inOrder(); + + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + } + + @Test + public void traceTimersInsidePerformanceLogContextCreatePerformanceLogNullValuesAllowed() { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + + try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); + + TraceContext.newTimer("test1").close(); + TraceContext.newTimer("test2", "foo", null).close(); + TraceContext.newTimer("test3", "foo1", null, "foo2", null).close(); + TraceContext.newTimer("test4", "foo1", null, "foo2", null, "foo3", null).close(); + TraceContext.newTimer("test5", "foo1", null, "foo2", null, "foo3", null, "foo4", null) + .close(); + + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(5); + } + + assertThat(testPerformanceLogger.logEntries()) + .containsExactly( + PerformanceLogEntry.create("test1", ImmutableMap.of()), + PerformanceLogEntry.create("test2", ImmutableMap.of("foo", Optional.empty())), + PerformanceLogEntry.create( + "test3", ImmutableMap.of("foo1", Optional.empty(), "foo2", Optional.empty())), + PerformanceLogEntry.create( + "test4", + ImmutableMap.of( + "foo1", Optional.empty(), "foo2", Optional.empty(), "foo3", Optional.empty())), + PerformanceLogEntry.create( + "test5", + ImmutableMap.of( + "foo1", + Optional.empty(), + "foo2", + Optional.empty(), + "foo3", + Optional.empty(), + "foo4", + Optional.empty()))) + .inOrder(); + + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + } + + @Test + public void traceTimersOutsidePerformanceLogContextDoNotCreatePerformanceLog() { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + + TraceContext.newTimer("test1").close(); + TraceContext.newTimer("test2", "foo", "bar").close(); + TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close(); + TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close(); + TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4") + .close(); + + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + assertThat(testPerformanceLogger.logEntries()).isEmpty(); + } + + @Test + public void + traceTimersInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers() { + // Remove test performance logger so that there are no registered performance loggers. + performanceLoggerRegistrationHandle.remove(); + + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + + try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + + TraceContext.newTimer("test1").close(); + TraceContext.newTimer("test2", "foo", "bar").close(); + TraceContext.newTimer("test3", "foo1", "bar1", "foo2", "bar2").close(); + TraceContext.newTimer("test4", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3").close(); + TraceContext.newTimer("test5", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4") + .close(); + + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + } + + assertThat(testPerformanceLogger.logEntries()).isEmpty(); + + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + } + + @Test + public void timerMetricsInsidePerformanceLogContextCreatePerformanceLog() { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + + try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); + + Timer0 timer0 = + metricMaker.newTimer("test1/latency", new Description("Latency metric for testing")); + timer0.start().close(); + + Timer1 timer1 = + metricMaker.newTimer( + "test2/latency", + new Description("Latency metric for testing"), + Field.ofString("foo")); + timer1.start("value1").close(); + + Timer2 timer2 = + metricMaker.newTimer( + "test3/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar")); + timer2.start("value1", "value2").close(); + + Timer3 timer3 = + metricMaker.newTimer( + "test4/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar"), + Field.ofString("baz")); + timer3.start("value1", "value2", "value3").close(); + + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(4); + } + + assertThat(testPerformanceLogger.logEntries()) + .containsExactly( + PerformanceLogEntry.create("test1/latency", ImmutableMap.of()), + PerformanceLogEntry.create( + "test2/latency", ImmutableMap.of("field1", Optional.of("value1"))), + PerformanceLogEntry.create( + "test3/latency", + ImmutableMap.of("field1", Optional.of("value1"), "field2", Optional.of("value2"))), + PerformanceLogEntry.create( + "test4/latency", + ImmutableMap.of( + "field1", + Optional.of("value1"), + "field2", + Optional.of("value2"), + "field3", + Optional.of("value3")))) + .inOrder(); + + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + } + + @Test + public void timerMetricsInsidePerformanceLogContextCreatePerformanceLogNullValuesAllowed() { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + + try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); + + Timer1 timer1 = + metricMaker.newTimer( + "test1/latency", + new Description("Latency metric for testing"), + Field.ofString("foo")); + timer1.start(null).close(); + + Timer2 timer2 = + metricMaker.newTimer( + "test2/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar")); + timer2.start(null, null).close(); + + Timer3 timer3 = + metricMaker.newTimer( + "test3/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar"), + Field.ofString("baz")); + timer3.start(null, null, null).close(); + + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(3); + } + + assertThat(testPerformanceLogger.logEntries()) + .containsExactly( + PerformanceLogEntry.create( + "test1/latency", ImmutableMap.of("field1", Optional.empty())), + PerformanceLogEntry.create( + "test2/latency", + ImmutableMap.of("field1", Optional.empty(), "field2", Optional.empty())), + PerformanceLogEntry.create( + "test3/latency", + ImmutableMap.of( + "field1", + Optional.empty(), + "field2", + Optional.empty(), + "field3", + Optional.empty()))) + .inOrder(); + + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + } + + @Test + public void timerMetricsOutsidePerformanceLogContextDoNotCreatePerformanceLog() { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + + Timer0 timer0 = + metricMaker.newTimer("test1/latency", new Description("Latency metric for testing")); + timer0.start().close(); + + Timer1 timer1 = + metricMaker.newTimer( + "test2/latency", new Description("Latency metric for testing"), Field.ofString("foo")); + timer1.start("value1").close(); + + Timer2 timer2 = + metricMaker.newTimer( + "test3/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar")); + timer2.start("value1", "value2").close(); + + Timer3 timer3 = + metricMaker.newTimer( + "test4/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar"), + Field.ofString("baz")); + timer3.start("value1", "value2", "value3").close(); + + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + assertThat(testPerformanceLogger.logEntries()).isEmpty(); + } + + @Test + public void + timerMetricssInsidePerformanceLogContextDoNotCreatePerformanceLogIfNoPerformanceLoggers() { + // Remove test performance logger so that there are no registered performance loggers. + performanceLoggerRegistrationHandle.remove(); + + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + + try (PerformanceLogContext traceContext = new PerformanceLogContext(performanceLoggers)) { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + + Timer0 timer0 = + metricMaker.newTimer("test1/latency", new Description("Latency metric for testing")); + timer0.start().close(); + + Timer1 timer1 = + metricMaker.newTimer( + "test2/latency", + new Description("Latency metric for testing"), + Field.ofString("foo")); + timer1.start("value1").close(); + + Timer2 timer2 = + metricMaker.newTimer( + "test3/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar")); + timer2.start("value1", "value2").close(); + + Timer3 timer3 = + metricMaker.newTimer( + "test4/latency", + new Description("Latency metric for testing"), + Field.ofString("foo"), + Field.ofString("bar"), + Field.ofString("baz")); + timer3.start("value1", "value2", "value3").close(); + + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + } + + assertThat(testPerformanceLogger.logEntries()).isEmpty(); + + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + } + + @Test + public void nestingPerformanceLogContextsIsPossible() { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + + try (PerformanceLogContext traceContext1 = new PerformanceLogContext(performanceLoggers)) { + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); + + TraceContext.newTimer("test1").close(); + + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1); + + try (PerformanceLogContext traceContext2 = new PerformanceLogContext(performanceLoggers)) { + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); + + TraceContext.newTimer("test2").close(); + TraceContext.newTimer("test3").close(); + + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(2); + } + + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isTrue(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).hasSize(1); + } + assertThat(LoggingContext.getInstance().isPerformanceLogging()).isFalse(); + assertThat(LoggingContext.getInstance().getPerformanceLogRecords()).isEmpty(); + } + + private static class TestPerformanceLogger implements PerformanceLogger { + private List logEntries = new ArrayList<>(); + + @Override + public void log(String operation, long durationMs, Map> metaData) { + logEntries.add(PerformanceLogEntry.create(operation, metaData)); + } + + ImmutableList logEntries() { + return ImmutableList.copyOf(logEntries); + } + } + + @AutoValue + abstract static class PerformanceLogEntry { + static PerformanceLogEntry create(String operation, Map> metaData) { + return new AutoValue_PerformanceLogContextTest_PerformanceLogEntry( + operation, ImmutableMap.copyOf(metaData)); + } + + abstract String operation(); + + abstract ImmutableMap metaData(); + } +} diff --git a/javatests/com/google/gerrit/server/logging/TraceContextTest.java b/javatests/com/google/gerrit/server/logging/TraceContextTest.java index 044d2378e3..fedbe8b7a5 100644 --- a/javatests/com/google/gerrit/server/logging/TraceContextTest.java +++ b/javatests/com/google/gerrit/server/logging/TraceContextTest.java @@ -15,6 +15,7 @@ package com.google.gerrit.server.logging; import static com.google.common.truth.Truth.assertThat; +import static com.google.gerrit.testing.GerritJUnit.assertThrows; import com.google.common.collect.ImmutableMap; import com.google.common.collect.ImmutableSet; @@ -236,6 +237,63 @@ public class TraceContextTest { } } + @Test + public void operationForTraceTimerCannotBeNull() throws Exception { + assertThrows(NullPointerException.class, () -> TraceContext.newTimer(null)); + assertThrows(NullPointerException.class, () -> TraceContext.newTimer(null, "foo", "bar")); + assertThrows( + NullPointerException.class, + () -> TraceContext.newTimer(null, "foo1", "bar1", "foo2", "bar2")); + assertThrows( + NullPointerException.class, + () -> TraceContext.newTimer(null, "foo1", "bar1", "foo2", "bar2", "foo3", "bar3")); + assertThrows( + NullPointerException.class, + () -> + TraceContext.newTimer( + null, "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4")); + } + + @Test + public void keysForTraceTimerCannotBeNull() throws Exception { + assertThrows(NullPointerException.class, () -> TraceContext.newTimer("test", null, "bar")); + assertThrows( + NullPointerException.class, + () -> TraceContext.newTimer("test", null, "bar1", "foo2", "bar2")); + assertThrows( + NullPointerException.class, + () -> TraceContext.newTimer("test", "foo1", "bar1", null, "bar2")); + assertThrows( + NullPointerException.class, + () -> TraceContext.newTimer("test", null, "bar1", "foo2", "bar2", "foo3", "bar3")); + assertThrows( + NullPointerException.class, + () -> TraceContext.newTimer("test", "foo1", "bar1", null, "bar2", "foo3", "bar3")); + assertThrows( + NullPointerException.class, + () -> TraceContext.newTimer("test", "foo1", "bar1", "foo2", "bar2", null, "bar3")); + assertThrows( + NullPointerException.class, + () -> + TraceContext.newTimer( + "test", null, "bar1", "foo2", "bar2", "foo3", "bar3", "foo4", "bar4")); + assertThrows( + NullPointerException.class, + () -> + TraceContext.newTimer( + "test", "foo1", "bar1", null, "bar2", "foo3", "bar3", "foo4", "bar4")); + assertThrows( + NullPointerException.class, + () -> + TraceContext.newTimer( + "test", "foo1", "bar1", "foo2", "bar2", null, "bar3", "foo4", "bar4")); + assertThrows( + NullPointerException.class, + () -> + TraceContext.newTimer( + "test", "foo1", "bar1", "foo2", "bar2", "foo3", "bar3", null, "bar4")); + } + private void assertTags(ImmutableMap> expectedTagMap) { SortedMap> actualTagMap = LoggingContext.getInstance().getTags().asMap(); From 31d08cde9f8091d348de46e4e4d872f718c4ab94 Mon Sep 17 00:00:00 2001 From: Edwin Kempin Date: Wed, 29 May 2019 13:58:22 +0200 Subject: [PATCH 3/5] Unset logging context before returning a thread back to the thread pool After doing work in a thread and before returning it to the thread pool we must clean up its LoggingContext. To do this we currently remember the existing LoggingContext when we get the thread and set it back when we return the thread. Since we expect that the provided thread always has an empty LoggingContext (and it's a bug if it's non-empty), it's simpler and safer to just unset the LoggingContext before we return the thread to the thread pool. Signed-off-by: Edwin Kempin Change-Id: I4cf614068679831c6dfdcc794c7e6beb0e66be47 --- .../logging/LoggingContextAwareCallable.java | 15 +++++---------- .../logging/LoggingContextAwareRunnable.java | 15 +++++---------- 2 files changed, 10 insertions(+), 20 deletions(-) diff --git a/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java b/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java index 3906630d9e..63a1f8863c 100644 --- a/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java +++ b/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java @@ -14,7 +14,6 @@ package com.google.gerrit.server.logging; -import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableSetMultimap; import java.util.concurrent.Callable; @@ -65,11 +64,6 @@ class LoggingContextAwareCallable implements Callable { // propagate logging context LoggingContext loggingCtx = LoggingContext.getInstance(); - ImmutableSetMultimap oldTags = loggingCtx.getTagsAsMap(); - boolean oldForceLogging = loggingCtx.isLoggingForced(); - boolean oldPerformanceLogging = loggingCtx.isPerformanceLogging(); - ImmutableList oldPerformanceLogRecords = - loggingCtx.getPerformanceLogRecords(); loggingCtx.setTags(tags); loggingCtx.forceLogging(forceLogging); loggingCtx.performanceLogging(performanceLogging); @@ -84,10 +78,11 @@ class LoggingContextAwareCallable implements Callable { try { return callable.call(); } finally { - loggingCtx.setTags(oldTags); - loggingCtx.forceLogging(oldForceLogging); - loggingCtx.performanceLogging(oldPerformanceLogging); - loggingCtx.setPerformanceLogRecords(oldPerformanceLogRecords); + // Cleanup logging context. This is important if the thread is pooled and reused. + loggingCtx.clearTags(); + loggingCtx.forceLogging(false); + loggingCtx.performanceLogging(false); + loggingCtx.clearPerformanceLogEntries(); } } } diff --git a/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java b/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java index 712459b2c6..9d9e8c53ad 100644 --- a/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java +++ b/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java @@ -14,7 +14,6 @@ package com.google.gerrit.server.logging; -import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableSetMultimap; /** @@ -88,11 +87,6 @@ public class LoggingContextAwareRunnable implements Runnable { // propagate logging context LoggingContext loggingCtx = LoggingContext.getInstance(); - ImmutableSetMultimap oldTags = loggingCtx.getTagsAsMap(); - boolean oldForceLogging = loggingCtx.isLoggingForced(); - boolean oldPerformanceLogging = loggingCtx.isPerformanceLogging(); - ImmutableList oldPerformanceLogRecords = - loggingCtx.getPerformanceLogRecords(); loggingCtx.setTags(tags); loggingCtx.forceLogging(forceLogging); loggingCtx.performanceLogging(performanceLogging); @@ -107,10 +101,11 @@ public class LoggingContextAwareRunnable implements Runnable { try { runnable.run(); } finally { - loggingCtx.setTags(oldTags); - loggingCtx.forceLogging(oldForceLogging); - loggingCtx.performanceLogging(oldPerformanceLogging); - loggingCtx.setPerformanceLogRecords(oldPerformanceLogRecords); + // Cleanup logging context. This is important if the thread is pooled and reused. + loggingCtx.clearTags(); + loggingCtx.forceLogging(false); + loggingCtx.performanceLogging(false); + loggingCtx.clearPerformanceLogEntries(); } } } From b3369b566a2b21367f15222876aa47ff0b903f58 Mon Sep 17 00:00:00 2001 From: Edwin Kempin Date: Wed, 12 Jun 2019 12:40:28 +0200 Subject: [PATCH 4/5] Log warning when LoggingContext of background thread is not initially empty When we execute work in a background thread we copy the logging context to it and unset it before we return it to the thread pool. If we get a thread from the pool that has a non-empty logging context this is unexpected and we want to know about it. Also add a clear() method to LoggingContext to make unsetting the logging context easier. Signed-off-by: Edwin Kempin Change-Id: Ic40ce525f5f4508fe4eb56d78a704256a98b8e0c --- .../gerrit/server/logging/LoggingContext.java | 25 +++++++++++++++++++ .../logging/LoggingContextAwareCallable.java | 15 +++++++---- .../logging/LoggingContextAwareRunnable.java | 15 +++++++---- .../logging/MutablePerformanceLogRecords.java | 8 ++++++ .../gerrit/server/logging/MutableTags.java | 7 ++++++ 5 files changed, 60 insertions(+), 10 deletions(-) diff --git a/java/com/google/gerrit/server/logging/LoggingContext.java b/java/com/google/gerrit/server/logging/LoggingContext.java index deb111a8b6..7f5cee3a2b 100644 --- a/java/com/google/gerrit/server/logging/LoggingContext.java +++ b/java/com/google/gerrit/server/logging/LoggingContext.java @@ -16,6 +16,7 @@ package com.google.gerrit.server.logging; import static java.util.Objects.requireNonNull; +import com.google.common.base.MoreObjects; import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableSetMultimap; import com.google.common.flogger.backend.Tags; @@ -79,6 +80,20 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log 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 public boolean shouldForceLogging(String loggerName, Level level, boolean isEnabled) { return isLoggingForced(); @@ -241,4 +256,14 @@ public class LoggingContext extends com.google.common.flogger.backend.system.Log } return records; } + + @Override + public String toString() { + return MoreObjects.toStringHelper(this) + .add("tags", tags.get()) + .add("forceLogging", forceLogging.get()) + .add("performanceLogging", performanceLogging.get()) + .add("performanceLogRecords", performanceLogRecords.get()) + .toString(); + } } diff --git a/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java b/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java index 63a1f8863c..d2701d7416 100644 --- a/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java +++ b/java/com/google/gerrit/server/logging/LoggingContextAwareCallable.java @@ -15,6 +15,7 @@ package com.google.gerrit.server.logging; import com.google.common.collect.ImmutableSetMultimap; +import com.google.common.flogger.FluentLogger; import java.util.concurrent.Callable; /** @@ -31,6 +32,8 @@ import java.util.concurrent.Callable; * @see LoggingContextAwareRunnable */ class LoggingContextAwareCallable implements Callable { + private static final FluentLogger logger = FluentLogger.forEnclosingClass(); + private final Callable callable; private final Thread callingThread; private final ImmutableSetMultimap tags; @@ -62,8 +65,13 @@ class LoggingContextAwareCallable implements Callable { return callable.call(); } - // propagate logging context LoggingContext loggingCtx = LoggingContext.getInstance(); + + 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); @@ -79,10 +87,7 @@ class LoggingContextAwareCallable implements Callable { return callable.call(); } finally { // Cleanup logging context. This is important if the thread is pooled and reused. - loggingCtx.clearTags(); - loggingCtx.forceLogging(false); - loggingCtx.performanceLogging(false); - loggingCtx.clearPerformanceLogEntries(); + loggingCtx.clear(); } } } diff --git a/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java b/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java index 9d9e8c53ad..23162b10e4 100644 --- a/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java +++ b/java/com/google/gerrit/server/logging/LoggingContextAwareRunnable.java @@ -15,6 +15,7 @@ package com.google.gerrit.server.logging; import com.google.common.collect.ImmutableSetMultimap; +import com.google.common.flogger.FluentLogger; /** * Wrapper for a {@link Runnable} that copies the {@link LoggingContext} from the current thread to @@ -49,6 +50,8 @@ import com.google.common.collect.ImmutableSetMultimap; * @see LoggingContextAwareCallable */ public class LoggingContextAwareRunnable implements Runnable { + private static final FluentLogger logger = FluentLogger.forEnclosingClass(); + private final Runnable runnable; private final Thread callingThread; private final ImmutableSetMultimap tags; @@ -85,8 +88,13 @@ public class LoggingContextAwareRunnable implements Runnable { return; } - // propagate logging context LoggingContext loggingCtx = LoggingContext.getInstance(); + + 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); @@ -102,10 +110,7 @@ public class LoggingContextAwareRunnable implements Runnable { runnable.run(); } finally { // Cleanup logging context. This is important if the thread is pooled and reused. - loggingCtx.clearTags(); - loggingCtx.forceLogging(false); - loggingCtx.performanceLogging(false); - loggingCtx.clearPerformanceLogEntries(); + loggingCtx.clear(); } } } diff --git a/java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java b/java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java index 02143f0dfb..4ee70d7c19 100644 --- a/java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java +++ b/java/com/google/gerrit/server/logging/MutablePerformanceLogRecords.java @@ -14,6 +14,7 @@ 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; @@ -44,4 +45,11 @@ public class MutablePerformanceLogRecords { public synchronized ImmutableList list() { return ImmutableList.copyOf(performanceLogRecords); } + + @Override + public String toString() { + return MoreObjects.toStringHelper(this) + .add("performanceLogRecords", performanceLogRecords) + .toString(); + } } diff --git a/java/com/google/gerrit/server/logging/MutableTags.java b/java/com/google/gerrit/server/logging/MutableTags.java index f70a8dbf1d..83009a6ae4 100644 --- a/java/com/google/gerrit/server/logging/MutableTags.java +++ b/java/com/google/gerrit/server/logging/MutableTags.java @@ -16,6 +16,7 @@ package com.google.gerrit.server.logging; import static java.util.Objects.requireNonNull; +import com.google.common.base.MoreObjects; import com.google.common.collect.ImmutableSetMultimap; import com.google.common.collect.MultimapBuilder; import com.google.common.collect.SetMultimap; @@ -110,4 +111,10 @@ public class MutableTags { tagMap.forEach(tagsBuilder::addTag); tags = tagsBuilder.build(); } + + @Override + public String toString() { + buildTags(); + return MoreObjects.toStringHelper(this).add("tags", tags).toString(); + } } From 2f6a8ffd27804c437f546c1ec3786666ee0d84d2 Mon Sep 17 00:00:00 2001 From: Edwin Kempin Date: Wed, 29 May 2019 16:20:50 +0200 Subject: [PATCH 5/5] ReceiveCommits: Pull up trace context from processCommandsUnsafe into processCommands This way the sendErrorMessages() step gets included into the trace context. This step has a debug log that logs the errors that will now show up as part of the trace. Signed-off-by: Edwin Kempin Change-Id: I76fa84c6c727c2b46fd4dd36d8e7d76fe87fc90a --- .../server/git/receive/ReceiveCommits.java | 189 +++++++++--------- 1 file changed, 95 insertions(+), 94 deletions(-) diff --git a/java/com/google/gerrit/server/git/receive/ReceiveCommits.java b/java/com/google/gerrit/server/git/receive/ReceiveCommits.java index 7a0b56eaa3..98ed97ac07 100644 --- a/java/com/google/gerrit/server/git/receive/ReceiveCommits.java +++ b/java/com/google/gerrit/server/git/receive/ReceiveCommits.java @@ -512,23 +512,6 @@ class ReceiveCommits { } void processCommands(Collection commands, MultiProgressMonitor progress) { - Task commandProgress = progress.beginSubTask("refs", UNKNOWN); - commands = commands.stream().map(c -> wrapReceiveCommand(c, commandProgress)).collect(toList()); - processCommandsUnsafe(commands, progress); - rejectRemaining(commands, "internal server error"); - - // This sends error messages before the 'done' string of the progress monitor is sent. - // Currently, the test framework relies on this ordering to understand if pushes completed - // successfully. - sendErrorMessages(); - - commandProgress.end(); - progress.end(); - } - - // Process as many commands as possible, but may leave some commands in state NOT_ATTEMPTED. - private void processCommandsUnsafe( - Collection commands, MultiProgressMonitor progress) { parsePushOptions(); try (TraceContext traceContext = TraceContext.newTrace( @@ -539,92 +522,110 @@ class ReceiveCommits { new PerformanceLogContext(performanceLoggers)) { traceContext.addTag(RequestId.Type.RECEIVE_ID, new RequestId(project.getNameKey().get())); - logger.atFinest().log("Calling user: %s", user.getLoggableName()); - // Log the push options here, rather than in parsePushOptions(), so that they are included // into the trace if tracing is enabled. logger.atFine().log("push options: %s", receivePack.getPushOptions()); - if (!projectState.getProject().getState().permitsWrite()) { - for (ReceiveCommand cmd : commands) { - reject(cmd, "prohibited by Gerrit: project state does not permit write"); - } - return; - } + Task commandProgress = progress.beginSubTask("refs", UNKNOWN); + commands = + commands.stream().map(c -> wrapReceiveCommand(c, commandProgress)).collect(toList()); + processCommandsUnsafe(commands, progress); + rejectRemaining(commands, "internal server error"); - logger.atFine().log("Parsing %d commands", commands.size()); + // This sends error messages before the 'done' string of the progress monitor is sent. + // Currently, the test framework relies on this ordering to understand if pushes completed + // successfully. + sendErrorMessages(); - List magicCommands = new ArrayList<>(); - List directPatchSetPushCommands = new ArrayList<>(); - List regularCommands = new ArrayList<>(); - - for (ReceiveCommand cmd : commands) { - if (MagicBranch.isMagicBranch(cmd.getRefName())) { - magicCommands.add(cmd); - } else if (isDirectChangesPush(cmd.getRefName())) { - directPatchSetPushCommands.add(cmd); - } else { - regularCommands.add(cmd); - } - } - - int commandTypes = - (magicCommands.isEmpty() ? 0 : 1) - + (directPatchSetPushCommands.isEmpty() ? 0 : 1) - + (regularCommands.isEmpty() ? 0 : 1); - - if (commandTypes > 1) { - rejectRemaining(commands, "cannot combine normal pushes and magic pushes"); - return; - } - - try { - if (!regularCommands.isEmpty()) { - handleRegularCommands(regularCommands, progress); - return; - } - - for (ReceiveCommand cmd : directPatchSetPushCommands) { - parseDirectChangesPush(cmd); - } - - boolean first = true; - for (ReceiveCommand cmd : magicCommands) { - if (first) { - parseMagicBranch(cmd); - first = false; - } else { - reject(cmd, "duplicate request"); - } - } - } catch (PermissionBackendException | NoSuchProjectException | IOException err) { - logger.atSevere().withCause(err).log("Failed to process refs in %s", project.getName()); - return; - } - - Task newProgress = progress.beginSubTask("new", UNKNOWN); - Task replaceProgress = progress.beginSubTask("updated", UNKNOWN); - - List newChanges = Collections.emptyList(); - if (magicBranch != null && magicBranch.cmd.getResult() == NOT_ATTEMPTED) { - newChanges = selectNewAndReplacedChangesFromMagicBranch(newProgress); - } - - // Commit validation has already happened, so any changes without Change-Id are for the - // deprecated feature. - warnAboutMissingChangeId(newChanges); - preparePatchSetsForReplace(newChanges); - insertChangesAndPatchSets(newChanges, replaceProgress); - newProgress.end(); - replaceProgress.end(); - queueSuccessMessages(newChanges); - - logger.atFine().log( - "Command results: %s", - lazy(() -> commands.stream().map(ReceiveCommits::commandToString).collect(joining(",")))); + commandProgress.end(); + progress.end(); } } + // Process as many commands as possible, but may leave some commands in state NOT_ATTEMPTED. + private void processCommandsUnsafe( + Collection commands, MultiProgressMonitor progress) { + logger.atFinest().log("Calling user: %s", user.getLoggableName()); + + if (!projectState.getProject().getState().permitsWrite()) { + for (ReceiveCommand cmd : commands) { + reject(cmd, "prohibited by Gerrit: project state does not permit write"); + } + return; + } + + logger.atFine().log("Parsing %d commands", commands.size()); + + List magicCommands = new ArrayList<>(); + List directPatchSetPushCommands = new ArrayList<>(); + List regularCommands = new ArrayList<>(); + + for (ReceiveCommand cmd : commands) { + if (MagicBranch.isMagicBranch(cmd.getRefName())) { + magicCommands.add(cmd); + } else if (isDirectChangesPush(cmd.getRefName())) { + directPatchSetPushCommands.add(cmd); + } else { + regularCommands.add(cmd); + } + } + + int commandTypes = + (magicCommands.isEmpty() ? 0 : 1) + + (directPatchSetPushCommands.isEmpty() ? 0 : 1) + + (regularCommands.isEmpty() ? 0 : 1); + + if (commandTypes > 1) { + rejectRemaining(commands, "cannot combine normal pushes and magic pushes"); + return; + } + + try { + if (!regularCommands.isEmpty()) { + handleRegularCommands(regularCommands, progress); + return; + } + + for (ReceiveCommand cmd : directPatchSetPushCommands) { + parseDirectChangesPush(cmd); + } + + boolean first = true; + for (ReceiveCommand cmd : magicCommands) { + if (first) { + parseMagicBranch(cmd); + first = false; + } else { + reject(cmd, "duplicate request"); + } + } + } catch (PermissionBackendException | NoSuchProjectException | IOException err) { + logger.atSevere().withCause(err).log("Failed to process refs in %s", project.getName()); + return; + } + + Task newProgress = progress.beginSubTask("new", UNKNOWN); + Task replaceProgress = progress.beginSubTask("updated", UNKNOWN); + + List newChanges = Collections.emptyList(); + if (magicBranch != null && magicBranch.cmd.getResult() == NOT_ATTEMPTED) { + newChanges = selectNewAndReplacedChangesFromMagicBranch(newProgress); + } + + // Commit validation has already happened, so any changes without Change-Id are for the + // deprecated feature. + warnAboutMissingChangeId(newChanges); + preparePatchSetsForReplace(newChanges); + insertChangesAndPatchSets(newChanges, replaceProgress); + newProgress.end(); + replaceProgress.end(); + queueSuccessMessages(newChanges); + + logger.atFine().log( + "Command results: %s", + lazy(() -> commands.stream().map(ReceiveCommits::commandToString).collect(joining(",")))); + } + private void sendErrorMessages() { if (!errors.isEmpty()) { logger.atFine().log("Handling error conditions: %s", errors.keySet());