log4j GC免费性能

Question

log4j GC免费性能

Din*_*inu 4 java configuration logging log4j log4j2

我们从v2.5迁移到log4j v 2.6.1(不含GC).我想测量一下如何改进我们的应用程序(非基于Web).

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

尽可能使用asyncloggers.唯一使用的异步appender是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秒] [次:用户= 0.21 sys = 0.00,实际= 0.03秒]

任何想法,如果我会缺少一些配置或其他方法来衡量这个？

Java版本:JRE 1.8u40 64位

    <?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>

Run Code Online (Sandbox Code Playgroud)

Answer 1

Rem*_*pma 8

你的表现目标是什么？

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

不同类型的应用程序是响应式应用程序,需要在某段时间内对某些输入做出反应.示例是面向用户的应用程序(对点击做出反应)或对消息或事件做出反应的应用程序.这里的响应时间很重要.响应时间可能更难测量.每个事件都有自己的响应时间,因此您最终会进行多次测量.平均这些测量是一个坏主意!您对异常值感兴趣:它们有多少以及它们有多糟糕.

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

提示:

确保对两个测试使用相同的log4j2配置.
实际上,除了log4j库版本之外,确保没有任何变化.使用相同的测试程序(当然),但也要确保机器不运行除基准测试之外的其他任务.
看一下JMH(Java基准测试工具)来帮助您编写基准测试.这有助于预热并避免某些基准测试陷阱.如果基准测试运行几分钟并实际执行完整的应用程序,这可能不那么重要.

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

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

提示:

看一下Log4j2中的Pacer类,ResponseTimeTest了解如何实现这样的测试.
HdrHistogram是一个有效捕获许多测量的好工具.
改变工作量以了解响应时间在各种负载下的行为.
要了解更多信息,请观看Gil Tene的开眼展示如何不测量延迟.

垃圾收集日志选项

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

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

Run Code Online (Sandbox Code Playgroud)

也许最简单的比较方法是使用一些固定数量的工作,如上面的吞吐量测试.GC日志中最重要的数字是ApplicationStoppedTime(这不仅包括GC暂停时间,还包括将所有线程带到安全点所花费的时间).然后收集统计数据:使用Log4j 2.5时应用程序有多少个小集合与Log4j 2.6.1有多少个集合？在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

Run Code Online (Sandbox Code Playgroud)

Java Flight Recorder可以让您深入了解应用程序的内存使用情况,垃圾收集发生的频率,以及最常创建的对象类型.它还有一个非常好的分析器,可以帮助您放大应用程序的CPU周期.

归档时间：	9 年，7 月前
查看次数：	781 次
最近记录：	8 年，3 月前