Log caller when submit rules are evaluated and tracing is enabled
Evaluating submit rules can be expensive, e.g. the code owners submit
rules must do some significant amount of work as it needs to check for
each file in a change who are the code owners and whether they approved
the change. Invoking the evaluation of submit rules too often can lead
to quite some extra latency (e.g. at Google we know of cases where
plugins unintentionally trigger a lot of submit rule evaluations making
requests very slow). At the moment from traces we can see how often
submit rules are evaluated and how long the evaluation of the submit
rules takes, however the trace is not telling us which code triggered
the submit rule evaluation. Knowing this is important so that we can
judge whether running the submit rule evaluation is expected (e.g.
because the change is being reindex) or unexpected (e.g. a plugin uses
the changes API to retrieve change details but doesn't need any of the
fields that are populated by running the submit rules). To make the
caller available we are logging it now on fine level, which means that
it's being logged if tracing is enabled. To find the caller we use
CallerFinder which inspects the current stacktrace to find the first
interesting class in it. Please refer to the class javadoc of
CallerFinder for details on how this works. In general using
CallerFinder is fragile and can easily break, which is why it should
only be used if there is a great benefit from logging the caller, which
I think is the case here. I tested the used CallerFinder targets with
calls from Gerrit core and plugins to verify that they are producing
the right callers that tell us who triggered the call.
Signed-off-by: Edwin Kempin <ekempin@google.com>
Change-Id: Iebd3a23676b5564c3d5ccffd30130051542305ea
diff --git a/java/com/google/gerrit/server/project/SubmitRuleEvaluator.java b/java/com/google/gerrit/server/project/SubmitRuleEvaluator.java
index cb8b686..eaf409b 100644
--- a/java/com/google/gerrit/server/project/SubmitRuleEvaluator.java
+++ b/java/com/google/gerrit/server/project/SubmitRuleEvaluator.java
@@ -18,15 +18,19 @@
import static com.google.gerrit.server.project.ProjectCache.noSuchProject;
import com.google.common.collect.Streams;
+import com.google.common.flogger.FluentLogger;
import com.google.gerrit.entities.Change;
import com.google.gerrit.entities.SubmitRecord;
import com.google.gerrit.entities.SubmitTypeRecord;
import com.google.gerrit.exceptions.StorageException;
+import com.google.gerrit.extensions.api.changes.ChangeApi;
import com.google.gerrit.metrics.Description;
import com.google.gerrit.metrics.Description.Units;
import com.google.gerrit.metrics.MetricMaker;
import com.google.gerrit.metrics.Timer0;
+import com.google.gerrit.server.change.ChangeJson;
import com.google.gerrit.server.index.OnlineReindexMode;
+import com.google.gerrit.server.logging.CallerFinder;
import com.google.gerrit.server.plugincontext.PluginSetContext;
import com.google.gerrit.server.query.change.ChangeData;
import com.google.gerrit.server.rules.DefaultSubmitRule;
@@ -42,12 +46,15 @@
* the results through rules found in the parent projects, all the way up to All-Projects.
*/
public class SubmitRuleEvaluator {
+ private static final FluentLogger logger = FluentLogger.forEnclosingClass();
+
private final ProjectCache projectCache;
private final PrologRule prologRule;
private final PluginSetContext<SubmitRule> submitRules;
private final Timer0 submitRuleEvaluationLatency;
private final Timer0 submitTypeEvaluationLatency;
private final SubmitRuleOptions opts;
+ private final CallerFinder callerFinder;
public interface Factory {
/** Returns a new {@link SubmitRuleEvaluator} with the specified options */
@@ -78,6 +85,14 @@
.setUnit(Units.MILLISECONDS));
this.opts = options;
+
+ this.callerFinder =
+ CallerFinder.builder()
+ .addTarget(ChangeApi.class)
+ .addTarget(ChangeJson.class)
+ .addTarget(ChangeData.class)
+ .addTarget(SubmitRequirementsEvaluatorImpl.class)
+ .build();
}
/**
@@ -88,6 +103,9 @@
* @param cd ChangeData to evaluate
*/
public List<SubmitRecord> evaluate(ChangeData cd) {
+ logger.atFine().log(
+ "Evaluate submit rules for change %d (caller: %s)",
+ cd.change().getId().get(), callerFinder.findCallerLazy());
try (Timer0.Context ignored = submitRuleEvaluationLatency.start()) {
Change change;
ProjectState projectState;
