英文:
log4j2 ReusableMessageFactory.getParameterized() create too many threadLocal, 125MB
问题
在我的项目中，使用ReusableMessageFactory创建日志消息，其中调用了以下代码：
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();
}
}
在最后一行中，result.reserved ? new ReusableParameterizedMessage().reserve() : result.reserve();会创建太多的ReusableParameterizedMessage，然后创建了threadLocal，但没有调用threadLocal.remove()，导致有太多的threadLocal存在。
在我的内存转储中，一个Tomcat线程拥有155857个threadLocal条目，其中几乎都是由ReusableParameterizedMessage.buffer创建的，占用了125MB的内存。
太多的threadLocal会导致threadLoalMap哈希冲突频繁发生，ThreadLocalMap.getEntryAfterMiss()消耗了过多的CPU时间。
通常情况下，logger.info()会调用ReusableMessageFactory.release()并将reserved设置为false，为什么会创建这么多的ReusableParameterizedMessage和buffer？
以下是Eclipse Memory Analyzer的屏幕截图。
这种情况是否正常？如果不正常，如何修复？
英文:
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?
答案1
得分: 1
在阅读了log4j的代码后，我们确实误用了ReusableMessageFactory，我们的代码如下：
@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();
// 添加标题、标签或跟踪标签...
String message = appendTitleTag(str);
logger.debug(message);
}
......
}
然后需要调用ReusableMessageFactory.newMessage()之后调用ReusableMessageFactory.release()来将reserved设置为false，以便在记录后释放，但我们没有调用。
这就是为什么我们有这么多ThreadLocals。
其他：
ReusableParameterizedMessage.buffer移除了静态修饰符，提交链接。
英文:
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:
ReusableParameterizedMessage.bufferremove static modifier, commit link
通过集体智慧和协作来改善编程学习和解决问题的方式。致力于成为全球开发者共同参与的知识库，让每个人都能够通过互相帮助和分享经验来进步。
评论