log4j无GC性能

Question

我们正在从v2.5迁移到log4j v 2.6.1（无GC）。想衡量一下这是如何改进我们的应用程序（非基于web的）。

我们在配置中所做的更改：

• 尽可能使用异步程序。唯一使用的异步附加程序是SMTP。
• 仅使用支持的模式（%d{dd MMM yyyy HH： mm： ss， SSS}）。
• 没有将log4j2.is.webapp显式设置为false，因为我们没有servlet类，这意味着启用了无垃圾日志记录。

为了比较性能，我们记录了GC输出-新版本有时每个GC（次要）需要更多时间。它确实按预期预分配了一些内存。分析确实显示分配了固定内存。

例如2016-06-28T04:39:49.015 0100: 1078.995：[GC（分配失败）[PSYoungGen：5603306K-

如果我遗漏了一些配置或其他方法来衡量这一点，有什么想法吗？

Java版本：JRE 1.8u40 64bit

    <?xml version="1.0" encoding="UTF-8"?>
<Configuration status="info" name="foo" packages="">
    <Appenders>
        <!--old appenders-->
        <!--<Async name="AsynchronousConsoleAppender" blocking="false" bufferSize="20000">-->
            <!--<AppenderRef ref="ConsoleAppender"/>-->
        <!--</Async>-->
        <!--<Async name="AsynchronousFoo1Appender" blocking="false" bufferSize="20000">-->
            <!--<AppenderRef ref="Foo1RollingFileAppender"/>-->
        <!--</Async>-->
        <!--<Async name="AsynchronousFoo2Appender" blocking="false" bufferSize="20000">-->
            <!--<AppenderRef ref="Foo2RollingFileAppender"/>-->
        <!--</Async>-->
        <!--<Async name="AsynchronousFoo3Appender" blocking="false" bufferSize="20000">-->
            <!--<AppenderRef ref="Foo3RollingFileAppender"/>-->
        <!--</Async>-->

        <Async name="AsynchronousSMTPAppender" blocking="false">
            <Filters>
                <RegexFilter regex=".*Reason: Refused invalid message \(Missing fo\):.*" onMatch="DENY"
                             onMismatch="NEUTRAL"/>
                <RegexFilter regex=".*log4j lib is not in the classpath java\.lang\.NoClassDefFoundError.*"
                             onMatch="DENY"
                             onMismatch="NEUTRAL"/>
                <ThresholdFilter level="${sys:smtpThreshold}" onMatch="ACCEPT" onMismatch="DENY"/>
            </Filters>
            <AppenderRef ref="smtpAppender"/>
        </Async>

        <Console name="ConsoleAppender">
            <PatternLayout>
                <pattern>%d{dd MMM yyyy HH:mm:ss.SSS} [L2] &lt;%t&gt; [%-5p] [%c{1}] %m%n</pattern>
            </PatternLayout>
        </Console>

        <RollingFile name="Foo1RollingFileAppender" fileName="${sys:log.log-name}.log"
                     filePattern="${sys:log.log-name}-%d{yyyy-MM-dd}.log" append="true">
            <PatternLayout>
                <pattern>%d{dd MMM yyyy HH:mm:ss.SSS} [L2] %m%n</pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true"/>
            </Policies>
        </RollingFile>

        <RollingFile name="Foo2RollingFileAppender" fileName="${sys:log.log-name}.log"
                     filePattern="${sys:log.log-name}-%d{yyyy-MM-dd}.log" append="true">
            <ThresholdFilter level="INFO" onMatch="ACCEPT"/>
            <PatternLayout>
                <pattern>%d{dd MMM yyyy HH:mm:ss.SSS} [L2] %m%n</pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true"/>
            </Policies>
        </RollingFile>

        <RollingFile name="Foo3RollingFileAppender" fileName="${sys:log.log-name}.log"
                     filePattern="${sys:log.log-name}-%d{yyyy-MM-dd}.log" append="true">
            <ThresholdFilter level="INFO" onMatch="ACCEPT"/>
            <PatternLayout>
                <pattern>%d{dd MMM yyyy HH:mm:ss.SSS} [L2] %m%n</pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy modulate="true"/>
            </Policies>
        </RollingFile>

        <!-- the buffer size needs to be bigger than the backlog.-->
        <ThrottlingSMTP name="smtpAppender" to="${sys:technicalIssueRecipients}"
                        from="test-${sys:mode}@xxx.com"
                        subject="test [${sys:instance.name}] Errors"
                        smtpHost="${sys:smtp.host}"
                        throttleTokens="3" throttleTokenRespawnMs="20000" throttleRestTimeMs="5000"
                        throttleMaxBacklogSize="100" ignoreExceptions="true">
            <HtmlLayoutWithTimesInUTC contentType="text/html"/>
        </ThrottlingSMTP>

    </Appenders>

    <Loggers>
        <!-- ============================== -->
        <!-- Noisy Loggers                  -->
        <!-- ============================== -->

        <AsyncLogger name="com.package1" level="fatal"/>
        <AsyncLogger name="com.package2" level="warn"/>

        <AsyncLogger name="com.package3" level="error"/>
        <AsyncLogger name="com.package4" level="error"/>
        <AsyncLogger name="com.package5" level="error"/>
        <AsyncLogger name="com.package6" level="error"/>

        <AsyncLogger name="com.package7" level="warn"/>
        <AsyncLogger name="com.package8" level="warn"/>
        <AsyncLogger name="com.package9" level="warn"/>
        <AsyncLogger name="com.package10" level="warn"/>
        <AsyncLogger name="com.package11" level="warn"/>
        <AsyncLogger name="com.package12" level="warn"/>
        <AsyncLogger name="com.package13" level="warn" />

        <AsyncLogger name="com.package14" level="warn"/>
        <AsyncLogger name="com.package15" level="warn"/>
        <AsyncLogger name="com.package16" level="warn"/>
        <AsyncLogger name="com.package17" level="warn"/>
        <AsyncLogger name="com.package18" level="warn"/>
        <AsyncLogger name="com.package19" level="warn"/>
        <AsyncLogger name="com.package20" level="warn"/>
        <AsyncLogger name="com.package21" level="warn"/>
        <AsyncLogger name="com.package22" level="warn"/>

        <AsyncLogger name="org.springframework" level="warn"/>
        <AsyncLogger name="com.package23" level="error"/>

        <AsyncLogger name="com.package24" level="warn"/>
        <AsyncLogger name="com.package25" level="warn"/>\
        <AsyncLogger name="com.package26" level="warn"/>
        <AsyncLogger name="com.package27" level="warn"/>

        <!-- ============================== -->
        <!-- DEBUG Loggers                  -->
        <!-- ============================== -->

        <AsyncLogger name="com.package28" level="debug"/>
        <AsyncLogger name="com.package29" level="debug"/>

        <!-- ============================== -->
        <!-- Different File loggers         -->
        <!-- ============================== -->

        <AsyncLogger name="EVENT_NOTIFICATION" additivity="false" level="${sys:event.logger.threshold}">
            <AppenderRef ref="ConsoleAppender"/>
        </AsyncLogger>


        <AsyncLogger name="FOO2_LOG" additivity="false">
            <AppenderRef ref="Foo2RollingFileAppender"/>
        </AsyncLogger>


        <AsyncLogger name="FOO3_LOG" additivity="false">
            <AppenderRef ref="Foo3RollingFileAppender"/>
        </AsyncLogger>

        <AsyncLogger name="FOO1_LOG" additivity="false">
            <appender-ref ref="Foo1FileAppender"/>
        </AsyncLogger>

        <Root level="info">
            <AppenderRef ref="ConsoleAppender"/>
            <AppenderRef ref="AsynchronousSMTPAppender"/>
        </Root>
    </Loggers>
</Configuration>

Answer 1

你的绩效目标是什么？

这一点很重要：对于某些应用程序来说，重要的是在尽可能短的时间内完成尽可能多的工作。这是吞吐量，通常以操作/时间来衡量。这种应用程序的一个很好的例子是批处理作业。

另一种应用程序是响应性应用程序，需要在一段时间内对某些输入做出反应。例如，面向用户的应用程序（对单击作出反应）或对消息或事件作出反应的应用程序。在这里，响应时间很重要。响应时间可能更难测量。每个事件都有自己的响应时间，因此最终需要进行许多测量。平均这些测量值是个坏主意！你对异常值感兴趣：有多少异常值，它们有多糟糕。

为了测量吞吐量，请创建一个可重复的测试，在该测试中，您的应用程序执行固定数量的工作（希望这也意味着固定数量的日志记录）。例如，处理100000条记录或类似的内容。您可以测量完成这一固定工作量所需的时间。然后用log4j 2.5库运行该测试几次，用log4j 2.6.1库运行几次，并比较用不同的log4j版本完成任务所需的时间。

小贴士：

• 确保两个测试使用相同的log4j2配置

响应时间最好在一些工作负载下测量。构建一个测试，以一定的速率向应用程序发送请求，比如说最大吞吐量的50%。测量所有请求完成所需的时间（“服务时间”）以及慢速异常值对随后的请求的影响（“排队时间”）。一个缓慢的请求可能会对后续的许多请求产生连锁反应。这种效果对用户来说非常真实，但不容易衡量。

同样，使用log4j 2.5多次运行此测试（针对特定工作负载），使用log4j 2.6.1多次运行此测试。

小贴士：

• 查看Log4j2的ResponseTimeTest中的Pacer类，了解如何实现这样的测试
• HdrHistogram是有效捕获许多测量值的绝佳工具
• 改变工作负载，了解在各种负载下响应时间的行为
• 要了解更多信息，请观看Gil Tene的《如何不测量延迟》一文

垃圾收集日志选项

如果您只是想查看GC日志中的差异，我建议至少设置以下选项：

-XX:+UnlockDiagnosticVMOptions -verbose:gc -XX:+PrintGCDetails
-XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution 
-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime

也许最简单的比较方法是使用一些固定的工作量，如上面的吞吐量测试。GC日志中最重要的数字是ApplicationStoppedTime（这不仅包括GC暂停时间，还包括将所有线程置于安全点所花费的时间）。然后收集统计数据：当使用Log4j 2.5时，应用程序有多少次要集合，而使用Log4j 2.6.1时有多少？GCs的总时间是多少？最后，收集暂停的直方图是什么样子的？

首先是最大的瓶颈

您可能会发现应用程序的瓶颈比GC暂停更大。在这种情况下，优化GC暂停可能没有多大帮助。始终首先关注最大的瓶颈，因为当最大的瓶颈被移除时，性能行为通常会完全改变。

你用过探查器吗？我发现Java飞行记录器（包括在JDK中）非常令人印象深刻。下面是将统计信息记录到文件中的命令行选项示例。jfr可以在任务控制中打开。

java -XX:+UnlockCommercialFeatures -XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints 
-XX:+FlightRecorder -XX:StartFlightRecording=duration=10m,filename=profResult.jfr
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution
-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime  -cp 
.;HdrHistogram-2.1.8.jar;disruptor-3.3.4.jar;log4j-api-2.6.1.jar;log4j-core-2.6.1.jar;myApp.jar
com.mycomp.Benchmark

JavaFlight Recorder可以让您了解应用程序的内存使用情况、垃圾回收机制发生的频率，以及最常创建的对象类型。它还有一个非常好的分析器来帮助您放大应用程序在哪里花费其CPU周期。