JMH和Arthas定位问题的案例分享

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);        }    }}

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

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);        }    }}

            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();  }

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

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();    }}

<configuration status="warn" monitorInterval="30">        <appenders>                <Console name="console" target="SYSTEM_OUT">                        <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>
                        <File name="fileAppender" fileName="log/test.log" append="false">            <PatternLayout pattern="[%d{HH:mm:ss.SSS}] [%-5p] %l - %m%n"/>        File>
                <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>
                <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>
        <loggers>                <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 level="INFO">
        root>    loggers>
configuration>

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

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

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();}

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;}

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

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