2

My application is using logback. Now I want to use perf4j 0.9.16 for my current application. The configuration comes from http://perf4j.codehaus.org/apidocs/org/perf4j/logback/package-summary.html

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <FileNamePattern>/var/log/myapp/myapp.log.%d{yyyy-MM-dd}</FileNamePattern>
    </rollingPolicy>
    <encoder>
        <pattern>%d %5p | %t | %-55logger{55} | %m %n</pattern>
    </encoder>
</appender>

<appender name="perf4jFileAppender" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
        <FileNamePattern>/var/log/myapp/myapp.timer.%d{yyyy-MM-dd}</FileNamePattern>
    </rollingPolicy>
    <encoder>
        <Pattern>%date %-5level [%thread] %logger{36} [%file:%line] %msg%n</Pattern>
    </encoder>
</appender>

<logger name="org.perf4j.TimingLogger" level="DEBUG" additivity="false">
    <appender-ref ref="perf4jFileAppender"/>
</logger>

<root level="INFO">
    <appender-ref ref="file"/>
</root>

myapp.log is still worked as before but myapp.timer is empty file. It logs to console like this:

start[1430914241369] time[4] tag[firstMethod.success] message[OK]
start[1430914241375] time[0] tag[secondMethod.success] message[OK]

I've tried this perf4j settings for logback.xml, but it can't help. Any idea?

Thank you.

===========================================

Update.

With <configuration debug="true">, application logs:

14:45:57,434 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/var/app/tomcat/webapps/myapp/WEB-INF/classes/logback.xml]
14:45:57,506 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
14:45:57,512 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Namingappender as [file]
14:45:57,533 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA- Pushing component [rollingPolicy] on top of the object stack.
14:45:57,561 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No compression will be used
14:45:57,563 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use thepattern /var/log/myapp/myapp.log.%d{yyyy-MM-dd} for the active file
14:45:57,569 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern '/var/log/myapp/myapp.log.%d{yyyy-MM-dd}'.
14:45:57,569 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
14:45:57,572 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Wed May 06     14:45:57 CEST 2015
14:45:57,573 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA- Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
14:45:57,574 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA- Pushing component [encoder] on top of the object stack.
14:45:57,597 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[file] - Active log file name: /var/log/myapp/myapp.log.2015-05-06
14:45:57,597 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[file] - File property is set to [null]
14:45:57,598 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.rolling.RollingFileAppender]
14:45:57,598 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Namingappender as [perf4jFileAppender]
14:45:57,598 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA- Pushing component [rollingPolicy] on top of the object stack.
14:45:57,599 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - No compression will be used
14:45:57,599 |-INFO in c.q.l.core.rolling.TimeBasedRollingPolicy - Will use thepattern /var/log/myapp/myapp.timer.%d{yyyy-MM-dd} for the active file
14:45:57,600 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - The date pattern is 'yyyy-MM-dd' from file name pattern '/var/log/myapp/myapp.timer.%d{yyyy-MM-dd}'.
14:45:57,600 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Roll-over at midnight.
14:45:57,600 |-INFO in c.q.l.core.rolling.DefaultTimeBasedFileNamingAndTriggeringPolicy - Setting initial period to Wed May 06     14:45:57 CEST 2015
14:45:57,600 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA- Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
14:45:57,600 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA- Pushing component [encoder] on top of the object stack.
14:45:57,601 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[perf4jFileAppender] - Active log file name: /var/log/myapp/myapp.timer.2015-05-06
14:45:57,601 |-INFO in ch.qos.logback.core.rolling.RollingFileAppender[perf4jFileAppender] - File property is set to [null]
14:45:57,601 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.perf4j.TimingLogger] to DEBUG
14:45:57,601 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting additivity of logger [org.perf4j.TimingLogger] to false
14:45:57,601 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [perf4jFileAppender] to Logger[org.perf4j.TimingLogger]
14:45:57,604 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
14:45:57,604 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [file] to Logger[ROOT]
14:45:57,604 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
Community
  • 1
  • 1
Duc Vu
  • 27
  • 6
  • I'm missing the name of the logger in your example. And I don't understand what you mean by "logs to console"; are the two lines from the stdout of your application (the console) or from `myapp.log` – Aaron Digulla May 06 '15 at 12:38
  • I mean application console, not myapp.log – Duc Vu May 06 '15 at 12:43
  • You get output on the console with the config above? That's certainly not possible. Either you have code which isn't using `slf4j` or the config above isn't being used. – Aaron Digulla May 06 '15 at 12:51
  • Steffen figures out the issue. Thank you for your supports! – Duc Vu May 06 '15 at 13:21

2 Answers2

3

This happens when you pass your own logger to one of the Slf4JStopWatch constructors. Either use the default constructor (new Slf4JStopWatch()) or change your config file to something like

<logger name="com.example.MyOwnPerformanceLogger" level="DEBUG" additivity="false">
    <appender-ref ref="perf4jFileAppender"/>
</logger>

org.perf4j.TimingLogger is just the default logger name for stopwatches.

By the way: One of your <pattern> elements is in capitalized.

steffen
  • 16,138
  • 4
  • 42
  • 81
  • You can also try to put all performance loggers into a certain package and then configure a logger on the package. That would catch every specific logger. But the key is that your logger name in the config and the one passed to the `Slf4JStopWatch` constructor must match somehow. – Aaron Digulla May 06 '15 at 13:12
0

The code looks correct. Note that logback loads config from a couple of places, so it's possible that your config isn't used. To find out what it going on, replace <configuration> with <configuration debug="true">.

Logback will then print it's own setup while it parses the configuration. If you don't see anything, then there is an additional logback.xml file somewhere on the classpath or logback-test.xml or logback.groovy.

Aaron Digulla
  • 321,842
  • 108
  • 597
  • 820