Am I the last to know about MDC?

Long time no see. I’m Walking. Today bring you a log of knowledge – MDC, DO not know you do not know, anyway, I just know 😂 recently

First the MDC

Looking at the code in the project a couple of days ago, I came across a custom thread pool

MDCThreadExecutor extends ThreadPoolTaskExecutor
Copy the code

The ThreadPoolTaskExecutor thread pool in spring-Context is extended, but not much, except for the introduction of two attributes, as follows:

private Map<String, String> threadContext;
private Boolean useThreadContext;
public Map<String, String> getThreadContext() {
    return useThreadContext ? (threadContext == null ? MDC.getCopyOfContextMap() : threadContext) : null;
}
Copy the code

Execute (Runnable task) and submit(Runnable task);

@Override public void execute(Runnable task) { super.execute(getMDCTask(task, getThreadContext())); } @Override public Future<? > submit(Runnable task) { return super.submit(getMDCTask(task,getThreadContext())); }Copy the code

My first reaction when I saw the mdC.java thing was, oh my God, what is MDC? What are you doing with this? No, so I thought I’d do some research and look at their code, which led to this article.

To explore

This is a class in the SLf4J package, and the custom extension thread pool class uses only this MDC to do some simple operations, as follows:

private Runnable getMDCTask(Runnable task, Map<String, String> threadContext){ return () -> { if (useThreadContext) { MDC.setContextMap(threadContext); MDC.put("tranceID", UUID.randomUUID().toString().replaceAll("-","")); }else{ MDC.setContextMap(null); } try { task.run(); } finally { MDC.remove("tranceID"); MDC.clear(); }}; }Copy the code

TranceId = ‘value’; tranceId = ‘value’; tranceId = ‘value’; Since the person who wrote it left the company, I can’t ask, so I’ll do my own research.

Click on the put method to see what it looks like:

/** * Puts the diagnostic context value identified by the key parameter (the val parameter) into the diagnostic context map for the current thread. The * key argument cannot be empty. It can only be null if the underlying implementation supports the val argument. * This method delegates all work to the MDC of the underlying logging system. * * @param Key Non-null key * @param val Value to put in the map * * @throws IllegalArgumentException if the parameter key is null */ public static void put(String key, String val) throws IllegalArgumentException { if (key == null) { throw new IllegalArgumentException("key parameter cannot be null"); } if (mdcAdapter == null) { throw new IllegalStateException("MDCAdapter cannot be null. See also " + NULL_MDCA_URL); } mdcAdapter.put(key, val); }Copy the code

Mdcadapter.put (key, val); mdcAdapter.put(key, val); Final execution is org. Slf4j. Spi. MDCAdapter. Java class definition method of put the interface. What is this interface? The note explains it like this:

This interface abstracts the services provided by various MDC implementations.

The interface comments the PUT method as follows:

Puts the context value identified by the key parameter (the val parameter) into the context map of the current thread. Key arguments cannot be empty. It can only be null if the underlying implementation supports the val argument. If the current thread does not have a context map, it is created as a side effect of this call.

While the class name ends with Adadiaoer to indicate that it is an adapter, slF4J is known as a logging interface facade (like JDBC) with logback, log4J, and so on. So we need to go into his implementation and see what’s going on, because we’re using logback and of course it depends on logback

The comments on the LogbackMDCAdapter class are as follows:

Mapped Diagnostic Context (MDC) is a tool used to distinguish between interleaved log output from different sources. When the server processes multiple clients almost simultaneously, the log output is typically staggered. MDC is managed on a per-thread basis. The child thread automatically inherits a copy of its parent thread’s mapping diagnostic context.

There are five levels of logging: Trace, DEBUG, INFO, WARN, and ERROR. MDC is an extension of logging. It should allow you to customize the information you want to display in your logs. We should be able to see that MDC is useful in a multi-threaded environment for managing logs for each thread.

Well, that’s all we know by looking briefly at the comments in its source code, which is still to be verified. Let’s look at the implementation of the put operation as follows:

/** * puts the context value identified by the key argument (the val argument) into the context map of the current thread. * Note that, in contrast to log4j, the val argument can be null. * If the current thread does not have a context map, it is created as a side effect of this call. Throws an exception when the parameter key is null */ public void put(String key, String val) throws IllegalArgumentException { if (key == null) { throw new IllegalArgumentException("key cannot be null"); } Map<String, String> oldMap = copyOnThreadLocal.get(); Integer lastOp = getAndSetLastOperation(WRITE_OPERATION); if (wasLastOpReadOrNull(lastOp) || oldMap == null) { Map<String, String> newMap = duplicateAndInsertNewMap(oldMap); newMap.put(key, val); } else { oldMap.put(key, val); }}Copy the code

The above code is also very simple, just get the saved map from ThreadLocal and put our key-value into it. We know that it uses ThreadLocal to hold our custom thread context information.

MDC functional Test

So that gives us a sense of what the MDC has done. This is just some of the information we got from looking at others using MDC and a bit of MDC source code in the project code. We will also go to the Internet to check whether we are right about MDC, and to get more information about MDC, including how to use it.

First let’s test this with the code above, which is the custom extension thread pool. Let’s put a tranceId value UUID to see what happens.

I wrote a test interface, as follows, simply simulate a task to submit to the thread pool, and then intersperse this task with many methods, assuming a lot of business logic, and each logic branch, method has its own log output, is such a test interface. We’ll test it out later to see how logging works with MDC.

@GetMapping("testMDCThreadPool") public Map<String, Object> testMDCThreadPool() { Map<String, Object> successResult = ResultUtil.getSuccessResult(); log.info("begin...." ); Taskexecutor.execute (() -> {log.info("task main......") ); / / in a custom thread pool of threads created in print log try {TimeUnit. MILLISECONDS. Sleep (1); doSome1(); //other... } catch (InterruptedException e) { log.error("task error:{}", e); }}); log.info("end...." ); return successResult; } public void doSome1() throws InterruptedException { log.info("this is print......" ); TimeUnit.MILLISECONDS.sleep(5); doSome2(); //other... } public void doSome2() throws InterruptedException { log.info("this is print......" ); TimeUnit.MILLISECONDS.sleep(1); //other... }Copy the code

Then we run the project (a simple springboot project with our extended threadPool MDCThreadExecutor). The constructor passes a map with a key-value in the map, mdc-threadpool, Then here are some parameters for the thread pool, and then our thread name starts with walk-MDC.)

 @Bean
 public MDCThreadExecutor taskExecutor(){
     MDCThreadExecutor mdcThreadExecutor = new MDCThreadExecutor(new HashMap<String, String>() {{
         put("appId", "mdc-threadPool");
     }});
     mdcThreadExecutor.setCorePoolSize(10);
     mdcThreadExecutor.setMaxPoolSize(20);
     mdcThreadExecutor.setKeepAliveSeconds(5);
     mdcThreadExecutor.setQueueCapacity(50);
    mdcThreadExecutor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
    mdcThreadExecutor.setThreadFactory(new DefaultThreadFactory("walking-mdc"));
    return mdcThreadExecutor;
}
Copy the code

Then we visit http://localhost:8899/testMDCThreadPool, observe the console output

09-05 21:48:20. 478 - nio - 8899 - exec -] [HTTP INFO [C.W.R.C ontroller. MDCTestController] useMDCThreadPool: 25 [] [] - the begin... 09-05 21:48:20. 487 - nio - 8899 - exec -] [HTTP INFO [C.W.R.C ontroller. MDCTestController] useMDCThreadPool: 37 [] [] - end... 09-05 21:48:20. 620] [walking - the MDC - 1-1 INFO [C.W.R.C ontroller. MDCTestController] lambda $$0:28 useMDCThreadPool [mdc-threadPool] [cc8d01b41cfd4b3b83d8e0120f855187]- task main...... 09-05 21:48:20. 622] [walking - the MDC - 1-1 INFO [C.W.R.C ontroller. MDCTestController] doSome1:42 [MDC - threadPool] [cc8d01b41cfd4b3b83d8e0120f855187]- this is print...... 09-05 21:48:20. 628] [walking - the MDC - 1-1 INFO [C.W.R.C ontroller. MDCTestController] doSome2:49 [MDC - threadPool] [cc8d01b41cfd4b3b83d8e0120f855187]- this is print......Copy the code

You can see that the first two lines of the log are printed by threads created by the Web container thread pool, because they are not printed by the same thread names as those created by our own thread pool (HTTP-NIO-8899-execu-xx and walking- MDC-1-xx). Back as you can see there are differences, the first two lines in the log has two empty brackets [], [], and then 3 rows in the log in brackets is that [the MDC – threadPool], [6 c60c8df5ff842adbd8aecef4aca3003], Isn’t that the appId we put in the map and the UUID we put in the MDC.put? Oh, the difference shown here is the implementation of printing our custom log parameters.

Does it print in a thread context? You can’t be that smart. So I searched globally for appId and tranceId, and sure enough, I found them in logback-spring.xml. Line 3 of the code below %X{appId} and %X{tranceId}, so the parameters put in will be displayed in the log as configured in the log print template.

<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
  <encoder>
    <pattern>%d{MM-dd HH:mm:ss.SSS} [%thread] %-5level [%logger{38}] %method:%line [%X{appId}] [%X{tranceID}]- %msg%n
    </pattern>
  </encoder>
</appender>
Copy the code

Remember the comments on the LogbackMDCAdapter class? As follows:

Mapped Diagnostic Context (MDC) is a tool used to distinguish between interleaved log output from different sources. When the server processes multiple clients almost simultaneously, the log output is typically staggered. MDC is managed on a per-thread basis. The child thread automatically inherits a copy of its parent thread’s mapping diagnostic context.

It is true that when a program is running on a server, the situation is often complicated. Multi-threaded run logs are intricate and the multi-threaded logs are alternate, so in this case it is difficult to tell which logs are printed by one thread or one task.

That’s what the MDC is for. If you still don’t understand, let’s simulate the test interface of multi-threaded request just now to see the effect.

I simulated sending 10 thread requests in 1 second to see what logging looks like to help understand.

As shown in the figure above, the effect of alternate log execution is displayed. In the actual production environment, the amount of concurrent log execution is larger than this. Sometimes, the logs of the same thread are far apart, and it is impossible to distinguish which logs are printed by the same thread and the same task. With MDC, keyword extraction with Linux grep is much easier. MDC is pretty good!

The above is through the use of MDC in the project, then through their own quiz and a simple bit of source code to get a preliminary understanding of MDC. I then gathered some information to gain a more comprehensive understanding of MDC.

What is MDC in SLF4J

MDC is a bit different from the way we use logging. My understanding of MDC is that it can unify the data in a processing thread that you want to display in a log file, depending on your log file configuration. Consider using MDC for this purpose in the following but not limited scenarios

  1. We want to show the requested user IP address in the log

  2. The user uses the USER-Agent of the HTTP client

  3. Record the log tracking number of a processing thread (this number is for the convenience of querying logs, combined with grep command can output all the processing logs according to the tracking number)

use

You can use AOP or a Filter or Interceptor, or a tool such as giving each thread a unique number in a custom thread pool (as I did above), to get the variables you want to output to the log and call MDC.put(String key, String val). Another example is used in AOP below

@Around(value = "execution(* com.xx.xx.waling.impl.*.*(..) ) ", argNames="bcdd") public Object validator(ProceedingJoinPoint pjp) throws Throwable { try { String traceId = TraceUtils.begin(); MDC.put("traceId", traceId); Object obj = pjp.proceed(args); return obj; } catch(Throwable e) {//TODO handle error} finally {traceutils.endtrace (); }}Copy the code

Benefits of MDC

  1. If your system is already online and one day your boss says let’s add some user data to the log and analyze it. Without MDC I guess you’d be in an avalanche right now. MDC is well placed to enable you to implement unexpected requirements on logging

  2. If you are a code freak and encapsulate the operation of the company LOG, and encapsulate the LOG number of the processing thread trace, only the part of the LOG that uses your encapsulation tool can print the trace LOG number, other parts of the LOG (such as Hibernate, Mybatis, HttpClient, etc.) will not show the trace number. Of course we can get around this with Linux commands.

  3. Make code concise and log style uniform

summary

Here comes the end of MDC, we understand the basic use and benefits of MDC, friends have you learned? Know that there is this thing, even if it is not used now, later if there is a demand to achieve similar functions, you can think of MDC is enough for the first time, can also install a force 😄

The code covered in this article is hosted in the code cloud, gitee.com/itwalking/s… , you can download it.

Thank you for your support

Redis and MQ knowledge point mind map to share with you, 2K+ friends have received you are not quick to get ~

Previous hot articles:

  • The storage structure and data search method of joint index in B+ tree

  • MySQL index stuff

  • What can be done with Redis’s various data types?

  • Redis usage Guide

  • Redis distributed lock combat

Welcome to follow me, thank you for your support

Reference:

Logback. Qos. Ch/manual/MDC…. www.cnblogs.com/sealedbook/…