文档章节

利用Slf4j的MDC跟踪方法调用链

杨春炼
 杨春炼
发布于 08/18 13:27
字数 1481
阅读 537
收藏 22

why?

一个web项目通常提供很多URL访问地址,

项目一般都是分层处理,例如Controller——>Service——>DAO。

如果想根据日志查看用户一次请求都走了哪些方法(多数是查错误)。

如果系统是多人访问,日志打印是无序的,想要串行拿到日志是大海捞针。

能通过一个字符串就能将一次请求调用了哪些方法按照顺序搜索出来就好了。

how?

Slf4j的MDC ( Mapped Diagnostic Contexts )专门为此需求而生。

MDC的基本原理是:

通过一个ThreadLocal保存设置的key值,在打印的时候从ThreadLocal中获取到打印出来。由此可知,如果一个请求中的某些方法调用是在另外的线程中执行,那MDC是获取不到该值的。

note 当前线程的子线程会继承其父线程中的MDC的内容,所以不用担心会话过程中,新创建的子线程无法追踪。

为什么最开始子线程会得到父线程MDC设置的内容?

创建子线程的时候会调用init(ThreadGroup g, Runnable target, String name,long stackSize)方法,判断如果parent.inheritableThreadLocals不为null就调用createInheritedMap方法把父线程的ThreadLocal里保存的变量都加载到子线程的ThreadLocal中去。

所以MDC类的静态变量mdcAdapter(LogbackMDCAdapter实现)中的copyOnInheritThreadLocal会得到父类MDC写入的内容,因为它用的是InheritableThreadLocal这个继承类。

底层代码

/**
 * This class hides and serves as a substitute for the underlying logging
 * system's MDC implementation.
 * 
 * <p>
 * If the underlying logging system offers MDC functionality, then SLF4J's MDC,
 * i.e. this class, will delegate to the underlying system's MDC. Note that at
 * this time, only two logging systems, namely log4j and logback, offer MDC
 * functionality. For java.util.logging which does not support MDC,
 * {@link BasicMDCAdapter} will be used. For other systems, i.e. slf4j-simple
 * and slf4j-nop, {@link NOPMDCAdapter} will be used.
 *
 * <p>
 * Thus, as a SLF4J user, you can take advantage of MDC in the presence of log4j,
 * logback, or java.util.logging, but without forcing these systems as
 * dependencies upon your users.
 * 
 * <p>
 * For more information on MDC please see the <a
 * href="http://logback.qos.ch/manual/mdc.html">chapter on MDC</a> in the
 * logback manual.
 * 
 * <p>
 * Please note that all methods in this class are static.
 * 
 * @author Ceki G&uuml;lc&uuml;
 * @since 1.4.1
 */
public class MDC {

/**
 * Basic MDC implementation, which can be used with logging systems that lack
 * out-of-the-box MDC support.
 *
 * This code was initially inspired by  logback's LogbackMDCAdapter. However,
 * LogbackMDCAdapter has evolved and is now considerably more sophisticated.
 *
 * @author Ceki Gulcu
 * @author Maarten Bosteels
 * @author Lukasz Cwik
 * 
 * @since 1.5.0
 */
public class BasicMDCAdapter implements MDCAdapter {

    private InheritableThreadLocal<Map<String, String>> inheritableThreadLocal = new InheritableThreadLocal<Map<String, String>>() {
        @Override
        protected Map<String, String> childValue(Map<String, String> parentValue) {
            if (parentValue == null) {
                return null;
            }
            return new HashMap<String, String>(parentValue);
        }
    };

    /**
     * Put a context value (the <code>val</code> parameter) as identified with
     * the <code>key</code> parameter into the current thread's context map.
     * Note that contrary to log4j, the <code>val</code> parameter can be null.
     *
     * <p>
     * If the current thread does not have a context map it is created as a side
     * effect of this call.
     *
     * @throws IllegalArgumentException
     *                 in case the "key" parameter is null
     */
    public void put(String key, String val) {
        if (key == null) {
            throw new IllegalArgumentException("key cannot be null");
        }
        Map<String, String> map = inheritableThreadLocal.get();
        if (map == null) {
            map = new HashMap<String, String>();
            inheritableThreadLocal.set(map);
        }
        map.put(key, val);
    }
/**
 * This class extends <tt>ThreadLocal</tt> to provide inheritance of values
 * from parent thread to child thread: when a child thread is created, the
 * child receives initial values for all inheritable thread-local variables
 * for which the parent has values.  Normally the child's values will be
 * identical to the parent's; however, the child's value can be made an
 * arbitrary function of the parent's by overriding the <tt>childValue</tt>
 * method in this class.
 *
 * <p>Inheritable thread-local variables are used in preference to
 * ordinary thread-local variables when the per-thread-attribute being
 * maintained in the variable (e.g., User ID, Transaction ID) must be
 * automatically transmitted to any child threads that are created.
 *
 * @author  Josh Bloch and Doug Lea
 * @see     ThreadLocal
 * @since   1.2
 */

public class InheritableThreadLocal<T> extends ThreadLocal<T> {
    /**
     * Computes the child's initial value for this inheritable thread-local
     * variable as a function of the parent's value at the time the child
     * thread is created.  This method is called from within the parent
     * thread before the child is started.
     * <p>
     * This method merely returns its input argument, and should be overridden
     * if a different behavior is desired.
     *
     * @param parentValue the parent thread's value
     * @return the child thread's initial value
     */
    protected T childValue(T parentValue) {
        return parentValue;
    }

1 修改日志文件

只需要在日志配置文件的pattern中中添加一个{key},在请求方法入口设置一个key=某字符串,logger日志就能输出此字符串。logger的所有日志方法不需要做任何改动。如下所示。

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
  <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">
      <pattern>%d{ISO8601} [%thread] [%-5level] [%-10X{tracing_id}] %logger - %msg%n</pattern>
    </layout>
  </appender>
  <!-- 文件输出日志 (文件大小策略进行文件输出,超过指定大小对文件备份)-->
  <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>/data/rec_loader/logs/rec_loader.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <fileNamePattern>/data/rec_loader/logs/rec_loader.log.%d{yyyy-MM-dd}.%d{hh-mm-ss}
      </fileNamePattern>
      <maxHistory>7</maxHistory>
      <totalSizeCap>100GB</totalSizeCap>
    </rollingPolicy>
    <layout class="ch.qos.logback.classic.PatternLayout">
	  <!--** 改动在此处 tracing_id**-->
      <Pattern>%d{ISO8601} [%thread] [%-5level] [%-10X{tracing_id}] %logger - %msg%n</Pattern>
    </layout>
  </appender>

  <root level="info">
    <appender-ref ref="STDOUT"/>
    <appender-ref ref="FILE"/>
  </root>

</configuration>

2 增加拦截器(跨系统之间可用,通过增加header字段)

import java.util.Objects;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.lang3.RandomStringUtils;
import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;

/* *
 * *    Starry Starry Night
 * *          __   __
 * *          \/---\/
 * *           ). .(
 * *          ( (") )
 * *           )   (
 * *          /     \
 * *         (       )``
 * *        ( \ /-\ / )
 * *         w'W   W'w
 * *
 * author   杨春炼
 * email    qdcccc@gmail.com
 * date     2018-08-18
 *
 */
@Slf4j
public class ResponseMetricsInterceptor extends HandlerInterceptorAdapter {
	private static final String TRACING_ID = "tracing_id";
	private static final String RESPONSE_TIME = "response_time";

	@Override
	public boolean preHandle(HttpServletRequest request, HttpServletResponse response,
			Object handler) throws Exception {
		String tracingId;
		//this judgement used for webs context
		if (StringUtils.isBlank(request.getHeader(TRACING_ID))) {
			tracingId = RandomStringUtils.randomAlphanumeric(10);
		} else {
			tracingId = request.getHeader(TRACING_ID);
		}
		response.setHeader(TRACING_ID, tracingId);
		//add a start time in request attribute
		request.setAttribute(RESPONSE_TIME, System.currentTimeMillis());
		MDC.put(TRACING_ID, tracingId);
		log.info("tracing.start.url={}", request.getServletPath());
		return super.preHandle(request, response, handler);
	}

	@Override
	public void afterCompletion(HttpServletRequest request, HttpServletResponse response,
			Object handler, Exception ex) throws Exception {
		try {
			Object attribute = request.getAttribute(RESPONSE_TIME);
			Long timeStart = Long.valueOf(Objects.toString(attribute, "0"));
			long responseTime = System.currentTimeMillis() - timeStart;
			log.info("tracing.end.url={}, 消耗时间:{}ms", request.getServletPath(), responseTime);
		} catch (Exception ignored) {
		} finally {
			//prevent memory leak
			MDC.remove(TRACING_ID);
			MDC.clear();
		}
		super.afterCompletion(request, response, handler, ex);
	}
import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurationSupport;

/* *
 * *    Starry Starry Night
 * *          __   __
 * *          \/---\/
 * *           ). .(
 * *          ( (") )
 * *           )   (
 * *          /     \
 * *         (       )``
 * *        ( \ /-\ / )
 * *         w'W   W'w
 * *
 * author   杨春炼
 * email    qdcccc@gmail.com
 * date     2018-08-18
 *
 */
@Configuration
public class InterceptorConfig extends WebMvcConfigurationSupport {
	@Override
	public void addInterceptors(InterceptorRegistry registry) {
		registry.addInterceptor(new ResponseMetricsInterceptor()).addPathPatterns("/**");
	}
}

Effect

向自己的项目发起一次http请求

结果如下图(顺便打印了该次http请求的总耗时)

更专业的分布式链路追踪中间件?

可以自行搜索 SOFATracer,比较重,觉得一般企业没必要应用。

© 著作权归作者所有

共有 人打赏支持
杨春炼
粉丝 11
博文 61
码字总数 33964
作品 0
海淀
高级程序员
分布式链路追踪中间件 - SOFATracer

SOFATracer 是一个用于分布式系统调用跟踪的组件,通过统一的 将调用链路中的各种网络调用情况以日志的方式记录下来,以达到透视化网络调用的目的。这些日志可用于故障的快速发现,服务治理等...

匿名
05/31
0
0
比较 SLF4J 与 log4j

SLF4J :JAVA简易日志门面(Simple Logging Facade for Java,缩写SLF4J) 他是一套包装Logging 框架的接口程式,以外观模式实现。可在软件部署的时候决定要使用的 Logging 框架,目前主要支援...

Candy_Desire
2014/03/19
0
0
让 Spring Framework 依赖 SLF4J 的 Maven 配置

Spring Framework 一直以来都是依赖 commons-logging,通过在 Maven pom.xml 进行配置,可以让 Spring Framework 依赖于越来越流行的 SLF4J,这是利用了 slf4j.org 提供的 jcl-over-slf4j 把...

张前程
2013/12/30
0
0
java日志组件介绍(common-logging,log4j,slf4j,logback)

common-logging common-logging是apache提供的一个通用的日志接口。用户可以自由选择第三方的日志组件作为具体实现,像log4j,或者jdk自带的logging, common-logging会通过动态查找的机制,...

五大三粗
2015/11/04
0
0
java日志组件介绍(common-logging,log4j,slf4j,logback )

common-logging是apache提供的一个通用的日志接口。用户可以自由选择第三方的日志组件作为具体实现,像log4j,或者jdk自带的logging, common-logging会通过动态查找的机制,在程序运行时自动...

凯文加内特
2015/05/08
0
0

没有更多内容

加载失败,请刷新页面

加载更多

Access denied for user 'root'@'localhost' 解决流程

ERROR 1698 (28000): Access denied for user 'root'@'localhost' 解决流程 基于debian 9 maridb 10 因为安装 时不知道 密码,所以在管理中下使用 mysqladmin -u root -p password ex(ex为密......

dragon_tech
33分钟前
0
0
nginx 负载均衡

一.配置方式 1.轮询(默认) 优点:实现简单; 缺点:不考虑每台服务器处理能力 2.权重 weight默认是1。如果有多个配置权重的节点,比较相对值。 15:10,只代表访问8080端口的概率是访问908...

imbiao
56分钟前
1
0
jQuery学习笔记180923

jQuery 操作 CSS jQuery 拥有若干进行 CSS 操作的方法。我们将学习下面这些: addClass() - 向被选元素添加一个或多个类 removeClass() - 从被选元素删除一个或多个类 toggleClass() - 对被选...

颖伙虫
今天
2
0
[python] colorama 模块 - 改变控制台输出文本的颜色

除了使用 PyQt 这样的图形化开发框架外,基本上 python 程序都是跑在控制台中的。很多时候,单纯使用黑白的文字不能很好地突出我们要显示的信息。有时候我们需要将错误的提示使用红色标注,而...

cometeme
今天
3
0
Makefile 学习 2 - 基于若干 Blog 的汇总

基于若干 Blog 汇总的 makefile 教程 陈皓 https://blog.csdn.net/haoel/article/details/2886 Makefile 进阶 1. Makefile 中的内容 显式规则。显式规则说明了,如何生成一个或多的的目标文件...

公孙衍
今天
2
0

没有更多内容

加载失败,请刷新页面

加载更多

返回顶部
顶部