search

ofpay / logback-mdc-ttl

logback扩展，集成transmittable-thread-local支持跨线程池的mdc跟踪
Apache License 2.0
153 stars 38 forks source link

slf4j+logback的MDC原生就支持多线程的困惑 #1

Closed taotao365s closed 7 years ago

taotao365s commented 7 years ago

我在验证slf4j+logback的MDC时，是支持在多线程中输出；还需要你这种扩展么？

 @Test
    public void run32() throws IOException {
        String token = UUID.randomUUID().toString();

        MDC.put("G_TOKEN", token);
        log.debug("token is {}", token);

        new Thread(new Runnable() {
            @Override
            public void run() {
                log.debug("thread-2 start");

                log.debug("map={}", MDC.getCopyOfContextMap());

                new Thread(new Runnable() {
                    @Override
                    public void run() {
                        log.debug("thread-3 start");

                        log.debug("map={}", MDC.getCopyOfContextMap());

                        Runnable runable = new Runnable() {
                            @Override
                            public void run() {
                                log.debug("abc");
                            }
                        };

                        ExecutorService executor = Executors.newFixedThreadPool(1);
                        executor.submit(runable);
                    }
                }).start();

            }
        }).start();

        System.in.read();
        MDC.clear();
    }

输出

2017/07/20 13:23:15.433 DEBUG [main][7f7f35f0-7adf-4792-810d-0a6c56502b04] com.spy.test.log.MDCTest:39>>token is 7f7f35f0-7adf-4792-810d-0a6c56502b04
2017/07/20 13:23:15.437 DEBUG [Thread-0][7f7f35f0-7adf-4792-810d-0a6c56502b04] com.spy.test.log.MDCTest$1:44>>thread-2 start
2017/07/20 13:23:15.437 DEBUG [Thread-0][7f7f35f0-7adf-4792-810d-0a6c56502b04] com.spy.test.log.MDCTest$1:46>>map={G_TOKEN=7f7f35f0-7adf-4792-810d-0a6c56502b04}
2017/07/20 13:23:15.439 DEBUG [Thread-1][7f7f35f0-7adf-4792-810d-0a6c56502b04] com.spy.test.log.MDCTest$1$1:51>>thread-3 start
2017/07/20 13:23:15.440 DEBUG [Thread-1][7f7f35f0-7adf-4792-810d-0a6c56502b04] com.spy.test.log.MDCTest$1$1:53>>map={G_TOKEN=7f7f35f0-7adf-4792-810d-0a6c56502b04}
2017/07/20 13:23:15.446 DEBUG [pool-2-thread-1][7f7f35f0-7adf-4792-810d-0a6c56502b04] com.spy.test.log.MDCTest$1$1$1:59>>abc
wuwen5 commented 7 years ago

这个测试没有验证线程池的问题哦，这种情况下测试肯定是好的。

线程池在共享的时候，假设第二次调用的时候，如果线程池是新扩展的线程来执行，那么没有问题，如果是复用池中上一次执行完的空闲线程，那么就取不到这次的本地变量值了， 所以第一次执行是正常的。 你可以仔细看下transmittable-thread-local#功能详细介绍

wuwen5 commented 7 years ago

而且你应该是使用的logback-1.1.5以下的版本测试的吧，1.1.5以上的高版本即使子线程测试也是不生效的。

wuwen5 commented 7 years ago

把你的测试代码改成这样就理解了.

static ExecutorService executor = Executors.newFixedThreadPool(1);

    @Test
    public void run32() throws IOException {

        for (int i = 0; i < 2; i++) {

            String token = UUID.randomUUID().toString();

            MDC.put("G_TOKEN", token);
            log.debug("token is {}", token);

            new Thread(new Runnable() {
                @Override
                public void run() {
                    log.debug("thread-2 start");

                    log.debug("map={}", MDC.getCopyOfContextMap());

                    new Thread(new Runnable() {
                        @Override
                        public void run() {
                            log.debug("thread-3 start");

                            log.debug("map={}", MDC.getCopyOfContextMap());

                            Runnable runable = new Runnable() {
                                @Override
                                public void run() {
                                    log.debug("abc");
                                }
                            };

                            executor.submit(runable);
                        }
                    }).start();

                }
            }).start();

            //System.in.read();
            MDC.clear();
            sleep(1000)
        }

        sleep(2000)
    }
2017-07-20 14:22:47.653|f3bd42c3-9e9f-4fb2-a1db-fec6e8481689|DEBUG|run32|com.Test:45|main|token is f3bd42c3-9e9f-4fb2-a1db-fec6e8481689|""
2017-07-20 14:22:47.670|f3bd42c3-9e9f-4fb2-a1db-fec6e8481689|DEBUG|run|com.Test$1:50|Thread-14|thread-2 start|""
2017-07-20 14:22:47.672|f3bd42c3-9e9f-4fb2-a1db-fec6e8481689|DEBUG|run|com.Test$1:52|Thread-14|map={G_TOKEN=f3bd42c3-9e9f-4fb2-a1db-fec6e8481689}|""
2017-07-20 14:22:47.687|f3bd42c3-9e9f-4fb2-a1db-fec6e8481689|DEBUG|run|com.Test$1$2:57|Thread-15|thread-3 start|""
2017-07-20 14:22:47.688|f3bd42c3-9e9f-4fb2-a1db-fec6e8481689|DEBUG|run|com.Test$1$2:59|Thread-15|map={G_TOKEN=f3bd42c3-9e9f-4fb2-a1db-fec6e8481689}|""
2017-07-20 14:22:47.697|f3bd42c3-9e9f-4fb2-a1db-fec6e8481689|DEBUG|run|com.Test$1$2$3:65|pool-1-thread-1|abc|""
2017-07-20 14:22:48.676|df1871aa-9689-4125-b778-4f69b092cac0|DEBUG|run32|com.Test:45|main|token is df1871aa-9689-4125-b778-4f69b092cac0|""
2017-07-20 14:22:48.677|df1871aa-9689-4125-b778-4f69b092cac0|DEBUG|run|com.Test$1:50|Thread-16|thread-2 start|""
2017-07-20 14:22:48.678|df1871aa-9689-4125-b778-4f69b092cac0|DEBUG|run|com.Test$1:52|Thread-16|map={G_TOKEN=df1871aa-9689-4125-b778-4f69b092cac0}|""
2017-07-20 14:22:48.679|df1871aa-9689-4125-b778-4f69b092cac0|DEBUG|run|com.Test$1$2:57|Thread-17|thread-3 start|""
2017-07-20 14:22:48.679|df1871aa-9689-4125-b778-4f69b092cac0|DEBUG|run|com.Test$1$2:59|Thread-17|map={G_TOKEN=df1871aa-9689-4125-b778-4f69b092cac0}|""
2017-07-20 14:22:48.680|f3bd42c3-9e9f-4fb2-a1db-fec6e8481689|DEBUG|run|com.Test$1$2$3:65|pool-1-thread-1|abc|""

+ 2017-07-20 14:22:48.679|df1871aa-9689-4125-b778-4f69b092cac0|DEBUG|run|com.Test$1$2:59|Thread-17|map={G_TOKEN=df1871aa-9689-4125-b778-4f69b092cac0}|""
- 2017-07-20 14:22:48.680|f3bd42c3-9e9f-4fb2-a1db-fec6e8481689|DEBUG|run|com.Test$1$2$3:65|pool-1-thread-1|abc|""
taotao365s commented 7 years ago

@wuwen5 好的，多谢指正，我再细看一下

Qsimple commented 7 years ago

早上过来想了下，简单粗暴点在Runnable上再封装一个Runnable就好了，我在学习学习TTL的代码吧

public class MDCTask implements Runnable{

    private final Map<String, String> parentMDCMap;

    private final Runnable task;

    @Override
    public void run() {
        MDC.setContextMap(parentMDCMap);
        task.run();
        MDC.clear();
    }
    public static MDCTask getMDCTask(final Runnable task)
    {
        Map<String, String> parentMDCMap = MDC.getCopyOfContextMap();
        return new MDCRunnableFactory(task, parentMDCMap); 
    }
    private MDCRunnableFactory(final Runnable task, Map<String, String> parentMDCMap)
    {
        this.parentMDCMap = parentMDCMap;
        this.task = task;
    }
}