目前java應用日志收集都是采用日志框架(slf4j、apache commons logging)+日志系統(log4j、log4j2、LogBack、JUL等)的方式。而針對在分布式環境需要實時分析統計的日志,一般采用apache flume、facebook scribe等分布式日志收集系統。
日志框架:提供日志調用的接口,實際的日志輸出委托給日志系統實現。
日志系統:負責輸出日志
目前我們的應用大部分都是使用了SLF4j作為門面,然後搭配log4j或者log4j2日志系統。
下面將介紹slf4j + Log4j2 日志組件的引入、以及配置和使用
org.slf4j slf4j-api1.7.13 org.apache.logging.log4j log4j-slf4j-impl2.4.1 org.apache.logging.log4j log4j-1.2-api2.0 org.apache.logging.log4j log4j-api2.4.1 org.apache.logging.log4j log4j-core2.4.1 com.lmax disruptor3.2.0
當Logger記錄一個事件時,它將事件轉發給適當的Appender。然後Appender使用Layout來對日志記錄進行格式化,並將其發送給控制台、文件或者其它目標位置。另外,Filters可以讓你進一步指定一個Appender是否可以應用在一條特定的日志記錄上。在日志配置中,Filters並不是必需的,但可以讓你更靈活地控制日志消息的流動。
ConsoleAppender是最常用的Appenders之一,它只是將日志消息顯示到控制台上。許多日志框架都將其作為默認的Appender,並且在基本的配置中進行預配置。例如,在Log4j中ConsoleAppender的配置參數如下所示。
FileAppenders將日志記錄寫入到文件中,它負責打開、關閉文件,向文件中追加日志記錄,並對文件進行加鎖,以免數據被破壞或者覆蓋。
在Log4j中,如果想創建一個FileAppender,需要指定目標文件的名字,寫入方式是追加還是覆蓋,以及是否需要在寫入日志時對文件進行加鎖:
RollingFileAppender跟FileAppender的基本用法一樣。但RollingFileAppender可以設置log文件的size(單位:KB/MB/GB)上限、數量上限,當log文件超過設置的size上限,會自動被壓縮。RollingFileAppender可以理解為滾動輸出日志,如果log4j2記錄的日志達到上限,舊的日志將被刪除,騰出的空間用於記錄新的日志。
我們已經介紹了一些經常用到的Appenders,還有很多其它Appender。它們添加了新功能或者在其它的一些Appender基礎上實現了新功能。例如,Log4j中的RollingFileAppender擴展了FileAppender,它可以在滿足特定條件時自動創建新的日志文件;SMTPAppender會將日志內容以郵件的形式發送出去;FailoverAppender會在處理日志的過程中,如果一個或者多個Appender失敗,自動切換到其他Appender上。
Layouts將日志記錄的內容從一種數據形式轉換成另外一種。日志框架為純文本、HTML、syslog、XML、JSON、序列化以及其它日志提供了Layouts。
Logger負責捕捉事件並將其發送給合適的Appender,Logger之間是有繼承關系的。總是存在一個rootLogger,即使沒有顯示配置也是存在的,並且默認輸出級別為DEBUG,其它的logger都繼承自這個rootLogger。
Log4J中的繼承關系是通過名稱可以看出來,如"A"、"A.B"、"A.B.C",A.B繼承A,A.B.C繼承A.B,比較類似於包名。
DEBUG , INFO ,WARN ,ERROR四種,分別對應Logger類的四種方法
debug(Object message ) ;
info(Object message ) ;
warn(Object message ) ;
error(Object message ) ;
如果設置級別為INFO,則優先級大於等於INFO級別(如:INFO、WARN、ERROR)的日志信息將可以被輸出,
小於該級別的如:DEBUG將不會被輸出
先上圖
第一張圖可以看出Log4j2的asyncLogger的性能較使用asyncAppender和sync模式有非常大的提升,特別是線程越多的時候。
第二張圖是將log4j2的異步日志機制和其他日志系統進行對比,log4j2的asyncLogger 性能也是很有優勢。
這裡主要涉及了兩個概念AsyncLogger和AysncAppender,是支持異步的Logger和Appender,下面分別簡要介紹下這兩個概念。
AsyncAppender持有其他的配置了aysnc的appender引用列表(appender需要通過配置注冊成異步的),當其他的logger需要打日志的時候(logEvent事件),asyncAppender會接收logEvent,緩存到queue中,然後用單獨的線程完成從queue中取logEvent打印到目的appender,這個邏輯比較簡單,看下源碼就能明白這個流程。ps. AsyncAppender是Log4j 和Log4j2 都有的,不是新東西,但從上面的性能對比上還是有一點點差異的,主要的原因是:(引用官方說法)Asynchronous Appendersalready 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:
%d %p %c{1.} [%t] %m%n
@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 ThreadLocalisAppenderThread = new ThreadLocal<>(); private final BlockingQueue 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 map = config.getAppenders(); final List 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 appenders; private final BlockingQueue queue; public AsyncThread(final List appenders, final BlockingQueue 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(); } }
1,Disruptor使用了一個RingBuffer替代隊列,用生產者消費者指針替代鎖。
2,生產者消費者指針使用CPU支持的整數自增,無需加鎖並且速度很快。Java的實現在Unsafe package中。
盡管AsyncLogger 能夠大幅度的提高性能,但是也會帶來一些問題,下面是翻譯官方的文檔的Trade-offs:
Benefits
Drawbacks
全局配置異步Logger
配置所有Logger都為AsyncLogger,只需要增加disruptor包,然後配置一個system property,-DLog4jContextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector,Log4j的配置文件不需要修改。
混合使用同步和異步Logger
單獨配置某個logger為async的,通過或者
%d %p %class{1.} [%t] %location %m %ex%n
當layouts配置了輸出%C or $class, %F or %file, %l or %location, %L or %line, %M or %method,或者HTMLlocationInfo,log4j會獲取location的一個快照,而這對於sync 和async的logger都是一個耗時的操作(官方文檔上說syncLogger會慢1.3~5倍,async會慢4-20倍),所以默認都是不會輸出location信息,除非Logger配置了includeLocation="true"(官方文檔這麼說的,但是我測試的是默認是輸出的,不管了,反正當日志出現慢的時候,可以考慮通過配置includeLocation控制是否輸出location信息)。