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信息)。