[前端工坊]微基准测试工具JMH 使用

Posted 2021-04-29 前端工坊

作者 |  京东金融-移动研发部-服务端开发工程师

1 微基准测试是什么

基准测试（benchmarking）http://www.blogjava.net/qileilove/archive/2012/07/05/382241.html 是一种测量和评估软件性能指标的活动。你可以在某个时候通过基准测试建立一个已知的性能水平（称为基准线），当系统的软硬件环境发生变化之后再进行一次基准测试以确定那些变化对性能的影响。这是基准测试最常见的用途。其他用途包括测定某种负载水平下的性能极限、管理系统或环境的变化、发现可能导致性能问题的条件，等等。

2  JMH是什么

JMH是一个用于java或者其他JVM语言的，提供构建，运行和分析（按照多种基准：纳秒，微妙、毫秒、宏）的工具。

http://openjdk.java.net/projects/code-tools/jmh/

一些JMH的code example：

http://hg.openjdk.java.net/code-tools/jmh/file/tip/jmh-samples/src/main/java/org/openjdk/jmh/samples/

3  利用JMH做一个小demo

项目中 使用了一些 日志打印框架，进行日志输出，目前主要是 logback（slf4j），log4j（common-logging）；

使用情况1： 代码中使用的打印方法低于配置文件中的log level时不同的框架，不同的写法有不同的性能；

举例：代码中使用.debug方法，调试完发布后，配置的level级别是info， 这时候日志不再打印；

使用情况2： 代码中使用的打印方法高于配置文件中的log level时不同的框架，不同的写法有不同的性能；

开始测试，具体代码如下：

jdk greater than 1.7+

a)  pom 依赖

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.7</version>
</dependency>
<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>1.0.11</version>
</dependency>
<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>1.2.16</version>
</dependency>
<dependency>
    <groupId>org.openjdk.jmh</groupId>
    <artifactId>jmh-core</artifactId>
    <version>1.11</version>
</dependency>
<dependency>
    <groupId>org.openjdk.jmh</groupId>
    <artifactId>jmh-generator-annprocess</artifactId>
    <version>1.11</version>
</dependency>

b) LogBack测试类

import org.openjdk.jmh.annotations.*;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import java.util.concurrent.TimeUnit;
/**
 * 对项目中使用的几种log 写法进行基准测试
 * log4j, logback
 */
public class LogLogBackTest {
    private static final Logger logger = LoggerFactory.getLogger(LogLogBackTest.class);
    @Benchmark
    //可通过OutputTimeUnit指定时间维度到ms，纳秒级别
//    @OutputTimeUnit(TimeUnit.SECONDS)
    public void testLogStr() {
        String x = "", y = "", z = "";
        for (int i = 0; i < 100; i++) {
            x += i; y += i; z += i;
　　　　　　　//常见的写法
            logger.debug("Concatenating strings " + x + y + z);
        }
    }
    @Benchmark
    public void testLog() {
        String x = "", y = "", z = "";
        for (int i = 0; i < 100; i++) {
            x += i; y += i; z += i;
            logger.debug("Variable arguments {} {} {}", x, y, z);
        }
    }
    @Benchmark
    //可通过OutputTimeUnit指定时间维度到ms，纳秒级别
    public void testLogIf() {
        String x = "", y = "", z = "";
        for (int i = 0; i < 100; i++) {
            x += i; y += i; z += i;
            if (logger.isDebugEnabled())
                logger.debug("If debug enabled {} {} {}", x, y, z);
        }
    }

LogBack配置文件logback.xml:

<configuration>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%highlight(%d{HH:mm:ss.SSS} [%thread] %-5level %logger - %msg%n)</pattern>
        </encoder>
    </appender>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder><pattern>%msg%n</pattern></encoder>
    </appender>
    <root level="INFO">
        <appender-ref ref="CONSOLE" />
    </root>
</configuration>

log4j测试类：

import org.openjdk.jmh.annotations.Benchmark;
import org.apache.log4j.Logger;
/**
 * log4j测试
 */
public class Log4jTest {
    private static final Logger logger = Logger.getLogger(Log4jTest.class);
    @Benchmark
    public void testLogStr() {
        String x = "", y = "", z = "";
        for (int i = 0; i < 100; i++) {
            x += i; y += i; z += i;
            logger.debug("Concatenating strings " + x + y + z);
        }
    }
    @Benchmark
    public void testLog() {
        String x = "", y = "", z = "";
        for (int i = 0; i < 100; i++) {
            x += i; y += i; z += i;
            logger.debug(String.format("Variable arguments %s %s %s",x,y,z));
        }
    }
    @Benchmark
    public void testLogIf() {
        String x = "", y = "", z = "";
        for (int i = 0; i < 100; i++) {
            x += i; y += i; z += i;
            if(logger.isDebugEnabled()){
                logger.debug(String.format("Variable arguments %s %s %s",x,y,z));
            }
        }
    }
}

log4j配置文件:

<?xml version='1.0' encoding='UTF-8' ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
    <appender name="Console" class="org.apache.log4j.ConsoleAppender">
        <param name="DatePattern" value="'.'yyyy-MM-dd-HH"/>
        <param name="Append" value="true"/>
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%d [%7r] %6p - %30.30c - %m \n"/>
        </layout>
        <filter class="org.apache.log4j.varia.LevelRangeFilter">
            <param name="LevelMin" value="INFO"/>
            <!--<param name="LevelMax" value="FATAL "/>-->
        </filter>
    </appender>
    <root>
        <priority value="info"/>
        <appender-ref ref="Console"/>
    </root>
</log4j:configuration>

统一测试类：

import org.openjdk.jmh.runner.Runner;
import org.openjdk.jmh.runner.options.Options;
import org.openjdk.jmh.runner.options.OptionsBuilder;
/**
 * 主测试类，可同时对比测试多个类
 */
public class LogTest {
    public static void main(String [] args) throws Exception{
 Options opt = new OptionsBuilder()
                .include(LogLogBackTest.class.getSimpleName())
//                .include(Log4jTest.class.getSimpleName())
                .forks(2) //需要运行的试验数量，每个试验运行在单独的jvm中，避免加载class上的一些数据不准确
                .warmupIterations(10) //预热次数, 做一些统一的准备工作
                .measurementIterations(10) //真正执行次数
                .threads(10)  //并发程度
                //-XX:-TieredCompilation 关闭分层优化 -server
                //-XX:+LogCompilation  运行之后项目路径会出现按照测试顺序输出hotspot_pid<PID>.log文件,可以使用JITWatch进行分析,可以根据最后运行的结果的顺序按文件时间找到对应的hotspot_pid<PID>.log文件
                .jvmArgs("-XX:+UnlockDiagnosticVMOptions", "-XX:+LogCompilation", "-XX:+TraceClassLoading", "-XX:+PrintAssembly")
                //  .addProfiler(CompilerProfiler.class)    // report JIT compiler profiling via standard MBeans
                //  .addProfiler(GCProfiler.class)    // report GC time
                // .addProfiler(StackProfiler.class) // report method stack execution profile
                // .addProfiler(PausesProfiler.class)
                /*
                WinPerfAsmProfiler
                You must install Windows Performance Toolkit. Once installed, locate directory with xperf.exe file
                and either add it to PATH environment variable, or set it to jmh.perfasm.xperf.dir system property.
                 */
                //.addProfiler(WinPerfAsmProfiler.class)
                //更多Profiler,请看JMH介绍
                //.output("InstructionsBenchmark.log")//输出信息到文件
                .build();
new Runner(opt).run(); } }

最后测试结果如下（ops/time：标识每秒钟执行的次数）：

情况1： 配置的是info，但代码中使用的是.debug()

Benchmark                  Mode   Cnt   Score        Error  Units
Log4jTest.testLog          thrpt   20   3567.110   231.604  ops/s
Log4jTest.testLogIf        thrpt   20  14623.985  1722.329  ops/s
Log4jTest.testLogStr       thrpt   20   7812.083   527.644  ops/s
LogLogBackTest.testLog     thrpt   20  14266.477   645.056  ops/s
LogLogBackTest.testLogIf   thrpt   20  14623.137  1141.877  ops/s
LogLogBackTest.testLogStr  thrpt   20   7036.504   791.166  ops/s

可以看出logback的

logger.info("Variable arguments {} {} {}", x, y, z);写法是优于

logger.info("Concatenating strings " + x + y + z);很多的。

log4j 加 if判断的写法表现最好；

情况2： 配置的是 greater than info，代码中使用的是info() 

Benchmark                   Mode  Cnt   Score   Error  Units
Log4jTest.testLog          thrpt   20  164.982  4.989  ops/s
Log4jTest.testLogIf        thrpt   20  172.038  3.742  ops/s
Log4jTest.testLogStr       thrpt   20  195.298  3.033  ops/s
LogLogBackTest.testLog     thrpt   20  170.267  3.762  ops/s
LogLogBackTest.testLogIf   thrpt   20  168.892  3.408  ops/s
LogLogBackTest.testLogStr  thrpt   20  171.753  3.559  ops/s

所以，情况1的结论是，尽量使用logback的info("Variable arguments {} {} {}", x, y, z)这种写法； 情况2的结论是，直接拼接字符串或者多个入参的写法吞吐量相差不大； 当然写if的话比较麻烦，综合来看应尽量使用logback做日志打印，并推荐可变参数写法；

 四 后记 

基准测试是进行框架选型的重要步骤，JMH是一个很简单的，完成该步骤的工具，希望大家以后在对某些point产生疑惑时，尽可能try来获得结果。