关于服务器:超牛逼的性能监控神器快速定位线上问题

明天想总结的货色是最近工作中应用到的测试工具 JMH 以及 Java 运行时监控工具 Arthas。他们在我的理论工作中也算是帮了大忙。所以在这里抛砖引玉一下这些工具的应用办法。同时也加深一下本人对这些工具的相熟水平。对这两个工具，我都会首先简略介绍一下这些工具的大抵应用场景，而后会应用一个在工作中真正遇到的性能问题排查为例具体解说这两个工具的理论用法。话不多说，直奔主题。

问题形容

为了可能让我前面的实例可能贯通这两个工具的应用，我首先简略形容下咱们在开发中遇到的理论的性能问题。而后再引出这两个性能工具的理论应用，看咱们如何应用这两个工具胜利定位到性能瓶颈的。

问题如下：为了可能反对失落率，咱们将原先 log4j2 的 Async+ 自定义 Appender 的形式进行了修改，把异步的逻辑放到了本人改版后的 Appender 中。但咱们发现批改后日志性能要比之前 Async+ 自定义 Appender 的形式降落不少。这里因为隐衷起因我并没有用理论公司中的实例，这里我用了一种其余同样可能体现问题的形式。咱们临时先不给出具体的配置文件，先给出性能测试代码和后果。

代码

package com.bryantchang.appendertest;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class AppenderTest {

    private static final String LOGGER_NAME_DEFAULT = "defaultLogger";
    private static final String LOGGER_NAME_INCLUDE = "includeLocationLogger";
    private static final Logger LOGGER = LoggerFactory.getLogger(LOGGER_NAME_INCLUDE);
    public static final long BATCH = 10000;

    public static void main(String[] args) throws InterruptedException {while(true) {
            long start, end;
            start = System.currentTimeMillis();
            for (int i = 0; i < BATCH; i++) {LOGGER.info("msg is {}", i);
            }
            end = System.currentTimeMillis();
            System.out.println("duration of" + LOGGER_NAME_INCLUDE +  "is" + (end - start) + "ms");
            Thread.sleep(1000);
        }
    }
}

代码逻辑及其简略，就是调用 logger.info 每次打印 10000 条日志，而后记录耗时。两者的比照如下。Java 技术资源分享（包含 Java 高阶编程、架构师、SSM、微服务、Spring Cloud、Spring 全家桶）

从这两张图片中咱们可能看到同样的逻辑，两个程序的耗时差距相差了数十倍，但看图片，貌似仅仅是 logger 的名称不一样。对下面的试验后果进行剖析，咱们可能会有两个疑难

• 下面的代码测试是否规范，标准
• 如果真的是性能问题，那么这两个代码到底在哪个办法上有了这么大的差距导致了最终的性能差别

上面这两个工具就别离来答复这两个问题

JMH 简介

第一个问题就是，测试的办法是否规范。咱们在编写代码时用的是死循环 + 前后“掐秒表”的形式。如果咱们要再加个多线程的测试，咱们还须要搞一个线程池，除了代码自身的逻辑还要关怀测试的逻辑。咱们会想，有没有一款工具可能将咱们从测试逻辑中彻底解放出来，只须要关怀咱们须要测试的代码逻辑。JMH 就是这样一款 Java 的测试框架。上面是 JMH 的官网定义

JMH 是一个面向 Java 语言或者其余 Java 虚拟机语言的性能基准测试框架 

这外面咱们须要留神的是，JMH 所测试的办法约简略越好，依赖越少越好，最适宜的场景就是，测试两个汇合 put，get 性能，例如 ArrayList 与 LinkedList 的比照等，这里咱们须要测试的是批量打一批日志所须要的工夫，也根本合乎应用 JMH 的测试场景。上面是测试代码，bench 框架代码以及主函数。

待测试方法

public class LogBenchMarkWorker {private LogBenchMarkWorker() {}

    private static class LogBenchMarkWorkerInstance {private static final LogBenchMarkWorker instance = new LogBenchMarkWorker();
    }

    public static LogBenchMarkWorker getInstance() {return LogBenchMarkWorkerInstance.instance;}

    private static final String LOGGER_DEFAULT_NAME = "defaultLogger";
    private static final String LOGGER_INCLUDE_LOCATION = "includeLocationLogger";
    private static final Logger LOGGER = LoggerFactory.getLogger(LOGGER_DEFAULT_NAME);
    private static long BATCH_SIZE = 10000;

    public void logBatch() {for (int i = 0; i < BATCH_SIZE; i++) {LOGGER.info("msg is {}", i);
        }
    }
}

能够看到待测试方法非常简单，就是单批次一次性打印 10000 条日志的操作，所以并没有须要额定阐明的局部。上面咱们再来看 benchmark 局部。

public class LogBenchMarkMain {

    @Benchmark
    @BenchmarkMode(Mode.AverageTime)
    @Fork(value = 1)
    @Threads(1)
    public void testLog1() {LogBenchMarkWorker.getInstance().logBatch();}

    @Benchmark
    @BenchmarkMode(Mode.AverageTime)
    @Fork(value = 1)
    @Threads(4)
    public void testLog4() {LogBenchMarkWorker.getInstance().logBatch();}

    @Benchmark
    @BenchmarkMode(Mode.AverageTime)
    @Fork(value = 1)
    @Threads(8)
    public void testLog8() {LogBenchMarkWorker.getInstance().logBatch();}

    @Benchmark
    @BenchmarkMode(Mode.AverageTime)
    @Fork(value = 1)
    @Threads(16)
    public void testLog16() {LogBenchMarkWorker.getInstance().logBatch();}

在这段代码中，咱们就会发现有了一些 JMH 中特有的货色，我上面进行简要介绍。

Benchmark 注解：标识在某个具体方法上，示意这个办法将是一个被测试的最小办法，在 JMH 中成为一个 OPS
BenmarkMode: 测试类型，JMH 提供了几种不同的 Mode
    Throughput: 整体吞吐量
    AverageTime: 调用的均匀工夫，每次 OPS 执行的工夫
    SampleTime: 取样，给出不同比例的 ops 工夫，例如 99% 的 ops 工夫，99.99% 的 ops 工夫
fork：fork 的次数，如果设置为 2，JMH 会 fork 出两个过程来测试
Threads：很容易了解，这个参数示意这个办法同时被多少个线程执行 

在下面的代码中，我定义了 4 个待测试的办法，办法的 Fork，BenchmarkMode 均为测试单次 OPS 的均匀工夫，但 4 个办法的线程数不同。除了这几个参数，还有几个参数，我会在 main 函数外面来讲，main 代码如下所示。Java 技术资源分享（包含 Java 高阶编程、架构师、SSM、微服务、Spring Cloud、Spring 全家桶）

public class Main {public static void main(String[] args) throws RunnerException {Options options = new OptionsBuilder()
                .include(LogBenchMarkMain.class.getSimpleName())
                .warmupIterations(5)
                .measurementIterations(5)
                .output("logs/BenchmarkCommon.log")
                .build();
        new Runner(options).run();}
}

咱们能够看到，在 main 函数中，咱们就是要设置 JMH 的根底配置，这外面的几个配置参数含意如下：

include:benchmark 所在类的名字，能够应用正则表白
warmupIteration: 预热的迭代次数，这里为什么要预热的起因是因为 JIT 的存在，随着代码的运行，会动静对代码的运行进行优化。因而在测试过程中须要先预热几轮，让代码运行稳固后再理论进行测试
measurementIterations: 理论测试轮次
output: 测试报告输入地位 

我别离用两种 logger 运行一下测试，查看性能测试报告比照

应用一般 logger

LogBenchMarkMain.testLog1   avgt    5  0.006 ± 0.001   s/op
LogBenchMarkMain.testLog16  avgt    5  0.062 ± 0.026   s/op
LogBenchMarkMain.testLog4   avgt    5  0.006 ± 0.002   s/op
LogBenchMarkMain.testLog8   avgt    5  0.040 ± 0.004   s/op

应用了 INCLUDE_LOCATION 的 logger

LogBenchMarkMain.testLog1   avgt    5  0.379 ± 0.007   s/op
LogBenchMarkMain.testLog16  avgt    5  1.784 ± 0.670   s/op
LogBenchMarkMain.testLog4   avgt    5  0.378 ± 0.003   s/op
LogBenchMarkMain.testLog8   avgt    5  0.776 ± 0.070   s/op

这里咱们看到，性能差距立现。应用 INCLUDE_LOCATION 的性能要显著低于应用一般 logger 的性能。这是咱们肯定很好奇，并且问一句“到底慢在哪”！！

Arthas 我的代码在运行时到底做了什么

Arthas 是阿里开源的一款 java 调试神器，与 greys 相似，不过有着比 greys 更加弱小的性能，例如，能够间接绘制 java 办法调用的火焰图等。这两个工具的原理都是应用了 Java 弱小的字节码技术。毕竟我也不是 JVM 大佬，所以具体的实现细节没法开展，咱们要做的就是站在伟人的肩膀上，承受并用纯熟的应用好这些好用的性能监控工具。

实际操作

talk is cheap, show me your code, 既然是工具，咱们间接进行实际操作。咱们在本机运行咱们一开始的程序，而后解说 arthas 的应用办法。

咱们首先通过 jps 找到程序的过程号，而后间接通过 arthas 给到的 as.sh 对咱们运行的程序进行字节码加强，而后启动 arthas，命令如下

./as.sh pid

能够看到，arthas 反对查看以后 jvm 的状态，查看以后的线程状态，监控某些办法的调用工夫，trace，profile 生成火焰图等，性能一应俱全 咱们这里也只将几个比拟罕用的命令，其余的命令如果大家感兴趣能够详见官网 arthas 官网。这篇文章次要介绍上面几个性能

• 反编译代码
• 监控某个办法的调用
• 查看某个办法的调用和返回值
• trace 某个办法

监控办法调用

这个次要的命令为 monitor，依据官网的介绍，罕用的应用办法为

monitor -c duration className methodName

其中 duration 代表每隔几秒展现一次统计后果，即单次的统计周期，className 就是类的全限定名，methodname 就是办法的名字，这外面咱们查看的办法是 Logger 类的 info 办法，咱们别离对应用两种不同 logger 的 info 办法。这外面的类是 org.slf4j.Logger，办法时 info，咱们的监控语句为

monitor -c 5 org.slf4j.Logger info

监控后果如下

应用一般 appender

咱们能够看到，应用 include appeder 的打印日志办法要比一般的 appender 高出了 3 倍，这就不禁让咱们有了疑难，到底这两个办法各个步骤耗时如何呢。上面咱们就介绍第二条命令，trace 办法。

trace 命令 & jad 命令

这两个程序的 log4j2 配置文件如下

<?xml version="1.0" encoding="UTF-8"?>
<!--status：日志等级   monitorInterval：更新配置文件的工夫距离，单位秒 -->
<configuration status="warn" monitorInterval="30">
    <!-- 定义所有的 appender -->
    <appenders>
        <!-- 这个输入控制台的配置 -->
        <Console name="console" target="SYSTEM_OUT">
            <!-- 控制台只输入 level 及以上级别的信息（onMatch），其余的间接回绝（onMismatch）-->
            <ThresholdFilter level="warn" onMatch="ACCEPT" onMismatch="DENY"/>
            <!-- 日志打印格局 -->
            <PatternLayout pattern="[%d{HH:mm:ss.SSS}] [%-5p] %l - %m%n"/>
        </Console>


        <Async name="AsyncDefault" blocking="false" includeLocation="false">
            <AppenderRef ref="fileAppender"/>
        </Async>

        <Async name="AsyncIncludeLocation" blocking="false" includeLocation="true">
            <AppenderRef ref="fileAppender"/>
        </Async>

        <!-- 文件会打印出所有信息，这个 log 每次运行程序会主动清空，由 append 属性决定，这个也挺有用的，适宜长期测试用 -->
        <!--append 为 TRUE 示意音讯减少到指定文件中，false 示意音讯笼罩指定的文件内容，默认值是 true -->
        <File name="fileAppender" fileName="log/test.log" append="false">
            <PatternLayout pattern="[%d{HH:mm:ss.SSS}] [%-5p] %l - %m%n"/>
        </File>

        <!-- 增加过滤器 ThresholdFilter, 能够有抉择的输入某个级别以上的类别  onMatch="ACCEPT" onMismatch="DENY" 意思是匹配就承受, 否则间接回绝  -->
        <File name="ERROR" fileName="logs/error.log">
            <ThresholdFilter level="error" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="[%d{yyyy.MM.dd'at'HH:mm:ss z}] [%-5p] %l - %m%n"/>
        </File>

        <!-- 这个会打印出所有的信息，每次大小超过 size，则这 size 大小的日志会主动存入按年份 - 月份建设的文件夹上面并进行压缩，作为存档 -->
        <RollingFile name="rollingFile" fileName="logs/app.log"
                     filePattern="logs/$${date:yyyy-MM}/web-%d{yyyy-MM-dd}.log.gz">
            <PatternLayout pattern="[%d{yyyy-MM-dd HH:mm:ss}] [%-5p] %l - %m%n"/>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true" interval="1"/>
            </Policies>
            <DefaultRolloverStrategy>
                <Delete basePath="logs" maxDepth="2">
                    <IfFileName glob="*/*.log.gz" />
                    <IfLastModified age="7d" />
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
    </appenders>

    <!-- 而后定义 logger，只有定义了 logger 并引入的 appender，appender 才会失效 -->
    <loggers>
        <!-- 过滤掉 spring 和 mybatis 的一些无用的 DEBUG 信息 -->
        <logger name="defaultLogger" additivity="false">
            <appender-ref ref="AsyncDefault"></appender-ref>
        </logger>

        <logger name="includeLocationLogger" additivity="false">
            <appender-ref ref="AsyncIncludeLocation"></appender-ref>
        </logger>

        <!-- 建设一个默认的 root 的 logger -->
        <root level="INFO">

        </root>
    </loggers>

</configuration>

咱们都是用了一个 AsyncAppender 套用了一个 FileAppender。查看 fileAppender，发现二者雷同齐全没区别，只有 asyncAppender 中的一个选项有区别，这就是 includeLocation，一个是 false，另一个是 true。至于这个参数的含意，咱们临时不探讨，咱们当初晓得问题可能出在 AsyncAppender 外面，然而咱们该如何验证呢。trace 命令就有了大用场。

trace 命令的根本用法与 monitor 相似，其中次要的一个参数是 - n 则是代表 trace 多少次的意思

trace -n trace_times className methodName

我在之前 Log4j2 的相干博客外面讲到过，任何一个 appender，最外围的办法就是他的 append 办法。所以咱们别离 trace 两个程序的 append 办法。

trace -n 5 org.apache.logging.log4j.core.appender.AsyncAppender append

trace 后果如下

应用一般 appender

咱们立即能够发现，两个 trace 的热点办法不一样，在应用 include 的 appender 中，耗时最长的办法时 org.apache.logging.log4j.core.impl.Log4jLogEvent 类中的 createMemento 办法，那么怎么能力晓得这个办法到底做了啥呢，那就请出咱们下一个常用命令 jad，这个命令可能反编译出对应办法的代码。这里咱们 jad 一下下面说的那个 createMemento 办法，命令很简略

jad org.apache.logging.log4j.core.impl.Log4jLogEvent createMemento

后果如下

watch 命令

watch 命令可能察看到某个特定办法的入参，返回值等信息，咱们应用这个命令查看一下这个 createMemento 办法的入参，如果两个程序的入参不同，那根本能够判定是这个起因引起命令如下

watch org.apache.logging.log4j.core.impl.Log4jLogEvent createMemento "params" -x 2 -n 5 -b -f

这外面的参数含意如下

• -x 参数开展档次
• -n 执行次数
• -b 查看办法调用前状态
• -f 办法调用后

其中的 param 代表查看办法的调用参数列表，还有其余的监控项详见官网官网

最终 watch 后果如下

应用一般 logger

果不其然，这两个参数果然是一个 true 一个 false，咱们简略看下这个参数是如何传进来的，咱们 jad 一下 AsyncAppender 的 append 办法

不过为了一探到底，我还是动态跟了一下这段代码

这个 includeLocation 会在 event 的 createMemento 中被用到，在序列化生成对象时会创立一个 LogEventProxy，代码如下

public LogEventProxy(final LogEvent event, final boolean includeLocation) {this.loggerFQCN = event.getLoggerFqcn();
    this.marker = event.getMarker();
    this.level = event.getLevel();
    this.loggerName = event.getLoggerName();

    final Message msg = event.getMessage();
    this.message = msg instanceof ReusableMessage
            ? memento((ReusableMessage) msg)
            : msg;
    this.timeMillis = event.getTimeMillis();
    this.thrown = event.getThrown();
    this.thrownProxy = event.getThrownProxy();
    this.contextData = memento(event.getContextData());
    this.contextStack = event.getContextStack();
    this.source = includeLocation ? event.getSource() : null;
    this.threadId = event.getThreadId();
    this.threadName = event.getThreadName();
    this.threadPriority = event.getThreadPriority();
    this.isLocationRequired = includeLocation;
    this.isEndOfBatch = event.isEndOfBatch();
    this.nanoTime = event.getNanoTime();}

如果 includeLocation 为 true，那么就会调用 getSource 函数，跟进去查看，代码如下

public StackTraceElement getSource() {if (source != null) {return source;}
        if (loggerFqcn == null || !includeLocation) {return null;}
        source = Log4jLogEvent.calcLocation(loggerFqcn);
        return source;
    }
     public static StackTraceElement calcLocation(final String fqcnOfLogger) {if (fqcnOfLogger == null) {return null;}
        // LOG4J2-1029 new Throwable().getStackTrace is faster than Thread.currentThread().getStackTrace().
        final StackTraceElement[] stackTrace = new Throwable().getStackTrace();
        StackTraceElement last = null;
        for (int i = stackTrace.length - 1; i > 0; i--) {final String className = stackTrace[i].getClassName();
            if (fqcnOfLogger.equals(className)) {return last;}
            last = stackTrace[i];
        }
        return null;
    }

咱们看到他会从整个的调用栈中去寻找调用这个办法的代码行，其性能可想而知。咱们用 arthas 监控一下，验证一下。

首先咱们 trace crateMemento 办法

trace -n 5 org.apache.logging.log4j.core.impl.Log4jLogEvent createMemento

trace -n 5 org.apache.logging.log4j.core.impl.Log4jLogEvent serialize

trace -n 5 org.apache.logging.log4j.core.impl.Log4jLogEvent$LogEventProxy <init>

trace -n 5 trace -n 5 org.apache.logging.log4j.core.LogEvent getSource

至此咱们通过联合 JMH 和 arthas 独特定位出了一个线上的性能问题。不过我介绍的只是冰山一角，更多罕用的命令还心愿大家通过官网本人理解和实际，有了几次亲自实际之后，这个工具也就玩熟了。

起源 | bryantchang.github.io/2019/12/08/java-profile-tools/