Java日志框架
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信息)。
posted on 2017-08-08 09:42 gavanwanggw 阅读(7180) 评论(0) 编辑 收藏 举报