当来自应用程序的大量日志记录时，Log4j2 异步日志记录会卡住
Log4j2 asynchronous logging is getting stuck when there is heavy logging from application
我们的一个应用程序遇到了一个问题，即峰值负载导致 log4j2 挂起并且应用程序没有响应。
log4j2.xml
- 我们有一个 CustomAppender，AppMessageAppender 是为我们的应用程序需求定制的。
- 当我们的应用程序突然出现时，我们看到将近 350 line/sec。
- 过一会就下来了，但是应用还是没反应。
- 我们已经尝试将默认值增加到 1024，然后现在增加到 2048。但我们仍然看到同样的问题。
- 我们将默认 log4j2.asyncLoggerConfigWaitStrategy 设置为默认值（超时）。
- log4j2.xml 如下所示。
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" name="myApplication" packages="com.application.logging.log4j">
<Properties>
<Property name="logLocation">./log</Property> <!-- current directory-->
<Property name="filename">application</Property>
<Property name="maxLogFileSize">50 MB</Property>
<Property name="rolloverCount">20</Property>
</Properties>
<Loggers>
<AsyncRoot level="WARN">
<AppenderRef ref="STDOUT"/>
<AppenderRef ref="STDERR" level="ERROR"/>
<AppenderRef ref="File"/>
<AppenderRef ref="FileErr" level="ERROR"/>
</AsyncRoot>
<AsyncLogger name="com.application" level="INFO" additivity="false">
<AppenderRef ref="STDOUT"/>
<AppenderRef ref="STDERR" level="ERROR"/>
<AppenderRef ref="File"/>
<AppenderRef ref="FileErr" level="ERROR"/>
</AsyncLogger>
<AsyncLogger name="CustomLogger" level="INFO" additivity="false">
<AppenderRef ref="Message"/>
</AsyncLogger>
<AsyncLogger name="com.application" level="INFO" additivity="false">
<AppenderRef ref="STDOUT"/>
<AppenderRef ref="STDERR" level="ERROR"/>
<AppenderRef ref="File"/>
<AppenderRef ref="FileErr" level="ERROR"/>
</AsyncLogger>
</Loggers>
<Appenders>
<Console name="STDOUT" target="SYSTEM_OUT">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
</Console>
<Console name="STDERR" target="SYSTEM_ERR">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
</Console>
<RollingRandomAccessFile name="File" fileName="${logLocation}/${filename}.log" filePattern="${logLocation}/${filename}-%d{MM-dd-yyyy}-%i.log" immediateFlush="false">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
<Policies>
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="${maxLogFileSize}"/>
</Policies>
<DefaultRolloverStrategy max="${rolloverCount}"/>
</RollingRandomAccessFile>
<RollingRandomAccessFile name="FileErr" fileName="${logLocation}/${filename}_err.log" filePattern="${logLocation}/${filename}_err-%d{MM-dd-yyyy}-%i.log" immediateFlush="false">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
<Policies>
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="${maxLogFileSize}"/>
</Policies>
<DefaultRolloverStrategy max="${rolloverCount}"/>
</RollingRandomAccessFile>
<RollingRandomAccessFile name="FileMetrics" fileName="${logLocation}/${filename}_metrics.log" filePattern="${logLocation}/${filename}_metrics-%d{MM-dd-yyyy}-%i.log" immediateFlush="false">
<PatternLayout pattern="%msg%n"/>
<Policies>
<SizeBasedTriggeringPolicy size="${maxLogFileSize}"/>
</Policies>
<DefaultRolloverStrategy max="${rolloverCount}"/>
</RollingRandomAccessFile>
<AppMessageAppender name="Message" directory="${logLocation}/messages"/>
</Appenders>
</Configuration>
- 自定义记录器代码如下。
package com.application.logging;
import java.net.URL;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public final class Log4j2Logger {
private static final String DEFAULT_CATEGORY = "com.application";
private Logger log;
static {
configureLogger();
}
public Logger(String category){
this.category = category;
}
/**
* Constructs Log4jLogger with default ("com.application") category
*/
public Log4j2Logger(){
log = LogManager.getLogger(DEFAULT_CATEGORY);
}
/**
* Constructs Log4jLogger with given category
* @param category
*/
public Log4j2Logger(String category){
super(category);
log = LogManager.getLogger(category);
}
/**
* Constructs Log4jLogger with given class
* @param clazz
*/
public Log4j2Logger(Class clazz){
super(clazz);
log = LogManager.getLogger(clazz.getName());
}
/**
* Log message at debug level
* @param message
*/
public void debug(Object message){
log.debug(message);
}
/**
* Log exception with given message at debug level
* @param message
* @param t
*/
public void debug(Object message, Throwable t){
log.debug(message,t);
}
/**
* Log message at info level
* @param message
*/
public void info(Object message){
log.info(message);
}
/**
* Log exception with given message at info level
* @param message
* @param t
*/
public void info(Object message, Throwable t){
log.info(message,t);
}
/**
* Log message at warn level
* @param message
*/
public void warn(Object message){
log.warn(message);
}
/**
* Log exception with given message at warn level
* @param message
* @param t
*/
public void warn(Object message, Throwable t){
log.warn(message,t);
}
/**
* Log message at error level
* @param message
*/
public void error(Object message){
log.error(message);
}
/**
* Log exception with given message at error level
* @param message
* @param t
*/
public void error(Object message, Throwable t){
log.error(message,t);
}
/**
* Log message at fatal level
* @param message
*/
public void fatal(Object message){
log.fatal(message);
}
/**
* Log exception with given message at fatal level
* @param message
* @param t
*/
public void fatal(Object message, Throwable t){
log.fatal(message,t);
}
@Override
public void debug(String message) {
log.debug(message);
}
@Override
public void debug(String message, Throwable t) {
log.debug(message,t);
}
@Override
public void error(String message) {
log.error(message);
}
@Override
public void error(String message, Throwable t) {
log.error(message,t);
}
@Override
public void fatal(String message) {
log.fatal(message);
}
@Override
public void fatal(String message, Throwable t) {
log.fatal(message,t);
}
@Override
public void info(String message) {
log.info(message);
}
@Override
public void info(String message, Throwable t) {
log.info(message,t);
}
@Override
public void warn(String message) {
log.warn(message);
}
@Override
public void warn(String message, Throwable t) {
log.warn(message,t);
}
@Override
public boolean isTraceEnabled() {
return log.isTraceEnabled();
}
@Override
public void trace(Object message) {
log.trace(message);
}
@Override
public void trace(Object message, Throwable t) {
log.trace(message,t);
}
@Override
public void trace(String message) {
log.trace(message);
}
@Override
public void trace(String message, Throwable t) {
log.trace(message,t);
}
/**
* @return true if debug level log is enabled
*/
public boolean isDebugEnabled(){
return log.isDebugEnabled();
}
public boolean isInfoEnabled(){
return log.isInfoEnabled();
}
public boolean isEnableForLevel(com.application.Level level){
return log.isEnabled(((Log4j2Level)level).getLog4jLevel());
}
public com.application.loggging.Level getLogLevel(){
return Log4j2Level.convert2Log4j(log.getLevel());
}
public void setLogLevel(com.application.Level level){
((org.apache.logging.log4j.core.Logger)log).setLevel(((Log4j2Level)level).getLog4jLevel());
}
private static void configureLogger(){
System.setProperty("Log4jContextSelector","org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
System.setProperty("AsyncLogger.ThreadNameStrategy","UNCACHED");
mbean.setSystemProperties();
try{
URL url = Thread.currentThread().getContextClassLoader().getResource("log4j2.xml");
if(url != null){
System.setProperty("log4j.configurationFile",url.toString());
}else{
System.err.println("No log4j2.xml configuration found in the classpath logger");
}
Log4j2Logger logger = new Log4j2Logger();
logger.info("Log4j2 logger configured");
}catch(Exception e){
e.printStackTrace();
}
}
}
- 应用程序 AppMessageAppender 侦听 JMS 队列并记录消息。
package com.application.logging;
import java.io.BufferedWriter;
import java.io.File;
import java.io.FileNotFoundException;
import java.io.FileWriter;
import java.io.IOException;
import java.io.Serializable;
import java.io.Writer;
import java.util.Date;`
import java.util.Properties;
import java.util.concurrent.atomic.AtomicLong;
import org.apache.commons.lang.time.FastDateFormat;
import org.apache.log4j.helpers.LogLog;
import org.apache.logging.log4j.core.Filter;
import org.apache.logging.log4j.core.Layout;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.appender.AbstractAppender;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
import org.apache.logging.log4j.core.config.plugins.PluginConfiguration;
import org.apache.logging.log4j.core.config.plugins.PluginElement;
import org.apache.logging.log4j.core.config.plugins.PluginFactory;
import org.apache.logging.log4j.core.layout.PatternLayout;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import com.application.logging.CustomMessage;
import com.application.framework.utils.PropertiesCache;
import com.application.utils.xml.SpringBeanFactory;
@Plugin(name = "AppMessageAppender", category = "Core", elementType = "appender", printObject = true)
public final class AppMessageAppender extends AbstractAppender {
private static final long serialVersionUID = 1L;
private static final String DEFAULT_DATE_FORMAT = "dd_MM_yyyy/HH";
private static final String DEFAULT_TIME_FORMAT = "HHmmss_SSS";
private static Logger logger = LoggerFactory.getLogger(AppMessageAppender.class);
private String directoryName;
private String dirTimeFormat = DEFAULT_DATE_FORMAT;
private FastDateFormat dateFormatter;
private static FastDateFormat timeFormatter = FastDateFormat.getInstance(DEFAULT_TIME_FORMAT);
private AtomicLong sequenceNo = new AtomicLong();
protected AppMessageAppender(String name, Filter filter, Layout<? extends Serializable> layout,
String directoryName, String subDirectoryDateFormat) {
super(name, filter, layout);
this.directoryName = directoryName;
if (subDirectoryDateFormat != null)
this.dirTimeFormat = subDirectoryDateFormat;
dateFormatter = FastDateFormat.getInstance(dirTimeFormat);
}
@Override
public void append(LogEvent event) {
Writer writer = null;
try {
CustomMessage logMessage = (CustomMessage) event.getMessage().getParameters()[0];
StringBuilder sb = new StringBuilder();
if (directoryName != null) {
sb.append(directoryName).append("/");
}
Date d = new Date(event.getTimeMillis());
sb.append(dateFormatter.format(d)).append("/").append(logMessage.getChannel());
String dir = sb.toString();
String processMessageId = logMessage.getMessageId();
sb.append("/Msg_").append(logMessage.getMessageId().replaceAll("/", "")).append("_")
.append(timeFormatter.format(d)).append("_").append(sequenceNo.getAndIncrement())
.append(".log");
String absFile = sb.toString();
writer = writeToFile(logMessage, dir, absFile);
logger.info("AppMessageAppender message logged: {} ", absFile);
String channelType = logMessage.getChannel();
Properties auditPropConfig = PropertiesCache.getAuditChannelCapability();
String beanName = auditPropConfig.getProperty(channelType);
} catch (IOException e) {
LogLog.error("Exception in writing to file", e);
} finally {
if (writer != null) {
try {
writer.close();
} catch (IOException e) {
logger.error("Error in closing the stream");
}
}
}
}
private Writer writeToFile(CustomMessage logMessage, String dir, String absFile) throws IOException {
Writer writer;
try {
writer = new BufferedWriter(new FileWriter(absFile));
} catch (FileNotFoundException fne) {
File f = new File(dir);
f.mkdirs();
writer = new BufferedWriter(new FileWriter(absFile));
}
logMessage.write(writer);
writer.flush();
return writer;
}
@PluginFactory
public static AppMessageAppender createAppender(@PluginAttribute("name") String name,
@PluginElement("Filter")
final Filter filter, @PluginElement("Layout") Layout<? extends Serializable> layout,
@PluginAttribute("directory")
final String directoryName, @PluginAttribute("subDirectoryDateFormat")
final String subDirectoryDateFormat, @PluginConfiguration
final Configuration config) {
if (layout == null) {
layout = PatternLayout.createDefaultLayout();
}
return new AppMessageAppender(name, filter, layout, directoryName, subDirectoryDateFormat);
}
}
- 我们还有一个 CustomMessage class。
package com.application.logging;
import java.io.IOException;
import java.io.Serializable;
import java.io.Writer;
import java.util.LinkedHashMap;
import java.util.Map;
public class CustomMessage implements Serializable{
private static final String HEADER_SEP = ": ";
private static final String NEWLINE = "\r\n";
private static final String CHANNEL_HEADER_NAME = "Channel";
private static final String MESSAGEID_HEADER_NAME = "MessageId";
private static final String DEFAULT_CHANNEL = "DefaultChannel";
private static final String DEFAULT_MESSAGEID = "Message";
protected Map<String,String> headers = new LinkedHashMap<String,String>(4);
protected String body;
public CustomMessage(String channel, String messageId){
addHeader(CHANNEL_HEADER_NAME,channel != null ? channel : DEFAULT_CHANNEL);
addHeader(MESSAGEID_HEADER_NAME,messageId != null ? messageId : DEFAULT_MESSAGEID);
}
public String getChannel(){
return headers.get(CHANNEL_HEADER_NAME);
}
public String getMessageId(){
return headers.get(MESSAGEID_HEADER_NAME);
}
public void addHeader(String name, String value){
headers.put(name, value);
}
public void setBody(String body){
this.body = body;
}
public void write(Writer w) throws IOException{
writeHeaders(w);
writeLine(w);
writeBody(w);
}
private void writeHeaders(Writer w) throws IOException {
if(headers != null){
for(Map.Entry<String,String> entry : headers.entrySet()){
w.append(entry.getKey()).append(HEADER_SEP).append(entry.getValue());
writeLine(w);
}
}
}
private void writeBody(Writer w) throws IOException {
if(body != null)
w.write(body);
}
private void writeLine(Writer w) throws IOException{
w.write(NEWLINE);
}
public String toString(){
StringBuilder sb = new StringBuilder();
if(headers != null){
for(Map.Entry<String,String> entry : headers.entrySet()){
sb.append(entry.getKey()).append(HEADER_SEP).append(entry.getValue());
sb.append(NEWLINE);
}
}
sb.append(NEWLINE);
sb.append(body);
return sb.toString();
}
}
- 当我们在问题期间查看线程转储时，我们看到很多线程都有 blow stacktrace。
"[STUCK] ExecuteThread: '33' for queue: 'weblogic.kernel.Default (self-tuning)'" #91 daemon prio=1 os_prio=0 tid=0x00007fe644022800 nid=0x3928 runnable [0x00007fe5b6ceb000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:465)
at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:331)
at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:222)
at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:181)
at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:166)
at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:161)
at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:131)
at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2170)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2125)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2108)
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2002)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1974)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:318)
at com.application.logging.log4j.Log4j2Logger.debug(Log4j2Logger.java:129)
at com.application.services.process.ejb.EventSubscriberBean.onMessage(EventSubscriberBean.java:52)
at weblogic.ejb.container.internal.MDListener.execute(MDListener.java:451)
at weblogic.ejb.container.internal.MDListener.transactionalOnMessage(MDListener.java:375)
at weblogic.ejb.container.internal.MDListener.onMessage(MDListener.java:310)
at weblogic.jms.client.JMSSession.onMessage(JMSSession.java:4855)
at weblogic.jms.client.JMSSession.execute(JMSSession.java:4529)
at weblogic.jms.client.JMSSession.executeMessage(JMSSession.java:3976)
at weblogic.jms.client.JMSSession.access[=14=]0(JMSSession.java:120)
at weblogic.jms.client.JMSSession$UseForRunnable.run(JMSSession.java:5375)
at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:553)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:311)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:263)
问题：
- 这是 log4j2 和干扰器的负载问题，无法处理吗？
- 除了增加ringBuffersize，还能做哪些优化？
- 我们正在使用 log4j2 2.11.0 和 disruptor 3.4.1 版本，运行 它在 OEL 3.8.13-98.el6uek.x86_64 中，这些组合是否存在任何已知问题？
很高兴能澄清更多问题。
快速编辑-：我们已经在一段时间内看到了这一点。最初，日志与服务器时间戳同步，即日志与服务器时间戳匹配。随着时间的推移，日志记录开始变慢，我们看到日志中打印了 3 小时前（有时会达到 8 小时）的日志。我希望这能在某个地方敲响警钟。
谢谢
我怀疑您的应用程序生成日志事件的速度快于 Appender 可以处理的速度。配置显示两个 ConsoleAppender。登录到控制台 extremely slow，实际上比登录到文件慢 50 倍。
异步记录器使用环形缓冲区。如果此缓冲区已满（因为 Appender 无法足够快地取出事件），则应用程序将无法将新事件添加到队列中，因此实际上应用程序会被阻止进行处理。
我的建议是只将 WARN 或 ERROR 事件记录到控制台，并将其他所有内容记录到文件。
另一个潜在的瓶颈是自定义 Appender。请注意，它会为每个事件 打开一个新的 FileWriter 。这会很慢。最好打开文件一次并继续附加到它。
我们的一个应用程序遇到了一个问题，即峰值负载导致 log4j2 挂起并且应用程序没有响应。 log4j2.xml
- 我们有一个 CustomAppender，AppMessageAppender 是为我们的应用程序需求定制的。
- 当我们的应用程序突然出现时，我们看到将近 350 line/sec。
- 过一会就下来了，但是应用还是没反应。
- 我们已经尝试将默认值增加到 1024，然后现在增加到 2048。但我们仍然看到同样的问题。
- 我们将默认 log4j2.asyncLoggerConfigWaitStrategy 设置为默认值（超时）。
- log4j2.xml 如下所示。
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN" name="myApplication" packages="com.application.logging.log4j">
<Properties>
<Property name="logLocation">./log</Property> <!-- current directory-->
<Property name="filename">application</Property>
<Property name="maxLogFileSize">50 MB</Property>
<Property name="rolloverCount">20</Property>
</Properties>
<Loggers>
<AsyncRoot level="WARN">
<AppenderRef ref="STDOUT"/>
<AppenderRef ref="STDERR" level="ERROR"/>
<AppenderRef ref="File"/>
<AppenderRef ref="FileErr" level="ERROR"/>
</AsyncRoot>
<AsyncLogger name="com.application" level="INFO" additivity="false">
<AppenderRef ref="STDOUT"/>
<AppenderRef ref="STDERR" level="ERROR"/>
<AppenderRef ref="File"/>
<AppenderRef ref="FileErr" level="ERROR"/>
</AsyncLogger>
<AsyncLogger name="CustomLogger" level="INFO" additivity="false">
<AppenderRef ref="Message"/>
</AsyncLogger>
<AsyncLogger name="com.application" level="INFO" additivity="false">
<AppenderRef ref="STDOUT"/>
<AppenderRef ref="STDERR" level="ERROR"/>
<AppenderRef ref="File"/>
<AppenderRef ref="FileErr" level="ERROR"/>
</AsyncLogger>
</Loggers>
<Appenders>
<Console name="STDOUT" target="SYSTEM_OUT">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
</Console>
<Console name="STDERR" target="SYSTEM_ERR">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
</Console>
<RollingRandomAccessFile name="File" fileName="${logLocation}/${filename}.log" filePattern="${logLocation}/${filename}-%d{MM-dd-yyyy}-%i.log" immediateFlush="false">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
<Policies>
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="${maxLogFileSize}"/>
</Policies>
<DefaultRolloverStrategy max="${rolloverCount}"/>
</RollingRandomAccessFile>
<RollingRandomAccessFile name="FileErr" fileName="${logLocation}/${filename}_err.log" filePattern="${logLocation}/${filename}_err-%d{MM-dd-yyyy}-%i.log" immediateFlush="false">
<PatternLayout pattern="[^%d^] [^%-5level^] [^%t^] - [^%msg^]%n"/>
<Policies>
<TimeBasedTriggeringPolicy />
<SizeBasedTriggeringPolicy size="${maxLogFileSize}"/>
</Policies>
<DefaultRolloverStrategy max="${rolloverCount}"/>
</RollingRandomAccessFile>
<RollingRandomAccessFile name="FileMetrics" fileName="${logLocation}/${filename}_metrics.log" filePattern="${logLocation}/${filename}_metrics-%d{MM-dd-yyyy}-%i.log" immediateFlush="false">
<PatternLayout pattern="%msg%n"/>
<Policies>
<SizeBasedTriggeringPolicy size="${maxLogFileSize}"/>
</Policies>
<DefaultRolloverStrategy max="${rolloverCount}"/>
</RollingRandomAccessFile>
<AppMessageAppender name="Message" directory="${logLocation}/messages"/>
</Appenders>
</Configuration>
- 自定义记录器代码如下。
package com.application.logging;
import java.net.URL;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
public final class Log4j2Logger {
private static final String DEFAULT_CATEGORY = "com.application";
private Logger log;
static {
configureLogger();
}
public Logger(String category){
this.category = category;
}
/**
* Constructs Log4jLogger with default ("com.application") category
*/
public Log4j2Logger(){
log = LogManager.getLogger(DEFAULT_CATEGORY);
}
/**
* Constructs Log4jLogger with given category
* @param category
*/
public Log4j2Logger(String category){
super(category);
log = LogManager.getLogger(category);
}
/**
* Constructs Log4jLogger with given class
* @param clazz
*/
public Log4j2Logger(Class clazz){
super(clazz);
log = LogManager.getLogger(clazz.getName());
}
/**
* Log message at debug level
* @param message
*/
public void debug(Object message){
log.debug(message);
}
/**
* Log exception with given message at debug level
* @param message
* @param t
*/
public void debug(Object message, Throwable t){
log.debug(message,t);
}
/**
* Log message at info level
* @param message
*/
public void info(Object message){
log.info(message);
}
/**
* Log exception with given message at info level
* @param message
* @param t
*/
public void info(Object message, Throwable t){
log.info(message,t);
}
/**
* Log message at warn level
* @param message
*/
public void warn(Object message){
log.warn(message);
}
/**
* Log exception with given message at warn level
* @param message
* @param t
*/
public void warn(Object message, Throwable t){
log.warn(message,t);
}
/**
* Log message at error level
* @param message
*/
public void error(Object message){
log.error(message);
}
/**
* Log exception with given message at error level
* @param message
* @param t
*/
public void error(Object message, Throwable t){
log.error(message,t);
}
/**
* Log message at fatal level
* @param message
*/
public void fatal(Object message){
log.fatal(message);
}
/**
* Log exception with given message at fatal level
* @param message
* @param t
*/
public void fatal(Object message, Throwable t){
log.fatal(message,t);
}
@Override
public void debug(String message) {
log.debug(message);
}
@Override
public void debug(String message, Throwable t) {
log.debug(message,t);
}
@Override
public void error(String message) {
log.error(message);
}
@Override
public void error(String message, Throwable t) {
log.error(message,t);
}
@Override
public void fatal(String message) {
log.fatal(message);
}
@Override
public void fatal(String message, Throwable t) {
log.fatal(message,t);
}
@Override
public void info(String message) {
log.info(message);
}
@Override
public void info(String message, Throwable t) {
log.info(message,t);
}
@Override
public void warn(String message) {
log.warn(message);
}
@Override
public void warn(String message, Throwable t) {
log.warn(message,t);
}
@Override
public boolean isTraceEnabled() {
return log.isTraceEnabled();
}
@Override
public void trace(Object message) {
log.trace(message);
}
@Override
public void trace(Object message, Throwable t) {
log.trace(message,t);
}
@Override
public void trace(String message) {
log.trace(message);
}
@Override
public void trace(String message, Throwable t) {
log.trace(message,t);
}
/**
* @return true if debug level log is enabled
*/
public boolean isDebugEnabled(){
return log.isDebugEnabled();
}
public boolean isInfoEnabled(){
return log.isInfoEnabled();
}
public boolean isEnableForLevel(com.application.Level level){
return log.isEnabled(((Log4j2Level)level).getLog4jLevel());
}
public com.application.loggging.Level getLogLevel(){
return Log4j2Level.convert2Log4j(log.getLevel());
}
public void setLogLevel(com.application.Level level){
((org.apache.logging.log4j.core.Logger)log).setLevel(((Log4j2Level)level).getLog4jLevel());
}
private static void configureLogger(){
System.setProperty("Log4jContextSelector","org.apache.logging.log4j.core.async.AsyncLoggerContextSelector");
System.setProperty("AsyncLogger.ThreadNameStrategy","UNCACHED");
mbean.setSystemProperties();
try{
URL url = Thread.currentThread().getContextClassLoader().getResource("log4j2.xml");
if(url != null){
System.setProperty("log4j.configurationFile",url.toString());
}else{
System.err.println("No log4j2.xml configuration found in the classpath logger");
}
Log4j2Logger logger = new Log4j2Logger();
logger.info("Log4j2 logger configured");
}catch(Exception e){
e.printStackTrace();
}
}
}
- 应用程序 AppMessageAppender 侦听 JMS 队列并记录消息。
package com.application.logging;
import java.io.BufferedWriter;
import java.io.File;
import java.io.FileNotFoundException;
import java.io.FileWriter;
import java.io.IOException;
import java.io.Serializable;
import java.io.Writer;
import java.util.Date;`
import java.util.Properties;
import java.util.concurrent.atomic.AtomicLong;
import org.apache.commons.lang.time.FastDateFormat;
import org.apache.log4j.helpers.LogLog;
import org.apache.logging.log4j.core.Filter;
import org.apache.logging.log4j.core.Layout;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.appender.AbstractAppender;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
import org.apache.logging.log4j.core.config.plugins.PluginConfiguration;
import org.apache.logging.log4j.core.config.plugins.PluginElement;
import org.apache.logging.log4j.core.config.plugins.PluginFactory;
import org.apache.logging.log4j.core.layout.PatternLayout;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import com.application.logging.CustomMessage;
import com.application.framework.utils.PropertiesCache;
import com.application.utils.xml.SpringBeanFactory;
@Plugin(name = "AppMessageAppender", category = "Core", elementType = "appender", printObject = true)
public final class AppMessageAppender extends AbstractAppender {
private static final long serialVersionUID = 1L;
private static final String DEFAULT_DATE_FORMAT = "dd_MM_yyyy/HH";
private static final String DEFAULT_TIME_FORMAT = "HHmmss_SSS";
private static Logger logger = LoggerFactory.getLogger(AppMessageAppender.class);
private String directoryName;
private String dirTimeFormat = DEFAULT_DATE_FORMAT;
private FastDateFormat dateFormatter;
private static FastDateFormat timeFormatter = FastDateFormat.getInstance(DEFAULT_TIME_FORMAT);
private AtomicLong sequenceNo = new AtomicLong();
protected AppMessageAppender(String name, Filter filter, Layout<? extends Serializable> layout,
String directoryName, String subDirectoryDateFormat) {
super(name, filter, layout);
this.directoryName = directoryName;
if (subDirectoryDateFormat != null)
this.dirTimeFormat = subDirectoryDateFormat;
dateFormatter = FastDateFormat.getInstance(dirTimeFormat);
}
@Override
public void append(LogEvent event) {
Writer writer = null;
try {
CustomMessage logMessage = (CustomMessage) event.getMessage().getParameters()[0];
StringBuilder sb = new StringBuilder();
if (directoryName != null) {
sb.append(directoryName).append("/");
}
Date d = new Date(event.getTimeMillis());
sb.append(dateFormatter.format(d)).append("/").append(logMessage.getChannel());
String dir = sb.toString();
String processMessageId = logMessage.getMessageId();
sb.append("/Msg_").append(logMessage.getMessageId().replaceAll("/", "")).append("_")
.append(timeFormatter.format(d)).append("_").append(sequenceNo.getAndIncrement())
.append(".log");
String absFile = sb.toString();
writer = writeToFile(logMessage, dir, absFile);
logger.info("AppMessageAppender message logged: {} ", absFile);
String channelType = logMessage.getChannel();
Properties auditPropConfig = PropertiesCache.getAuditChannelCapability();
String beanName = auditPropConfig.getProperty(channelType);
} catch (IOException e) {
LogLog.error("Exception in writing to file", e);
} finally {
if (writer != null) {
try {
writer.close();
} catch (IOException e) {
logger.error("Error in closing the stream");
}
}
}
}
private Writer writeToFile(CustomMessage logMessage, String dir, String absFile) throws IOException {
Writer writer;
try {
writer = new BufferedWriter(new FileWriter(absFile));
} catch (FileNotFoundException fne) {
File f = new File(dir);
f.mkdirs();
writer = new BufferedWriter(new FileWriter(absFile));
}
logMessage.write(writer);
writer.flush();
return writer;
}
@PluginFactory
public static AppMessageAppender createAppender(@PluginAttribute("name") String name,
@PluginElement("Filter")
final Filter filter, @PluginElement("Layout") Layout<? extends Serializable> layout,
@PluginAttribute("directory")
final String directoryName, @PluginAttribute("subDirectoryDateFormat")
final String subDirectoryDateFormat, @PluginConfiguration
final Configuration config) {
if (layout == null) {
layout = PatternLayout.createDefaultLayout();
}
return new AppMessageAppender(name, filter, layout, directoryName, subDirectoryDateFormat);
}
}
- 我们还有一个 CustomMessage class。
package com.application.logging;
import java.io.IOException;
import java.io.Serializable;
import java.io.Writer;
import java.util.LinkedHashMap;
import java.util.Map;
public class CustomMessage implements Serializable{
private static final String HEADER_SEP = ": ";
private static final String NEWLINE = "\r\n";
private static final String CHANNEL_HEADER_NAME = "Channel";
private static final String MESSAGEID_HEADER_NAME = "MessageId";
private static final String DEFAULT_CHANNEL = "DefaultChannel";
private static final String DEFAULT_MESSAGEID = "Message";
protected Map<String,String> headers = new LinkedHashMap<String,String>(4);
protected String body;
public CustomMessage(String channel, String messageId){
addHeader(CHANNEL_HEADER_NAME,channel != null ? channel : DEFAULT_CHANNEL);
addHeader(MESSAGEID_HEADER_NAME,messageId != null ? messageId : DEFAULT_MESSAGEID);
}
public String getChannel(){
return headers.get(CHANNEL_HEADER_NAME);
}
public String getMessageId(){
return headers.get(MESSAGEID_HEADER_NAME);
}
public void addHeader(String name, String value){
headers.put(name, value);
}
public void setBody(String body){
this.body = body;
}
public void write(Writer w) throws IOException{
writeHeaders(w);
writeLine(w);
writeBody(w);
}
private void writeHeaders(Writer w) throws IOException {
if(headers != null){
for(Map.Entry<String,String> entry : headers.entrySet()){
w.append(entry.getKey()).append(HEADER_SEP).append(entry.getValue());
writeLine(w);
}
}
}
private void writeBody(Writer w) throws IOException {
if(body != null)
w.write(body);
}
private void writeLine(Writer w) throws IOException{
w.write(NEWLINE);
}
public String toString(){
StringBuilder sb = new StringBuilder();
if(headers != null){
for(Map.Entry<String,String> entry : headers.entrySet()){
sb.append(entry.getKey()).append(HEADER_SEP).append(entry.getValue());
sb.append(NEWLINE);
}
}
sb.append(NEWLINE);
sb.append(body);
return sb.toString();
}
}
- 当我们在问题期间查看线程转储时，我们看到很多线程都有 blow stacktrace。
"[STUCK] ExecuteThread: '33' for queue: 'weblogic.kernel.Default (self-tuning)'" #91 daemon prio=1 os_prio=0 tid=0x00007fe644022800 nid=0x3928 runnable [0x00007fe5b6ceb000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:338)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:136)
at com.lmax.disruptor.MultiProducerSequencer.next(MultiProducerSequencer.java:105)
at com.lmax.disruptor.RingBuffer.publishEvent(RingBuffer.java:465)
at com.lmax.disruptor.dsl.Disruptor.publishEvent(Disruptor.java:331)
at org.apache.logging.log4j.core.async.AsyncLoggerDisruptor.enqueueLogMessageInfo(AsyncLoggerDisruptor.java:222)
at org.apache.logging.log4j.core.async.AsyncLogger.handleRingBufferFull(AsyncLogger.java:181)
at org.apache.logging.log4j.core.async.AsyncLogger.publish(AsyncLogger.java:166)
at org.apache.logging.log4j.core.async.AsyncLogger.logWithThreadLocalTranslator(AsyncLogger.java:161)
at org.apache.logging.log4j.core.async.AsyncLogger.logMessage(AsyncLogger.java:131)
at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2170)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2125)
at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2108)
at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2002)
at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1974)
at org.apache.logging.log4j.spi.AbstractLogger.debug(AbstractLogger.java:318)
at com.application.logging.log4j.Log4j2Logger.debug(Log4j2Logger.java:129)
at com.application.services.process.ejb.EventSubscriberBean.onMessage(EventSubscriberBean.java:52)
at weblogic.ejb.container.internal.MDListener.execute(MDListener.java:451)
at weblogic.ejb.container.internal.MDListener.transactionalOnMessage(MDListener.java:375)
at weblogic.ejb.container.internal.MDListener.onMessage(MDListener.java:310)
at weblogic.jms.client.JMSSession.onMessage(JMSSession.java:4855)
at weblogic.jms.client.JMSSession.execute(JMSSession.java:4529)
at weblogic.jms.client.JMSSession.executeMessage(JMSSession.java:3976)
at weblogic.jms.client.JMSSession.access[=14=]0(JMSSession.java:120)
at weblogic.jms.client.JMSSession$UseForRunnable.run(JMSSession.java:5375)
at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:553)
at weblogic.work.ExecuteThread.execute(ExecuteThread.java:311)
at weblogic.work.ExecuteThread.run(ExecuteThread.java:263)
问题：
- 这是 log4j2 和干扰器的负载问题，无法处理吗？
- 除了增加ringBuffersize，还能做哪些优化？
- 我们正在使用 log4j2 2.11.0 和 disruptor 3.4.1 版本，运行 它在 OEL 3.8.13-98.el6uek.x86_64 中，这些组合是否存在任何已知问题？
很高兴能澄清更多问题。
快速编辑-：我们已经在一段时间内看到了这一点。最初，日志与服务器时间戳同步，即日志与服务器时间戳匹配。随着时间的推移，日志记录开始变慢，我们看到日志中打印了 3 小时前（有时会达到 8 小时）的日志。我希望这能在某个地方敲响警钟。
谢谢
我怀疑您的应用程序生成日志事件的速度快于 Appender 可以处理的速度。配置显示两个 ConsoleAppender。登录到控制台 extremely slow，实际上比登录到文件慢 50 倍。
异步记录器使用环形缓冲区。如果此缓冲区已满（因为 Appender 无法足够快地取出事件），则应用程序将无法将新事件添加到队列中，因此实际上应用程序会被阻止进行处理。
我的建议是只将 WARN 或 ERROR 事件记录到控制台，并将其他所有内容记录到文件。
另一个潜在的瓶颈是自定义 Appender。请注意，它会为每个事件 打开一个新的 FileWriter 。这会很慢。最好打开文件一次并继续附加到它。