Мы столкнулись с проблемой одного из наших приложений, когда пиковая нагрузка приводит к зависанию log4j2, а приложение не отвечает. log4j2. xml
- У нас есть CustomAppender, AppMessageAppender, настроенный для нужд нашего приложения.
- Когда в нашем приложении наблюдается всплеск, мы видим почти 350 строк / сек c.
- Это происходит после короткого пакета, но приложение по-прежнему не отвечает.
- Мы попытались увеличить значение по умолчанию с первого до 1024, а затем до 2048. но все же мы видим ту же проблему.
- У нас по умолчанию log4j2.asyncLoggerConfigWaitStrategy установлен по умолчанию (Timeout).
- 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.
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();
}
}
Когда мы посмотрели на дамп потока во время выпуска, мы увидели множество потоков с трассировкой стека удара.
"[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$000(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 и прерыватель 3.4 .1 версия, запустив ее в OEL 3.8.13-98.el6uek.x86_64, есть ли какие-либо известные проблемы для этих комбинаций?
Рад прояснить что-нибудь еще.
Быстрый Изменить -: мы видели это в течение определенного периода времени. Первоначально журналы синхронизируются c с отметкой времени сервера, т.е. журналы соответствуют отметке времени сервера. С течением времени регистрация начинает замедляться, и мы видим журналы, которые на 3 часа раньше (иногда до 8 часов) печатаются в журналах. Я надеюсь, что где-то звонит.
Спасибо