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

4 files changed, 264 insertions, 63 deletions

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<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 @@ public class Formatter extends ExtFormatter {
       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 @@ 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<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 @@ 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;
+  }
 }