Migrate Recycler API to log4j-api #1194

jvz · 2023-01-09T18:47:36Z

This will allow for reuse of this API in places where ThreadLocal-recycled objects are currently used. This will be beneficial to runtimes where workloads don't correspond to threads such as virtual threads, coroutines, and reactive streams. This adds an optional dependency on JCTools to log4j-api for one of the QueueingRecycler implementations.

Just one of many PRs to break out from #1144.

This adds executions during process-sources and process-test-sources to ensure that modified files are formatted properly.

This will allow for reuse of this API in places where ThreadLocal-recycled objects are currently used. This will be beneficial to runtimes where workloads don't correspond to threads such as virtual threads, coroutines, and reactive streams. This adds an optional dependency on JCTools to log4j-api for one of the QueueingRecycler implementations.

ppkarwasz

I am not sure if o.a.l.l.util is the right package for this: RecyclerFactory is something a provider might like to implement. Maybe o.a.l.l.spi is more appropriate?

I would also remove the implementations from the exported packages, leaving just RecyclerFactory and the RecyclerFactories meta-factory.

Any ideas on how an implementer would add new factories? ServiceLoader?

jvz · 2023-01-09T20:59:17Z

Could be pluggable via dependency injection. That's how I was initially using it, so I suppose that could mean moving the concrete implementations to core. Having access to DI from the API module is related to a new API added in the larger PR that this was separated from.

jvz · 2023-01-10T18:05:31Z

While I was working on LOG4J2-3228, I noticed what you were referring to in the reusable message classes. Yes, I'd like to make the Recycler API available there, though I'll need to consider the SPI here a little more first. I'll continue porting the other changes first.

Signed-off-by: Matt Sicker <[email protected]>

Also updates ThreadLocalRecyclerFactory to support nested calls to acquire() by using an ArrayDeque to track potentially more than one object. Signed-off-by: Matt Sicker <[email protected]>

jvz · 2023-01-14T22:21:40Z

So I've moved it to the SPI package. As it stands now, there's already a mini configuration spec string you can specify for recyclers based on the existing JTL configuration parsing logic documented here and here for how to specifically make it work for JTL. I expect that to be generally sufficient when using the API by itself without the backend. In the backend, we have the Injector API where it's much easier to bind things.

jvz · 2023-01-14T22:34:57Z

Looks like some test failures. Still a work in progress I suppose.

Signed-off-by: Matt Sicker <[email protected]>

- Split cleaner concerns in RecyclerFactory: eager versus lazy cleaning. This makes the Recycler API work naturally with existing StringBuilder post-usage trimming. - Uses a simpler method for checking for the presence of JCTools. Given that it's an optional (static) dependency, we can compile direct references to it in classes and see if our classes throw LinkageError-related exceptions at runtime when attempting to link to JCTools. - Rename QueueSupplier to QueueFactory - Extract a Queues util for easier access to different JCTools queue implementations when available - Update implementations of AbstractStringLayout to use Recycler API - CsvLogEventLayout - CsvParameterLayout - GelfLayout - HtmlLayout - Log4j1SyslogLayout - Log4j1XmlLayout - PatternLayout - Rfc5424Layout - SyslogLayout Signed-off-by: Matt Sicker <[email protected]>

jvz · 2023-01-16T21:20:11Z

Alright, I think I've figured out one key update to RecyclerFactory to make this API natural to use as a replacement for ad hoc ThreadLocal<StringBuilder>-style object reuse. This is to allow for two different types of cleaner functions to be supplied: one for cleaning a recycled instance when acquired, and another for cleaning a recycled instance when it's released. There are plenty of areas in Log4j where it's expected that StringBuilder instances will be trimmed right after being used, so this helps support that given that other areas that already use Recycler expect that the cleaner is lazily applied. Therefore, I've named them "eager" and "lazy" cleaner functions.

I've also gone ahead and abstracted out some Queue-related utilities to more simply construct JCTools queue classes indirectly when available. Will have some commits to push shortly.

jvz · 2023-01-16T21:23:36Z

@vy care to have a look at my changes to the Recycler API?

jvz · 2023-01-16T21:34:39Z

log4j-core/src/main/java/org/apache/logging/log4j/core/layout/GelfLayout.java

-                final StringBuilder messageBuffer = getMessageStringBuilder();
-                layout.serialize(event, messageBuffer);
-                JsonUtils.quoteAsString(messageBuffer, builder);
+                final StringBuilder messageBuffer = acquireStringBuilder();


Interesting little use case where you can now abuse the recursion support in ThreadLocalRecyclerFactory to get multiple recyclable objects. Already works as expected with the QueueingRecyclerFactory version.

jvz · 2023-01-16T21:35:30Z

log4j-core/src/main/java/org/apache/logging/log4j/core/layout/GelfLayout.java

        return builder;
    }

-    private static final ThreadLocal<StringBuilder> timestampStringBuilder = new ThreadLocal<>();
-
-    private static StringBuilder getTimestampStringBuilder() {


Also got a kick out of how pointless this buffer is when using the buffer provided by AbstractStringLayout already. The joys of new APIs!

Signed-off-by: Matt Sicker <[email protected]>

ppkarwasz · 2023-01-20T10:54:25Z

There is one Recycler usage case that is not covered by this PR: some objects like LogBuilder must be aware of the recycling lifecycle and be able to signal the recycler, when they are available.

In the case of LogBuilder I imagine a sequence like this:

the logger acquires a LogBuilder from a Recycler,
the recycler calls reset(Runnable release) on the LogBuilder,
when the log method on the LogBuilder is called, the LogBuilder runs the release action.

vy · 2023-01-20T09:13:43Z

log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableMessageFactory.java

@@ -89,9 +83,21 @@ public static void release(final Message message) { // LOG4J2-1583
        }
    }

+    @Override
+    public void recycle(final Message message) {


How does this new method compare to release(Message)?

Instead of merely clearing the message, this also returns the object back to its pool.

Oh, and I wasn't able to name this method release because it conflicts with the static method with the same signature.

release javadoc states the following

This flag is used internally to verify that a reusable message is no longer in use and can be reused.

This sounds to me exactly like what recycle does. I am curious why do we need separate recycle() and release() methods. Can't we simply move the recycle() logic to the bottom of the release()?

log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java

log4j-api/src/main/java/org/apache/logging/log4j/spi/RecyclerFactories.java

log4j-api/src/main/java/org/apache/logging/log4j/spi/RecyclerFactory.java

log4j-api/src/main/java/org/apache/logging/log4j/spi/ThreadLocalRecyclerFactory.java

log4j-api-test/src/test/java/org/apache/logging/log4j/spi/ThreadLocalRecyclerFactoryTest.java

vy · 2023-01-20T10:38:25Z

log4j-core/src/main/java/org/apache/logging/log4j/core/async/AsyncLogger.java

    private void onPropertiesPresent(final RingBufferLogEvent event, final List<Property> properties) {
        final StringMap contextData = getContextData(event);
-        for (int i = 0, size = properties.size(); i < size; i++) {
-            final Property prop = properties.get(i);
+        // List::forEach is garbage-free when using an ArrayList or Arrays.asList


Is it? You need to pass a lambda, which needs to be allocated. I think this needs to be reverted along with the switch from List.of() to Arrays.asList() change in LoggerConfig.

I discovered the temporary allocation due to our existing GC tests. Lambdas compile down to some sort of synthetic static method on the class it was declared in.

I am not able to follow. Are you saying that our GC-tests are returning false negatives and in reality JIT optimizes this piece of code to have no allocations?

log4j-core/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout.java

log4j-core/src/main/java/org/apache/logging/log4j/core/layout/GelfLayout.java

…actories.java Co-authored-by: Volkan Yazıcı <[email protected]>

Signed-off-by: Matt Sicker <[email protected]>

jvz · 2023-01-22T23:05:27Z

Ignore test failures as those are broken in master already.

This simplifies DefaultLogBuilder as reuse is now handled by the recycler. This also adds a place to store a default RecyclerFactory in LoggingSystem. Signed-off-by: Matt Sicker <[email protected]>

jvz · 2023-01-22T23:47:17Z

There is one Recycler usage case that is not covered by this PR: some objects like LogBuilder must be aware of the recycling lifecycle and be able to signal the recycler, when they are available.

In the case of LogBuilder I imagine a sequence like this:

the logger acquires a LogBuilder from a Recycler,

the recycler calls reset(Runnable release) on the LogBuilder,

when the log method on the LogBuilder is called, the LogBuilder runs the release action.

Updated to support this. The recycler doesn't even need to reset the LogBuilder as that can be done in a central place already.

ppkarwasz · 2023-01-23T07:13:55Z

log4j-core/src/main/java/org/apache/logging/log4j/core/layout/AbstractStringLayout.java

-        final LogEvent logEvent = getLogEventFactory().createEvent(rootLogger.getName(), null, Strings.EMPTY,
+        final LogEvent logEvent = logEventFactory.createEvent(rootLogger.getName(), null, Strings.EMPTY,


I don't see the need for extracting a local variable.

The getter wasn't for a field; it was doing work each time. I realized upon fixing this that Configuration must be non-null at this point, so we can just get it from Configuration::getLogEventFactory (recently added method).

Agreeing with @jvz here. If a method is not merely a simple field getter (which is a shame that it is still called getBlah), its result should first better be stored in a self-explanatory variable. This greatly helps while stepping in a debugger.

vy · 2023-02-02T14:28:30Z

the logger acquires a LogBuilder from a Recycler

@ppkarwasz, does the logger already pool returned LogBuilders? If not, I would rather create a follow-up ticket for this.

vy · 2023-02-02T14:40:26Z

the logger acquires a LogBuilder from a Recycler

@ppkarwasz, does the logger already pool returned LogBuilders? If not, I would rather create a follow-up ticket for this.

Ignore this please. @jvz says he has already implemented it.

ppkarwasz · 2023-02-02T19:12:26Z

log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java

+    protected final Recycler<LogBuilder> recycler = LoggingSystem.getRecyclerFactory()
+            .create(() -> new DefaultLogBuilder(this));


As a future extension we should probably allow any LogBuilder...

ppkarwasz · 2023-02-02T19:14:18Z

log4j-api/src/main/java/org/apache/logging/log4j/spi/AbstractLogger.java

+        final DefaultLogBuilder builder = (DefaultLogBuilder) recycler.acquire();
+        return builder.atLevel(Level.OFF);


...so that we don't need this unchecked cast.

I can open a new issue for this, since this PR is getting huge.

ppkarwasz · 2023-02-02T19:15:17Z

log4j-api/src/main/java/org/apache/logging/log4j/internal/DefaultLogBuilder.java

+            // recycle self
+            this.level = null;
+            this.marker = null;
+            this.throwable = null;
+            this.location = null;


I fail to understand how can the recycler knows that the LogBuilder can be used again?

jvz added 2 commits January 9, 2023 12:06

Apply spotless automatically

b69adc2

This adds executions during process-sources and process-test-sources to ensure that modified files are formatted properly.

jvz requested review from vy and ppkarwasz January 9, 2023 18:47

ppkarwasz reviewed Jan 9, 2023

View reviewed changes

jvz added this to the 3.0.0 milestone Jan 13, 2023

jvz added 2 commits January 14, 2023 14:34

Move Recycler API to spi and fix related queue factory classes

156e747

Signed-off-by: Matt Sicker <[email protected]>

Update ReusableMessageFactory to use Recycler API

b001831

Also updates ThreadLocalRecyclerFactory to support nested calls to acquire() by using an ArrayDeque to track potentially more than one object. Signed-off-by: Matt Sicker <[email protected]>

jvz added the api Affects the public API label Jan 14, 2023

jvz added 3 commits January 14, 2023 17:22

Merge branch 'master' into dev-master-recycler-api

22d2db5

Extract ReusableLogEvent interface and use Recycler API

ade3184

Signed-off-by: Matt Sicker <[email protected]>

Use a bounded queue for recursion

f2f43d7

jvz commented Jan 16, 2023

View reviewed changes

Update StatusLogger to use MPMC queue

633938f

Signed-off-by: Matt Sicker <[email protected]>

vy requested changes Jan 20, 2023

View reviewed changes

jvz and others added 6 commits January 22, 2023 14:53

Update log4j-api/src/main/java/org/apache/logging/log4j/spi/RecyclerF…

ab7b640

…actories.java Co-authored-by: Volkan Yazıcı <[email protected]>

Minimize visibility of inner classes

0b96146

Signed-off-by: Matt Sicker <[email protected]>

Fix RecyclerFactories

160670f

Signed-off-by: Matt Sicker <[email protected]>

Rename defaultCleaner() to getDefaultCleaner()

13d498f

Signed-off-by: Matt Sicker <[email protected]>

Add more tests for ThreadLocalRecyclerFactory

44744c5

Signed-off-by: Matt Sicker <[email protected]>

Use constant for reusable messages

815c22c

Signed-off-by: Matt Sicker <[email protected]>

jvz added 2 commits January 22, 2023 15:54

Simplify LogEventFactory lookup

583bf6b

Signed-off-by: Matt Sicker <[email protected]>

Merge branch 'master' into dev-master-recycler-api

b10e118

jvz requested a review from vy January 22, 2023 22:00

Add missing license header

bcc1ee1

Signed-off-by: Matt Sicker <[email protected]>

Use Recycler API for LogBuilder

86c6ec4

This simplifies DefaultLogBuilder as reuse is now handled by the recycler. This also adds a place to store a default RecyclerFactory in LoggingSystem. Signed-off-by: Matt Sicker <[email protected]>

jvz requested a review from ppkarwasz January 22, 2023 23:47

ppkarwasz reviewed Jan 23, 2023

View reviewed changes

ppkarwasz reviewed Feb 2, 2023

View reviewed changes

ppkarwasz mentioned this pull request Feb 9, 2023

ReusableMessages not getting released when using entry/exit logging #1273

Open

vy deleted the branch apache:master February 28, 2023 15:03

vy closed this Feb 28, 2023

vy mentioned this pull request Mar 29, 2023

Recycler API #1401

Merged

2 tasks

ppkarwasz modified the milestones: 3.0.0, 3.0.0-beta1 Feb 17, 2024

		final LogEvent logEvent = getLogEventFactory().createEvent(rootLogger.getName(), null, Strings.EMPTY,
		final LogEvent logEvent = logEventFactory.createEvent(rootLogger.getName(), null, Strings.EMPTY,

		protected final Recycler<LogBuilder> recycler = LoggingSystem.getRecyclerFactory()
		.create(() -> new DefaultLogBuilder(this));

		final DefaultLogBuilder builder = (DefaultLogBuilder) recycler.acquire();
		return builder.atLevel(Level.OFF);

Uh oh!

Migrate Recycler API to log4j-api #1194

Migrate Recycler API to log4j-api #1194

Uh oh!

Conversation

jvz commented Jan 9, 2023

Uh oh!

ppkarwasz left a comment

Choose a reason for hiding this comment

Uh oh!

jvz commented Jan 9, 2023

Uh oh!

jvz commented Jan 10, 2023

Uh oh!

jvz commented Jan 14, 2023

Uh oh!

jvz commented Jan 14, 2023

Uh oh!

jvz commented Jan 16, 2023

Uh oh!

jvz commented Jan 16, 2023

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ppkarwasz commented Jan 20, 2023

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

jvz commented Jan 22, 2023

Uh oh!

jvz commented Jan 22, 2023

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

vy commented Feb 2, 2023

Uh oh!

vy commented Feb 2, 2023

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ppkarwasz Feb 2, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

ppkarwasz Feb 2, 2023 •

edited

Loading