From 54e813615d88956eee6c76730935282066f58f05 Mon Sep 17 00:00:00 2001 From: Matthias Andreas Benkard Date: Wed, 3 Jul 2024 06:13:26 +0200 Subject: Generate JSON by hand. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This improves performance further. Before: Benchmark Mode Cnt Score Error Units FormatterBenchmark.massivelyStructuredLogRecord thrpt 10 137879.001 ± 30467.644 ops/s FormatterBenchmark.simpleLogRecord thrpt 10 896085.217 ± 249890.421 ops/s FormatterBenchmark.structuredLogRecord thrpt 10 553428.807 ± 194787.754 ops/s After: Benchmark Mode Cnt Score Error Units FormatterBenchmark.massivelyStructuredLogRecord thrpt 10 220855.729 ± 56336.321 ops/s FormatterBenchmark.simpleLogRecord thrpt 10 4456647.085 ± 1041546.047 ops/s FormatterBenchmark.structuredLogRecord thrpt 10 1500896.509 ± 543358.587 ops/s There is also a new benchmark: FormatterBenchmark.nestedLogRecord thrpt 10 878620.441 ± 297024.983 ops/s Change-Id: If3e323b133f8e3e3ff29431a92d1b1e500f9b8b2 --- core/pom.xml | 23 ++- .../quarkus/googlecloud/jsonlogging/Formatter.java | 12 +- .../quarkus/googlecloud/jsonlogging/LogEntry.java | 218 +++++++++++++++++---- .../jsonlogging/FormatterBenchmark.java | 8 + .../googlecloud/jsonlogging/FormatterTest.java | 89 +++++++-- 5 files changed, 279 insertions(+), 71 deletions(-) diff --git a/core/pom.xml b/core/pom.xml index 595cf38..5a97f43 100644 --- a/core/pom.xml +++ b/core/pom.xml @@ -32,11 +32,18 @@ SPDX-License-Identifier: LGPL-3.0-or-later 3.0.6.Final true + + jakarta.json + jakarta.json-api + 2.1.3 + io.smallrye.common smallrye-common-constraint 2.4.0 + + org.eclipse.parsson parsson @@ -57,16 +64,16 @@ SPDX-License-Identifier: LGPL-3.0-or-later - org.openjdk.jmh - jmh-core - 1.35 - test + org.openjdk.jmh + jmh-core + 1.35 + test - org.openjdk.jmh - jmh-generator-annprocess - 1.35 - test + org.openjdk.jmh + jmh-generator-annprocess + 1.35 + test diff --git a/core/src/main/java/eu/mulk/quarkus/googlecloud/jsonlogging/Formatter.java b/core/src/main/java/eu/mulk/quarkus/googlecloud/jsonlogging/Formatter.java index a7fd551..4aa8f9f 100644 --- a/core/src/main/java/eu/mulk/quarkus/googlecloud/jsonlogging/Formatter.java +++ b/core/src/main/java/eu/mulk/quarkus/googlecloud/jsonlogging/Formatter.java @@ -4,7 +4,6 @@ package eu.mulk.quarkus.googlecloud.jsonlogging; -import jakarta.json.spi.JsonProvider; import java.io.PrintWriter; import java.io.StringWriter; import java.util.ArrayList; @@ -43,7 +42,7 @@ public class Formatter extends ExtFormatter { private final List parameterProviders; private final List labelProviders; - private final JsonProvider json; + private final ThreadLocal stringBuilder; /** * Constructs a {@link Formatter} with custom configuration. @@ -59,7 +58,7 @@ public class Formatter extends ExtFormatter { Collection labelProviders) { this.parameterProviders = List.copyOf(parameterProviders); this.labelProviders = List.copyOf(labelProviders); - this.json = JsonProvider.provider(); + this.stringBuilder = ThreadLocal.withInitial(StringBuilder::new); } /** @@ -154,7 +153,12 @@ public class Formatter extends ExtFormatter { ndc, logRecord.getLevel().intValue() >= 1000 ? ERROR_EVENT_TYPE : null); - return entry.json(json).build().toString() + "\n"; + var b = stringBuilder.get(); + b.delete(0, b.length()); + b.append("{"); + entry.json(b); + b.append("}\n"); + return b.toString(); } private static LogEntry.SourceLocation sourceLocationOf(ExtLogRecord logRecord) { diff --git a/core/src/main/java/eu/mulk/quarkus/googlecloud/jsonlogging/LogEntry.java b/core/src/main/java/eu/mulk/quarkus/googlecloud/jsonlogging/LogEntry.java index 8bcea2b..19e6a3f 100644 --- a/core/src/main/java/eu/mulk/quarkus/googlecloud/jsonlogging/LogEntry.java +++ b/core/src/main/java/eu/mulk/quarkus/googlecloud/jsonlogging/LogEntry.java @@ -5,9 +5,8 @@ package eu.mulk.quarkus.googlecloud.jsonlogging; import io.smallrye.common.constraint.Nullable; -import jakarta.json.JsonObject; -import jakarta.json.JsonObjectBuilder; -import jakarta.json.spi.JsonProvider; +import jakarta.json.JsonString; +import jakarta.json.JsonValue; import java.time.Instant; import java.util.List; import java.util.Map; @@ -74,22 +73,31 @@ final class LogEntry { this.function = function; } - JsonObject json(JsonProvider json) { - var b = json.createObjectBuilder(); + void json(StringBuilder b) { + var commaNeeded = false; if (file != null) { - b.add("file", file); + b.append("\"file\":"); + appendEscapedString(b, file); + commaNeeded = true; } if (line != null) { - b.add("line", line); + if (commaNeeded) { + b.append(","); + } + b.append("\"line\":"); + appendEscapedString(b, line); + commaNeeded = true; } if (function != null) { - b.add("function", function); + if (commaNeeded) { + b.append(","); + } + b.append("\"function\":"); + appendEscapedString(b, function); } - - return b.build(); } } @@ -107,58 +115,192 @@ final class LogEntry { this(t.getEpochSecond(), t.getNano()); } - JsonObject json(JsonProvider json) { - return json.createObjectBuilder().add("seconds", seconds).add("nanos", nanos).build(); + void json(StringBuilder b) { + b.append("\"seconds\":"); + b.append(seconds); + b.append(",\"nanos\":"); + b.append(nanos); } } - JsonObjectBuilder json(JsonProvider json) { - var b = json.createObjectBuilder(); - + void json(StringBuilder b) { if (trace != null) { - b.add("logging.googleapis.com/trace", trace); + b.append("\"logging.googleapis.com/trace\":"); + appendEscapedString(b, trace); + b.append(","); } if (spanId != null) { - b.add("logging.googleapis.com/spanId", spanId); + b.append("\"logging.googleapis.com/spanId\":"); + appendEscapedString(b, spanId); + b.append(","); } if (nestedDiagnosticContext != null && !nestedDiagnosticContext.isEmpty()) { - b.add("nestedDiagnosticContext", nestedDiagnosticContext); + b.append("\"nestedDiagnosticContext\":"); + appendEscapedString(b, nestedDiagnosticContext); + b.append(","); } if (!labels.isEmpty()) { - b.add("logging.googleapis.com/labels", jsonOfStringMap(json, labels)); + b.append("\"logging.googleapis.com/labels\":{"); + + var first = true; + for (var entry : labels.entrySet()) { + if (!first) { + b.append(","); + } else { + first = false; + } + + appendEscapedString(b, entry.getKey()); + b.append(":"); + appendEscapedString(b, entry.getValue()); + } + + b.append("},"); } - if (type != null) { - b.add("@type", type); + for (var entry : mappedDiagnosticContext.entrySet()) { + appendEscapedString(b, entry.getKey()); + b.append(":"); + appendEscapedString(b, entry.getValue()); + b.append(","); + } + + for (var parameter : parameters) { + var jsonObject = parameter.json().build(); + jsonObject.forEach( + (key, value) -> { + appendEscapedString(b, key); + b.append(":"); + appendJsonObject(b, value); + b.append(","); + }); } - b.add("message", message).add("severity", severity).add("timestamp", timestamp.json(json)); + if (type != null) { + b.append("\"@type\":"); + appendEscapedString(b, type); + b.append(","); + } if (sourceLocation != null) { - b.add("logging.googleapis.com/sourceLocation", sourceLocation.json(json)); + b.append("\"logging.googleapis.com/sourceLocation\":{"); + sourceLocation.json(b); + b.append("},"); } - return b.addAll(jsonOfStringMap(json, mappedDiagnosticContext)) - .addAll(jsonOfParameterMap(json, parameters)); + b.append("\"message\":"); + appendEscapedString(b, message); + + b.append(",\"severity\":"); + appendEscapedString(b, severity); + + b.append(",\"timestamp\":{"); + timestamp.json(b); + b.append("}"); } - private JsonObjectBuilder jsonOfStringMap(JsonProvider json, Map stringMap) { - return stringMap.entrySet().stream() - .reduce( - json.createObjectBuilder(), - (acc, x) -> acc.add(x.getKey(), x.getValue()), - JsonObjectBuilder::addAll); + private void appendJsonObject(StringBuilder b, JsonValue value) { + switch (value.getValueType()) { + case ARRAY: + b.append("["); + var array = value.asJsonArray(); + for (var i = 0; i < array.size(); i++) { + if (i > 0) { + b.append(","); + } + appendJsonObject(b, array.get(i)); + } + b.append("]"); + break; + + case OBJECT: + b.append("{"); + var object = value.asJsonObject(); + var first = true; + for (var entry : object.entrySet()) { + if (!first) { + b.append(","); + } else { + first = false; + } + appendEscapedString(b, entry.getKey()); + b.append(":"); + appendJsonObject(b, entry.getValue()); + } + b.append("}"); + break; + + case STRING: + appendEscapedString(b, ((JsonString) value).getString()); + break; + + case NUMBER: + b.append(value); + break; + + case TRUE: + b.append("true"); + break; + + case FALSE: + b.append("false"); + break; + + case NULL: + b.append("null"); + break; + } } - private JsonObjectBuilder jsonOfParameterMap( - JsonProvider json, List parameters) { - return parameters.stream() - .reduce( - json.createObjectBuilder(), - (acc, p) -> acc.addAll(p.json()), - JsonObjectBuilder::addAll); + private static void appendEscapedString(StringBuilder b, String s) { + b.append('"'); + + for (var i = 0; i < s.length(); i++) { + var c = s.charAt(i); + + switch (c) { + case '"': + b.append("\\\""); + break; + + case '\\': + b.append("\\\\"); + break; + + case '\b': + b.append("\\b"); + break; + + case '\f': + b.append("\\f"); + break; + + case '\n': + b.append("\\n"); + break; + + case '\r': + b.append("\\r"); + break; + + case '\t': + b.append("\\t"); + break; + + default: + if (c < 0x20) { + b.append("\\u00"); + b.append(Character.forDigit((c >> 4) & 0xf, 16)); + b.append(Character.forDigit(c & 0xf, 16)); + } else { + b.append(c); + } + } + } + + b.append('"'); } } diff --git a/core/src/test/java/eu/mulk/quarkus/googlecloud/jsonlogging/FormatterBenchmark.java b/core/src/test/java/eu/mulk/quarkus/googlecloud/jsonlogging/FormatterBenchmark.java index 4900a01..78291c1 100644 --- a/core/src/test/java/eu/mulk/quarkus/googlecloud/jsonlogging/FormatterBenchmark.java +++ b/core/src/test/java/eu/mulk/quarkus/googlecloud/jsonlogging/FormatterBenchmark.java @@ -14,6 +14,7 @@ public class FormatterBenchmark { private ExtLogRecord simpleLogRecord; private ExtLogRecord structuredLogRecord; private ExtLogRecord massivelyStructuredLogRecord; + private ExtLogRecord nestedLogRecord; private Formatter formatter; @Setup @@ -21,6 +22,7 @@ public class FormatterBenchmark { simpleLogRecord = FormatterTest.makeSimpleRecord(); structuredLogRecord = FormatterTest.makeStructuredRecord(); massivelyStructuredLogRecord = FormatterTest.makeMassivelyStructuredRecord(); + nestedLogRecord = FormatterTest.makeNestedRecord(); formatter = new Formatter(List.of(), List.of()); } @@ -39,4 +41,10 @@ public class FormatterBenchmark { var f = formatter.format(massivelyStructuredLogRecord); blackhole.consume(f); } + + @Benchmark + public void nestedLogRecord(Blackhole blackhole) { + var f = formatter.format(nestedLogRecord); + blackhole.consume(f); + } } diff --git a/core/src/test/java/eu/mulk/quarkus/googlecloud/jsonlogging/FormatterTest.java b/core/src/test/java/eu/mulk/quarkus/googlecloud/jsonlogging/FormatterTest.java index 6d40b15..16fc537 100644 --- a/core/src/test/java/eu/mulk/quarkus/googlecloud/jsonlogging/FormatterTest.java +++ b/core/src/test/java/eu/mulk/quarkus/googlecloud/jsonlogging/FormatterTest.java @@ -23,14 +23,14 @@ class FormatterTest { assertLinesMatch( List.of( "\\{" - + "\"message\":\"Hello, world!\"," - + "\"severity\":\"INFO\"," - + "\"timestamp\":\\{\"seconds\":\\d+,\"nanos\":\\d+\\}," + "\"logging.googleapis.com/sourceLocation\":" + "\\{\"file\":\"ReflectionUtils.java\"," + "\"line\":\"\\d+\"," + "\"function\":\"org.junit.platform.commons.util.ReflectionUtils.invokeMethod\"" - + "\\}" + + "\\}," + + "\"message\":\"Hello, world!\"," + + "\"severity\":\"INFO\"," + + "\"timestamp\":\\{\"seconds\":\\d+,\"nanos\":\\d+\\}" + "\\}\n"), List.of(formattingResult)); } @@ -68,19 +68,19 @@ class FormatterTest { List.of( "\\{" + "\"logging.googleapis.com/labels\":\\{\"a\":\"b\",\"requestId\":\"123\"\\}," - + "\"message\":\"Hello, world!\"," - + "\"severity\":\"INFO\"," - + "\"timestamp\":\\{\"seconds\":\\d+,\"nanos\":\\d+\\}," + + "\"traceId\":\"39f9a49a9567a8bd7087b708f8932550\"," + + "\"spanId\":\"c7431b14630b633d\"," + + "\"one\":1," + + "\"two\":2.0," + + "\"yes\":true," + "\"logging.googleapis.com/sourceLocation\":" + "\\{\"file\":\"ReflectionUtils.java\"," + "\"line\":\"\\d+\"," + "\"function\":\"org.junit.platform.commons.util.ReflectionUtils.invokeMethod\"" + "\\}," - + "\"traceId\":\"39f9a49a9567a8bd7087b708f8932550\"," - + "\"spanId\":\"c7431b14630b633d\"," - + "\"one\":1," - + "\"two\":2.0," - + "\"yes\":true" + + "\"message\":\"Hello, world!\"," + + "\"severity\":\"INFO\"," + + "\"timestamp\":\\{\"seconds\":\\d+,\"nanos\":\\d+\\}" + "\\}\n"), List.of(formattingResult)); } @@ -105,21 +105,21 @@ class FormatterTest { assertLinesMatch( List.of( "\\{" - + "\"message\":\"Hello, world!\"," - + "\"severity\":\"INFO\"," - + "\"timestamp\":\\{\"seconds\":\\d+,\"nanos\":\\d+\\}," - + "\"logging.googleapis.com/sourceLocation\":" - + "\\{\"file\":\"ReflectionUtils.java\"," - + "\"line\":\"\\d+\"," - + "\"function\":\"org.junit.platform.commons.util.ReflectionUtils.invokeMethod\"" - + "\\}," + "\"int-0\":0,\"int-1\":1,\"int-2\":2,\"int-3\":3,\"int-4\":4,\"int-5\":5,\"int-6\":6,\"int-7\":7,\"int-8\":8,\"int-9\":9," + "\"double-10\":10.0,\"double-11\":11.0,\"double-12\":12.0,\"double-13\":13.0,\"double-14\":14.0," + "\"double-15\":15.0,\"double-16\":16.0,\"double-17\":17.0,\"double-18\":18.0,\"double-19\":19.0," + "\"boolean-20\":true,\"boolean-21\":false,\"boolean-22\":true,\"boolean-23\":false,\"boolean-24\":true," + "\"boolean-25\":false,\"boolean-26\":true,\"boolean-27\":false,\"boolean-28\":true,\"boolean-29\":false," + "\"string-30\":\"30\",\"string-31\":\"31\",\"string-32\":\"32\",\"string-33\":\"33\",\"string-34\":\"34\"," - + "\"string-35\":\"35\",\"string-36\":\"36\",\"string-37\":\"37\",\"string-38\":\"38\",\"string-39\":\"39\"" + + "\"string-35\":\"35\",\"string-36\":\"36\",\"string-37\":\"37\",\"string-38\":\"38\",\"string-39\":\"39\"," + + "\"logging.googleapis.com/sourceLocation\":" + + "\\{\"file\":\"ReflectionUtils.java\"," + + "\"line\":\"\\d+\"," + + "\"function\":\"org.junit.platform.commons.util.ReflectionUtils.invokeMethod\"" + + "\\}," + + "\"message\":\"Hello, world!\"," + + "\"severity\":\"INFO\"," + + "\"timestamp\":\\{\"seconds\":\\d+,\"nanos\":\\d+\\}" + "\\}\n"), List.of(formattingResult)); } @@ -148,4 +148,51 @@ class FormatterTest { }); return logRecord; } + + @Test + void nestedRecord() { + var logRecord = makeNestedRecord(); + + var formatter = new Formatter(List.of(), List.of()); + var formattingResult = formatter.format(logRecord); + assertLinesMatch( + List.of( + "\\{" + + "\"anObject\":\\{\"a\":\"b\\\\nc\\\\nd\\\\u0000\\\\u0001\\\\u0002e\"\\}," + + "\"anArray\":\\[1,2,3\\]," + + "\"anArrayOfObjects\":\\[" + + "\\{\"a\":1,\"b\":2\\}," + + "\\{\"b\":2,\"c\":3\\}," + + "\\{\"c\":3,\"d\":4\\}" + + "\\]," + + "\"logging.googleapis.com/sourceLocation\":" + + "\\{\"file\":\"ReflectionUtils.java\"," + + "\"line\":\"\\d+\"," + + "\"function\":\"org.junit.platform.commons.util.ReflectionUtils.invokeMethod\"" + + "\\}," + + "\"message\":\"Hello, world!\"," + + "\"severity\":\"INFO\"," + + "\"timestamp\":\\{\"seconds\":\\d+,\"nanos\":\\d+\\}" + + "\\}\n"), + List.of(formattingResult)); + } + + static ExtLogRecord makeNestedRecord() { + var logRecord = makeSimpleRecord(); + logRecord.setParameters( + new Object[] { + (StructuredParameter) + () -> + JSON.createObjectBuilder() + .add("anObject", JSON.createObjectBuilder().add("a", "b\nc\nd\0\1\2e")) + .add("anArray", JSON.createArrayBuilder().add(1).add(2).add(3)) + .add( + "anArrayOfObjects", + JSON.createArrayBuilder() + .add(JSON.createObjectBuilder().add("a", 1).add("b", 2)) + .add(JSON.createObjectBuilder().add("b", 2).add("c", 3)) + .add(JSON.createObjectBuilder().add("c", 3).add("d", 4))) + }); + return logRecord; + } } -- cgit v1.2.3