log4j2 ReusableMessageFactory.getParameterized() create too many threadLocal, 125MB

Question

In my project, using ReusableMessageFactory create log message, which call

private static ThreadLocal<ReusableParameterizedMessage> threadLocalParameterized = new ThreadLocal<>();
private static ReusableParameterizedMessage getParameterized() {
    ReusableParameterizedMessage result = threadLocalParameterized.get();
    if (result == null) {
        result = new ReusableParameterizedMessage();
        threadLocalParameterized.set(result);
    }
    return result.reserved ? new ReusableParameterizedMessage().reserve() : result.reserve();
}

public static void release(final Message message) { // LOG4J2-1583
    if (message instanceof Clearable) {
        ((Clearable) message).clear();
    }
}

In the last line, result.reserved ? new ReusableParameterizedMessage().reserve() : result.reserve();, create too many ReusableParameterizedMessage which then create threadLocal and not call threadLocal.remove(), too may threadLocal exist.

In my memory dump, one tomcat thread have 155857 threadLocal entry where almost created by ReusableParameterizedMessage.buffer, occupy 125MB.

Two many threadLocal lead to frequently threadLoalMap hash conflict, ThreadLocalMap.getEntryAfterMiss() consuming excessive CPU time.

Usually logger.info() will call ReusableMessageFactory.release() set reserved to false, why create so many ReusableParameterizedMessage and buffer.

Below is Eclipse Memory Analyzer screen.

Is this normal? if not, how fix this?

Answer 1

After read log4j code, We did indeed misuse the ReusableMessageFactory, our code :

@AllArgsConstructor
public class MyLogger {

    private static final MessageFactory2 MESSAGE_FACTORY = new ReusableMessageFactory();
    private Logger logger;

    public static MyLogger getLogger(String name) {
        return new MyLogger(org.slf4j.LoggerFactory.getLogger(name));
    }

    public void info(String title, String format, Map<String, String> attrs, Object... arguments) {
        String str = MESSAGE_FACTORY.newMessage(format, arguments).getFormattedMessage();
        // append title, tags or trace tags...
        String message = appendTitleTag(str);
        logger.debug(message);
    }
    .....
}

ReusableMessageFactory.newMessage() then need call ReusableMessageFactory.release() to set reserved to false after log, bus we did not call.

That's why wo have so many threadLocals.

Other:

1. ReusableParameterizedMessage.buffer remove static modifier, commit link