logback не печатает perf4j в файл журнала

Question

Мое приложение использует логин. Теперь я хочу использовать perf4j 0.9.16 для моего текущего приложения. Конфигурация происходит от 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 по-прежнему работает, как и раньше, но myapp.timer пустой файл. Он входит в консоль, как это:

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

Я попробовал этот perf4j settings for logback.xml, но он не может помочь. Любая идея?

спасибо.

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

Обновление.

С <configuration debug="true">, журналы приложений:

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. 

Answer 1

Это происходит, когда вы передаете свой собственный регистратор одному из конструкторов Slf4JStopWatch. Либо использовать конструктор по умолчанию (new Slf4JStopWatch()) или изменить конфигурационный файл, чтобы что-то вроде

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

org.perf4j.TimingLogger только имя регистратора по умолчанию для секундомеров.

К слову: Один из ваших элементов <pattern> находится в заглавной форме.

Answer 2

Код выглядит правильно. Обратите внимание, что logback загружает конфигурацию из нескольких мест, поэтому возможно, что ваша конфигурация не используется. Чтобы узнать, что происходит, замените <configuration> на <configuration debug="true">.

После этого журнал будет распечатывать собственную настройку, в то время как она анализирует конфигурацию. Если вы ничего не видите, то есть дополнительный файл logback.xml где-то на пути к классу или logback-test.xml или logback.groovy.