探索Java日志的奥秘：底层日志系统-log4j2
生活随笔
收集整理的這篇文章主要介紹了
探索Java日志的奥秘：底层日志系统-log4j2
小編覺得挺不錯的,現在分享給大家,幫大家做個參考.
前言
log4j2是apache在log4j的基礎上，參考logback架構實現的一套新的日志系統（我感覺是apache害怕logback了）。
log4j2的官方文檔上寫著一些它的優點：
- 在擁有全部logback特性的情況下，還修復了一些隱藏問題
- API 分離：現在log4j2也是門面模式使用日志，默認的日志實現是log4j2，當然你也可以用logback（應該沒有人會這么做）
- 性能提升：log4j2包含下一代基于LMAX Disruptor library的異步logger，在多線程場景下，擁有18倍于log4j和logback的性能
- 多API支持：log4j2提供Log4j 1.2, SLF4J, Commons Logging and java.util.logging (JUL) 的API支持
- 避免鎖定：使用Log4j2 API的應用程序始終可以選擇使用任何符合SLF4J的庫作為log4j-to-slf4j適配器的記錄器實現
- 自動重新加載配置：與Logback一樣，Log4j 2可以在修改時自動重新加載其配置。與Logback不同，它會在重新配置發生時不會丟失日志事件。
- 高級過濾： 與Logback一樣，Log4j 2支持基于Log事件中的上下文數據，標記，正則表達式和其他組件進行過濾。
- 插件架構： Log4j使用插件模式配置組件。因此，您無需編寫代碼來創建和配置Appender，Layout，Pattern Converter等。Log4j自動識別插件并在配置引用它們時使用它們。
- 屬性支持：您可以在配置中引用屬性，Log4j將直接替換它們，或者Log4j將它們傳遞給將動態解析它們的底層組件。
- Java 8 Lambda支持
- 自定義日志級別
- 產生垃圾少：在穩態日志記錄期間，Log4j 2 在獨立應用程序中是無垃圾的，在Web應用程序中是低垃圾。這減少了垃圾收集器的壓力，并且可以提供更好的響應時間性能。
- 和應用server集成：版本2.10.0引入了一個模塊log4j-appserver，以改進與Apache Tomcat和Eclipse Jetty的集成。
Log4j2類圖：
這次從四個地方去探索源碼：啟動，配置，異步，插件化
源碼探索
啟動
log4j2的關鍵組件
- LogManager
根據配置指定LogContexFactory，初始化對應的LoggerContext
- LoggerContext
1、解析配置文件，解析為對應的java對象。
2、通過LoggerRegisty緩存Logger配置
3、Configuration配置信息
4、start方法解析配置文件，轉化為對應的java對象
5、通過getLogger獲取logger對象
- Logger
LogManaer
該組件是Log4J啟動的入口，后續的LoggerContext以及Logger都是通過調用LogManager的靜態方法獲得。我們可以使用下面的代碼獲取Logger
Logger logger = LogManager.getLogger();可以看出LogManager是十分關鍵的組件，因此在這個小節中我們詳細分析LogManager的啟動流程。
LogManager啟動的入口是下面的static代碼塊：
這段靜態代碼段主要分為下面的幾個步驟：
根據配置文件載入LoggerContextFactory
// Shortcut binding to force a specific logging implementation.final PropertiesUtil managerProps = PropertiesUtil.getProperties();final String factoryClassName = managerProps.getStringProperty(FACTORY_PROPERTY_NAME);if (factoryClassName != null) {try {factory = LoaderUtil.newCheckedInstanceOf(factoryClassName, LoggerContextFactory.class);} catch (final ClassNotFoundException cnfe) {LOGGER.error("Unable to locate configured LoggerContextFactory {}", factoryClassName);} catch (final Exception ex) {LOGGER.error("Unable to create configured LoggerContextFactory {}", factoryClassName, ex);}}在這段邏輯中，LogManager優先通過配置文件”log4j2.component.properties”通過配置項”log4j2.loggerContextFactory”來獲取LoggerContextFactory，如果用戶做了對應的配置，通過newCheckedInstanceOf方法實例化LoggerContextFactory的對象，最終的實現方式為：
public static <T> T newInstanceOf(final Class<T> clazz)throws InstantiationException, IllegalAccessException, InvocationTargetException {try {return clazz.getConstructor().newInstance();} catch (final NoSuchMethodException ignored) {// FIXME: looking at the code for Class.newInstance(), this seems to do the same thing as abovereturn clazz.newInstance();}}在默認情況下，不存在初始的默認配置文件log4j2.component.properties，因此需要從其他途徑獲取LoggerContextFactory。
通過Provider實例化LoggerContextFactory對象
代碼：
if (factory == null) {final SortedMap<Integer, LoggerContextFactory> factories = new TreeMap<>();// note that the following initial call to ProviderUtil may block until a Provider has been installed when// running in an OSGi environmentif (ProviderUtil.hasProviders()) {for (final Provider provider : ProviderUtil.getProviders()) {final Class<? extends LoggerContextFactory> factoryClass = provider.loadLoggerContextFactory();if (factoryClass != null) {try {factories.put(provider.getPriority(), factoryClass.newInstance());} catch (final Exception e) {LOGGER.error("Unable to create class {} specified in provider URL {}", factoryClass.getName(), provider.getUrl(), e);}}}if (factories.isEmpty()) {LOGGER.error("Log4j2 could not find a logging implementation. "+ "Please add log4j-core to the classpath. Using SimpleLogger to log to the console...");factory = new SimpleLoggerContextFactory();} else if (factories.size() == 1) {factory = factories.get(factories.lastKey());} else {final StringBuilder sb = new StringBuilder("Multiple logging implementations found: \n");for (final Map.Entry<Integer, LoggerContextFactory> entry : factories.entrySet()) {sb.append("Factory: ").append(entry.getValue().getClass().getName());sb.append(", Weighting: ").append(entry.getKey()).append('\n');}factory = factories.get(factories.lastKey());sb.append("Using factory: ").append(factory.getClass().getName());LOGGER.warn(sb.toString());}} else {LOGGER.error("Log4j2 could not find a logging implementation. "+ "Please add log4j-core to the classpath. Using SimpleLogger to log to the console...");factory = new SimpleLoggerContextFactory();}}這里比較有意思的是hasProviders和getProviders都會通過線程安全的方式去懶加載ProviderUtil這個對象。跟進lazyInit方法：
protected static void lazyInit() {//noinspection DoubleCheckedLockingif (INSTANCE == null) {try {STARTUP_LOCK.lockInterruptibly();if (INSTANCE == null) {INSTANCE = new ProviderUtil();}} catch (final InterruptedException e) {LOGGER.fatal("Interrupted before Log4j Providers could be loaded.", e);Thread.currentThread().interrupt();} finally {STARTUP_LOCK.unlock();}}}再看構造方法：
private ProviderUtil() {for (final LoaderUtil.UrlResource resource : LoaderUtil.findUrlResources(PROVIDER_RESOURCE)) {loadProvider(resource.getUrl(), resource.getClassLoader());}}這里的懶加載其實就是懶加載Provider對象。在創建新的providerUtil實例的過程中就會直接實例化provider對象，其過程是先通過getClassLoaders方法獲取provider的類加載器，然后通過loadProviders(classLoader);加載類。在providerUtil實例化的最后，會統一查找”META-INF/log4j-provider.properties”文件中對應的provider的url，會考慮從遠程加載provider。而loadProviders方法就是在ProviderUtil的PROVIDERS列表中添加對一個的provider。可以看到默認的provider是org.apache.logging.log4j.core.impl.Log4jContextFactory
LoggerContextFactory = org.apache.logging.log4j.core.impl.Log4jContextFactory Log4jAPIVersion = 2.1.0 FactoryPriority= 10很有意思的是這里懶加載加上了鎖，而且使用的是
lockInterruptibly這個方法。lockInterruptibly和lock的區別如下：
lock 與 lockInterruptibly比較區別在于：
lock 優先考慮獲取鎖，待獲取鎖成功后，才響應中斷。
lockInterruptibly 優先考慮響應中斷，而不是響應鎖的普通獲取或重入獲取。
ReentrantLock.lockInterruptibly允許在等待時由其它線程調用等待線程的
Thread.interrupt 方法來中斷等待線程的等待而直接返回，這時不用獲取鎖，而會拋出一個InterruptedException。 ReentrantLock.lock方法不允許Thread.interrupt中斷,即使檢測到Thread.isInterrupted,一樣會繼續嘗試獲取鎖，失敗則繼續休眠。只是在最后獲取鎖成功后再把當前線程置為interrupted狀態,然后再中斷線程。
上面有一句注釋值得注意：
/*** Guards the ProviderUtil singleton instance from lazy initialization. This is primarily used for OSGi support.** @since 2.1*/protected static final Lock STARTUP_LOCK = new ReentrantLock();// STARTUP_LOCK guards INSTANCE for lazy initialization; this allows the OSGi Activator to pause the startup and// wait for a Provider to be installed. See LOG4J2-373private static volatile ProviderUtil INSTANCE;原來這里是為了讓osgi可以阻止啟動。
再回到logManager：
可以看到在加載完Provider之后，會做factory的綁定：
到這里，logmanager的啟動流程就結束了。
配置
在不使用slf4j的情況下，我們獲取logger的方式是這樣的：
Logger logger = logManager.getLogger(xx.class)跟進getLogger方法：
public static Logger getLogger(final Class<?> clazz) {final Class<?> cls = callerClass(clazz);return getContext(cls.getClassLoader(), false).getLogger(toLoggerName(cls));}這里有一個getContext方法，跟進，
public static LoggerContext getContext(final ClassLoader loader, final boolean currentContext) {try {return factory.getContext(FQCN, loader, null, currentContext);} catch (final IllegalStateException ex) {LOGGER.warn(ex.getMessage() + " Using SimpleLogger");return new SimpleLoggerContextFactory().getContext(FQCN, loader, null, currentContext);}}上文提到factory的具體實現是Log4jContextFactory，跟進getContext
方法：
直接看start：
public void start() {LOGGER.debug("Starting LoggerContext[name={}, {}]...", getName(), this);if (PropertiesUtil.getProperties().getBooleanProperty("log4j.LoggerContext.stacktrace.on.start", false)) {LOGGER.debug("Stack trace to locate invoker",new Exception("Not a real error, showing stack trace to locate invoker"));}if (configLock.tryLock()) {try {if (this.isInitialized() || this.isStopped()) {this.setStarting();reconfigure();if (this.configuration.isShutdownHookEnabled()) {setUpShutdownHook();}this.setStarted();}} finally {configLock.unlock();}}LOGGER.debug("LoggerContext[name={}, {}] started OK.", getName(), this);}發現其中的核心方法是reconfigure方法，繼續跟進：
private void reconfigure(final URI configURI) {final ClassLoader cl = ClassLoader.class.isInstance(externalContext) ? (ClassLoader) externalContext : null;LOGGER.debug("Reconfiguration started for context[name={}] at URI {} ({}) with optional ClassLoader: {}",contextName, configURI, this, cl);final Configuration instance = ConfigurationFactory.getInstance().getConfiguration(this, contextName, configURI, cl);if (instance == null) {LOGGER.error("Reconfiguration failed: No configuration found for '{}' at '{}' in '{}'", contextName, configURI, cl);} else {setConfiguration(instance);/** instance.start(); Configuration old = setConfiguration(instance); updateLoggers(); if (old != null) {* old.stop(); }*/final String location = configuration == null ? "?" : String.valueOf(configuration.getConfigurationSource());LOGGER.debug("Reconfiguration complete for context[name={}] at URI {} ({}) with optional ClassLoader: {}",contextName, location, this, cl);}}可以看到每一個configuration都是從ConfigurationFactory拿出來的，我們先看看這個類的getInstance看看：
public static ConfigurationFactory getInstance() {// volatile works in Java 1.6+, so double-checked locking also works properly//noinspection DoubleCheckedLockingif (factories == null) {LOCK.lock();try {if (factories == null) {final List<ConfigurationFactory> list = new ArrayList<ConfigurationFactory>();final String factoryClass = PropertiesUtil.getProperties().getStringProperty(CONFIGURATION_FACTORY_PROPERTY);if (factoryClass != null) {addFactory(list, factoryClass);}final PluginManager manager = new PluginManager(CATEGORY);manager.collectPlugins();final Map<String, PluginType<?>> plugins = manager.getPlugins();final List<Class<? extends ConfigurationFactory>> ordered =new ArrayList<Class<? extends ConfigurationFactory>>(plugins.size());for (final PluginType<?> type : plugins.values()) {try {ordered.add(type.getPluginClass().asSubclass(ConfigurationFactory.class));} catch (final Exception ex) {LOGGER.warn("Unable to add class {}", type.getPluginClass(), ex);}}Collections.sort(ordered, OrderComparator.getInstance());for (final Class<? extends ConfigurationFactory> clazz : ordered) {addFactory(list, clazz);}// see above comments about double-checked locking//noinspection NonThreadSafeLazyInitializationfactories = Collections.unmodifiableList(list);}} finally {LOCK.unlock();}}LOGGER.debug("Using configurationFactory {}", configFactory);return configFactory;}這里可以看到ConfigurationFactory中利用了PluginManager來進行初始化，PluginManager會將ConfigurationFactory的子類加載進來，默認使用的XmlConfigurationFactory，JsonConfigurationFactory，YamlConfigurationFactory這三個子類，這里插件化加載暫時按下不表。
回到reconfigure這個方法，我們看到獲取ConfigurationFactory實例之后會去調用getConfiguration方法：
跟進getConfiguration，這里值得注意的是有很多個getConfiguration，注意甄別，如果不確定的話可以通過debug的方式來確定。
public Configuration getConfiguration(final String name, final URI configLocation) {if (configLocation == null) {final String config = this.substitutor.replace(PropertiesUtil.getProperties().getStringProperty(CONFIGURATION_FILE_PROPERTY));if (config != null) {ConfigurationSource source = null;try {source = getInputFromUri(FileUtils.getCorrectedFilePathUri(config));} catch (final Exception ex) {// Ignore the error and try as a String.LOGGER.catching(Level.DEBUG, ex);}if (source == null) {final ClassLoader loader = LoaderUtil.getThreadContextClassLoader();source = getInputFromString(config, loader);}if (source != null) {for (final ConfigurationFactory factory : factories) {final String[] types = factory.getSupportedTypes();if (types != null) {for (final String type : types) {if (type.equals("*") || config.endsWith(type)) {final Configuration c = factory.getConfiguration(source);if (c != null) {return c;}}}}}}}} else {for (final ConfigurationFactory factory : factories) {final String[] types = factory.getSupportedTypes();if (types != null) {for (final String type : types) {if (type.equals("*") || configLocation.toString().endsWith(type)) {final Configuration config = factory.getConfiguration(name, configLocation);if (config != null) {return config;}}}}}}Configuration config = getConfiguration(true, name);if (config == null) {config = getConfiguration(true, null);if (config == null) {config = getConfiguration(false, name);if (config == null) {config = getConfiguration(false, null);}}}if (config != null) {return config;}LOGGER.error("No log4j2 configuration file found. Using default configuration: logging only errors to the console.");return new DefaultConfiguration();}這里就會根據之前加載進來的factory進行配置的獲取，具體的不再解析。
回到reconfigure，之后的步驟就是setConfiguration，入參就是剛才獲取的config
這個方法最重要的步驟就是config.start,這才是真正做配置解析的
public void start() {LOGGER.debug("Starting configuration {}", this);this.setStarting();pluginManager.collectPlugins(pluginPackages);final PluginManager levelPlugins = new PluginManager(Level.CATEGORY);levelPlugins.collectPlugins(pluginPackages);final Map<String, PluginType<?>> plugins = levelPlugins.getPlugins();if (plugins != null) {for (final PluginType<?> type : plugins.values()) {try {// Cause the class to be initialized if it isn't already.Loader.initializeClass(type.getPluginClass().getName(), type.getPluginClass().getClassLoader());} catch (final Exception e) {LOGGER.error("Unable to initialize {} due to {}", type.getPluginClass().getName(), e.getClass().getSimpleName(), e);}}}setup();setupAdvertisement();doConfigure();final Set<LoggerConfig> alreadyStarted = new HashSet<LoggerConfig>();for (final LoggerConfig logger : loggers.values()) {logger.start();alreadyStarted.add(logger);}for (final Appender appender : appenders.values()) {appender.start();}if (!alreadyStarted.contains(root)) { // LOG4J2-392root.start(); // LOG4J2-336}super.start();LOGGER.debug("Started configuration {} OK.", this);}這里面有如下步驟：
先看一下初始化，也就是setup這個方法，setup是一個需要被復寫的方法，我們以XMLConfiguration作為例子，
@Overridepublic void setup() {if (rootElement == null) {LOGGER.error("No logging configuration");return;}constructHierarchy(rootNode, rootElement);if (status.size() > 0) {for (final Status s : status) {LOGGER.error("Error processing element {}: {}", s.name, s.errorType);}return;}rootElement = null;}發現這里面有一個比較重要的方法constructHierarchy，跟進：
private void constructHierarchy(final Node node, final Element element) {processAttributes(node, element);final StringBuilder buffer = new StringBuilder();final NodeList list = element.getChildNodes();final List<Node> children = node.getChildren();for (int i = 0; i < list.getLength(); i++) {final org.w3c.dom.Node w3cNode = list.item(i);if (w3cNode instanceof Element) {final Element child = (Element) w3cNode;final String name = getType(child);final PluginType<?> type = pluginManager.getPluginType(name);final Node childNode = new Node(node, name, type);constructHierarchy(childNode, child);if (type == null) {final String value = childNode.getValue();if (!childNode.hasChildren() && value != null) {node.getAttributes().put(name, value);} else {status.add(new Status(name, element, ErrorType.CLASS_NOT_FOUND));}} else {children.add(childNode);}} else if (w3cNode instanceof Text) {final Text data = (Text) w3cNode;buffer.append(data.getData());}}final String text = buffer.toString().trim();if (text.length() > 0 || (!node.hasChildren() && !node.isRoot())) {node.setValue(text);}}發現這個就是一個樹遍歷的過程。誠然，配置文件是以xml的形式給出的，xml的結構就是一個樹形結構。回到start方法，跟進doConfiguration：
protected void doConfigure() {if (rootNode.hasChildren() && rootNode.getChildren().get(0).getName().equalsIgnoreCase("Properties")) {final Node first = rootNode.getChildren().get(0);createConfiguration(first, null);if (first.getObject() != null) {subst.setVariableResolver((StrLookup) first.getObject());}} else {final Map<String, String> map = this.getComponent(CONTEXT_PROPERTIES);final StrLookup lookup = map == null ? null : new MapLookup(map);subst.setVariableResolver(new Interpolator(lookup, pluginPackages));}boolean setLoggers = false;boolean setRoot = false;for (final Node child : rootNode.getChildren()) {if (child.getName().equalsIgnoreCase("Properties")) {if (tempLookup == subst.getVariableResolver()) {LOGGER.error("Properties declaration must be the first element in the configuration");}continue;}createConfiguration(child, null);if (child.getObject() == null) {continue;}if (child.getName().equalsIgnoreCase("Appenders")) {appenders = child.getObject();} else if (child.isInstanceOf(Filter.class)) {addFilter(child.getObject(Filter.class));} else if (child.getName().equalsIgnoreCase("Loggers")) {final Loggers l = child.getObject();loggers = l.getMap();setLoggers = true;if (l.getRoot() != null) {root = l.getRoot();setRoot = true;}} else if (child.getName().equalsIgnoreCase("CustomLevels")) {customLevels = child.getObject(CustomLevels.class).getCustomLevels();} else if (child.isInstanceOf(CustomLevelConfig.class)) {final List<CustomLevelConfig> copy = new ArrayList<CustomLevelConfig>(customLevels);copy.add(child.getObject(CustomLevelConfig.class));customLevels = copy;} else {LOGGER.error("Unknown object \"{}\" of type {} is ignored.", child.getName(),child.getObject().getClass().getName());}}if (!setLoggers) {LOGGER.warn("No Loggers were configured, using default. Is the Loggers element missing?");setToDefault();return;} else if (!setRoot) {LOGGER.warn("No Root logger was configured, creating default ERROR-level Root logger with Console appender");setToDefault();// return; // LOG4J2-219: creating default root=ok, but don't exclude configured Loggers}for (final Map.Entry<String, LoggerConfig> entry : loggers.entrySet()) {final LoggerConfig l = entry.getValue();for (final AppenderRef ref : l.getAppenderRefs()) {final Appender app = appenders.get(ref.getRef());if (app != null) {l.addAppender(app, ref.getLevel(), ref.getFilter());} else {LOGGER.error("Unable to locate appender {} for logger {}", ref.getRef(), l.getName());}}}setParents();}發現就是對剛剛獲取的configuration進行解析，然后塞進正確的地方。回到start方法，可以看到昨晚配置之后就是開啟logger和appender了。
異步
AsyncAppender
log4j2突出于其他日志的優勢，異步日志實現。我們先從日志打印看進去。找到Logger，隨便找一個log日志的方法。
public void debug(final Marker marker, final Message msg) {logIfEnabled(FQCN, Level.DEBUG, marker, msg, msg != null ? msg.getThrowable() : null);}一路跟進
@PerformanceSensitive// NOTE: This is a hot method. Current implementation compiles to 29 bytes of byte code.// This is within the 35 byte MaxInlineSize threshold. Modify with care!private void logMessageTrackRecursion(final String fqcn,final Level level,final Marker marker,final Message msg,final Throwable throwable) {try {incrementRecursionDepth(); // LOG4J2-1518, LOG4J2-2031tryLogMessage(fqcn, level, marker, msg, throwable);} finally {decrementRecursionDepth();}}可以看出這個在打日志之前做了調用次數的記錄。跟進tryLogMessage，
@PerformanceSensitive// NOTE: This is a hot method. Current implementation compiles to 26 bytes of byte code.// This is within the 35 byte MaxInlineSize threshold. Modify with care!private void tryLogMessage(final String fqcn,final Level level,final Marker marker,final Message msg,final Throwable throwable) {try {logMessage(fqcn, level, marker, msg, throwable);} catch (final Exception e) {// LOG4J2-1990 Log4j2 suppresses all exceptions that occur once application called the loggerhandleLogMessageException(e, fqcn, msg);}}繼續跟進：
@Overridepublic void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,final Throwable t) {final Message msg = message == null ? new SimpleMessage(Strings.EMPTY) : message;final ReliabilityStrategy strategy = privateConfig.loggerConfig.getReliabilityStrategy();strategy.log(this, getName(), fqcn, marker, level, msg, t);}這里可以看到在實際打日志的時候，會從config中獲取打日志的策略，跟蹤ReliabilityStrategy的創建，發現默認的實現類為DefaultReliabilityStrategy，跟進看實際打日志的方法
@Overridepublic void log(final Supplier<LoggerConfig> reconfigured, final String loggerName, final String fqcn, final Marker marker, final Level level,final Message data, final Throwable t) {loggerConfig.log(loggerName, fqcn, marker, level, data, t);}這里實際打日志的方法居然是交給一個config去實現的。。。感覺有點奇怪。。跟進看看
@PerformanceSensitive("allocation")public void log(final String loggerName, final String fqcn, final Marker marker, final Level level,final Message data, final Throwable t) {List<Property> props = null;if (!propertiesRequireLookup) {props = properties;} else {if (properties != null) {props = new ArrayList<>(properties.size());final LogEvent event = Log4jLogEvent.newBuilder().setMessage(data).setMarker(marker).setLevel(level).setLoggerName(loggerName).setLoggerFqcn(fqcn).setThrown(t).build();for (int i = 0; i < properties.size(); i++) {final Property prop = properties.get(i);final String value = prop.isValueNeedsLookup() // since LOG4J2-1575? config.getStrSubstitutor().replace(event, prop.getValue()) //: prop.getValue();props.add(Property.createProperty(prop.getName(), value));}}}final LogEvent logEvent = logEventFactory.createEvent(loggerName, marker, fqcn, level, data, props, t);try {log(logEvent, LoggerConfigPredicate.ALL);} finally {// LOG4J2-1583 prevent scrambled logs when logging calls are nested (logging in toString())ReusableLogEventFactory.release(logEvent);}}可以清楚的看到try之前是在創建LogEvent，try里面做的才是真正的log（好tm累），一路跟進。
private void processLogEvent(final LogEvent event, LoggerConfigPredicate predicate) {event.setIncludeLocation(isIncludeLocation());if (predicate.allow(this)) {callAppenders(event);}logParent(event, predicate);}接下來就是callAppender了，我們直接開始看AsyncAppender的append方法：
/*** Actual writing occurs here.** @param logEvent The LogEvent.*/@Overridepublic void append(final LogEvent logEvent) {if (!isStarted()) {throw new IllegalStateException("AsyncAppender " + getName() + " is not active");}final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage());if (!transfer(memento)) {if (blocking) {if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031// If queue is full AND we are in a recursive call, call appender directly to prevent deadlockAsyncQueueFullMessageUtil.logWarningToStatusLogger();logMessageInCurrentThread(logEvent);} else {// delegate to the event router (which may discard, enqueue and block, or log in current thread)final EventRoute route = asyncQueueFullPolicy.getRoute(thread.getId(), memento.getLevel());route.logMessage(this, memento);}} else {error("Appender " + getName() + " is unable to write primary appenders. queue is full");logToErrorAppenderIfNecessary(false, memento);}}}這里主要的步驟就是：
同樣的，這里也有一個線程用來做異步消費的事情
private class AsyncThread extends Log4jThread {private volatile boolean shutdown = false;private final List<AppenderControl> appenders;private final BlockingQueue<LogEvent> queue;public AsyncThread(final List<AppenderControl> appenders, final BlockingQueue<LogEvent> queue) {super("AsyncAppender-" + THREAD_SEQUENCE.getAndIncrement());this.appenders = appenders;this.queue = queue;setDaemon(true);}@Overridepublic void run() {while (!shutdown) {LogEvent event;try {event = queue.take();if (event == SHUTDOWN_LOG_EVENT) {shutdown = true;continue;}} catch (final InterruptedException ex) {break; // LOG4J2-830}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 LogEvent event = queue.take();if (event instanceof Log4jLogEvent) {final Log4jLogEvent logEvent = (Log4jLogEvent) event;logEvent.setEndOfBatch(queue.isEmpty());callAppenders(logEvent);count++;} else {ignored++;LOGGER.trace("Ignoring event of class {}", event.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 LogEvent 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_LOG_EVENT);}if (getState() == State.TIMED_WAITING || getState() == State.WAITING) {this.interrupt(); // LOG4J2-1422: if underlying appender is stuck in wait/sleep/join/park call}}}直接看run方法：
AsyncLogger
直接從AsyncLogger的logMessage看進去：
public void logMessage(final String fqcn, final Level level, final Marker marker, final Message message,final Throwable thrown) {if (loggerDisruptor.isUseThreadLocals()) {logWithThreadLocalTranslator(fqcn, level, marker, message, thrown);} else {// LOG4J2-1172: avoid storing non-JDK classes in ThreadLocals to avoid memory leaks in web appslogWithVarargTranslator(fqcn, level, marker, message, thrown);}}跟進logWithThreadLocalTranslator，
private void logWithThreadLocalTranslator(final String fqcn, final Level level, final Marker marker,final Message message, final Throwable thrown) {// Implementation note: this method is tuned for performance. MODIFY WITH CARE!final RingBufferLogEventTranslator translator = getCachedTranslator();initTranslator(translator, fqcn, level, marker, message, thrown);initTranslatorThreadValues(translator);publish(translator);}這里的邏輯很簡單，就是將日志相關的信息轉換成RingBufferLogEvent（RingBuffer是Disruptor的無所隊列），然后將其發布到RingBuffer中。發布到RingBuffer中，那肯定也有消費邏輯。這時候有兩種方式可以找到這個消費的邏輯。
- 找disruptor被使用的地方，然后查看，但是這樣做會很容易迷惑
- 按照Log4j2的尿性，這種Logger都有對應的start方法，我們可以從start方法入手尋找
在start方法中，我們找到了一段代碼：
final RingBufferLogEventHandler[] handlers = {new RingBufferLogEventHandler()};disruptor.handleEventsWith(handlers);直接看看這個RingBufferLogEventHandler的實現：
public class RingBufferLogEventHandler implementsSequenceReportingEventHandler<RingBufferLogEvent>, LifecycleAware {private static final int NOTIFY_PROGRESS_THRESHOLD = 50;private Sequence sequenceCallback;private int counter;private long threadId = -1;@Overridepublic void setSequenceCallback(final Sequence sequenceCallback) {this.sequenceCallback = sequenceCallback;}@Overridepublic void onEvent(final RingBufferLogEvent event, final long sequence,final boolean endOfBatch) throws Exception {event.execute(endOfBatch);event.clear();// notify the BatchEventProcessor that the sequence has progressed.// Without this callback the sequence would not be progressed// until the batch has completely finished.if (++counter > NOTIFY_PROGRESS_THRESHOLD) {sequenceCallback.set(sequence);counter = 0;}}/*** Returns the thread ID of the background consumer thread, or {@code -1} if the background thread has not started* yet.* @return the thread ID of the background consumer thread, or {@code -1}*/public long getThreadId() {return threadId;}@Overridepublic void onStart() {threadId = Thread.currentThread().getId();}@Overridepublic void onShutdown() {} }順著接口找上去，發現一個接口：
/*** Callback interface to be implemented for processing events as they become available in the {@link RingBuffer}** @param <T> event implementation storing the data for sharing during exchange or parallel coordination of an event.* @see BatchEventProcessor#setExceptionHandler(ExceptionHandler) if you want to handle exceptions propagated out of the handler.*/ public interface EventHandler<T> {/*** Called when a publisher has published an event to the {@link RingBuffer}** @param event published to the {@link RingBuffer}* @param sequence of the event being processed* @param endOfBatch flag to indicate if this is the last event in a batch from the {@link RingBuffer}* @throws Exception if the EventHandler would like the exception handled further up the chain.*/void onEvent(T event, long sequence, boolean endOfBatch) throws Exception; }通過注釋可以發現，這個onEvent就是處理邏輯，回到RingBufferLogEventHandler的onEvent方法，發現里面有一個execute方法，跟進：
public void execute(final boolean endOfBatch) {this.endOfBatch = endOfBatch;asyncLogger.actualAsyncLog(this);}這個方法就是實際打日志了，AsyncLogger看起來還是比較簡單的，只是使用了一個Disruptor。
插件化
之前在很多代碼里面都可以看到
final PluginManager manager = new PluginManager(CATEGORY); manager.collectPlugins(pluginPackages);其實整個log4j2為了獲得更好的擴展性，將自己的很多組件都做成了插件，然后在配置的時候去加載plugin。
跟進collectPlugins。
處理邏輯如下：
邏輯還是比較簡單的，但是我在看源碼的時候發現了一個很有意思的東西，就是在加載log4j2 core插件的時候，也就是
PluginRegistry.getInstance().loadFromMainClassLoader()這個方法，跟進到decodeCacheFiles：
private Map<String, List<PluginType<?>>> decodeCacheFiles(final ClassLoader loader) {final long startTime = System.nanoTime();final PluginCache cache = new PluginCache();try {final Enumeration<URL> resources = loader.getResources(PluginProcessor.PLUGIN_CACHE_FILE);if (resources == null) {LOGGER.info("Plugin preloads not available from class loader {}", loader);} else {cache.loadCacheFiles(resources);}} catch (final IOException ioe) {LOGGER.warn("Unable to preload plugins", ioe);}final Map<String, List<PluginType<?>>> newPluginsByCategory = new HashMap<>();int pluginCount = 0;for (final Map.Entry<String, Map<String, PluginEntry>> outer : cache.getAllCategories().entrySet()) {final String categoryLowerCase = outer.getKey();final List<PluginType<?>> types = new ArrayList<>(outer.getValue().size());newPluginsByCategory.put(categoryLowerCase, types);for (final Map.Entry<String, PluginEntry> inner : outer.getValue().entrySet()) {final PluginEntry entry = inner.getValue();final String className = entry.getClassName();try {final Class<?> clazz = loader.loadClass(className);final PluginType<?> type = new PluginType<>(entry, clazz, entry.getName());types.add(type);++pluginCount;} catch (final ClassNotFoundException e) {LOGGER.info("Plugin [{}] could not be loaded due to missing classes.", className, e);} catch (final LinkageError e) {LOGGER.info("Plugin [{}] could not be loaded due to linkage error.", className, e);}}}final long endTime = System.nanoTime();final DecimalFormat numFormat = new DecimalFormat("#0.000000");final double seconds = (endTime - startTime) * 1e-9;LOGGER.debug("Took {} seconds to load {} plugins from {}",numFormat.format(seconds), pluginCount, loader);return newPluginsByCategory;}可以發現加載時候是從一個文件（PLUGIN_CACHE_FILE）獲取所有要獲取的plugin。看到這里的時候我有一個疑惑就是，為什么不用反射的方式直接去掃描，而是要從文件中加載進來，而且文件是寫死的，很不容易擴展啊。然后我找了一下PLUGIN_CACHE_FILE這個靜態變量的用處，發現了PluginProcessor這個類，這里用到了注解處理器。
/*** Annotation processor for pre-scanning Log4j 2 plugins.*/ @SupportedAnnotationTypes("org.apache.logging.log4j.core.config.plugins.*") public class PluginProcessor extends AbstractProcessor {// TODO: this could be made more abstract to allow for compile-time and run-time plugin processing/*** The location of the plugin cache data file. This file is written to by this processor, and read from by* {@link org.apache.logging.log4j.core.config.plugins.util.PluginManager}.*/public static final String PLUGIN_CACHE_FILE ="META-INF/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat";private final PluginCache pluginCache = new PluginCache();@Overridepublic boolean process(final Set<? extends TypeElement> annotations, final RoundEnvironment roundEnv) {System.out.println("Processing annotations");try {final Set<? extends Element> elements = roundEnv.getElementsAnnotatedWith(Plugin.class);if (elements.isEmpty()) {System.out.println("No elements to process");return false;}collectPlugins(elements);writeCacheFile(elements.toArray(new Element[elements.size()]));System.out.println("Annotations processed");return true;} catch (final IOException e) {e.printStackTrace();error(e.getMessage());return false;} catch (final Exception ex) {ex.printStackTrace();error(ex.getMessage());return false;}} }（不太重要的方法省略）
我們可以看到在process方法中，PluginProcessor會先收集所有的Plugin，然后在寫入文件。這樣做的好處就是可以省去反射時候的開銷。
然后我又看了一下Plugin這個注解，發現它的RetentionPolicy是RUNTIME，一般來說PluginProcessor是搭配RetentionPolicy.SOURCE，CLASS使用的，而且既然你把自己的Plugin掃描之后寫在文件中了，RetentionPolicy就沒有必要是RUNTIME了吧，這個是一個很奇怪的地方。
小結
總算是把Log4j2的代碼看完了，發現它的設計理念很值得借鑒，為了靈活性，所有的東西都設計成插件式。互聯網技術日益發展，各種中間件層出不窮，而作為工程師的我們更需要做的是去思考代碼與代碼之間的關系，毫無疑問的是，解耦是最具有美感的關系。
原文鏈接
本文為云棲社區原創內容，未經允許不得轉載。
總結
以上是生活随笔為你收集整理的探索Java日志的奥秘：底层日志系统-log4j2的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： 在Kubernetes上运行区块链服务（
- 下一篇： 如何在一分钟内实现微服务系统下的架构可视