Refactor: Pull tracing into its own class

5 files changed, 258 insertions, 12 deletions

diff --git a/container-search/src/main/java/com/yahoo/search/query/Model.java b/container-search/src/main/java/com/yahoo/search/query/Model.java
index dbaab3045bf..63fc386963a 100644
--- a/container-search/src/main/java/com/yahoo/search/query/Model.java
+++ b/container-search/src/main/java/com/yahoo/search/query/Model.java
@@ -248,7 +248,7 @@ public class Model implements Cloneable {
             try {
                 Parser parser = ParserFactory.newInstance(type, ParserEnvironment.fromExecutionContext(execution.context()));
                 queryTree = parser.parse(Parsable.fromQueryModel(this));
-                if (parent.getTraceLevel() >= 2)
+                if (parent.getTrace().getLevel() >= 2)
                     parent.trace("Query parsed to: " + parent.yqlRepresentation(), 2);
             }
             catch (IllegalArgumentException e) {
diff --git a/container-search/src/main/java/com/yahoo/search/query/Trace.java b/container-search/src/main/java/com/yahoo/search/query/Trace.java
new file mode 100644
index 00000000000..873cda4415e
--- /dev/null
+++ b/container-search/src/main/java/com/yahoo/search/query/Trace.java
@@ -0,0 +1,234 @@
+// Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
+package com.yahoo.search.query;
+
+import com.yahoo.api.annotations.Beta;
+import com.yahoo.prelude.query.textualrepresentation.TextualQueryRepresentation;
+import com.yahoo.processing.request.CompoundName;
+import com.yahoo.search.Query;
+import com.yahoo.search.query.profile.QueryProfileProperties;
+import com.yahoo.search.query.profile.compiled.CompiledQueryProfile;
+import com.yahoo.search.query.profile.types.FieldDescription;
+import com.yahoo.search.query.profile.types.QueryProfileType;
+
+import java.util.HashSet;
+import java.util.Map;
+import java.util.Objects;
+import java.util.Set;
+import java.util.logging.Level;
+import java.util.logging.Logger;
+
+/**
+ * Trace settings and methods for tracing a query.
+ * The actual trace is a tree structure stored in the query execution.
+ *
+ * @author bratseth
+ */
+@Beta
+public class Trace implements Cloneable {
+
+    private static final Logger log = Logger.getLogger(Trace.class.getName());
+
+    /** The type representing the property arguments consumed by this */
+    private static final QueryProfileType argumentType;
+
+    public static final String TRACE = "trace";
+    public static final String LEVEL = "level";
+    public static final String TIMESTAMPS = "timestamps";
+    public static final String QUERY = "query";
+
+    static {
+        argumentType = new QueryProfileType(TRACE);
+        argumentType.setStrict(true);
+        argumentType.setBuiltin(true);
+        argumentType.addField(new FieldDescription(LEVEL, "integer", "tracelevel traceLevel"));
+        argumentType.addField(new FieldDescription(TIMESTAMPS, "boolean"));
+        argumentType.addField(new FieldDescription(QUERY, "boolean"));
+        argumentType.freeze();
+    }
+
+    public static QueryProfileType getArgumentType() { return argumentType; }
+
+    private Query parent;
+
+    private int level = 0;
+    private boolean timestamps = false;
+    private boolean query = true;
+
+    public Trace(Query parent) {
+        this.parent = Objects.requireNonNull(parent);
+    }
+
+    /** Returns the level of detail we'll be tracing at in this query. The default level is 0; no tracing. */
+    public int getLevel() { return level; }
+    public void setLevel(int level) { this.level = level; }
+    public boolean isTraceable(int level) { return level <= this.level; }
+
+    /** Returns whether trace entries should have a timestamp. Default is false. */
+    public boolean getTimestamps() { return timestamps; }
+    public void setTimestamps(boolean timestamps) { this.timestamps = timestamps; }
+
+    /** Returns whether any trace entries should include the query. Default is true. */
+    public boolean getQuery() { return query; }
+    public void setQuery(boolean query) { this.query = query; }
+
+    /**
+     * Adds a context message to this query and to the info log,
+     * if the context level of the query is sufficiently high.
+     * The context information will be carried over to the result at creation.
+     * The message parameter will be included <i>with</i> XML escaping.
+     *
+     * @param message      the message to add
+     * @param traceLevel   the context level of the message, this method will do nothing
+     *                     if the traceLevel of the query is lower than this value
+     */
+    public void trace(String message, int traceLevel) {
+        trace(message, false, traceLevel);
+    }
+
+    public void trace(Object message, int traceLevel) {
+        if ( ! isTraceable(traceLevel)) return;
+        parent.getContext(true).trace(message, 0);
+    }
+
+    /**
+     * Adds a trace message to this query
+     * if the trace level of the query is sufficiently high.
+     *
+     * @param message      the message to add
+     * @param includeQuery true to append the query root stringValue at the end of the message
+     * @param traceLevel   the context level of the message, this method will do nothing
+     *                     if the traceLevel of the query is lower than this value
+     */
+    public void trace(String message, boolean includeQuery, int traceLevel) {
+        if ( ! isTraceable(traceLevel)) return;
+
+        if (includeQuery && parent.properties().getBoolean(CompoundName.fromComponents("trace", "query"), true))
+            message += ": [" + queryTreeText() + "]";
+
+        log.log(Level.FINE, message);
+
+        // Pass 0 as traceLevel as the trace level check is already done above,
+        // and it is not propagated to trace until execution has started
+        // (it is done in the execution.search method)
+        parent.getContext(true).trace(message, 0);
+    }
+
+    /**
+     * Adds a trace message to this query
+     * if the trace level of the query is sufficiently high.
+     *
+     * @param includeQuery true to append the query root stringValue at the end of the message
+     * @param traceLevel   the context level of the message, this method will do nothing
+     *                     if the traceLevel of the query is lower than this value
+     * @param messages     the messages whose toStrings will be concatenated into the trace message.
+     *                     Concatenation will only happen if the trace level is sufficiently high.
+     */
+    public void trace(boolean includeQuery, int traceLevel, Object... messages) {
+        if ( ! isTraceable(traceLevel)) return;
+
+        StringBuilder concatenated = new StringBuilder();
+        for (Object message : messages)
+            concatenated.append(message);
+        trace(concatenated.toString(), includeQuery, traceLevel);
+    }
+
+    /**
+     * Traces how properties was resolved and from where. Done after the fact to avoid special handling
+     * of tracelevel, which is the property deciding whether this needs to be done
+     */
+    public void traceProperties() {
+        if (level == 0) return;
+        CompiledQueryProfile profile = null;
+        QueryProfileProperties profileProperties = parent.properties().getInstance(QueryProfileProperties.class);
+        if (profileProperties != null)
+            profile = profileProperties.getQueryProfile();
+
+        if (profile == null)
+            trace("No query profile is used", false, 1);
+        else
+            trace("Using " + profile.toString(), false, 1);
+
+        if (level < 4) return;
+        StringBuilder b = new StringBuilder("Resolved properties:\n");
+        Set<String> mentioned = new HashSet<>();
+        for (Map.Entry<String,String> requestProperty : requestProperties().entrySet() ) {
+            Object resolvedValue = parent.properties().get(requestProperty.getKey(), requestProperties());
+            if (resolvedValue == null && requestProperty.getKey().equals("queryProfile"))
+                resolvedValue = requestProperty.getValue();
+
+            b.append(requestProperty.getKey());
+            b.append(": ");
+            b.append(resolvedValue); // (may be null)
+            b.append(" (");
+
+            if (profile != null && ! profile.isOverridable(new CompoundName(requestProperty.getKey()), requestProperties()))
+                b.append("from query profile - unoverridable, ignoring request value");
+            else
+                b.append("from request");
+            b.append(")\n");
+            mentioned.add(requestProperty.getKey());
+        }
+        if (profile != null) {
+            appendQueryProfileProperties(profile, mentioned, b);
+        }
+        trace(b.toString(),false,4);
+    }
+
+    private void appendQueryProfileProperties(CompiledQueryProfile profile, Set<String> mentioned, StringBuilder b) {
+        for (var property : profile.listValuesWithSources(CompoundName.empty, requestProperties(), parent.properties()).entrySet()) {
+            if ( ! mentioned.contains(property.getKey()))
+                b.append(property.getKey()).append(": ").append(property.getValue()).append("\n");
+        }
+    }
+
+    private Map<String, String> requestProperties() {
+        return parent.getHttpRequest().propertyMap();
+    }
+
+    private String queryTreeText() {
+        QueryTree root = parent.getModel().getQueryTree();
+
+        if (level < 2)
+            return root.toString();
+        if (level < 6)
+            return parent.yqlRepresentation();
+        else
+            return "\n" + parent.yqlRepresentation() + "\n" + new TextualQueryRepresentation(root.getRoot()) + "\n";
+    }
+
+    public Trace cloneFor(Query parent) {
+        Trace trace = this.clone();
+        trace.parent = parent;
+        return trace;
+    }
+
+    @Override
+    public boolean equals(Object o) {
+        if (o == this ) return true;
+        if ( ! (o instanceof Trace)) return false;
+        Trace other = (Trace)o;
+        if (other.level != this.level) return false;
+        if (other.timestamps != this.timestamps) return false;
+        if (other.query != this.query) return false;
+        return true;
+    }
+
+    @Override
+    public int hashCode() { return Objects.hash(level, timestamps, query); }
+
+    @Override
+    public Trace clone() {
+        try {
+            return (Trace)super.clone();
+        }
+        catch (CloneNotSupportedException e) {
+            throw new RuntimeException(e);
+        }
+    }
+
+    @Override
+    public String toString() {
+        return "trace [level: " + level + ", timestamps: " + timestamps + ", query: " + query + "]";
+    }
+
+}
diff --git a/container-search/src/main/java/com/yahoo/search/query/context/QueryContext.java b/container-search/src/main/java/com/yahoo/search/query/context/QueryContext.java
index 38f76c6ca49..c0ca5ac4731 100644
--- a/container-search/src/main/java/com/yahoo/search/query/context/QueryContext.java
+++ b/container-search/src/main/java/com/yahoo/search/query/context/QueryContext.java
@@ -87,7 +87,7 @@ public class QueryContext implements Cloneable {
     }
 
     public boolean render(Writer writer) throws java.io.IOException {
-        if (owner.getTraceLevel()!=0) {
+        if (owner.getTrace().getLevel()!=0) {
             XMLWriter xmlWriter=XMLWriter.from(writer);
             xmlWriter.openTag("meta").attribute("type",ID);
             TraceNode traceRoot=owner.getModel().getExecution().trace().traceNode().root();
diff --git a/container-search/src/main/java/com/yahoo/search/query/profile/QueryProfile.java b/container-search/src/main/java/com/yahoo/search/query/profile/QueryProfile.java
index 989f12172b3..e3ab49f0e32 100644
--- a/container-search/src/main/java/com/yahoo/search/query/profile/QueryProfile.java
+++ b/container-search/src/main/java/com/yahoo/search/query/profile/QueryProfile.java
@@ -344,7 +344,7 @@ public class QueryProfile extends FreezableSimpleComponent implements Cloneable
      * a primitive value, a substitutable string, a query profile, or null if not found.
      */
     public final Object lookup(String name, Map<String, String> context) {
-        return lookup(new CompoundName(name),true,DimensionBinding.createFrom(getDimensions(),context));
+        return lookup(new CompoundName(name), true, DimensionBinding.createFrom(getDimensions(),context));
     }
 
     /** Sets a value in this or any nested profile using null as context */
@@ -733,7 +733,7 @@ public class QueryProfile extends FreezableSimpleComponent implements Cloneable
 
     // ----------------- Private  ----------------------------------------------------------------------------------
 
-    private Boolean isDeclaredOverridable(CompoundName name,DimensionBinding dimensionBinding) {
+    private Boolean isDeclaredOverridable(CompoundName name, DimensionBinding dimensionBinding) {
         QueryProfile parent = lookupParentExact(name, true, dimensionBinding);
         if (parent.overridable == null) return null;
         return parent.overridable.get(name.last());
@@ -743,15 +743,15 @@ public class QueryProfile extends FreezableSimpleComponent implements Cloneable
      * Sets the overridability of a field in this profile,
      * this overrides the corresponding setting in the type (if any)
      */
-    private void setOverridable(CompoundName fieldName, boolean overridable, DimensionBinding dimensionBinding) {
-        QueryProfile parent = lookupParentExact(fieldName, true, dimensionBinding);
+    private void setOverridable(CompoundName name, boolean overridable, DimensionBinding dimensionBinding) {
+        QueryProfile parent = lookupParentExact(name, true, dimensionBinding);
         if (dimensionBinding.isNull()) {
             if (parent.overridable == null)
                 parent.overridable = new HashMap<>();
-            parent.overridable.put(fieldName.last(), overridable);
+            parent.overridable.put(name.last(), overridable);
         }
         else {
-            variants.setOverridable(fieldName.last(), overridable, dimensionBinding.getValues());
+            variants.setOverridable(name.last(), overridable, dimensionBinding.getValues());
         }
     }
 
diff --git a/container-search/src/main/java/com/yahoo/search/query/properties/QueryProperties.java b/container-search/src/main/java/com/yahoo/search/query/properties/QueryProperties.java
index 4cced8d7923..cc84cba327f 100644
--- a/container-search/src/main/java/com/yahoo/search/query/properties/QueryProperties.java
+++ b/container-search/src/main/java/com/yahoo/search/query/properties/QueryProperties.java
@@ -11,6 +11,7 @@ import com.yahoo.search.query.Presentation;
 import com.yahoo.search.query.Properties;
 import com.yahoo.search.query.Ranking;
 import com.yahoo.search.query.Select;
+import com.yahoo.search.query.Trace;
 import com.yahoo.search.query.profile.compiled.CompiledQueryProfileRegistry;
 import com.yahoo.search.query.profile.types.ConversionContext;
 import com.yahoo.search.query.profile.types.FieldDescription;
@@ -132,10 +133,15 @@ public class QueryProperties extends Properties {
             } else if (key.size() == 3 && key.get(1).equals(Presentation.FORMAT)) {
                 if (key.last().equals(Presentation.TENSORS)) return query.getPresentation().getTensorShortForm();
             }
-        } else if (key.size() == 1) {
+        }
+        else if (key.size() == 2 && key.first().equals(Trace.TRACE)) {
+            if (key.last().equals(Trace.LEVEL)) return query.getTrace().getLevel();
+            if (key.last().equals(Trace.TIMESTAMPS)) return query.getTrace().getTimestamps();
+            if (key.last().equals(Trace.QUERY)) return query.getTrace().getQuery();
+        }
+        else if (key.size() == 1) {
             if (key.equals(Query.HITS)) return query.getHits();
             if (key.equals(Query.OFFSET)) return query.getOffset();
-            if (key.equals(Query.TRACE_LEVEL)) return query.getTraceLevel();
             if (key.equals(Query.EXPLAIN_LEVEL)) return query.getExplainLevel();
             if (key.equals(Query.TIMEOUT)) return query.getTimeout();
             if (key.equals(Query.NO_CACHE)) return query.getNoCache();
@@ -301,6 +307,14 @@ public class QueryProperties extends Properties {
                 else
                     throwIllegalParameter(key.last(), Presentation.PRESENTATION);
             }
+            else if (key.size() == 2 && key.first().equals(Trace.TRACE)) {
+                if (key.last().equals(Trace.LEVEL))
+                    query.getTrace().setLevel(asInteger(value, 0));
+                if (key.last().equals(Trace.TIMESTAMPS))
+                    query.getTrace().setTimestamps(asBoolean(value, false));
+                if (key.last().equals(Trace.QUERY))
+                    query.getTrace().setQuery(asBoolean(value, true));
+            }
             else if (key.first().equals(Select.SELECT)) {
                 if (key.size() == 1) {
                     query.getSelect().setGroupingExpressionString(asString(value, ""));
@@ -322,8 +336,6 @@ public class QueryProperties extends Properties {
                     query.setHits(asInteger(value,10));
                 else if (key.equals(Query.OFFSET))
                     query.setOffset(asInteger(value,0));
-                else if (key.equals(Query.TRACE_LEVEL))
-                    query.setTraceLevel(asInteger(value,0));
                 else if (key.equals(Query.EXPLAIN_LEVEL))
                     query.setExplainLevel(asInteger(value,0));
                 else if (key.equals(Query.TIMEOUT))