perf4j settings for logback.xml

java performance unit-testing testing perf4j
khan picture khan · Jun 1, 2012 · Viewed 10.5k times · Source

hi folks I want to know exact config settings of logback.xml when it was using with perf4j. i create this configuration in logback.xml

<configuration>
    <!-- Perf4J appenders -->
    <!--
       This AsyncCoalescingStatisticsAppender groups StopWatch log messages
       into GroupedTimingStatistics messages which it sends on the
       file appender defined below
    -->
    <appender name="CoalescingStatistics" class="org.perf4j.logback.AsyncCoalescingStatisticsAppender">
        <param name="TimeSlice" value="60000"/>
        <appender-ref ref="graphExecutionTimes"/>
        <appender-ref ref="graphExecutionTPS"/>
        <!-- We add the JMX Appender reference onto the CoalescingStatistics -->
        <appender-ref ref="perf4jJmxAppender"/>
    </appender>

    <appender name="graphExecutionTimes" class="org.perf4j.logback.GraphingStatisticsAppender">
        <!-- Possible GraphTypes are Mean, Min, Max, StdDev, Count and TPS -->
        <param name="GraphType" value="Mean"/>
        <!-- The tags of the timed execution blocks to graph are specified here -->
        <param name="TagNamesToGraph" value="DESTROY_TICKET_GRANTING_TICKET,GRANT_SERVICE_TICKET,GRANT_PROXY_GRANTING_TICKET,VALIDATE_SERVICE_TICKET,CREATE_TICKET_GRANTING_TICKET" />
    </appender>

    <appender name="graphExecutionTPS" class="org.perf4j.logback.GraphingStatisticsAppender">
        <param name="GraphType" value="TPS" />
        <param name="TagNamesToGraph" value="DESTROY_TICKET_GRANTING_TICKET,GRANT_SERVICE_TICKET,GRANT_PROXY_GRANTING_TICKET,VALIDATE_SERVICE_TICKET,CREATE_TICKET_GRANTING_TICKET" />
    </appender>

    <!--
      This JMX appender creates an MBean and publishes it to the platform MBean server by
      default.
    -->
    <appender name="perf4jJmxAppender" class="org.perf4j.logback.JmxAttributeStatisticsAppender">
        <!--
          You must specify the tag names whose statistics should be exposed as
          MBean attributes.
        -->
        <TagNamesToExpose>firstBlock,secondBlock</TagNamesToExpose>
        <!--
          The NotificationThresholds param configures the sending of JMX notifications
          when statistic values exceed specified thresholds. This config states that
          the firstBlock max value should be between 0 and 800ms, and the secondBlock max
          value should be less than 1500 ms. You can also set thresholds on the Min,
          Mean, StdDev, Count and TPS statistics - e.g. firstBlockMean(<600).

        <NotificationThresholds>firstBlockMax(0-800),secondBlockMax(<1500)</NotificationThresholds>-->
        <!--
          You can also specify an optional MBeanName param, which overrides
          the default MBean name of org.perf4j:type=StatisticsExposingMBean,name=Perf4J
        -->
    </appender>

    <!-- Loggers -->
    <!--
      The Perf4J logger. Note that org.perf4j.TimingLogger is the value of the
      org.perf4j.StopWatch.DEFAULT_LOGGER_NAME constant. Also, note that
      additivity is set to false, which is usually what is desired - this means
      that timing statements will only be sent to this logger and NOT to
      upstream loggers.
    -->
    <logger name="org.perf4j.TimingLogger" additivity="false">
        <level value="INFO"/>
        <appender-ref ref="CoalescingStatistics"/>
        <appender-ref ref="perf4jFileAppender"/>
    </logger>

    <!-- This file appender is used to output aggregated performance statistics -->
    <appender name="perf4jFileAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <File>logs/perf4j.log</File>
        <encoder>
            <Pattern>%date %-5level [%thread] %logger{36} [%file:%line] %msg%n</Pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <FileNamePattern>logs/perf4j.%d{yyyy-MM-dd}.log</FileNamePattern>
        </rollingPolicy>
    </appender>
</configuration>


i got it from perf4j logback documentation . So when i tried to use this logback conf it tdidn't through any exception but it prints some strange statements which are given below 

18:26:19,945 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
18:26:19,945 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
18:26:19,945 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/home/ifkaar/Backup/eclipse/workspace/Perf4jTestProject/bin/logback.xml]
18:26:20,245 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
18:26:20,263 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [org.perf4j.logback.AsyncCoalescingStatisticsAppender]
18:26:20,308 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [CoalescingStatistics]
18:26:20,462 |-ERROR in ch.qos.logback.core.joran.action.AppenderRefAction - Could not find an appender named [graphExecutionTimes]. Did you define it below in the config file?
18:26:20,462 |-ERROR in ch.qos.logback.core.joran.action.AppenderRefAction - See http://logback.qos.ch/codes.html#appender_order for more details.
18:26:20,462 |-ERROR in ch.qos.logback.core.joran.action.AppenderRefAction - Could not find an appender named [graphExecutionTPS]. Did you define it below in the config file?
18:26:20,462 |-ERROR in ch.qos.logback.core.joran.action.AppenderRefAction - See http://logback.qos.ch/codes.html#appender_order for more details.
18:26:20,462 |-ERROR in ch.qos.logback.core.joran.action.AppenderRefAction - Could not find an appender named [perf4jJmxAppender]. Did you define it below in the config file?
18:26:20,462 |-ERROR in ch.qos.logback.core.joran.action.AppenderRefAction - See http://logback.qos.ch/codes.html#appender_order for more details.
18:26:20,471 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [org.perf4j.logback.GraphingStatisticsAppender]
18:26:20,506 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [graphExecutionTimes]
18:26:20,535 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [org.perf4j.logback.GraphingStatisticsAppender]
18:26:20,535 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [graphExecutionTPS]
18:26:20,538 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [org.perf4j.logback.JmxAttributeStatisticsAppender]
18:26:20,554 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [perf4jJmxAppender]
18:26:20,913 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.perf4j.TimingLogger] to false
18:26:20,914 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - org.perf4j.TimingLogger level set to INFO
18:26:20,914 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [CoalescingStatistics] to Logger[org.perf4j.TimingLogger]
18:26:20,914 |-ERROR in ch.qos.logback.core.joran.action.AppenderRefAction - Could not find an appender named [perf4jFileAppender]. Did you define it below in the config file?
18:26:20,914 |-ERROR in ch.qos.logback.core.joran.action.AppenderRefAction - See http://logback.qos.ch/codes.html#appender_order for more details.
18:26:20,914 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
18:26:20,930 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [perf4jFileAppender]
18:26:20,962 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
18:26:21,136 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No compression will be used
18:26:21,141 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use the pattern logs/perf4j.%d{yyyy-MM-dd}.log for the active file
18:26:21,151 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern 'logs/perf4j.%d{yyyy-MM-dd}.log'.
18:26:21,151 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
18:26:21,158 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Thu May 31 18:26:21 PKT 2012
18:26:21,161 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[perf4jFileAppender] - Active log file name: logs/perf4j.log
18:26:21,161 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[perf4jFileAppender] - File property is set to [logs/perf4j.log]

enter code here

Answer

Tomasz Nurkiewicz picture Tomasz Nurkiewicz · Jun 1, 2012

The error message is very descriptive:

18:26:20,462 |-ERROR in ch.qos.logback.core.joran.action.AppenderRefAction - Could not find an appender named [graphExecutionTimes]. Did you define it below in the config file?

[...]

18:26:20,506 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [graphExecutionTimes]

The error message explicitly asks you: Did you define [graphExecutionTimes] appender below in the config file? And in fact, this is the case, as shown above. Just switch these declarations:

<appender name="graphExecutionTimes" class="org.perf4j.logback.GraphingStatisticsAppender">
    <!-- Possible GraphTypes are Mean, Min, Max, StdDev, Count and TPS -->
    <param name="GraphType" value="Mean"/>
    <!-- The tags of the timed execution blocks to graph are specified here -->
    <param name="TagNamesToGraph" value="DESTROY_TICKET_GRANTING_TICKET,GRANT_SERVICE_TICKET,GRANT_PROXY_GRANTING_TICKET,VALIDATE_SERVICE_TICKET,CREATE_TICKET_GRANTING_TICKET" />
</appender>

<appender name="graphExecutionTPS" class="org.perf4j.logback.GraphingStatisticsAppender">
    <param name="GraphType" value="TPS" />
    <param name="TagNamesToGraph" value="DESTROY_TICKET_GRANTING_TICKET,GRANT_SERVICE_TICKET,GRANT_PROXY_GRANTING_TICKET,VALIDATE_SERVICE_TICKET,CREATE_TICKET_GRANTING_TICKET" />
</appender>

<appender name="CoalescingStatistics" class="org.perf4j.logback.AsyncCoalescingStatisticsAppender">
    <param name="TimeSlice" value="60000"/>
    <appender-ref ref="graphExecutionTimes"/>
    <appender-ref ref="graphExecutionTPS"/>
    <!-- We add the JMX Appender reference onto the CoalescingStatistics -->
    <appender-ref ref="perf4jJmxAppender"/>
</appender>

Just in case move perf4jFileAppender to the top as well. If this code snippet comes from Perf4J documentation, you should ask the authors to fix it.

Related questions

Why is processing a sorted array faster than processing an unsorted array?

Here is a piece of C++ code that shows some very peculiar behavior. For some strange reason, sorting the data miraculously makes the code almost six times faster: #include <algorithm> #include <ctime> #include <iostream> …

Read More
How can I read a large text file line by line using Java?

I need to read a large text file of around 5-6 GB line by line using Java. How can I do this quickly?

Read More
Convert Set to List without creating new List

I am using this code to convert a Set to a List: Map<String, List<String>> mainMap = new HashMap<>(); for (int i=0; i < something.size(); i++) { Set<String> set = getSet(...); //returns …

Read More