diff --git a/docs/SpringBoot/SpringBoot-LogSystem.md b/docs/SpringBoot/SpringBoot-LogSystem.md index 596f0b2..c3b9045 100644 --- a/docs/SpringBoot/SpringBoot-LogSystem.md +++ b/docs/SpringBoot/SpringBoot-LogSystem.md @@ -1,109 +1,456 @@ -该文所涉及的 netty 源码版本为 4.1.6。 +# SpringBoot 日志系统 -## Netty 中的 ByteBuf 为什么会发生内存泄漏 +- Author: [HuiFer](https://github.com/huifer) +- 源码阅读仓库: [SourceHot-spring-boot](https://github.com/SourceHot/spring-boot-read) -在 Netty 中,ByetBuf 并不是只采用可达性分析来对 ByteBuf 底层的 byte[]数组来进行垃圾回收,而同时采用引用计数法来进行回收,来保证堆外内存的准确时机的释放。 -在每个 ByteBuf 中都维护着一个 refCnt 用来对 ByteBuf 的被引用数进行记录,当 ByteBuf 的 retain()方法被调用时,将会增加 refCnt 的计数,而其 release()方法被调用时将会减少其被引用数计数。 +- 包路径: `org.springframework.boot.logging` + +## 日志级别 + +- 日志级别: `org.springframework.boot.logging.LogLevel` ```java -private boolean release0(int decrement) { - for (;;) { - int refCnt = this.refCnt; - if (refCnt < decrement) { - throw new IllegalReferenceCountException(refCnt, -decrement); - } - if (refCntUpdater.compareAndSet(this, refCnt, refCnt - decrement)) { - if (refCnt == decrement) { - deallocate(); - return true; - } - return false; - } - } +public enum LogLevel { + TRACE, DEBUG, INFO, WARN, ERROR, FATAL, OFF } ``` -当调用了 ByteBuf 的 release()方法的时候,最后在上方的 release0()方法中将会为 ByteBuf 的引用计数减一,当引用计数归于 0 的时候,将会调用 deallocate()方法对其对应的底层存储数组进行释放(在池化的 ByteBuf 中,在 deallocate()方法里会把该 ByteBuf 的 byte[]回收到底层内存池中,以确保 byte[]可以重复利用)。 -由于 Netty 中的 ByteBuf 并不是随着申请之后会马上使其引用计数归 0 而进行释放,往往在这两个操作之间还有许多操作,如果在这其中如果发生异常抛出导致引用没有及时释放,在使用池化 ByetBuffer 的情况下内存泄漏的问题就会产生。 -当采用了池化的 ByteBuffer 的时候,比如 PooledHeapByteBuf 和 PooledDirectByteBuf,其 deallocate()方法一共主要分为两个步骤。 +## java 日志实现 -```java -@Override -protected final void deallocate() { - if (handle >= 0) { - final long handle = this.handle; - this.handle = -1; - memory = null; - chunk.arena.free(chunk, handle, maxLength); - recycle(); +- `org.springframework.boot.logging.java.JavaLoggingSystem` + +![image-20200323144523848](../../images/SpringBoot/image-20200323144523848.png) + +```JAVA + static { + // KEY : springBoot 定义的日志级别, value: jdk 定义的日志级别 + LEVELS.map(LogLevel.TRACE, Level.FINEST); + LEVELS.map(LogLevel.DEBUG, Level.FINE); + LEVELS.map(LogLevel.INFO, Level.INFO); + LEVELS.map(LogLevel.WARN, Level.WARNING); + LEVELS.map(LogLevel.ERROR, Level.SEVERE); + LEVELS.map(LogLevel.FATAL, Level.SEVERE); + LEVELS.map(LogLevel.OFF, Level.OFF); } -} ``` -- 将其底层的 byte[]通过 free()方法回收到内存池中等待下一次使用。 -- 通过 recycle()方法将其本身回收到对象池中等待下一次使用。 - 关键在第一步的内存回收到池中,如果其引用计数未能在 ByteBuf 对象被回收之前归 0,将会导致其底层占用 byte[]无法回收到内存池 PoolArena 中,导致该部分无法被重复利用,下一次将会申请新的内存进行操作,从而产生内存泄漏。 - 而非池化的 ByteBuffer 即使引用计数没有在对象被回收的时候被归 0,因为其使用的是单独一块 byte[]内存,因此也会随着 java 对象被回收使得底层 byte[]被释放(由 JDK 的 Cleaner 来保证)。 +- LEVELS 对象 + + ```java + protected static class LogLevels { + + /** + * key : SpringBoot 中定义的日志级别, value: 其他日志框架的日志级别 + */ + private final Map systemToNative; + + /** + * key : 其他日志框架的日志级别 , value: springBoot 中定义中定义的日志级别 + */ + private final Map nativeToSystem; + } + ``` + +## LoggingSystem + +- 抽象类 +- `org.springframework.boot.logging.LoggingSystem` + +- 一个 map 对象: `SYSTEMS` + +```JAVA + /** + * key: 第三方日志框架的类 value: springBoot 中的处理类 + */ + private static final Map SYSTEMS; + + static { + Map systems = new LinkedHashMap<>(); + systems.put("ch.qos.logback.core.Appender", "org.springframework.boot.logging.logback.LogbackLoggingSystem"); + systems.put("org.apache.logging.log4j.core.impl.Log4jContextFactory", + "org.springframework.boot.logging.log4j2.Log4J2LoggingSystem"); + systems.put("java.util.logging.LogManager", "org.springframework.boot.logging.java.JavaLoggingSystem"); + SYSTEMS = Collections.unmodifiableMap(systems); + } + +``` + +- 各个抽象方法 -## Netty 进行内存泄漏检测的原理 +| 方法名称 | 作用 | +| ----------------------- | ---------------------------------- | +| beforeInitialize | 初始化之前调用,目的是减少日志输出 | +| initialize | 初始化日志 | +| cleanUp | 清除日志 | +| getShutdownHandler | | +| getSupportedLogLevels | 获取支持的日志级别 | +| setLogLevel | 设置日志级别 | +| getLoggerConfigurations | 获取日志配置 | -在 Netty 对于 ByteBuf 的检测中,一共包含 4 个级别。 +### get ```java -if (level.ordinal() < Level.PARANOID.ordinal()) { - if (leakCheckCnt ++ % samplingInterval == 0) { - reportLeak(level); - return new DefaultResourceLeak(obj); - } else { - return null; +public static LoggingSystem get(ClassLoader classLoader) { + // 获取系统属性 + String loggingSystem = System.getProperty(SYSTEM_PROPERTY); + + if (StringUtils.hasLength(loggingSystem)) { + // 是不是NONE + if (NONE.equals(loggingSystem)) { + // 空的日志系统 + return new NoOpLoggingSystem(); + } + return get(classLoader, loggingSystem); + } + // 循环所有日志, + return SYSTEMS.entrySet().stream().filter((entry) -> ClassUtils.isPresent(entry.getKey(), classLoader)) + .map((entry) -> + // 实例化具体日志 + get(classLoader, entry.getValue())).findFirst() + .orElseThrow(() -> new IllegalStateException("No suitable logging system located")); } -} ``` -以默认的 SIMPLE 级别为例,在这个级别下,Netty 将会根据以 ByteBuf 创建的序列号与 113 进行取模来判断是否需要进行内存泄漏的检测追踪。当取模成功的时候,将会为这个 ByteBuf 产生一个对应的 DefaultResourceLeak 对象,DefaultResourceLeak 是一个 PhantomReference 虚引用的子类,并有其对应的 ReferenceQueue。之后通过 SimpleLeakAwareByteBuf 类来将被追踪的 ByteBuf 和 DefaultResourceLeak 包装起来。 +- 实例化日志系统 ```java -@Override -public boolean release(int decrement) { - boolean deallocated = super.release(decrement); - if (deallocated) { - leak.close(); + private static LoggingSystem get(ClassLoader classLoader, String loggingSystemClass) { + try { + Class systemClass = ClassUtils.forName(loggingSystemClass, classLoader); + Constructor constructor = systemClass.getDeclaredConstructor(ClassLoader.class); + constructor.setAccessible(true); + return (LoggingSystem) constructor.newInstance(classLoader); + } + catch (Exception ex) { + throw new IllegalStateException(ex); + } } - return deallocated; -} + ``` -在包装类中,如果该 ByteBuf 成功 deallocated 释放掉了其持有的 byte[]数组将会调用 DefaultResourceLeak 的 close()方法来已通知当前 ByteBuf 已经释放了其持有的内存。 -正是这个虚引用使得该 DefaultResourceLeak 对象被回收的时候将会被放入到与这个虚引用所对应的 ReferenceQueue 中。 +![image-20200323151409473](../../images/SpringBoot/image-20200323151409473.png) + +- 默认日志: `org.springframework.boot.logging.logback.LogbackLoggingSystem` + +### beforeInitialize + +- 初始化之前 + + ![image-20200323154205484](../../images/SpringBoot/image-20200323154205484.png) + + - 链路 + 1. `org.springframework.boot.context.logging.LoggingApplicationListener#onApplicationEvent` + 2. `org.springframework.boot.context.logging.LoggingApplicationListener#onApplicationStartingEvent` + 3. `org.springframework.boot.logging.LoggingSystem#beforeInitialize` + +- 因为前文中我们已知对象是:`org.springframework.boot.logging.logback.LogbackLoggingSystem` 直接看这个类的**`beforeInitialize`**方法 + + ```JAVA + @Override + public void beforeInitialize() { + // 日志上下文 + LoggerContext loggerContext = getLoggerContext(); + // 是否初始化 + if (isAlreadyInitialized(loggerContext)) { + return; + } + // 父类方法 + super.beforeInitialize(); + // 添加过滤器 + loggerContext.getTurboFilterList().add(FILTER); + } + + ``` + +- 初始化之前的的操作完成了初始化方法开始 + +### initialize + +- `org.springframework.boot.context.logging.LoggingApplicationListener#onApplicationEnvironmentPreparedEvent` + + ```JAVA + private void onApplicationEnvironmentPreparedEvent(ApplicationEnvironmentPreparedEvent event) { + if (this.loggingSystem == null) { + this.loggingSystem = LoggingSystem.get(event.getSpringApplication().getClassLoader()); + } + initialize(event.getEnvironment(), event.getSpringApplication().getClassLoader()); + } + + ``` + +- `org.springframework.boot.context.logging.LoggingApplicationListener#initializeSystem` + + ```JAVA + protected void initialize(ConfigurableEnvironment environment, ClassLoader classLoader) { + new LoggingSystemProperties(environment).apply(); + this.logFile = LogFile.get(environment); + if (this.logFile != null) { + this.logFile.applyToSystemProperties(); + } + this.loggerGroups = new LoggerGroups(DEFAULT_GROUP_LOGGERS); + // 早期 的日志级别 + initializeEarlyLoggingLevel(environment); + // 初始化日志系统 + initializeSystem(environment, this.loggingSystem, this.logFile); + // 初始化日志级别 + initializeFinalLoggingLevels(environment, this.loggingSystem); + registerShutdownHookIfNecessary(environment, this.loggingSystem); + } + + ``` + + ```JAVA + private void initializeSystem(ConfigurableEnvironment environment, LoggingSystem system, LogFile logFile) { + LoggingInitializationContext initializationContext = new LoggingInitializationContext(environment); + String logConfig = environment.getProperty(CONFIG_PROPERTY); + if (ignoreLogConfig(logConfig)) { + // 日志系统初始化 + system.initialize(initializationContext, null, logFile); + } + else { + try { + ResourceUtils.getURL(logConfig).openStream().close(); + system.initialize(initializationContext, logConfig, logFile); + } + catch (Exception ex) { + // NOTE: We can't use the logger here to report the problem + System.err.println("Logging system failed to initialize using configuration from '" + logConfig + "'"); + ex.printStackTrace(System.err); + throw new IllegalStateException(ex); + } + } + } + + ``` + +- `org.springframework.boot.logging.logback.LogbackLoggingSystem#initialize` ```java -DefaultResourceLeak ref = (DefaultResourceLeak) refQueue.poll(); -if (ref == null) { - break; -} + @Override + public void initialize(LoggingInitializationContext initializationContext, String configLocation, LogFile logFile) { + LoggerContext loggerContext = getLoggerContext(); + if (isAlreadyInitialized(loggerContext)) { + return; + } + // 日志初始化 + super.initialize(initializationContext, configLocation, logFile); + loggerContext.getTurboFilterList().remove(FILTER); + markAsInitialized(loggerContext); + if (StringUtils.hasText(System.getProperty(CONFIGURATION_FILE_PROPERTY))) { + getLogger(LogbackLoggingSystem.class.getName()).warn("Ignoring '" + CONFIGURATION_FILE_PROPERTY + + "' system property. Please use 'logging.config' instead."); + } + } + +``` -ref.clear(); +- `org.springframework.boot.logging.AbstractLoggingSystem#initializeWithConventions` -if (!ref.close()) { - continue; -} + ```JAVA + private void initializeWithConventions(LoggingInitializationContext initializationContext, LogFile logFile) { + String config = getSelfInitializationConfig(); + if (config != null && logFile == null) { + // self initialization has occurred, reinitialize in case of property changes + reinitialize(initializationContext); + return; + } + if (config == null) { + config = getSpringInitializationConfig(); + } + if (config != null) { + loadConfiguration(initializationContext, config, logFile); + return; + } + // 加载默认配置 + loadDefaults(initializationContext, logFile); + } + + ``` + + - `org.springframework.boot.logging.logback.LogbackLoggingSystem#loadDefaults` + + ```JAVA + @Override + protected void loadDefaults(LoggingInitializationContext initializationContext, LogFile logFile) { + LoggerContext context = getLoggerContext(); + stopAndReset(context); + boolean debug = Boolean.getBoolean("logback.debug"); + if (debug) { + StatusListenerConfigHelper.addOnConsoleListenerInstance(context, new OnConsoleStatusListener()); + } + LogbackConfigurator configurator = debug ? new DebugLogbackConfigurator(context) + : new LogbackConfigurator(context); + Environment environment = initializationContext.getEnvironment(); + context.putProperty(LoggingSystemProperties.LOG_LEVEL_PATTERN, + environment.resolvePlaceholders("${logging.pattern.level:${LOG_LEVEL_PATTERN:%5p}}")); + context.putProperty(LoggingSystemProperties.LOG_DATEFORMAT_PATTERN, environment.resolvePlaceholders( + "${logging.pattern.dateformat:${LOG_DATEFORMAT_PATTERN:yyyy-MM-dd HH:mm:ss.SSS}}")); + context.putProperty(LoggingSystemProperties.ROLLING_FILE_NAME_PATTERN, environment + .resolvePlaceholders("${logging.pattern.rolling-file-name:${LOG_FILE}.%d{yyyy-MM-dd}.%i.gz}")); + new DefaultLogbackConfiguration(initializationContext, logFile).apply(configurator); + context.setPackagingDataEnabled(true); + } + + ``` -String records = ref.toString(); -if (reportedLeaks.putIfAbsent(records, Boolean.TRUE) == null) { - if (records.isEmpty()) { - logger.error("LEAK: {}.release() was not called before it's garbage-collected. " + - "Enable advanced leak reporting to find out where the leak occurred. " + - "To enable advanced leak reporting, " + - "specify the JVM option '-D{}={}' or call {}.setLevel()", - resourceType, PROP_LEVEL, Level.ADVANCED.name().toLowerCase(), simpleClassName(this)); - } else { - logger.error( - "LEAK: {}.release() was not called before it's garbage-collected.{}", - resourceType, records); +```JAVA + @Override + public void initialize(LoggingInitializationContext initializationContext, String configLocation, LogFile logFile) { + LoggerContext loggerContext = getLoggerContext(); + // 是否加载过 + if (isAlreadyInitialized(loggerContext)) { + return; + } + // 日志初始化 + super.initialize(initializationContext, configLocation, logFile); + // 删除 FILTER + loggerContext.getTurboFilterList().remove(FILTER); + // 初始化标记 + markAsInitialized(loggerContext); + if (StringUtils.hasText(System.getProperty(CONFIGURATION_FILE_PROPERTY))) { + getLogger(LogbackLoggingSystem.class.getName()).warn("Ignoring '" + CONFIGURATION_FILE_PROPERTY + + "' system property. Please use 'logging.config' instead."); + } } -} ``` -Netty 会在下一次 ByteBuf 的采样中通过 reportLeak()方法将 ReferenceQueue 中的 DefaultResourceLeak 取出并判断其对应的 ByteBuf 是否已经在其回收前调用过其 close()方法,如果没有,显然在池化 ByteBuf 的场景下内存泄漏已经产生,将会以 ERROR 日志的方式进行日志打印。 +标记`markAsInitialized` + +```JAVA + private void markAsInitialized(LoggerContext loggerContext) { + loggerContext.putObject(LoggingSystem.class.getName(), new Object()); + } + +``` + +此时日志初始化完成 + +### 默认配置文件 + +- `getStandardConfigLocations` 这个方法定义了默认配置文件有哪些 + +```java + @Override + protected String[] getStandardConfigLocations() { + return new String[] { "logback-test.groovy", "logback-test.xml", "logback.groovy", "logback.xml" }; + } + +``` + +- 切回`org.springframework.boot.logging.AbstractLoggingSystem#initializeWithConventions`方法 + +- 添加依赖 + +```XML + + org.springframework.boot + spring-boot-starter-logging + ${revision} + + +``` + +- 添加配置文件 + +![image-20200323161442058](../../images/SpringBoot/image-20200323161442058.png) + +![image-20200323161522570](../../images/SpringBoot/image-20200323161522570.png) + +- 此时配置文件地址出现了 + +```JAVA + protected String getSelfInitializationConfig() { + // 寻找配置文件 + return findConfig(getStandardConfigLocations()); + } + +``` + +```JAVA + @Override + protected String[] getStandardConfigLocations() { + return new String[] { "logback-test.groovy", "logback-test.xml", "logback.groovy", "logback.xml" }; + } + +``` + +```JAVA + private String findConfig(String[] locations) { + for (String location : locations) { + ClassPathResource resource = new ClassPathResource(location, this.classLoader); + if (resource.exists()) { + return "classpath:" + location; + } + } + return null; + } + +``` + +- 此时自定义配置文件如何获取的已经明了 + +#### reinitialize + +```JAVA + @Override + protected void reinitialize(LoggingInitializationContext initializationContext) { + // 日志上下文重新设置 + getLoggerContext().reset(); + getLoggerContext().getStatusManager().clear(); + // 加载配置文件 + loadConfiguration(initializationContext, getSelfInitializationConfig(), null); + } + +``` + +```JAVA + @Override + protected void loadConfiguration(LoggingInitializationContext initializationContext, String location, + LogFile logFile) { + // 父类方法 + super.loadConfiguration(initializationContext, location, logFile); + // 获取上下文 + LoggerContext loggerContext = getLoggerContext(); + // 停止并且重启 + stopAndReset(loggerContext); + try { + // 配置文件加载 + configureByResourceUrl(initializationContext, loggerContext, ResourceUtils.getURL(location)); + } + catch (Exception ex) { + throw new IllegalStateException("Could not initialize Logback logging from " + location, ex); + } + List statuses = loggerContext.getStatusManager().getCopyOfStatusList(); + StringBuilder errors = new StringBuilder(); + for (Status status : statuses) { + if (status.getLevel() == Status.ERROR) { + errors.append((errors.length() > 0) ? String.format("%n") : ""); + errors.append(status.toString()); + } + } + if (errors.length() > 0) { + throw new IllegalStateException(String.format("Logback configuration error detected: %n%s", errors)); + } + } + +``` + +```java + private void configureByResourceUrl(LoggingInitializationContext initializationContext, LoggerContext loggerContext, + URL url) throws JoranException { + if (url.toString().endsWith("xml")) { + // logback 日志操作 + JoranConfigurator configurator = new SpringBootJoranConfigurator(initializationContext); + // 设置上下文 + configurator.setContext(loggerContext); + // 执行配置 + configurator.doConfigure(url); + } + else { + new ContextInitializer(loggerContext).configureByResource(url); + } + } + +``` -以上内容可以结合 JVM 堆外内存的资料进行阅读。 +- 执行配置属于 logback 操作源码不在此进行分析