log4j2打印一行日志做了啥

你的名字 2022-11-30 00:21 124阅读 0赞

## 1.是什么？ ##

log4j已成为大型系统必不可少的一部分，log4j可以很方便的帮助我们在程序的任何位置输出所要打印的信息，便于我们对系统在调试阶段和正式运行阶段对问题分析和定位。  
![在这里插入图片描述][20200822103722342.png_pic_center]

## 2.日志级别 ##

1.日志级从低到高：`debug`,`info`,`warn`,`error`, 依次升高，性能越高；

2.影响输出性能条件：

*  输出到文件系统 > 控制台
 *  SimpleLayout > PatternLayout，不带格式化的直接输出更快；
 *  日志级别越高，内容输出越少，应用受日志打印影响越少，性能越高；

> 根据不同场景选择不同的日志级别，一般按环境划分（开发，测试，生产），开发需要足够的调试日志信息，线上只需要一些关键的warn/更高级别的日志，避免日志过多或影响性能。

## 3.日志门面 ##

1.  Simple Logging Facade for Java（SLF4J）用作各种日志框架（例如 java.util.logging，logback，log4j）的简单外观或抽象，允许最终用户在部署时插入所需的日志框架;

> 总的来说，slf4j就是众多日志接口的集合（接口定义），不负责具体的日志实现，只在编译时寻找合适的日志系统进行绑定；

![format_png][]

## 4.外观模式应用 ##

外观模式：外部与一个子系统的通信必须通过一个统一的外观对象进行，为子系统中的一组接口提供一个一致的界面；

> SLF4j的logger需要直接或间接指向实际依赖的日志系统的logger，通过实现LoggerFactoryBinder接口完成日志实现的绑定；

![format_png 1][]

## 5.使用规范 ##

【强制】应用中不可直接使用日志系统（Log4j、Logback）中的 API，而应依赖使用日志框架 SLF4J 中的 API，使用门面模式的日志框架，有利于维护和各个类的日志处理方式统一。

import org.slf4j.Logger;
    import org.slf4j.LoggerFactory;
    private static final Logger logger = LoggerFactory.getLogger(Abc.class);

保证不会创建多个日志系统的logger，会选择绑定其中一个（根据配置文件,无配置文件则根据pom引入顺序）  
![format_png 2][]  
lombok slf4j  
![format_png 3][]

## 6.log.info做了什么 ##

1.找到log.info()

@Override
    public void info(final Marker marker, final String s, final Object o, final Object o1) { 
            logger.logIfEnabled(FQCN, Level.INFO, getMarker(marker), s, o, o1);
        }

2.进一步查看：

private void logMessageSafely(final String fqcn, final Level level, final Marker marker, final Message msg,
                final Throwable throwable) { 
            try { 
                logMessage(fqcn, level, marker, msg, throwable);
            } finally { 
                // LOG4J2-1583 prevent scrambled logs when logging calls are nested (logging in toString())
                ReusableMessageFactory.release(msg);
            }
        }

3.从日志中读取要输出到appender的策略（从`log4j2.xml`中解析），执行log操作：

@Override
    public 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);
        }

4.这时会发现打印日志却是由config去执行的(黑人问号脸❓)：

@Override
    public void log(final Supplier<LoggerConfig> reconfigured, final String loggerName, final String fqcn,
                final Marker marker, final Level level, final Message data, final Throwable t) { 
    
            final LoggerConfig config = getActiveLoggerConfig(reconfigured);
            try { 
                config.log(loggerName, fqcn, marker, level, data, t);
            } finally { 
                config.getReliabilityStrategy().afterLogEvent();
            }
        }

5.查看具体实现：

*  若值包含需要解析才能被替换的属性，则使用该属性；
 *  否则则使用log.info时初始化的配置；
 *  做完logEvent的初始化工作，接下来的log(logEvent)才是真正的log操作;

@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);
            } finally { 
                // LOG4J2-1583 prevent scrambled logs when logging calls are nested (logging in toString())
                ReusableLogEventFactory.release(logEvent);
            }
        }

6.经过一系列标志位确认，过滤器确定是否输出appender日志，以AsyncAppender为例进行进一步实现分析，实际写日志的操作，执行步骤有：

*  生成logEvent事件；
 *  将指定的日志logEvent放进BlockingQueue，如果失败（队列满或是没有接收者消费logEvent事件），则启用相应的策略，委托给事件路由去执行；
 *  同时，这里需要一个异步事件去消费日志事件；

@Override
    public void append(final LogEvent logEvent) { 
            if (!isStarted()) { 
                throw new IllegalStateException("AsyncAppender " + getName() + " is not active");
            }
            if (!Constants.FORMAT_MESSAGES_IN_BACKGROUND) {  // LOG4J2-898: user may choose
                logEvent.getMessage().getFormattedMessage(); // LOG4J2-763: ask message to freeze parameters
            }
            final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);
            if (!transfer(memento)) { 
                if (blocking) { 
                    // 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);
                }
            }
        }

> 处处皆异步，还委托小三来干活。

![format_png 4][]

7.执行线程实现日志异步输出：

*  从队列中获取logEvent事件;
 *  callAppender调用已注册的日志事件；
 *  线程退出前将对列中的元素都消费完再退出；  
    org.apache.logging.log4j.core.appender.AsyncAppender.AsyncThread\#run

@Override
            public void run() { 
                while (!shutdown) { 
                    LogEvent event;
                    try { 
                        event = queue.take();
                        if (event == SHUTDOWN) { 
                            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);
            }

> 看到这些操作套路可能会有些熟悉，【添加任务到队列中（workers池子）->根据相应策略->由异步线程（thread）去执行】，与java线程池的设计较为相似；

> AsyncAppender采用的是生产者消费者的模型,异步地将Logging Event送到对应的Appender中。

8.AsyncLogger的`logMsessage`方法，通过日志分发确定是否使用ThreadLocal对象，这里以`org.apache.logging.log4j.core.async.AsyncLogger#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);
        }

10.同理，会有消费逻辑, 由disruptor执行;  
![format_png 5][]

> log4j2的异步模式表现了绝对的性能优势，优势主要得益于Disruptor框架的使用

`LMAX Disruptor technology. Asynchronous Loggers internally use the Disruptor, a lock-free inter-thread communication library, instead of queues, resulting in higher throughput and lower latency.`

> 即一个无锁的线程间通信库代替了原来的队列

![format_png 6][]  
调用操作，当发布者将事件发送到RingBuffer时即调用![format_png 7][]  
最终调用：  
![format_png 8][]

## 7.log4j2 all async ##

1.不同日志组件的性能表现：  
![format_png 9][]  
2.总结：

异步模式+Disruptor

[20200822103722342.png_pic_center]: /images/20221124/072c88cc30644052af1378c1225f5733.png
[format_png]: /images/20221124/1fa7e7756ca4402d8d82d98b23df3171.png
[format_png 1]: /images/20221124/d449d28be0eb4742b903c16aeed36747.png
[format_png 2]: /images/20221124/f34796ab83f3484d8bfc0663e816fab5.png
[format_png 3]: /images/20221124/7e6e86eb20364a5aa467938b005c7567.png
[format_png 4]: /images/20221124/7442c0e3e5f44c47b34b1991cc0d2e30.png
[format_png 5]: /images/20221124/a1f5304d277f4444808ddb42d7eba177.png
[format_png 6]: /images/20221124/286b7fd3b8e94b1ba9d7c8d2f97231d1.png
[format_png 7]: /images/20221124/ab4d39db05074e67b95df6b46a81c597.png
[format_png 8]: /images/20221124/0211b5a25cba4595964f0ef6c7928cb9.png
[format_png 9]: /images/20221124/0ea122b6c6aa4a24938311942a991dd3.png