1、概述
目前java应用日志收集都是采用日志框架(slf4j、apache commons logging)+日志系统(log4j、log4j2、LogBack、JUL等)的方式。而针对在分布式环境需要实时分析统计的日志,一般采用apache flume、facebook scribe等分布式日志收集系统。
日志框架:提供日志调用的接口,实际的日志输出委托给日志系统实现。
- JCL(Jakarta Commons Logging):比较流行的日志框架,很多框架都依赖JCL,例如Spring等。
- SLF4j:提供新的API,初衷是配合Logback使用,但同时兼容Log4j。
日志系统:负责输出日志
- Log4j:经典的一种日志解决方案。内部把日志系统抽象封装成Logger 、appender 、pattern 等实现。我们可以通过配置文件轻松的实现日志系统的管理和多样化配置。
- Log4j2:Log4j的2.0版本,对Log4j进行了优化,比如支持参数API、支持异步appender、插件式架构等
- Logback:Log4j的替代产品,需要配合日志框架SLF4j使用
- JUL(java.util.logging):JDK提供的日志系统,较混乱,不常用
目前我们的应用大部分都是使用了SLF4j作为门面,然后搭配log4j或者log4j2日志系统。
下面将介绍slf4j + Log4j2 日志组件的引入、以及配置和使用
2、Maven依赖
</pre><pre name="code" class="html"><dependency> <groupId>org.slf4j</groupId> <artifactId>slf4j-api</artifactId> <version>1.7.13</version> </dependency> <dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-slf4j-impl</artifactId> <version>2.4.1</version> </dependency> <!--兼容log4j--> <dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-1.2-api</artifactId> <version>2.0</version> </dependency> <dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-api</artifactId> <version>2.4.1</version> </dependency> <dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-core</artifactId> <version>2.4.1</version> </dependency> <!--log4j2 异步appender需要--> <dependency> <groupId>com.lmax</groupId> <artifactId>disruptor</artifactId> <version>3.2.0</version> </dependency>
3、配置
- Appenders:也被称为Handlers,负责将日志事件记录到目标位置。在将日志事件输出之前,Appenders使用Layouts来对事件进行格式化处理。
- Layouts:也被称为Formatters,它负责对日志事件中的数据进行转换和格式化。Layouts决定了数据在一条日志记录中的最终形式。
- Loggers:Logger负责捕捉事件并将其发送给合适的Appender。
当Logger记录一个事件时,它将事件转发给适当的Appender。然后Appender使用Layout来对日志记录进行格式化,并将其发送给控制台、文件或者其它目标位置。另外,Filters可以让你进一步指定一个Appender是否可以应用在一条特定的日志记录上。在日志配置中,Filters并不是必需的,但可以让你更灵活地控制日志消息的流动。
3.1 Appender
3.1.1 ConsoleAppender
ConsoleAppender是最常用的Appenders之一,它只是将日志消息显示到控制台上。许多日志框架都将其作为默认的Appender,并且在基本的配置中进行预配置。例如,在Log4j中ConsoleAppender的配置参数如下所示。
参数 | 描述 |
---|---|
filter | 用于决定是否需要使用该Appender来处理日志事件 |
layout | 用于决定如何对日志记录进行格式化,默认情况下使用“%m%n”,它会在每一行显示一条日志记录 |
follow | 用于决定Appender是否需要了解输出(system.out或者system.err)的变化,默认情况是不需要跟踪这种变化 |
name | 用于设置Appender的名字 |
ignoreExceptions | 用于决定是否需要记录在日志事件处理过程中出现的异常 |
target | 用于指定输出目标位置,默认情况下使用SYSTEM_OUT,但也可以修改成SYSTEM_ERR |
<!--这个输出控制台的配置--> <Console name="Console" target="SYSTEM_OUT"> <!--控制台只输出level及以上级别的信息(onMatch),其他的直接拒绝(onMismatch)--> <ThresholdFilter level="DEBUG" onMatch="ACCEPT" onMismatch="DENY"/> <!--这个都知道是输出日志的格式--> <PatternLayout pattern="%d{HH:mm:ss.SSS} %-5level %class{36} %L %M - %msg%xEx%n"/> </Console>
3.1.2 FileAppender
FileAppenders将日志记录写入到文件中,它负责打开、关闭文件,向文件中追加日志记录,并对文件进行加锁,以免数据被破坏或者覆盖。
在Log4j中,如果想创建一个FileAppender,需要指定目标文件的名字,写入方式是追加还是覆盖,以及是否需要在写入日志时对文件进行加锁:
<File name="File" fileName="fileAppender.log" append="true" locking="true"> <PatternLayout pattern="%d{HH:mm:ss.SSS} %-5level %class{36} %L %M - %msg%xEx%n"/> </File>
3.1.3 RollingFileAppender
RollingFileAppender跟FileAppender的基本用法一样。但RollingFileAppender可以设置log文件的size(单位:KB/MB/GB)上限、数量上限,当log文件超过设置的size上限,会自动被压缩。RollingFileAppender可以理解为滚动输出日志,如果log4j 2记录的日志达到上限,旧的日志将被删除,腾出的空间用于记录新的日志。
<!--这个会打印出所有的信息,每次大小超过size,则这size大小的日志会自动存入按年份-月份建立的文件夹下面并进行压缩,作为存档--> <RollingFile name="RollingFile1" fileName="logs/log1.log" filePattern="logs/$${date:yyyy-MM}/log-%d{MM-dd-yyyy}-%i.log"> <PatternLayout pattern="%d{yyyy-MM-dd 'at' HH:mm:ss z} %-5level %class{36} %L %M - %msg%xEx%n"/> <SizeBasedTriggeringPolicy size="100MB"/> </RollingFile>
3.1.5 其他appender
我们已经介绍了一些经常用到的Appenders,还有很多其它Appender。它们添加了新功能或者在其它的一些Appender基础上实现了新功能。例如,Log4j中的RollingFileAppender扩展了FileAppender,它可以在满足特定条件时自动创建新的日志文件;SMTPAppender会将日志内容以邮件的形式发送出去;FailoverAppender会在处理日志的过程中,如果一个或者多个Appender失败,自动切换到其他Appender上。
如果想了解其他可以参考:https://logging.apache.org/log4j/2.0/manual/appenders.html
3.2 Layouts
Layouts将日志记录的内容从一种数据形式转换成另外一种。日志框架为纯文本、HTML、syslog、XML、JSON、序列化以及其它日志提供了Layouts。
这里贴一篇文章简单介绍下我们常用的PatternLayout :http://wiki.jikexueyuan.com/project/log4j/log4j-patternlayout.html
其他的layouts配置可以参考:https://logging.apache.org/log4j/2.0/manual/layouts.html
<PatternLayout pattern="%d{yyyy-MM-dd 'at' HH:mm:ss z} %-5level %class{36} %L %M - %msg%xEx%n"/>
3.3 Loggers
Logger负责捕捉事件并将其发送给合适的Appender,Logger之间是有继承关系的。总是存在一个rootLogger,即使没有显示配置也是存在的,并且默认输出级别为DEBUG,其它的logger都继承自这个rootLogger。
Log4J中的继承关系是通过名称可以看出来,如"A"、"A.B"、"A.B.C",A.B继承A,A.B.C继承A.B,比较类似于包名。
<loggers> <logger name="com.sankuai" level="info" includeLocation="true" additivity="true"> <appender-ref ref="RollingFile2"/> <appender-ref ref="RollingFile1"/> </logger> <logger name="com.sankuai.meituan" level="error" includeLocation="true" additivity="true"> <appender-ref ref="RollingFile2"/> <appender-ref ref="RollingFile1"/> </logger> <!--建立一个默认的root的logger--> <root level="error"> <appender-ref ref="Console"/> <appender-ref ref="RollingFile1"/> </root> </loggers>
additivity是 子Logger 是否继承 父Logger 的 输出源(appender) 的标志位。具体说,默认情况下 子Logger 会继承 父Logger 的appender,也就是说 子Logger 会在 父Logger 的appender里输出。若是additivity设为false,则 子Logger 只会在自己的appender里输出,而不会在 父Logger 的appender里输出。
3.4 日志级别
DEBUG , INFO ,WARN ,ERROR四种,分别对应Logger类的四种方法
debug(Object message ) ;
info(Object message ) ;
warn(Object message ) ;
error(Object message ) ;
如果设置级别为INFO,则优先级大于等于INFO级别(如:INFO、WARN、ERROR)的日志信息将可以被输出,
小于该级别的如:DEBUG将不会被输出
4、Log4j2 AsyncLogger与AsyncAppender
先上图
第一张图可以看出Log4j2的asyncLogger的性能较使用asyncAppender和sync模式有非常大的提升,特别是线程越多的时候。
第二张图是将log4j2的异步日志机制和其他日志系统进行对比,log4j2的asyncLogger 性能也是很有优势。
这里主要涉及了两个概念AsyncLogger和AysncAppender,是支持异步的Logger和Appender,下面分别简要介绍下这两个概念。
4.1 AsyncAppender
AsyncAppender持有其他的配置了aysnc的appender引用列表(appender需要通过配置注册成异步的),当其他的logger需要打日志的时候(logEvent事件),asyncAppender会接收logEvent,缓存到queue中,然后用单独的线程完成从queue中取logEvent打印到目的appender,这个逻辑比较简单,看下源码就能明白这个流程。ps. AsyncAppender是Log4j 和Log4j2 都有的,不是新东西,但从上面的性能对比上还是有一点点差异的,主要的原因是:(引用官方说法)Asynchronous
Appenders already existed in Log4j 1.x, but have been enhanced to flush to disk at the end of a batch (when the queue is empty).
关于AsyncAppender能提高性能的场景,可以看下这个篇文章。 http://littcai.iteye.com/blog/316605
如何配置一个AsyncAppender:
<?xml version="1.0" encoding="UTF-8"?> <Configuration status="warn" name="MyApp" packages=""> <Appenders> <File name="MyFile" fileName="logs/app.log"> <PatternLayout> <Pattern>%d %p %c{1.} [%t] %m%n</Pattern> </PatternLayout> </File> <Async name="Async"> <AppenderRef ref="MyFile"/> </Async> </Appenders> <Loggers> <Root level="error"> <AppenderRef ref="Async"/> </Root> </Loggers> </Configuration>
@Plugin(name = "Async", category = "Core", elementType = "appender", printObject = true) public final class AsyncAppender extends AbstractAppender { private static final long serialVersionUID = 1L; private static final int DEFAULT_QUEUE_SIZE = 128; private static final String SHUTDOWN = "Shutdown"; private static final AtomicLong THREAD_SEQUENCE = new AtomicLong(1); private static ThreadLocal<Boolean> isAppenderThread = new ThreadLocal<>(); private final BlockingQueue<Serializable> queue; private final int queueSize; private final boolean blocking; private final long shutdownTimeout; private final Configuration config; private final AppenderRef[] appenderRefs; private final String errorRef; private final boolean includeLocation; private AppenderControl errorAppender; private AsyncThread thread; private AsyncAppender(final String name, final Filter filter, final AppenderRef[] appenderRefs, final String errorRef, final int queueSize, final boolean blocking, final boolean ignoreExceptions, final long shutdownTimeout, final Configuration config, final boolean includeLocation) { super(name, filter, null, ignoreExceptions); this.queue = new ArrayBlockingQueue<>(queueSize); this.queueSize = queueSize; this.blocking = blocking; this.shutdownTimeout = shutdownTimeout; this.config = config; this.appenderRefs = appenderRefs; this.errorRef = errorRef; this.includeLocation = includeLocation; } @Override public void start() { final Map<String, Appender> map = config.getAppenders(); final List<AppenderControl> appenders = new ArrayList<>(); for (final AppenderRef appenderRef : appenderRefs) { final Appender appender = map.get(appenderRef.getRef()); if (appender != null) { appenders.add(new AppenderControl(appender, appenderRef.getLevel(), appenderRef.getFilter())); } else { LOGGER.error("No appender named {} was configured", appenderRef); } } if (errorRef != null) { final Appender appender = map.get(errorRef); if (appender != null) { errorAppender = new AppenderControl(appender, null, null); } else { LOGGER.error("Unable to set up error Appender. No appender named {} was configured", errorRef); } } if (appenders.size() > 0) { thread = new AsyncThread(appenders, queue); thread.setName("AsyncAppender-" + getName()); } else if (errorRef == null) { throw new ConfigurationException("No appenders are available for AsyncAppender " + getName()); } thread.start(); super.start(); } @Override public void stop() { super.stop(); LOGGER.trace("AsyncAppender stopping. Queue still has {} events.", queue.size()); thread.shutdown(); try { thread.join(shutdownTimeout); } catch (final InterruptedException ex) { LOGGER.warn("Interrupted while stopping AsyncAppender {}", getName()); } LOGGER.trace("AsyncAppender stopped. Queue has {} events.", queue.size()); } /** * Actual writing occurs here. * * @param logEvent The LogEvent. */ @Override public void append(LogEvent logEvent) { if (!isStarted()) { throw new IllegalStateException("AsyncAppender " + getName() + " is not active"); } if (!(logEvent instanceof Log4jLogEvent)) { if (!(logEvent instanceof RingBufferLogEvent)) { return; // only know how to Serialize Log4jLogEvents and RingBufferLogEvents } logEvent = ((RingBufferLogEvent) logEvent).createMemento(); } logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters final Log4jLogEvent coreEvent = (Log4jLogEvent) logEvent; boolean appendSuccessful = false; if (blocking) { if (isAppenderThread.get() == Boolean.TRUE && queue.remainingCapacity() == 0) { // LOG4J2-485: avoid deadlock that would result from trying // to add to a full queue from appender thread coreEvent.setEndOfBatch(false); // queue is definitely not empty! appendSuccessful = thread.callAppenders(coreEvent); } else { final Serializable serialized = Log4jLogEvent.serialize(coreEvent, includeLocation); try { // wait for free slots in the queue queue.put(serialized); appendSuccessful = true; } catch (final InterruptedException e) { // LOG4J2-1049: Some applications use Thread.interrupt() to send // messages between application threads. This does not necessarily // mean that the queue is full. To prevent dropping a log message, // quickly try to offer the event to the queue again. // (Yes, this means there is a possibility the same event is logged twice.) // // Finally, catching the InterruptedException means the // interrupted flag has been cleared on the current thread. // This may interfere with the application's expectation of // being interrupted, so when we are done, we set the interrupted // flag again. appendSuccessful = queue.offer(serialized); if (!appendSuccessful) { LOGGER.warn("Interrupted while waiting for a free slot in the AsyncAppender LogEvent-queue {}", getName()); } // set the interrupted flag again. Thread.currentThread().interrupt(); } } } else { appendSuccessful = queue.offer(Log4jLogEvent.serialize(coreEvent, includeLocation)); if (!appendSuccessful) { error("Appender " + getName() + " is unable to write primary appenders. queue is full"); } } if (!appendSuccessful && errorAppender != null) { errorAppender.callAppender(coreEvent); } } /** * Create an AsyncAppender. * * @param appenderRefs The Appenders to reference. * @param errorRef An optional Appender to write to if the queue is full or other errors occur. * @param blocking True if the Appender should wait when the queue is full. The default is true. * @param shutdownTimeout How many milliseconds the Appender should wait to flush outstanding log events * in the queue on shutdown. The default is zero which means to wait forever. * @param size The size of the event queue. The default is 128. * @param name The name of the Appender. * @param includeLocation whether to include location information. The default is false. * @param filter The Filter or null. * @param config The Configuration. * @param ignoreExceptions If {@code "true"} (default) exceptions encountered when appending events are logged; * otherwise they are propagated to the caller. * @return The AsyncAppender. */ @PluginFactory public static AsyncAppender createAppender(@PluginElement("AppenderRef") final AppenderRef[] appenderRefs, @PluginAttribute("errorRef") @PluginAliases("error-ref") final String errorRef, @PluginAttribute(value = "blocking", defaultBoolean = true) final boolean blocking, @PluginAttribute(value = "shutdownTimeout", defaultLong = 0L) final long shutdownTimeout, @PluginAttribute(value = "bufferSize", defaultInt = DEFAULT_QUEUE_SIZE) final int size, @PluginAttribute("name") final String name, @PluginAttribute(value = "includeLocation", defaultBoolean = false) final boolean includeLocation, @PluginElement("Filter") final Filter filter, @PluginConfiguration final Configuration config, @PluginAttribute(value = "ignoreExceptions", defaultBoolean = true) final boolean ignoreExceptions) { if (name == null) { LOGGER.error("No name provided for AsyncAppender"); return null; } if (appenderRefs == null) { LOGGER.error("No appender references provided to AsyncAppender {}", name); } return new AsyncAppender(name, filter, appenderRefs, errorRef, size, blocking, ignoreExceptions, shutdownTimeout, config, includeLocation); } /** * Thread that calls the Appenders. */ private class AsyncThread extends Thread { private volatile boolean shutdown = false; private final List<AppenderControl> appenders; private final BlockingQueue<Serializable> queue; public AsyncThread(final List<AppenderControl> appenders, final BlockingQueue<Serializable> queue) { this.appenders = appenders; this.queue = queue; setDaemon(true); setName("AsyncAppenderThread" + THREAD_SEQUENCE.getAndIncrement()); } @Override public void run() { isAppenderThread.set(Boolean.TRUE); // LOG4J2-485 while (!shutdown) { Serializable s; try { s = queue.take(); if (s != null && s instanceof String && SHUTDOWN.equals(s.toString())) { shutdown = true; continue; } } catch (final InterruptedException ex) { break; // LOG4J2-830 } final Log4jLogEvent event = Log4jLogEvent.deserialize(s); event.setEndOfBatch(queue.isEmpty()); final boolean success = callAppenders(event); if (!success && errorAppender != null) { try { errorAppender.callAppender(event); } catch (final Exception ex) { // Silently accept the error. } } } // Process any remaining items in the queue. LOGGER.trace("AsyncAppender.AsyncThread shutting down. Processing remaining {} queue events.", queue.size()); int count = 0; int ignored = 0; while (!queue.isEmpty()) { try { final Serializable s = queue.take(); if (Log4jLogEvent.canDeserialize(s)) { final Log4jLogEvent event = Log4jLogEvent.deserialize(s); event.setEndOfBatch(queue.isEmpty()); callAppenders(event); count++; } else { ignored++; LOGGER.trace("Ignoring event of class {}", s.getClass().getName()); } } catch (final InterruptedException ex) { // May have been interrupted to shut down. // Here we ignore interrupts and try to process all remaining events. } } LOGGER.trace("AsyncAppender.AsyncThread stopped. Queue has {} events remaining. " + "Processed {} and ignored {} events since shutdown started.", queue.size(), count, ignored); } /** * Calls {@link AppenderControl#callAppender(LogEvent) callAppender} on all registered {@code AppenderControl} * objects, and returns {@code true} if at least one appender call was successful, {@code false} otherwise. Any * exceptions are silently ignored. * * @param event the event to forward to the registered appenders * @return {@code true} if at least one appender call succeeded, {@code false} otherwise */ boolean callAppenders(final Log4jLogEvent event) { boolean success = false; for (final AppenderControl control : appenders) { try { control.callAppender(event); success = true; } catch (final Exception ex) { // If no appender is successful the error appender will get it. } } return success; } public void shutdown() { shutdown = true; if (queue.isEmpty()) { queue.offer(SHUTDOWN); } } } /** * Returns the names of the appenders that this asyncAppender delegates to as an array of Strings. * * @return the names of the sink appenders */ public String[] getAppenderRefStrings() { final String[] result = new String[appenderRefs.length]; for (int i = 0; i < result.length; i++) { result[i] = appenderRefs[i].getRef(); } return result; } /** * Returns {@code true} if this AsyncAppender will take a snapshot of the stack with every log event to determine * the class and method where the logging call was made. * * @return {@code true} if location is included with every event, {@code false} otherwise */ public boolean isIncludeLocation() { return includeLocation; } /** * Returns {@code true} if this AsyncAppender will block when the queue is full, or {@code false} if events are * dropped when the queue is full. * * @return whether this AsyncAppender will block or drop events when the queue is full. */ public boolean isBlocking() { return blocking; } /** * Returns the name of the appender that any errors are logged to or {@code null}. * * @return the name of the appender that any errors are logged to or {@code null} */ public String getErrorRef() { return errorRef; } public int getQueueCapacity() { return queueSize; } public int getQueueRemainingCapacity() { return queue.remainingCapacity(); } }
AsyncLogger是Log4j2引入的新特性,业务代码调用Logger.log的时候直接返回,而不需要等到appender输出到日志目的地后才返回。Log4j2的Asynclogger是通过LMAX Disruptor代替queue实现的异步(无锁的并发框架,http://ifeve.com/disruptor/,Disruptor简介),达到更高的并发和lower
latency。
4.2 AsyncLogger
1,Disruptor使用了一个RingBuffer替代队列,用生产者消费者指针替代锁。 2,生产者消费者指针使用CPU支持的整数自增,无需加锁并且速度很快。Java的实现在Unsafe package中。 |
尽管AsyncLogger 能够大幅度的提高性能,但是也会带来一些问题,下面是翻译官方的文档的Trade-offs:
Benefits
- Higher throughput,达到相对于sync logger的6-68倍的吞吐量
- Lower logging latency,latency是调用Logger.log直到return的时间,asyncLogger的latency比syncLogger以及基于queue的aysncAppender都要低,不仅平均latency低,而且99%、95%latency 也都低于后两者
- 降低极端大的日志量时候的延迟尖峰
Drawbacks
- Error handling, 如果在打印日志的时候出现错误,使用asyncLogger,业务是不知道异常的(可以通过配置ExceptionHandler处理异常),如果打印日志是业务逻辑的一部分,不建议使用asyncLogger
- 打印一些可变的内容的时候,使用asyncLogger 会出现问题。大部分时间,不需要担心这点,Log4j确保了类似于 logger.debug("My object is {}", myObject),使用myObject在打印日志的时刻的版本打印(Log4j 所有打印都日志都是封装到Message的实现类里,存储在
final String里),不管之后是否改变。但是log4j也支持一些了可变的Message,如 MapMessage and StructuredDataMessage ,这些如果在打印日志时候改变,就有问题了
全局配置异步Logger
配置所有Logger都为AsyncLogger,只需要增加disruptor包,然后配置一个system property,-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector,Log4j的配置文件不需要修改。
混合使用同步和异步Logger
单独配置某个logger为async的,通过<asyncRoot>或者<asyncLogger>
<Configuration status="WARN"> <Appenders> <!-- Async Loggers will auto-flush in batches, so switch off immediateFlush. --> <RandomAccessFile name="RandomAccessFile" fileName="asyncWithLocation.log" immediateFlush="false" append="false"> <PatternLayout> <Pattern>%d %p %class{1.} [%t] %location %m %ex%n</Pattern> </PatternLayout> </RandomAccessFile> </Appenders> <Loggers> <!-- pattern layout actually uses location, so we need to include it --> <AsyncLogger name="com.foo.Bar" level="trace" includeLocation="true"> <AppenderRef ref="RandomAccessFile"/> </AsyncLogger> <Root level="info" includeLocation="true"> <AppenderRef ref="RandomAccessFile"/> </Root> </Loggers> </Configuration>
ps. location的问题
当layouts配置了输出%C or $class, %F or %file, %l or %location, %L or %line, %M or %method,或者HTML locationInfo, log4j会获取location的一个快照,而这对于sync
和async的logger都是一个耗时的操作(官方文档上说syncLogger会慢1.3~5倍,async会慢4-20倍),所以默认都是不会输出location信息,除非Logger配置了includeLocation="true"(官方文档这么说的,但是我测试的是默认是输出的,不管了,反正当日志出现慢的时候,可以考虑通过配置includeLocation控制是否输出location信息)。