perf4J with MDC

Question

Does anyone know if perf4J has support for log4j MDC. All my log statements are appended with MDC values, however the perf4J log statements don't show the MDC value.

Please see below, I expect MDCMappedValue to be shown at the end of [TimingLogger] log statements as well.

18:35:48,038 INFO [LoginAction] Logging in user kermit into application - MDCMappedValue 18:35:48,749 INFO [PostAuthenticationHandler] doPostAuthenticate() started - MDCMappedValue 18:36:03,653 INFO [PostAuthenticationHandler] Profile Loaded for kermit - MDCMappedValue 18:36:08,224 INFO [TimingLogger] start[1300905347914] time[20310] tag[HTTP.Success] message[/csa/login.seam] -
18:36:09,142 INFO [TimingLogger] start[1300905368240] time[902] tag[HTTP.Success] message[/csa/home.seam] -

Did you find a solution to your problem? – Paaske Apr 06 '12 at 07:36 — Paaske, Apr 06 '12 at 07:36

score 0 · Answer 1 · answered Mar 26 '12 at 18:43

My test seems to produce the expected results. Notice that I use the Log4JStopWatch, not the LoggingStopWatch:

package test;

import org.apache.log4j.Logger;
import org.apache.log4j.MDC;
import org.perf4j.StopWatch;
import org.perf4j.log4j.Log4JStopWatch;

public class Perf4jMdcTest {
    private Logger _ = Logger.getLogger(Perf4jMdcTest.class);

    public static void main(String[] args) {
        for (int i = 0; i < 3; i++) {
            new Thread() {
                @Override
                public void run() {
                    MDC.put("id", getName());
                    Perf4jMdcTest perf4jMdcTest = new Perf4jMdcTest();
                    perf4jMdcTest.test1();
                    perf4jMdcTest.test2();
                    MDC.clear();
                }
            }.start();
        }
    }

    private void test1() {
        _.info("test1");
        StopWatch stopWatch = new Log4JStopWatch();
        stopWatch.start("a");
        try { Thread.sleep(300); } 
        catch (InterruptedException e) { }
        stopWatch.stop();
    }

    private void test2() {
        _.info("test2");
        StopWatch stopWatch = new Log4JStopWatch();
        stopWatch.start("b");
        try { Thread.sleep(600); } 
        catch (InterruptedException e) { }
        stopWatch.stop();

    }
}

My log4j.properties is as follows:

log4j.rootLogger=debug, stdout

log4j.appender.stdout=org.apache.log4j.ConsoleAppender
log4j.appender.stdout.layout=org.apache.log4j.PatternLayout

# Pattern to output the caller's file name and line number.
log4j.appender.stdout.layout.ConversionPattern=%d [%-5p] MDC:%X{id} - %m%n

And the output is:

2012-03-26 20:37:43,049 [INFO ] MDC:Thread-1 - test1
2012-03-26 20:37:43,050 [INFO ] MDC:Thread-3 - test1
2012-03-26 20:37:43,049 [INFO ] MDC:Thread-2 - test1
2012-03-26 20:37:43,353 [INFO ] MDC:Thread-2 - start[1332787063053] time[300] tag[a]
2012-03-26 20:37:43,353 [INFO ] MDC:Thread-2 - test2
2012-03-26 20:37:43,353 [INFO ] MDC:Thread-1 - start[1332787063053] time[300] tag[a]
2012-03-26 20:37:43,354 [INFO ] MDC:Thread-1 - test2
2012-03-26 20:37:43,353 [INFO ] MDC:Thread-3 - start[1332787063053] time[300] tag[a]
2012-03-26 20:37:43,354 [INFO ] MDC:Thread-3 - test2
2012-03-26 20:37:43,955 [INFO ] MDC:Thread-2 - start[1332787063354] time[600] tag[b]
2012-03-26 20:37:43,955 [INFO ] MDC:Thread-1 - start[1332787063354] time[601] tag[b]
2012-03-26 20:37:43,955 [INFO ] MDC:Thread-3 - start[1332787063354] time[601] tag[b]

perf4J with MDC

1 Answers1