Trace?在多線程異步體系下傳遞流程解析
JAVA 線程異步常見的實(shí)現(xiàn)方式有
new Thread
ExecutorService
當(dāng)然還有其他的,比如fork-join
,這些下文會有提及,下面主要針對這兩種場景結(jié)合 DDTrace 和 Springboot 下進(jìn)行實(shí)踐。
引入 DDTrace sdk
<properties> <java.version>1.8</java.version> <dd.version>1.21.0</dd.version> </properties> <dependencies> <dependency> <groupId>com.datadoghq</groupId> <artifactId>dd-trace-api</artifactId> <version>${dd.version}</version> </dependency> <dependency> <groupId>io.opentracing</groupId> <artifactId>opentracing-api</artifactId> <version>0.33.0</version> </dependency> <dependency> <groupId>io.opentracing</groupId> <artifactId>opentracing-mock</artifactId> <version>0.33.0</version> </dependency> <dependency> <groupId>io.opentracing</groupId> <artifactId>opentracing-util</artifactId> <version>0.33.0</version> </dependency> ...
關(guān)于 DDTrace sdk 使用方式參考文檔ddtrace-api使用指南
Logback 配置
配置 logback
,讓其輸出 traceId
和 spanId
, 將以下 pattern
應(yīng)用到所有的 appender
中。
<property name="log.pattern" value="%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger - [%method,%line] %X{dd.service} %X{dd.trace_id} %X{dd.span_id} - %msg%n" />
如果有鏈路信息產(chǎn)生,則會在日志里面輸出 Trace 信息。
new Thread
實(shí)現(xiàn)一個簡單的接口,使用 logback
輸出日志信息,觀察日志輸出情況
@RequestMapping("/thread") @ResponseBody public String threadTest(){ logger.info("this func is threadTest."); return "success"; }
請求后,日志如下
2023-10-23 11:33:09.983 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.CalcFilter - [doFilter,28] springboot-server 7209831467195902001 958235974016818257 - START /thread
host localhost:8086
connection Keep-Alive
user-agent Apache-HttpClient/4.5.14 (Java/17.0.7)
accept-encoding br,deflate,gzip,x-gzip
2023-10-23 11:33:10.009 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,277] springboot-server 7209831467195902001 2587871298938674772 - this func is threadTest.
2023-10-23 11:33:10.022 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.CalcFilter - [doFilter,34] springboot-server 7209831467195902001 958235974016818257 - END : /thread耗時:39
日志里面有 trace 信息產(chǎn)生, 7209831467195902001
為 traceId
,2587871298938674772
為 spanId
。
向該接口加入 new Thread ,創(chuàng)建一個線程。
@RequestMapping("/thread") @ResponseBody public String threadTest(){ logger.info("this func is threadTest."); new Thread(()->{ logger.info("this is new Thread."); }).start(); return "success"; }
通過請求對應(yīng)的 URL,觀察日志輸出情況。
2023-10-23 11:40:00.994 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,277] springboot-server 319673369251953601 5380270359912403278 - this func is threadTest.
2023-10-23 11:40:00.995 [Thread-10] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,279] springboot-server - this is new Thread.
通過日志輸出發(fā)現(xiàn),new Thread
方式,并不能夠輸出 Trace
信息,也就是說 Trace
并未傳遞進(jìn)去。
如果我們顯示的把 Trace
信息傳遞進(jìn)去是不是就可以了,說干就干。
ThreadLocal 為什么不行
ThreadLocal 本地線程變量,該變量為當(dāng)前線程獨(dú)有。
為了方便使用,我們創(chuàng)建一個工具類 ThreadLocalUtil
。
public static final ThreadLocal<Span> THREAD_LOCAL = new ThreadLocal<>();
然后將當(dāng)前 Span 信息存儲到 ThreadLocal
。
@RequestMapping("/thread") @ResponseBody public String threadTest(){ logger.info("this func is threadTest."); ThreadLocalUtil.setValue(GlobalTracer.get().activeSpan()); logger.info("current traceiD:{}",GlobalTracer.get().activeSpan().context().toTraceId()); new Thread(()->{ logger.info("this is new Thread."); logger.info("new Thread get span:{}",ThreadLocalUtil.getValue()); }).start(); return "success"; }
通過請求對應(yīng)的 URL,觀察日志輸出情況。
2023-10-23 14:14:02.339 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,278] springboot-server 4492960774800816442 4097884453719637622 - this func is threadTest.
2023-10-23 14:14:02.340 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,280] springboot-server 4492960774800816442 4097884453719637622 - current traceiD:4492960774800816442
2023-10-23 14:14:02.341 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,283] springboot-server - this is new Thread.
2023-10-23 14:14:02.342 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,284] springboot-server - new Thread get span:null
在新線程內(nèi)獲取外部線程 ThreadLocal
,獲取到的值為 null
。
通過分析ThreadLocal
源碼發(fā)現(xiàn),當(dāng)我們使用 ThreadLocal
的 set()
方法時,ThreadLocal
內(nèi)部使用了Thread.currentThread()
作為了 ThreadLocal
的數(shù)據(jù)存儲的 key
,也就是說當(dāng)從新線程里面獲取變量信息,key
發(fā)生了變化,所以取不到值。
public class ThreadLocal<T> { ... public void set(T value) { Thread t = Thread.currentThread(); ThreadLocalMap map = getMap(t); if (map != null) { map.set(this, value); } else { createMap(t, value); } } public T get() { Thread t = Thread.currentThread(); ThreadLocalMap map = getMap(t); if (map != null) { ThreadLocalMap.Entry e = map.getEntry(this); if (e != null) { @SuppressWarnings("unchecked") T result = (T)e.value; return result; } } return setInitialValue(); } ... }
InheritableThreadLocal
InheritableThreadLocal
擴(kuò)展了 ThreadLocal
,以提供從父線程到子線程的值繼承:當(dāng)創(chuàng)建子線程時,子線程接收父線程具有值的所有可繼承線程局部變量的初始值。
官方解釋:
This class extends ThreadLocal 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 childValue method in this class.
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.
Note: During the creation of a new thread, it is possible to opt out of receiving initial values for inheritable thread-local variables.
為了方便使用,我們創(chuàng)建一個工具類 InheritableThreadLocalUtil.java
,用于存放 Span 信息
public static final InheritableThreadLocal<Span> THREAD_LOCAL = new InheritableThreadLocal<>();
將 ThreadLocalUtil
換成 InheritableThreadLocalUtil
@RequestMapping("/thread") @ResponseBody public String threadTest(){ logger.info("this func is threadTest."); InheritableThreadLocalUtil.setValue(GlobalTracer.get().activeSpan()); logger.info("current traceiD:{}",GlobalTracer.get().activeSpan().context().toTraceId()); new Thread(()->{ logger.info("this is new Thread."); logger.info("new Thread get span:{}",InheritableThreadLocalUtil.getValue()); }).start(); return "success"; }
通過請求對應(yīng)的 URL,觀察日志輸出情況。
2023-10-23 14:37:05.415 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,278] springboot-server 8754268856419787293 5276611939997441402 - this func is threadTest.
2023-10-23 14:37:05.416 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,280] springboot-server 8754268856419787293 5276611939997441402 - current traceiD:8754268856419787293
2023-10-23 14:37:05.416 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,283] springboot-server - this is new Thread.
2023-10-23 14:37:05.417 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,284] springboot-server - new Thread get span:datadog.trace.instrumentation.opentracing32.OTSpan@712ad7e2
通過觀測以上日志信息,線程內(nèi)部已經(jīng)獲取到了 span
對象地址,但日志 pattern
部分并沒有 Trace
信息輸出,原因在于,DDTrace
對 logback
的getMDCPropertyMap()
和 getMdc()
方法做了插樁處理,將 Trace 信息 put
到 MDC
中。
@Advice.OnMethodExit(suppress = Throwable.class) public static void onExit( @Advice.This ILoggingEvent event, @Advice.Return(typing = Assigner.Typing.DYNAMIC, readOnly = false) Map<String, String> mdc) { if (mdc instanceof UnionMap) { return; } AgentSpan.Context context = InstrumentationContext.get(ILoggingEvent.class, AgentSpan.Context.class).get(event); // Nothing to add so return early if (context == null && !AgentTracer.traceConfig().isLogsInjectionEnabled()) { return; } Map<String, String> correlationValues = new HashMap<>(8); if (context != null) { DDTraceId traceId = context.getTraceId(); String traceIdValue = InstrumenterConfig.get().isLogs128bTraceIdEnabled() && traceId.toHighOrderLong() != 0 ? traceId.toHexString() : traceId.toString(); correlationValues.put(CorrelationIdentifier.getTraceIdKey(), traceIdValue); correlationValues.put( CorrelationIdentifier.getSpanIdKey(), DDSpanId.toString(context.getSpanId())); }else{ AgentSpan span = activeSpan(); if (span!=null){ correlationValues.put( CorrelationIdentifier.getTraceIdKey(), span.getTraceId().toString()); correlationValues.put( CorrelationIdentifier.getSpanIdKey(), DDSpanId.toString(span.getSpanId())); } } String serviceName = Config.get().getServiceName(); if (null != serviceName && !serviceName.isEmpty()) { correlationValues.put(Tags.DD_SERVICE, serviceName); } String env = Config.get().getEnv(); if (null != env && !env.isEmpty()) { correlationValues.put(Tags.DD_ENV, env); } String version = Config.get().getVersion(); if (null != version && !version.isEmpty()) { correlationValues.put(Tags.DD_VERSION, version); } mdc = null != mdc ? new UnionMap<>(mdc, correlationValues) : correlationValues; }
為了讓新創(chuàng)建的線程的日志也能夠獲取父線程 Trace 信息,可以通過創(chuàng)建 span
來實(shí)現(xiàn),該 span
需要作為父線程的子 span
才能完成串聯(lián)。
new Thread(()->{ logger.info("this is new Thread."); logger.info("new Thread get span:{}",InheritableThreadLocalUtil.getValue()); Span span = null; try { Tracer tracer = GlobalTracer.get(); span = tracer.buildSpan("thread") .asChildOf(InheritableThreadLocalUtil.getValue()) .start(); span.setTag("threadName", Thread.currentThread().getName()); GlobalTracer.get().activateSpan(span); logger.info("thread:{}",span.context().toTraceId()); }finally { if (span!=null) { span.finish(); } } }).start();
通過請求對應(yīng)的 URL,觀察日志輸出情況。
2023-10-23 14:51:28.969 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,278] springboot-server 2303424716416355903 7690232490489894572 - this func is threadTest.
2023-10-23 14:51:28.969 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,280] springboot-server 2303424716416355903 7690232490489894572 - current traceiD:2303424716416355903
2023-10-23 14:51:28.970 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,283] springboot-server - this is new Thread.
2023-10-23 14:51:28.971 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,284] springboot-server - new Thread get span:datadog.trace.instrumentation.opentracing32.OTSpan@c3a1aae
2023-10-23 14:51:28.971 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,292] springboot-server - thread:2303424716416355903
2023-10-23 14:51:28.971 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,294] springboot-server 2303424716416355903 5766505477412800739 - thread:2303424716416355903
為何線程內(nèi)有兩條日志的 pattern
沒有輸出 Trace 信息?原因在于當(dāng)前線程內(nèi)部的 span
是在日志輸出之后創(chuàng)建的,只需要將日志放到 span
創(chuàng)建下面即可。
new Thread(()->{ Span span = null; try { Tracer tracer = GlobalTracer.get(); span = tracer.buildSpan("thread") .asChildOf(InheritableThreadLocalUtil.getValue()) .start(); span.setTag("threadName", Thread.currentThread().getName()); GlobalTracer.get().activateSpan(span); logger.info("this is new Thread."); logger.info("new Thread get span:{}",InheritableThreadLocalUtil.getValue()); logger.info("thread:{}",span.context().toTraceId()); }finally { if (span!=null) { span.finish(); } } }).start();
通過請求對應(yīng)的 URL,觀察日志輸出情況。
2023-10-23 15:01:00.490 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,278] springboot-server 472828375731745486 6076606716618097397 - this func is threadTest.
2023-10-23 15:01:00.491 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [threadTest,280] springboot-server 472828375731745486 6076606716618097397 - current traceId:472828375731745486
2023-10-23 15:01:00.492 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,291] springboot-server 472828375731745486 9214366589561638347 - this is new Thread.
2023-10-23 15:01:00.492 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,292] springboot-server 472828375731745486 9214366589561638347 - new Thread get span:datadog.trace.instrumentation.opentracing32.OTSpan@12fd40f0
2023-10-23 15:01:00.493 [Thread-9] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$threadTest$1,293] springboot-server 472828375731745486 9214366589561638347 - thread:472828375731745486
ExecutorService
創(chuàng)建一個 API ,并通過Executors
創(chuàng)建 ExecutorService
對象。
@RequestMapping("/execThread") @ResponseBody public String ExecutorServiceTest(){ ExecutorService executor = Executors.newCachedThreadPool(); logger.info("this func is ExecutorServiceTest."); executor.submit(()->{ logger.info("this is executor Thread."); }); return "ExecutorService"; }
通過請求對應(yīng)的 URL,觀察日志輸出情況。
2023-10-23 15:24:41.828 [http-nio-8086-exec-1] INFO com.zy.observable.ddtrace.controller.IndexController - [ExecutorServiceTest,309] springboot-server 2170215511602500482 4370366221958823908 - this func is ExecutorServiceTest.
2023-10-23 15:24:41.832 [pool-2-thread-1] INFO com.zy.observable.ddtrace.controller.IndexController - [lambda$ExecutorServiceTest$2,311] springboot-server 2170215511602500482 4370366221958823908 - this is executor Thread.
ExecutorService
線程池方式會自動傳遞 Trace 信息,這種自動的能力源于 DDTrace 對相應(yīng)組件埋點(diǎn)操作實(shí)現(xiàn)。
JAVA 對于很多線程組件框架都做了鏈路傳遞的支持,如:ForkJoinTask
、ForkJoinPool
、TimerTask
、FutureTask
、ThreadPoolExecutor
等等。
以上就是Trace 在多線程異步體系下傳遞流程解析的詳細(xì)內(nèi)容,更多關(guān)于Trace多線程異步傳遞的資料請關(guān)注腳本之家其它相關(guān)文章!
相關(guān)文章
SecurityUtils.getSubject().getPrincipal()為null的問題
這篇文章主要介紹了SecurityUtils.getSubject().getPrincipal()為null的問題及解決,具有很好的參考價值,希望對大家有所幫助。如有錯誤或未考慮完全的地方,望不吝賜教2022-07-07IDEA中properties與yml文件的轉(zhuǎn)變方式
文章介紹了如何在IntelliJ IDEA 2021.1.1中安裝和使用ConvertYAMLandPropertiesFile插件進(jìn)行YAML和Properties文件之間的轉(zhuǎn)換,安裝步驟包括導(dǎo)航到設(shè)置、安裝插件、找到并安裝插件等,插件支持從Properties文件轉(zhuǎn)換為YAML文件,但轉(zhuǎn)換過程中會丟失注釋2024-12-12Java基于接口實(shí)現(xiàn)模擬動物聲音代碼實(shí)例
這篇文章主要介紹了Java基于接口實(shí)現(xiàn)模擬動物聲音代碼實(shí)例,文中通過示例代碼介紹的非常詳細(xì),對大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價值,需要的朋友可以參考下2020-06-06解決java啟動時報線程占用報錯:Exception?in?thread?“Thread-14“?java.ne
這篇文章主要給大家介紹了關(guān)于解決java啟動時報線程占用:Exception?in?thread?“Thread-14“?java.net.BindException:?Address?already?in?use:?bind的相關(guān)資料,文中將解決的辦法介紹的非常詳細(xì),需要的朋友可以參考下2023-04-04