首页 文章

log4j GC免费性能

提问于
浏览
4

我们从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>

1 回答

  • 7

    What are your performance objectives?

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

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

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

    提示:

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

    • 事实上,除了log4j库版本之外,确保没有任何变化 . 使用相同的测试程序(当然),但也要确保机器不运行除基准测试之外的其他任务 .

    • 看一下JMH(Java基准测试工具)来帮助您编写基准测试 . 这有助于预热并避免某些基准测试陷阱 . 如果基准测试运行几分钟并实际执行完整的应用程序,这可能不那么重要 .

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

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

    提示:

    • 看看Log4j2的 ResponseTimeTest 中的Pacer类,了解如何实现这样的测试 .

    • HdrHistogram是有效捕获多个测量值的绝佳工具 .

    • 改变工作量以了解响应时间在各种负载下的行为 .

    • 要了解更多信息,请观看Gil Tene的精彩演讲How NOT to measure latency .

    Garbage Collection log options

    如果您只想查看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有多少个集合?在GC中花费的总时间是多少?最后,集合的直方图暂停了什么?

    Biggest bottleneck first

    您可能会发现您的应用程序存在比GC暂停更大的瓶颈 . 在那里面案例,优化GC暂停可能没有多大帮助 . 始终首先关注最大的瓶颈,因为当最大的瓶颈被消除时,性能行为通常会完全改变 .

    你使用过探查器吗?我发现Java Flight Recorder(包含在JDK中)非常令人印象深刻 . 下面是将统计信息记录到文件_1183858中的示例命令行选项,然后可以在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周期 .

相关问题