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 <ekempin@google.com>
Change-Id: I6417d8ddc4755cc7bfb60f3e57f050c262c28f17

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<String> labels)
       throws IOException, InvalidLabelsException {
     try (TraceTimer traceTimer =
-            TraceContext.newTimer("Update star labels in %s (labels=%s)", refName, labels);
+            TraceContext.newTimer("Update star labels", "ref", refName, "labels", labels);
         RevWalk rw = new RevWalk(repo)) {
       RefUpdate u = repo.updateRef(refName);
       u.setExpectedOldObjectId(oldObjectId);
@@ -487,7 +487,7 @@ public class StarredChangesUtil {
       return;
     }
 
-    try (TraceTimer traceTimer = TraceContext.newTimer("Delete star labels in %s", refName)) {
+    try (TraceTimer traceTimer = TraceContext.newTimer("Delete star labels", "ref", refName)) {
       RefUpdate u = repo.updateRef(refName);
       u.setForceUpdate(true);
       u.setExpectedOldObjectId(oldObjectId);

java/com/google/gerrit/server/account/AccountCacheImpl.java

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

java/com/google/gerrit/server/account/GroupCacheImpl.java

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

java/com/google/gerrit/server/account/GroupIncludeCacheImpl.java

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

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 =
+      try (TraceTimer timer = TraceContext.newTimer("Loading external IDs", "revision", notesRev)) {
-          TraceContext.newTimer("Loading external IDs (revision=%s)", notesRev)) {
         ImmutableSet<ExternalId> externalIds = externalIdReader.all(notesRev);
         externalIds.forEach(ExternalId::checkThatBlobIdIsSet);
         return AllExternalIds.create(externalIds);

java/com/google/gerrit/server/auth/ldap/LdapRealm.java

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

java/com/google/gerrit/server/cache/h2/H2CacheImpl.java

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

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

java/com/google/gerrit/server/git/SearchingChangeCacheImpl.java

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

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'",
+                "Read file",
-                fileName, getRefName(), projectName, revision.name());
+                "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);

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<Timestamp> updatedOn = groupUpdate.getUpdatedOn();
       if (!updatedOn.isPresent()) {
         updatedOn = Optional.of(TimeUtil.nowTs());

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

java/com/google/gerrit/server/index/change/ChangeIndexer.java

@@ -174,8 +174,11 @@ public class ChangeIndexer {
     for (Index<?, ChangeData> i : getWriteIndexes()) {
       try (TraceTimer traceTimer =
           TraceContext.newTimer(
-              "Replacing change %d in index version %d",
+              "Replacing change in index",
-              cd.getId().get(), i.getSchema().getVersion())) {
+              "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);
         }
       }

java/com/google/gerrit/server/logging/TraceContext.java

@@ -169,12 +169,13 @@ public class TraceContext implements AutoCloseable {
    *
    * <p>If request tracing is not enabled this is a no-op.
    *
-   * @param format the message format string
+   * @param message the message
-   * @param arg argument for the message
+   * @param key meta data key
+   * @param value meta data value
    * @return the trace timer
    */
-  public static TraceTimer newTimer(String format, Object arg) {
+  public static TraceTimer newTimer(String message, String key, Object value) {
-    return new TraceTimer(format, arg);
+    return new TraceTimer(message + " (%s=%s)", key, value);
   }
 
   /**
@@ -182,45 +183,80 @@ public class TraceContext implements AutoCloseable {
    *
    * <p>If request tracing is not enabled this is a no-op.
    *
-   * @param format the message format string
+   * @param message the message
-   * @param arg1 first argument for the message
+   * @param key1 first meta data key
-   * @param arg2 second argument for the message
+   * @param value1 first meta data value
-   * @return the trace timer
+   * @param key2 second meta data key
-   */
+   * @param value2 second meta data value
-  public static TraceTimer newTimer(String format, Object arg1, Object arg2) {
-    return new TraceTimer(format, arg1, arg2);
-  }
-
-  /**
-   * Opens a new timer that logs the time for an operation if request tracing is enabled.
-   *
-   * <p>If request tracing is not enabled this is a no-op.
-   *
-   * @param format the message format string
-   * @param arg1 first argument for the message
-   * @param arg2 second argument for the message
-   * @param arg3 third argument for the message
-   * @return the trace timer
-   */
-  public static TraceTimer newTimer(String format, Object arg1, Object arg2, Object arg3) {
-    return new TraceTimer(format, arg1, arg2, arg3);
-  }
-
-  /**
-   * Opens a new timer that logs the time for an operation if request tracing is enabled.
-   *
-   * <p>If request tracing is not enabled this is a no-op.
-   *
-   * @param format the message format string
-   * @param arg1 first argument for the message
-   * @param arg2 second argument for the message
-   * @param arg3 third argument for the message
-   * @param arg4 fourth argument for the message
    * @return the trace timer
    */
   public static TraceTimer newTimer(
-      String format, Object arg1, Object arg2, Object arg3, Object arg4) {
+      String message, String key1, Object value1, String key2, Object value2) {
-    return new TraceTimer(format, arg1, arg2, arg3, arg4);
+    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.
+   *
+   * <p>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.
+   *
+   * <p>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<Long> logFn) {
       this.logFn = logFn;
       this.stopwatch = Stopwatch.createStarted();

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)) {

java/com/google/gerrit/sshd/SshKeyCacheImpl.java

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