java - log4j GC的免费性能

Question

我们正在从v2.5迁移到log4j v 2.6.1(不含GC)。想衡量这如何改善了我们的应用程序(非基于Web)。

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

尽可能使用asyncloggers。唯一使用的异步附加程序是
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-> 91449K(6422528K)] 5603489K-> 91640K(7471104K)， 0.0332092 secs [时间:用户= 0.21 sys = 0.00，真实= 0.03秒]

有什么想法，如果我会缺少一些配置或其他方法来衡量这一点？

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

您的绩效目标是什么？

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

另一种类型的应用程序是响应式应用程序，需要在一段时间内对某些输入使用react。例如面向用户的应用程序(对单击使用react)或对消息或事件使用react的应用程序。在这里响应时间很重要。响应时间很难衡量。每个事件都有自己的响应时间，因此您需要进行许多测量。平均这些度量是一个坏主意!您对异常值感兴趣:它们有多少种，有多糟糕。

要测量吞吐量，请创建一个可重复的测试，其中您的应用程序将执行固定数量的工作(希望这也意味着固定数量的日志记录)。例如，处理100,000条记录或类似的记录。您测量完成此固定数量的工作需要多少时间。然后，使用log4j 2.5库几次运行此测试，使用log4j 2.6.1库几次运行此测试，并比较使用不同的log4j版本完成任务所需的时间。

尖端:

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

实际上，请确保除了log4j库版本以外没有其他更改。 (当然)使用相同的测试程序，但还要确保计算机未运行除基准测试以外的其他任务。

看一看JMH(Java基准测试工具)以帮助您编写基准测试。这有助于进行预热并避免某些基准测试陷阱。如果基准测试运行了几分钟并实际执行了整个应用程序，那么这可能就不太重要了。

响应时间是在某些工作负载下的最佳度量。建立一个测试，以某种速率将请求发送到您的应用程序，例如最大吞吐量的50％。测量所有请求完成它们所花费的时间(“服务时间”)以及异常值对后续请求的影响(“排队时间”)。一个缓慢的请求可能会对随后的许多请求产生链式 react 。此效果对您的用户而言非常真实，但不容易测量。

再次，使用log4j 2.5多次运行此测试(针对特定工作负载)，使用log4j 2.6.1多次运行该测试。

尖端:

看一下Log4j2的ResponseTimeTest中的Pacer类，以获取有关如何实现这种测试的一些想法。

HdrHistogram是有效捕获许多测量值的出色工具。

改变工作量以了解在各种负载下响应时间的表现。

要了解更多信息，请观看Gil Tene令人惊讶的演示文稿How NOT to measure latency。

垃圾收集日志选项

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

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

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

瓶颈最大的是

您可能会发现您的应用程序的瓶颈大于GC暂停的瓶颈。在这种情况下，优化GC暂停可能无济于事。始终首先关注最大的瓶颈，因为移除最大的瓶颈后，性能行为通常会完全改变。

您使用过探查器吗？我发现Java Flight Recorder(包含在JDK中)给人留下了深刻的印象。以下是示例命令行选项，用于将统计信息记录到文件profResult.jfr中，然后可以在Mission Control中打开该文件。

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

Java Flight Recorder可以让您深入了解应用程序的内存使用情况，垃圾回收发生的频率以及最常创建的对象类型。它还具有一个非常好的分析器，可帮助您放大应用程序在其CPU周期上所花费的位置。