Log time that is spent on loading cache entries

Change-Id: I13c53228da3b2f5d2869406fe9568fc655d6d9b4
Signed-off-by: Edwin Kempin <ekempin@google.com>

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

@@ -27,6 +27,8 @@ import com.google.gerrit.server.account.externalids.ExternalId;
 import com.google.gerrit.server.account.externalids.ExternalIds;
 import com.google.gerrit.server.cache.CacheModule;
 import com.google.gerrit.server.config.AllUsersName;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.gerrit.server.util.time.TimeUtil;
 import com.google.inject.Inject;
 import com.google.inject.Module;
@@ -181,8 +183,9 @@ public class AccountCacheImpl implements AccountCache {
 
     @Override
     public Optional<AccountState> load(Account.Id who) throws Exception {
-      logger.atFine().log("Loading account %s", who);
+      try (TraceTimer timer = TraceContext.newTimer("Loading account %s", who)) {
-      return accounts.get(who);
+        return accounts.get(who);
+      }
     }
   }
 }

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

@@ -21,6 +21,8 @@ import com.google.gerrit.reviewdb.client.AccountGroup;
 import com.google.gerrit.server.cache.CacheModule;
 import com.google.gerrit.server.group.InternalGroup;
 import com.google.gerrit.server.group.db.Groups;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.gerrit.server.query.group.InternalGroupQuery;
 import com.google.inject.Inject;
 import com.google.inject.Module;
@@ -147,8 +149,9 @@ public class GroupCacheImpl implements GroupCache {
 
     @Override
     public Optional<InternalGroup> load(AccountGroup.Id key) throws Exception {
-      logger.atFine().log("Loading group %s by ID", key);
+      try (TraceTimer timer = TraceContext.newTimer("Loading group %s by ID", key)) {
-      return groupQueryProvider.get().byId(key);
+        return groupQueryProvider.get().byId(key);
+      }
     }
   }
 
@@ -162,8 +165,9 @@ public class GroupCacheImpl implements GroupCache {
 
     @Override
     public Optional<InternalGroup> load(String name) throws Exception {
-      logger.atFine().log("Loading group '%s' by name", name);
+      try (TraceTimer timer = TraceContext.newTimer("Loading group '%s' by name", name)) {
-      return groupQueryProvider.get().byName(new AccountGroup.NameKey(name));
+        return groupQueryProvider.get().byName(new AccountGroup.NameKey(name));
+      }
     }
   }
 
@@ -177,8 +181,9 @@ public class GroupCacheImpl implements GroupCache {
 
     @Override
     public Optional<InternalGroup> load(String uuid) throws Exception {
-      logger.atFine().log("Loading group %s by UUID", uuid);
+      try (TraceTimer timer = TraceContext.newTimer("Loading group %s by UUID", uuid)) {
-      return groups.getGroup(new AccountGroup.UUID(uuid));
+        return groups.getGroup(new AccountGroup.UUID(uuid));
+      }
     }
   }
 }

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

@@ -27,6 +27,8 @@ import com.google.gerrit.reviewdb.client.AccountGroup;
 import com.google.gerrit.server.cache.CacheModule;
 import com.google.gerrit.server.group.InternalGroup;
 import com.google.gerrit.server.group.db.Groups;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.gerrit.server.query.group.InternalGroupQuery;
 import com.google.gwtorm.server.OrmException;
 import com.google.inject.Inject;
@@ -151,13 +153,14 @@ public class GroupIncludeCacheImpl implements GroupIncludeCache {
 
     @Override
     public ImmutableSet<AccountGroup.UUID> load(Account.Id memberId) throws OrmException {
-      logger.atFine().log("Loading groups with member %s", memberId);
+      try (TraceTimer timer = TraceContext.newTimer("Loading groups with member %s", memberId)) {
-      return groupQueryProvider
+        return groupQueryProvider
-          .get()
+            .get()
-          .byMember(memberId)
+            .byMember(memberId)
-          .stream()
+            .stream()
-          .map(InternalGroup::getGroupUUID)
+            .map(InternalGroup::getGroupUUID)
-          .collect(toImmutableSet());
+            .collect(toImmutableSet());
+      }
     }
   }
 
@@ -172,13 +175,14 @@ public class GroupIncludeCacheImpl implements GroupIncludeCache {
 
     @Override
     public ImmutableList<AccountGroup.UUID> load(AccountGroup.UUID key) throws OrmException {
-      logger.atFine().log("Loading parent groups of %s", key);
+      try (TraceTimer timer = TraceContext.newTimer("Loading parent groups of %s", key)) {
-      return groupQueryProvider
+        return groupQueryProvider
-          .get()
+            .get()
-          .bySubgroup(key)
+            .bySubgroup(key)
-          .stream()
+            .stream()
-          .map(InternalGroup::getGroupUUID)
+            .map(InternalGroup::getGroupUUID)
-          .collect(toImmutableList());
+            .collect(toImmutableList());
+      }
     }
   }
 
@@ -192,8 +196,9 @@ public class GroupIncludeCacheImpl implements GroupIncludeCache {
 
     @Override
     public ImmutableList<AccountGroup.UUID> load(String key) throws Exception {
-      logger.atFine().log("Loading all external groups");
+      try (TraceTimer timer = TraceContext.newTimer("Loading all external groups")) {
-      return groups.getExternalGroups().collect(toImmutableList());
+        return groups.getExternalGroups().collect(toImmutableList());
+      }
     }
   }
 }

java/com/google/gerrit/server/account/externalids/ExternalIdCacheImpl.java

@@ -22,6 +22,8 @@ import com.google.common.collect.MultimapBuilder;
 import com.google.common.collect.SetMultimap;
 import com.google.common.flogger.FluentLogger;
 import com.google.gerrit.reviewdb.client.Account;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.inject.Inject;
 import com.google.inject.Singleton;
 import com.google.inject.name.Named;
@@ -150,10 +152,12 @@ class ExternalIdCacheImpl implements ExternalIdCache {
 
     @Override
     public AllExternalIds load(ObjectId notesRev) throws Exception {
-      logger.atFine().log("Loading external IDs (revision=%s)", notesRev);
+      try (TraceTimer timer =
-      ImmutableSet<ExternalId> externalIds = externalIdReader.all(notesRev);
+          TraceContext.newTimer("Loading external IDs (revision=%s)", notesRev)) {
-      externalIds.forEach(ExternalId::checkThatBlobIdIsSet);
+        ImmutableSet<ExternalId> externalIds = externalIdReader.all(notesRev);
-      return AllExternalIds.create(externalIds);
+        externalIds.forEach(ExternalId::checkThatBlobIdIsSet);
+        return AllExternalIds.create(externalIds);
+      }
     }
   }
 }

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

@@ -37,6 +37,8 @@ import com.google.gerrit.server.auth.AuthenticationUnavailableException;
 import com.google.gerrit.server.auth.NoSuchUserException;
 import com.google.gerrit.server.config.AuthConfig;
 import com.google.gerrit.server.config.GerritServerConfig;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.inject.Inject;
 import com.google.inject.Singleton;
 import com.google.inject.name.Named;
@@ -351,10 +353,11 @@ class LdapRealm extends AbstractRealm {
 
     @Override
     public Optional<Account.Id> load(String username) throws Exception {
-      logger.atFine().log("Loading account for username %s", username);
+      try (TraceTimer timer = TraceContext.newTimer("Loading account for username %s", username)) {
-      return externalIds
+        return externalIds
-          .get(ExternalId.Key.create(SCHEME_GERRIT, username))
+            .get(ExternalId.Key.create(SCHEME_GERRIT, username))
-          .map(ExternalId::accountId);
+            .map(ExternalId::accountId);
+      }
     }
   }
 
@@ -368,12 +371,14 @@ class LdapRealm extends AbstractRealm {
 
     @Override
     public Set<AccountGroup.UUID> load(String username) throws Exception {
-      logger.atFine().log("Loading group for member with username %s", username);
+      try (TraceTimer timer =
-      final DirContext ctx = helper.open();
+          TraceContext.newTimer("Loading group for member with username %s", username)) {
-      try {
+        final DirContext ctx = helper.open();
-        return helper.queryForGroups(ctx, username, null);
+        try {
-      } finally {
+          return helper.queryForGroups(ctx, username, null);
-        helper.close(ctx);
+        } finally {
+          helper.close(ctx);
+        }
       }
     }
   }
@@ -388,18 +393,19 @@ class LdapRealm extends AbstractRealm {
 
     @Override
     public Boolean load(String groupDn) throws Exception {
-      logger.atFine().log("Loading groupDn %s", groupDn);
+      try (TraceTimer timer = TraceContext.newTimer("Loading groupDn %s", groupDn)) {
-      final DirContext ctx = helper.open();
+        final DirContext ctx = helper.open();
-      try {
-        Name compositeGroupName = new CompositeName().add(groupDn);
         try {
-          ctx.getAttributes(compositeGroupName);
+          Name compositeGroupName = new CompositeName().add(groupDn);
-          return true;
+          try {
-        } catch (NamingException e) {
+            ctx.getAttributes(compositeGroupName);
-          return false;
+            return true;
+          } catch (NamingException e) {
+            return false;
+          }
+        } finally {
+          helper.close(ctx);
         }
-      } finally {
-        helper.close(ctx);
       }
     }
   }

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

@@ -26,6 +26,8 @@ import com.google.common.hash.BloomFilter;
 import com.google.gerrit.common.Nullable;
 import com.google.gerrit.server.cache.PersistentCache;
 import com.google.gerrit.server.cache.serialize.CacheSerializer;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.gerrit.server.util.time.TimeUtil;
 import com.google.inject.TypeLiteral;
 import java.io.IOException;
@@ -235,19 +237,19 @@ public class H2CacheImpl<K, V> extends AbstractLoadingCache<K, V> implements Per
 
     @Override
     public ValueHolder<V> load(K key) throws Exception {
-      logger.atFine().log("Loading value for %s from cache", key);
+      try (TraceTimer timer = TraceContext.newTimer("Loading value for %s from cache", key)) {
-
+        if (store.mightContain(key)) {
-      if (store.mightContain(key)) {
+          ValueHolder<V> h = store.getIfPresent(key);
-        ValueHolder<V> h = store.getIfPresent(key);
+          if (h != null) {
-        if (h != null) {
+            return h;
-          return h;
+          }
         }
-      }
 
-      final ValueHolder<V> h = new ValueHolder<>(loader.load(key));
+        final ValueHolder<V> h = new ValueHolder<>(loader.load(key));
-      h.created = TimeUtil.nowMs();
+        h.created = TimeUtil.nowMs();
-      executor.execute(() -> store.put(key, h));
+        executor.execute(() -> store.put(key, h));
-      return h;
+        return h;
+      }
     }
   }
 

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

@@ -28,6 +28,8 @@ import com.google.gerrit.reviewdb.server.ReviewDb;
 import com.google.gerrit.server.ReviewerSet;
 import com.google.gerrit.server.cache.CacheModule;
 import com.google.gerrit.server.index.change.ChangeField;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.gerrit.server.query.change.ChangeData;
 import com.google.gerrit.server.query.change.InternalChangeQuery;
 import com.google.gerrit.server.util.ManualRequestContext;
@@ -144,8 +146,8 @@ public class SearchingChangeCacheImpl implements GitReferenceUpdatedListener {
 
     @Override
     public List<CachedChange> load(Project.NameKey key) throws Exception {
-      logger.atFine().log("Loading changes of project %s", key);
+      try (TraceTimer timer = TraceContext.newTimer("Loading changes of project %s", key);
-      try (ManualRequestContext ctx = requestContext.open()) {
+          ManualRequestContext ctx = requestContext.open()) {
         List<ChangeData> cds =
             queryProvider
                 .get()

java/com/google/gerrit/server/project/ProjectCacheImpl.java

@@ -31,6 +31,8 @@ import com.google.gerrit.server.cache.CacheModule;
 import com.google.gerrit.server.config.AllProjectsName;
 import com.google.gerrit.server.config.AllUsersName;
 import com.google.gerrit.server.git.GitRepositoryManager;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.inject.Inject;
 import com.google.inject.Module;
 import com.google.inject.Provider;
@@ -270,16 +272,17 @@ public class ProjectCacheImpl implements ProjectCache {
 
     @Override
     public ProjectState load(String projectName) throws Exception {
-      logger.atFine().log("Loading project %s", projectName);
+      try (TraceTimer timer = TraceContext.newTimer("Loading project %s", projectName)) {
-      long now = clock.read();
+        long now = clock.read();
-      Project.NameKey key = new Project.NameKey(projectName);
+        Project.NameKey key = new Project.NameKey(projectName);
-      try (Repository git = mgr.openRepository(key)) {
+        try (Repository git = mgr.openRepository(key)) {
-        ProjectConfig cfg = new ProjectConfig(key);
+          ProjectConfig cfg = new ProjectConfig(key);
-        cfg.load(key, git);
+          cfg.load(key, git);
 
-        ProjectState state = projectStateFactory.create(cfg);
+          ProjectState state = projectStateFactory.create(cfg);
-        state.initLastCheck(now);
+          state.initLastCheck(now);
-        return state;
+          return state;
+        }
       }
     }
   }
@@ -300,8 +303,9 @@ public class ProjectCacheImpl implements ProjectCache {
 
     @Override
     public ImmutableSortedSet<Project.NameKey> load(ListKey key) throws Exception {
-      logger.atFine().log("Loading project list");
+      try (TraceTimer timer = TraceContext.newTimer("Loading project list")) {
-      return ImmutableSortedSet.copyOf(mgr.list());
+        return ImmutableSortedSet.copyOf(mgr.list());
+      }
     }
   }
 }

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

@@ -24,6 +24,8 @@ import com.google.gerrit.server.account.VersionedAuthorizedKeys;
 import com.google.gerrit.server.account.externalids.ExternalId;
 import com.google.gerrit.server.account.externalids.ExternalIds;
 import com.google.gerrit.server.cache.CacheModule;
+import com.google.gerrit.server.logging.TraceContext;
+import com.google.gerrit.server.logging.TraceContext.TraceTimer;
 import com.google.gerrit.server.ssh.SshKeyCache;
 import com.google.gerrit.server.ssh.SshKeyCreator;
 import com.google.inject.Inject;
@@ -103,24 +105,26 @@ public class SshKeyCacheImpl implements SshKeyCache {
 
     @Override
     public Iterable<SshKeyCacheEntry> load(String username) throws Exception {
-      logger.atFine().log("Loading SSH keys for account with username %s", username);
+      try (TraceTimer timer =
-
+          TraceContext.newTimer("Loading SSH keys for account with username %s", username)) {
-      Optional<ExternalId> user = externalIds.get(ExternalId.Key.create(SCHEME_USERNAME, username));
+        Optional<ExternalId> user =
-      if (!user.isPresent()) {
+            externalIds.get(ExternalId.Key.create(SCHEME_USERNAME, username));
-        return NO_SUCH_USER;
+        if (!user.isPresent()) {
-      }
+          return NO_SUCH_USER;
-
-      List<SshKeyCacheEntry> kl = new ArrayList<>(4);
-      for (AccountSshKey k : authorizedKeys.getKeys(user.get().accountId())) {
-        if (k.valid()) {
-          add(kl, k);
         }
-      }
 
-      if (kl.isEmpty()) {
+        List<SshKeyCacheEntry> kl = new ArrayList<>(4);
-        return NO_KEYS;
+        for (AccountSshKey k : authorizedKeys.getKeys(user.get().accountId())) {
+          if (k.valid()) {
+            add(kl, k);
+          }
+        }
+
+        if (kl.isEmpty()) {
+          return NO_KEYS;
+        }
+        return Collections.unmodifiableList(kl);
       }
-      return Collections.unmodifiableList(kl);
     }
 
     private void add(List<SshKeyCacheEntry> kl, AccountSshKey k) {