diff options
6 files changed, 123 insertions, 38 deletions
diff --git a/container-search/src/main/java/com/yahoo/prelude/fastsearch/VespaBackEndSearcher.java b/container-search/src/main/java/com/yahoo/prelude/fastsearch/VespaBackEndSearcher.java index 5154a61634c..55df050e915 100644 --- a/container-search/src/main/java/com/yahoo/prelude/fastsearch/VespaBackEndSearcher.java +++ b/container-search/src/main/java/com/yahoo/prelude/fastsearch/VespaBackEndSearcher.java @@ -2,6 +2,7 @@ package com.yahoo.prelude.fastsearch; import com.yahoo.collections.TinyIdentitySet; +import com.yahoo.data.access.slime.SlimeAdapter; import com.yahoo.fs4.DocsumPacket; import com.yahoo.fs4.DocumentInfo; import com.yahoo.fs4.FS4Properties; @@ -421,8 +422,8 @@ public abstract class VespaBackEndSearcher extends PingableSearcher { if ( ! properties.getName().startsWith("trace")) continue; for (FS4Properties.Entry entry : properties.getEntries()) { if (!entry.key.equals("slime")) continue; - Slime trace = BinaryFormat.decode(entry.getValue()); - query.trace("Backend trace :" + entry.key + " => " + Utf8.toString(JsonFormat.toJsonBytes(trace)), query.getTraceLevel()); + SlimeAdapter adapter = new SlimeAdapter(BinaryFormat.decode(entry.getValue()).get()); + query.trace(adapter, query.getTraceLevel()); } } } diff --git a/container-search/src/main/java/com/yahoo/search/Query.java b/container-search/src/main/java/com/yahoo/search/Query.java index 85cccd87015..e3fb9b1a544 100644 --- a/container-search/src/main/java/com/yahoo/search/Query.java +++ b/container-search/src/main/java/com/yahoo/search/Query.java @@ -678,6 +678,11 @@ public class Query extends com.yahoo.processing.Request implements Cloneable { trace(message, false, traceLevel); } + public void trace(Object message, int traceLevel) { + if ( ! isTraceable(traceLevel)) return; + getContext(true).trace(message, 0); + } + /** * Adds a trace message to this query * if the trace level of the query is sufficiently high. 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 6b28b166150..1ba30275dc1 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 @@ -31,9 +31,12 @@ public class QueryContext implements Cloneable { /** Adds a context message to this context */ public void trace(String message, int traceLevel) { - owner.getModel().getExecution().trace().trace(message,traceLevel); + trace((Object)message, traceLevel); } + public void trace(Object message, int traceLevel) { + owner.getModel().getExecution().trace().trace(message,traceLevel); + } /** * Adds a key-value which will be logged to the access log for this query (by doing toString() on the value * Multiple values may be set to the same key. A value cannot be removed once set. diff --git a/container-search/src/main/java/com/yahoo/search/rendering/JsonRenderer.java b/container-search/src/main/java/com/yahoo/search/rendering/JsonRenderer.java index c6e64a32c48..1754b6cc028 100644 --- a/container-search/src/main/java/com/yahoo/search/rendering/JsonRenderer.java +++ b/container-search/src/main/java/com/yahoo/search/rendering/JsonRenderer.java @@ -18,7 +18,6 @@ import com.yahoo.document.datatypes.StringFieldValue; import com.yahoo.document.datatypes.TensorFieldValue; import com.yahoo.document.json.JsonWriter; import com.yahoo.lang.MutableBoolean; -import com.yahoo.prelude.hitfield.HitField; import com.yahoo.processing.Response; import com.yahoo.processing.execution.Execution.Trace; import com.yahoo.processing.rendering.AsynchronousSectionedRenderer; @@ -185,7 +184,8 @@ public class JsonRenderer extends AsynchronousSectionedRenderer<Result> { header(); generator.writeStartObject(); } - generator.writeStringField(TRACE_MESSAGE, payload.toString()); + generator.writeFieldName(TRACE_MESSAGE); + fieldConsumer.renderFieldContentsDirect(payload); dirty = true; } if (dirty) { @@ -763,17 +763,32 @@ public class JsonRenderer extends AsynchronousSectionedRenderer<Result> { } private void renderInspector(Inspector data) throws IOException { - StringBuilder intermediate = new StringBuilder(); Inspector asMap = wrapAsMap(data); if (asMap != null) { + StringBuilder intermediate = new StringBuilder(); JsonRender.render(asMap, intermediate, true); + generator.writeRawValue(intermediate.toString()); } else { - JsonRender.render(data, intermediate, true); + renderInspectorDirect(data); } + + } + + private void renderInspectorDirect(Inspector data) throws IOException { + StringBuilder intermediate = new StringBuilder(); + JsonRender.render(data, intermediate, true); generator.writeRawValue(intermediate.toString()); } private void renderFieldContents(Object field) throws IOException { + if (field instanceof Inspectable) { + renderInspector(((Inspectable)field).inspect()); + } else { + renderFieldContentsDirect(field); + } + } + + private void renderFieldContentsDirect(Object field) throws IOException { if (field == null) { generator.writeNull(); } else if (field instanceof Boolean) { @@ -785,7 +800,7 @@ public class JsonRenderer extends AsynchronousSectionedRenderer<Result> { } else if (field instanceof Tensor) { renderTensor(Optional.of((Tensor)field)); } else if (field instanceof Inspectable) { - renderInspector(((Inspectable)field).inspect()); + renderInspectorDirect(((Inspectable)field).inspect()); } else if (field instanceof JsonProducer) { generator.writeRawValue(((JsonProducer) field).toJson()); } else if (field instanceof StringFieldValue) { diff --git a/container-search/src/test/java/com/yahoo/search/rendering/JsonRendererTestCase.java b/container-search/src/test/java/com/yahoo/search/rendering/JsonRendererTestCase.java index f3167cceaaf..2627f6fa85d 100644 --- a/container-search/src/test/java/com/yahoo/search/rendering/JsonRendererTestCase.java +++ b/container-search/src/test/java/com/yahoo/search/rendering/JsonRendererTestCase.java @@ -229,7 +229,8 @@ public class JsonRendererTestCase { } @Test - public void testEmptyTracing() throws IOException, InterruptedException, ExecutionException { + public void testTracingOfSlime() throws IOException, InterruptedException, ExecutionException { + // which clearly shows a trace child is created once too often... String expected = "{\n" + " \"root\": {\n" + " \"fields\": {\n" @@ -237,8 +238,64 @@ public class JsonRendererTestCase { + " },\n" + " \"id\": \"toplevel\",\n" + " \"relevance\": 1.0\n" - + " }\n" - + "}\n"; + + " },\n" + + " \"trace\": {\n" + + " \"children\": [\n" + + " {\n" + + " \"message\": \"No query profile is used\"\n" + + " },\n" + + " {\n" + + " \"children\": [\n" + + " {\n" + + " \"message\": \"something\"\n" + + " },\n" + + " {\n" + + " \"message\": \"something else\"" + + " },\n" + + " {\n" + + " \"children\": [\n" + + " {\n" + + " \"message\": { \"colour\": \"yellow\"}" + + " }\n" + + " ]\n" + + " },\n" + + " {\n" + + " \"message\": \"marker\"" + + " }\n" + + " ]\n" + + " }\n" + + " ]" + + " }" + + "}"; + Query q = new Query("/?query=a&tracelevel=1"); + Execution execution = new Execution(Execution.Context.createContextStub()); + Result r = new Result(q); + + execution.search(q); + q.trace("something", 1); + q.trace("something else", 1); + Execution e2 = new Execution(new Chain<Searcher>(), execution.context()); + Query subQuery = new Query("/?query=b&tracelevel=1"); + e2.search(subQuery); + Slime slime = new Slime(); + slime.setObject().setString("colour","yellow"); + subQuery.trace(new SlimeAdapter(slime.get()), 1); + q.trace("marker", 1); + String summary = render(execution, r); + assertEqualJson(expected, summary); + } + + @Test + public void testEmptyTracing() throws IOException, InterruptedException, ExecutionException { + String expected = "{" + + " \"root\": {" + + " \"fields\": {" + + " \"totalCount\": 0" + + " }," + + " \"id\": \"toplevel\"," + + " \"relevance\": 1.0" + + " }" + + "}"; Query q = new Query("/?query=a&tracelevel=0"); Execution execution = new Execution(Execution.Context.createContextStub()); Result r = new Result(q); @@ -259,31 +316,31 @@ public class JsonRendererTestCase { @SuppressWarnings("unchecked") @Test public void testTracingWithEmptySubtree() throws IOException, InterruptedException, ExecutionException { - String expected = "{\n" - + " \"root\": {\n" - + " \"fields\": {\n" - + " \"totalCount\": 0\n" - + " },\n" - + " \"id\": \"toplevel\",\n" - + " \"relevance\": 1.0\n" - + " },\n" - + " \"trace\": {\n" - + " \"children\": [\n" - + " {\n" - + " \"message\": \"No query profile is used\"\n" - + " },\n" - + " {\n" - + " \"message\": \"Resolved properties:\\ntracelevel=10 (value from request)\\nquery=a (value from request)\\n\"\n" - + " },\n" - + " {\n" - + " \"children\": [\n" - + " {\n" - + " \"timestamp\": 42\n" - + " }\n" - + " ]\n" - + " }\n" - + " ]\n" - + " }\n" + String expected = "{" + + " \"root\": {" + + " \"fields\": {" + + " \"totalCount\": 0" + + " }," + + " \"id\": \"toplevel\"," + + " \"relevance\": 1.0" + + " }," + + " \"trace\": {" + + " \"children\": [" + + " {" + + " \"message\": \"No query profile is used\"" + + " }," + + " {" + + " \"message\": \"Resolved properties:\\ntracelevel=10 (value from request)\\nquery=a (value from request)\\n\"" + + " }," + + " {" + + " \"children\": [" + + " {" + + " \"timestamp\": 42" + + " }" + + " ]" + + " }" + + " ]" + + " }" + "}"; Query q = new Query("/?query=a&tracelevel=10"); Execution execution = new Execution(Execution.Context.createContextStub()); @@ -1218,12 +1275,13 @@ public class JsonRendererTestCase { @SuppressWarnings("unchecked") private void assertEqualJson(String expected, String generated) throws IOException { + assertEquals("", validateJSON(expected)); + assertEquals("", validateJSON(generated)); + ObjectMapper m = new ObjectMapper(); Map<String, Object> exp = m.readValue(expected, Map.class); Map<String, Object> gen = m.readValue(generated, Map.class); assertEquals(exp, gen); - assertEquals("", validateJSON(expected)); - assertEquals("", validateJSON(generated)); } private String validateJSON(String presumablyValidJson) { diff --git a/processing/src/main/java/com/yahoo/processing/execution/Execution.java b/processing/src/main/java/com/yahoo/processing/execution/Execution.java index 957e39bf41f..9aff586ef75 100644 --- a/processing/src/main/java/com/yahoo/processing/execution/Execution.java +++ b/processing/src/main/java/com/yahoo/processing/execution/Execution.java @@ -310,6 +310,9 @@ public class Execution { * Adds a trace message to this trace, if this trace has at most the given trace level */ public void trace(String message, int traceLevel) { + trace((Object)message, traceLevel); + } + public void trace(Object message, int traceLevel) { if (this.traceLevel >= traceLevel) { traceNode.add(new TraceNode(message, timestamp(traceLevel, forceTimestamps))); } |