How to Use Mdc with Thread Pools

Java ExecutorService and ThreadPoolExecutor

As I expected you are failing because of thread-locality. The line here is almost certainly returning null

MDC.get(ORIG_LOG_FILE_NAME)

When/where do you MDC.put? The issue here is that MDC uses a thread-local map. So when you are running the Callable it will attempt to log in a separate thread. That thread has not been registered with MDC and get will return null.

Imagine your application looks similar to

Main-Thread
  MDC.put -> sets thread-local-map(Main-Thread, ORIG_LOG_FILE_NAME)

Executor-Thread-1
Executor-Thread-2
Executor-Thread-N

Now when you are in Executor-Thread-1..N it will do

Executor-Thread-N
    MDC.get(Executor-Thread-N, ORIG_LOG_FILE_NAME)

It will return null

If you run outside of the Executor Service threads it works

Main-Thread
   MDC.get(Main-Thread, ORIG_LOG_FILE_NAME) // will be non-null

So your next question is, "Why is it not failing with an ExecutorService?" It probably is or would be and may not be reported. I do notice your order of submission to the ExecutorService is different then TPE. May want to try and match them up and see if you get the same output.

Edit: May want to try this as a fix

ThreadFactory threadFactory = new ThreadFactory() {
    public Thread newThread(final Runnable r) {
        return Executors.defaultThreadFactory().newThread(new Runnable(){
            public void run() {
                MDC.put(ORIG_LOG_FILE_NAME, fileName);
                r.run();
            }
        });
    }
};

Additional thread pools within Tomcat apps

It's hard to give a general answer to this question, because it depends so much on the specific workload. There's no substitute for testing and profiling your own application. Here are some things to think about, however.

Running a CPU-bound task in a separate thread pool isn't guaranteed to give you any performance benefit at all. There are two main reasons it might be beneficial:

1. When one thread submits a task to an executor to run on a separate thread, it can then continue on to do other work concurrently.
2. If the task can be broken down into multiple sub-tasks that are each run on separate threads, you can take advantage of parallel processing on multiple CPU cores to get it done faster.

The costs of having more threads are:

1. Memory allocated to each thread.
2. Latency caused by context switching when the OS reallocates CPU time from one thread to another.

The defaults for the Tomcat request thread pool size are based on the common situation that threads are spending a lot of time blocking on I/O: reading the request over the network, making database queries and updates, and writing the response back to the client. This means that these threads can't make use of all available CPU time and it is beneficial to have a lot more threads than CPU cores so that blocked threads can be preempted by ones that need CPU time.

So, a big question is what is invoking these tasks: is it a request thread? If so, what does that request thread do while the task is in progress? Is it making blocking I/O calls? Is it just waiting for the task to complete?

If most of your requests are invoking one of these CPU-intensive tasks and then blocked waiting for it to complete, and if these tasks are not split up to run in parallel on multiple cores, then you might not get any benefit from running tasks in a separate thread pool. It might be better to avoid the overhead of context switching and run these tasks on the request thread. If most of the requests handled by your service run this type of task, then you might want to reduce the number of request threads in the Tomcat thread pool, because your actual concurrency will be limited by the available CPU time. You could end up with a large number of waiting threads and high response latency. These requests might then time out on the client side, wasting a lot of server resources on requests that ultimately fail.

How to retain slf4j MDC logging context in CompletableFuture?

The most readable way I solved this problem was as below -

---------------Thread utils class--------------------

public static Runnable withMdc(Runnable runnable) {
    Map<String, String> mdc = MDC.getCopyOfContextMap();
    return () -> {
        MDC.setContextMap(mdc);
        runnable.run();
    };
}

public static <U> Supplier<U> withMdc(Supplier<U> supplier) {
    Map<String, String> mdc = MDC.getCopyOfContextMap();
    return (Supplier) () -> {
        MDC.setContextMap(mdc);
        return supplier.get();
    };
}

---------------Usage--------------

CompletableFuture.supplyAsync(withMdc(() -> someSupplier()))
                 .thenRunAsync(withMdc(() -> someRunnable())
                 ....

WithMdc in ThreadUtils would have to be overloaded to include other functional interfaces which are accepted by CompletableFuture

Please note that the withMdc() method is statically imported to improve readability.

---

Related Topics