Generate JSON by hand.
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
diff --git a/core/pom.xml b/core/pom.xml
index 595cf38..5a97f43 100644
--- a/core/pom.xml
+++ b/core/pom.xml
@@ -33,10 +33,17 @@
<optional>true</optional>
</dependency>
<dependency>
+ <groupId>jakarta.json</groupId>
+ <artifactId>jakarta.json-api</artifactId>
+ <version>2.1.3</version>
+ </dependency>
+ <dependency>
<groupId>io.smallrye.common</groupId>
<artifactId>smallrye-common-constraint</artifactId>
<version>2.4.0</version>
</dependency>
+
+ <!-- Include Parsson for backwards-compatibility. -->
<dependency>
<groupId>org.eclipse.parsson</groupId>
<artifactId>parsson</artifactId>
@@ -57,16 +64,16 @@
</dependency>
<dependency>
- <groupId>org.openjdk.jmh</groupId>
- <artifactId>jmh-core</artifactId>
- <version>1.35</version>
- <scope>test</scope>
+ <groupId>org.openjdk.jmh</groupId>
+ <artifactId>jmh-core</artifactId>
+ <version>1.35</version>
+ <scope>test</scope>
</dependency>
<dependency>
- <groupId>org.openjdk.jmh</groupId>
- <artifactId>jmh-generator-annprocess</artifactId>
- <version>1.35</version>
- <scope>test</scope>
+ <groupId>org.openjdk.jmh</groupId>
+ <artifactId>jmh-generator-annprocess</artifactId>
+ <version>1.35</version>
+ <scope>test</scope>
</dependency>
</dependencies>
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 @@
private final List<StructuredParameterProvider> parameterProviders;
private final List<LabelProvider> labelProviders;
- private final JsonProvider json;
+ private final ThreadLocal<StringBuilder> stringBuilder;
/**
* Constructs a {@link Formatter} with custom configuration.
@@ -59,7 +58,7 @@
Collection<LabelProvider> 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 @@
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 @@
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 @@
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("},");
+ }
+
+ 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(",");
+ });
}
if (type != null) {
- b.add("@type", type);
+ b.append("\"@type\":");
+ appendEscapedString(b, type);
+ b.append(",");
}
- b.add("message", message).add("severity", severity).add("timestamp", timestamp.json(json));
-
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<String, String> 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<StructuredParameter> 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 @@
private ExtLogRecord simpleLogRecord;
private ExtLogRecord structuredLogRecord;
private ExtLogRecord massivelyStructuredLogRecord;
+ private ExtLogRecord nestedLogRecord;
private Formatter formatter;
@Setup
@@ -21,6 +22,7 @@
simpleLogRecord = FormatterTest.makeSimpleRecord();
structuredLogRecord = FormatterTest.makeStructuredRecord();
massivelyStructuredLogRecord = FormatterTest.makeMassivelyStructuredRecord();
+ nestedLogRecord = FormatterTest.makeNestedRecord();
formatter = new Formatter(List.of(), List.of());
}
@@ -39,4 +41,10 @@
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 @@
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 @@
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 @@
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 @@
});
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;
+ }
}