Merge "Fix performance bug in logging: Avoid expensive stack trace/reflection"
diff --git a/java/com/google/gerrit/index/query/QueryProcessor.java b/java/com/google/gerrit/index/query/QueryProcessor.java
index 61d609b..9501e52 100644
--- a/java/com/google/gerrit/index/query/QueryProcessor.java
+++ b/java/com/google/gerrit/index/query/QueryProcessor.java
@@ -218,7 +218,7 @@
logger.atFine().log(
"Executing %d %s index queries for %s",
- cnt, schemaDef.getName(), callerFinder.findCaller());
+ cnt, schemaDef.getName(), callerFinder.findCallerLazy());
List<QueryResult<T>> out;
try {
// Parse and rewrite all queries.
diff --git a/java/com/google/gerrit/server/account/externalids/ExternalIdNotes.java b/java/com/google/gerrit/server/account/externalids/ExternalIdNotes.java
index 2c72f56..d75aa17 100644
--- a/java/com/google/gerrit/server/account/externalids/ExternalIdNotes.java
+++ b/java/com/google/gerrit/server/account/externalids/ExternalIdNotes.java
@@ -675,7 +675,8 @@
@Override
protected void onLoad() throws IOException, ConfigInvalidException {
if (revision != null) {
- logger.atFine().log("Reading external ID note map (caller: %s)", callerFinder.findCaller());
+ logger.atFine().log(
+ "Reading external ID note map (caller: %s)", callerFinder.findCallerLazy());
noteMap = NoteMap.read(reader, revision);
} else {
noteMap = NoteMap.newEmptyMap();
diff --git a/java/com/google/gerrit/server/logging/CallerFinder.java b/java/com/google/gerrit/server/logging/CallerFinder.java
index 73ffeb5..bd7e608 100644
--- a/java/com/google/gerrit/server/logging/CallerFinder.java
+++ b/java/com/google/gerrit/server/logging/CallerFinder.java
@@ -142,7 +142,7 @@
/**
* The minimum number of calls known to have occurred between the first call to the target class
- * and the call of {@link #findCaller()}. If in doubt, specify zero here to avoid accidentally
+ * and the call of {@link #findCallerLazy()}. If in doubt, specify zero here to avoid accidentally
* skipping past the caller.
*
* @return the number of stack elements to skip when computing the caller
@@ -195,7 +195,7 @@
public abstract CallerFinder build();
}
- public LazyArg<String> findCaller() {
+ public LazyArg<String> findCallerLazy() {
return lazy(
() ->
targets().stream()
diff --git a/java/com/google/gerrit/server/logging/Metadata.java b/java/com/google/gerrit/server/logging/Metadata.java
index dae78c0..c3df289 100644
--- a/java/com/google/gerrit/server/logging/Metadata.java
+++ b/java/com/google/gerrit/server/logging/Metadata.java
@@ -18,11 +18,14 @@
import com.google.common.base.MoreObjects;
import com.google.common.base.MoreObjects.ToStringHelper;
import com.google.common.collect.ImmutableList;
+import com.google.common.flogger.LazyArg;
+import com.google.common.flogger.LazyArgs;
import com.google.gerrit.common.Nullable;
import java.lang.reflect.InvocationTargetException;
import java.lang.reflect.Method;
import java.lang.reflect.Modifier;
import java.util.Arrays;
+import java.util.Comparator;
import java.util.Optional;
/** Metadata that is provided to {@link PerformanceLogger}s as context for performance records. */
@@ -141,7 +144,8 @@
public abstract Optional<String> username();
/**
- * Returns a string representation of this instance that is suitable for logging.
+ * Returns a string representation of this instance that is suitable for logging. This is wrapped
+ * in a {@link LazyArg<String>} because it is expensive to evaluate.
*
* <p>{@link #toString()} formats the {@link Optional} fields as {@code key=Optional[value]} or
* {@code key=Optional.empty}. Since this class has many optional fields from which usually only a
@@ -178,59 +182,64 @@
*
* @return string representation of this instance that is suitable for logging
*/
- public String toStringForLogging() {
- // Append class name.
- String className = getClass().getSimpleName();
- if (className.startsWith("AutoValue_")) {
- className = className.substring(10);
- }
- ToStringHelper stringHelper = MoreObjects.toStringHelper(className);
+ LazyArg<String> toStringForLoggingLazy() {
+ return LazyArgs.lazy(
+ () -> {
+ // Append class name.
+ String className = getClass().getSimpleName();
+ if (className.startsWith("AutoValue_")) {
+ className = className.substring(10);
+ }
+ ToStringHelper stringHelper = MoreObjects.toStringHelper(className);
- // Append key-value pairs for field which are set.
- Method[] methods = Metadata.class.getDeclaredMethods();
- Arrays.<Method>sort(methods, (m1, m2) -> m1.getName().compareTo(m2.getName()));
- for (Method method : methods) {
- if (Modifier.isStatic(method.getModifiers())) {
- // skip static method
- continue;
- }
+ // Append key-value pairs for field which are set.
+ Method[] methods = Metadata.class.getDeclaredMethods();
+ Arrays.sort(methods, Comparator.comparing(Method::getName));
+ for (Method method : methods) {
+ if (Modifier.isStatic(method.getModifiers())) {
+ // skip static method
+ continue;
+ }
- if (method.getName().equals(Thread.currentThread().getStackTrace()[1].getMethodName())) {
- // skip this method (toStringForLogging() method)
- continue;
- }
+ if (method.getName().matches("(lambda\\$)?toStringForLoggingLazy(\\$0)?")) {
+ // skip toStringForLoggingLazy() and the lambda itself
+ continue;
+ }
- if (method.getReturnType().equals(Void.TYPE) || method.getParameterCount() > 0) {
- // skip method since it's not a getter
- continue;
- }
+ if (method.getReturnType().equals(Void.TYPE) || method.getParameterCount() > 0) {
+ // skip method since it's not a getter
+ continue;
+ }
- method.setAccessible(true);
+ method.setAccessible(true);
- Object returnValue;
- try {
- returnValue = method.invoke(this);
- } catch (IllegalArgumentException | IllegalAccessException | InvocationTargetException e) {
- // should never happen
- throw new IllegalStateException(e);
- }
+ Object returnValue;
+ try {
+ returnValue = method.invoke(this);
+ } catch (IllegalArgumentException
+ | IllegalAccessException
+ | InvocationTargetException e) {
+ // should never happen
+ throw new IllegalStateException(e);
+ }
- if (returnValue instanceof Optional) {
- Optional<?> fieldValueOptional = (Optional<?>) returnValue;
- if (!fieldValueOptional.isPresent()) {
- // drop this key-value pair
- continue;
- }
+ if (returnValue instanceof Optional) {
+ Optional<?> fieldValueOptional = (Optional<?>) returnValue;
+ if (!fieldValueOptional.isPresent()) {
+ // drop this key-value pair
+ continue;
+ }
- // format as 'key=value' instead of 'key=Optional[value]'
- stringHelper.add(method.getName(), fieldValueOptional.get());
- } else {
- // not an Optional value, keep as is
- stringHelper.add(method.getName(), returnValue);
- }
- }
+ // format as 'key=value' instead of 'key=Optional[value]'
+ stringHelper.add(method.getName(), fieldValueOptional.get());
+ } else {
+ // not an Optional value, keep as is
+ stringHelper.add(method.getName(), returnValue);
+ }
+ }
- return stringHelper.toString();
+ return stringHelper.toString();
+ });
}
public static Metadata.Builder builder() {
diff --git a/java/com/google/gerrit/server/logging/TraceContext.java b/java/com/google/gerrit/server/logging/TraceContext.java
index 30c5250..21a4ce6 100644
--- a/java/com/google/gerrit/server/logging/TraceContext.java
+++ b/java/com/google/gerrit/server/logging/TraceContext.java
@@ -196,13 +196,13 @@
this(
() ->
logger.atFine().log(
- "Starting timer for %s (%s)", operation, metadata.toStringForLogging()),
+ "Starting timer for %s (%s)", operation, metadata.toStringForLoggingLazy()),
elapsedMs -> {
LoggingContext.getInstance()
.addPerformanceLogRecord(
() -> PerformanceLogRecord.create(operation, elapsedMs, metadata));
logger.atFine().log(
- "%s (%s) done (%d ms)", operation, metadata.toStringForLogging(), elapsedMs);
+ "%s (%s) done (%d ms)", operation, metadata.toStringForLoggingLazy(), elapsedMs);
});
}
diff --git a/java/com/google/gerrit/server/permissions/RefControl.java b/java/com/google/gerrit/server/permissions/RefControl.java
index 9a2ecdd..694bb82 100644
--- a/java/com/google/gerrit/server/permissions/RefControl.java
+++ b/java/com/google/gerrit/server/permissions/RefControl.java
@@ -395,7 +395,7 @@
withForce,
projectControl.getProject().getName(),
refName,
- callerFinder.findCaller());
+ callerFinder.findCallerLazy());
return false;
}
@@ -408,7 +408,7 @@
withForce,
projectControl.getProject().getName(),
refName,
- callerFinder.findCaller());
+ callerFinder.findCallerLazy());
return true;
}
}
@@ -420,7 +420,7 @@
withForce,
projectControl.getProject().getName(),
refName,
- callerFinder.findCaller());
+ callerFinder.findCallerLazy());
return false;
}
diff --git a/javatests/com/google/gerrit/server/logging/MetadataTest.java b/javatests/com/google/gerrit/server/logging/MetadataTest.java
index 89e5690..f9ae2c1 100644
--- a/javatests/com/google/gerrit/server/logging/MetadataTest.java
+++ b/javatests/com/google/gerrit/server/logging/MetadataTest.java
@@ -23,7 +23,7 @@
@Test
public void stringForLoggingOmitsEmptyOptionalValuesAndReformatsOptionalValuesThatArePresent() {
Metadata metadata = Metadata.builder().accountId(1000001).branchName("refs/heads/foo").build();
- assertThat(metadata.toStringForLogging())
+ assertThat(metadata.toStringForLoggingLazy().evaluate())
.isEqualTo("Metadata{accountId=1000001, branchName=refs/heads/foo, pluginMetadata=[]}");
}
@@ -31,6 +31,7 @@
public void
stringForLoggingOmitsEmptyOptionalValuesAndReformatsOptionalValuesThatArePresentNoFieldsSet() {
Metadata metadata = Metadata.builder().build();
- assertThat(metadata.toStringForLogging()).isEqualTo("Metadata{pluginMetadata=[]}");
+ assertThat(metadata.toStringForLoggingLazy().evaluate())
+ .isEqualTo("Metadata{pluginMetadata=[]}");
}
}
