Improving the rendering performance

[vy]

We think we're going to be able to open-source our message class fairly soon, at which point it might be interesting to explore alternate layout/message interfaces that reduce serialization overhead. Maybe something along the lines of a visitor pattern, where the Layout passes a visitor to the Message and the Message does the tree-walk? Some people refer to that as a SAX-style API, and Jackson's "Streaming API" (JsonGenerator, https://fasterxml.github.io/jackson-core/javadoc/2.9/com/fasterxml/jackson/core/JsonGenerator.html) works that way.

Have you worked at all with log4j2 upstream? It seems like this system would benefit from some hard-core perfomance work, which generally involves some API refactoring. If we could get a team together, it would be satisfying to build a "fish tagging" system for Java distributed architectures, comparable to what I've helped build previously in a Javascript/Python/C++ world. (That system resembled log4j2's ContextDataInjector scheme, with the local context transferred as metadata on RESTful API requests and auto-captured by task closures for delegation across thread boundaries.) Netty-based services really need such a thing.

Originally posted by @mkedwards in #15 (comment)

[mkedwards]

For discussion's sake, this is the bit of code that could be reworked to use a JsonGenerator instead of an ObjectWriter:

 86     private String render(LogEvent event, ObjectNode srcRootNode) {
 87 
 88         // Resolve node and bail-out if empty.
 89         JsonNode dstRootNode = resolveNode(event, srcRootNode);
 90         if (dstRootNode.isNull()) {
 91             return "{}";
 92         }
 93 
 94         // Serialize resolved node.
 95         try {
 96             ByteArrayOutputStream outputStream = new ByteArrayOutputStream();
 97             try (OutputStreamWriter writer = new OutputStreamWriter(outputStream, JSON_CHARSET)) {
 98                 objectWriter.writeValue(writer, dstRootNode);
 99                 writer.write(System.lineSeparator());
100             }
101             return outputStream.toString(JSON_CHARSET_NAME);
102         } catch (IOException error) {
103             throw new RuntimeException("failed serializing JSON", error);
104         }
105 
106     }

It would be ideal not to have to create the dstRootNode intermediate object at all. As a halfway step to that, I think it would be useful to subclass the MultiformatMessage interface (or add an interface mixin or something) to add a streamMessageTo(JsonGenerator out) method. Pass it an instance buffer of TokenBuffer, and then use objectMapper.readTree(buffer.asParser()) to get a JsonNode that can be inserted into dstRootNode.

[mkedwards]

Note that streaming events into a JsonGenerator implementation is also a good way to serialize to XML. See FasterXML/jackson-dataformat-xml#216 for details of the setup (which the Message doesn't need to care about; it's the Layout's job to prepare the outer envelope).

[vy]

@mkedwards, really appreciated the detailed feedback and hard work (incl. #18)! Please, keep them coming! (Apologies for my slow pace. Could not take much time off from my day job due to upcoming season in e-commerce business.)

In addition to things you mentioned, in its current state, resolveNode() is working more like an interpreter rather than a compiler. That is, at each invocation it repeats many if/else branching on the templateRootNode tree, whereas they could have checked once and compiled the appropriate Function<LogEvent, JsonNode> function to avoid the repeating branching.

But before diving into nitty gritty details of all this optimization tricks, I first want to build a harness to enable us to quantify the performance impact of changes. For this purpose, I will add a JMH benchmark for measuring the rendering performance. Give me 1-2 days to push it to the master.

[vy]

TODOs:

• Accept ObjectMapper as a parameter in LogstashLayout.Builder.
• Use Jackson Afterburner module.

[vy]

Adding Afterburner is not improving anything -- makes sense, we are not doing any POJO serialization. Long live benchmarks!

[mkedwards]

I love what you're doing, and there's no need to apologize for the pace. We're going through the open-sourcing motions here, should have something out that uses the Streamable API shortly.

[mkedwards]

Public now: https://github.com/nexiahome/formatted_data_message/tree/logstash-streamable

[vy]

I think fish tagging and using JsonGenerator are two separate concerns, let me address them individually.

Fish Tagging

Trying to push a streamable LogEvent API to the upstream (that is, Log4j 2.X master) is quite some challenge. Further, due to the consumer agnostic nature of streaming, our root visitor will need to pass over each emitted item (exception, log level, message, etc.), even though it might not necessarily be interested in particular items.

In the commit 591ed46 that I pushed to master, I traverse the template JSON object once and compile a function that accesses only to the fields of interest. AFAIC, this approach delivers the same efficiency goal the fish tagging aims and avoids unnecessary visits to fields that are not of interest.

Using JsonGenerator

I spent quite some time to get JsonGenerator working, though failed each time due to the following short-coming: there is no clean way to exclude empty/null fields in JsonGenerator, AFAIK. You can see my work in json-generator branch (221e68c). Layout works, but fails to clean-up null fields.

Consider the following case: Given {"exception": {"stacktrace": "${json:exceptionStackTrace}"}} template, how would you know if you need to start exception object without knowing if stacktrace is available in the LogEvent, it will not be excluded due to an exclusion pattern, etc.? In json-generator branch, see the output of the failing test.

One important remark: Replacing ObjectMapper with JsonGenerator raised the bar from 29k log/sec to 37k log/sec on a single thread!

Conclusion

At this stage, plugin delivers 29k log/sec. (Note that these are full blown LogEvents, that is, they contain MDC, NDC, and all the exception whistles and bells. In reality, the majority of the log messages are way more lightweight.) I can employ ThreadLocal<ByteArrayOutputStream> in TemplateRenderer, use TransactionalByteArrayOutputStream for the JsonGenerator short-coming aforementioned, etc. But I have my doubts about the functionality we will get in return compared to the complexity we will be introducing to a simple, maintainable code base. What do you think? What is the use case that would necessitate a throughput more than 29k log/sec?

[mkedwards]

Distributed trace/profiling infrastructure, à la Google Dapper https://ai.google/research/pubs/pub36356 . A colleague and I built something similar a few years ago for a JavaScript/Python/C++ ETL/datastore/query architecture, with always-on tracing down to tasks with a granularity less than a millisecond, at an overhead of (depending on how it was measured) 1/2 to 2 percent. We then fed the trace data into an instance of our own product and used it to drive performance work. I find myself needing to do something similar again, this time in a JS/Ruby/Java world. The last time around we paid a lot of attention to minimizing allocation churn in the logging and thread-context maintenance pathways, and that paid off in minimal overhead. Don't see why it'd be any different this time. 😎

I'll take a look at the null-handling issues you've encountered, and see if I can propose something constructive. We've got one strategy for that built into the lazy-evaluation/memoization wrapper we whipped up, which isn't yet hardened for production but sort of illustrates the idea. We have some work to do around conditional logging too. And we're using this in a Netty-based event-driven system, so context agility is very important. (Probably needs a custom ContextDataInjector.)

[mkedwards]

The other thing that we found to be very important in the previous project was readability/familiarity of the syntactic sugar at the log site. In C++ that was handled with macro/template magic to interpolate tagged values into a template string, with automagical fallbacks for untagged parameters, all wrapped up in a syntax identical to the Google-logging library we were already using. We'll want to do something similar in Java-space, probably involving horrible generic/reflection machinery. I'm not that clever at Java 8+ yet, but I fear that's going to have to change.