明天想总结的货色是最近工作中应用到的测试工具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中成为一个OPSBenmarkMode:测试类型，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/opLogBenchMarkMain.testLog16 avgt 5 0.062 ± 0.026 s/opLogBenchMarkMain.testLog4 avgt 5 0.006 ± 0.002 s/opLogBenchMarkMain.testLog8 avgt 5 0.040 ± 0.004 s/op应用了INCLUDE_LOCATION的logger
LogBenchMarkMain.testLog1 avgt 5 0.379 ± 0.007 s/opLogBenchMarkMain.testLog16 avgt 5 1.784 ± 0.670 s/opLogBenchMarkMain.testLog4 avgt 5 0.378 ± 0.003 s/opLogBenchMarkMain.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 appendtrace后果如下
应用一般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 createMementotrace -n 5 org.apache.logging.log4j.core.impl.Log4jLogEvent serializetrace -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/