记录一次skywalking并行traceId丢失的问题

陈寄文
1,489 阅读4分钟

1、现象描述

提供了一个专门的并行处理类，具体的代码如下：

private <T> List<T> executeSubTask(List<ParallelTask<T>> taskList) {
        Map<String, String> map = SlsContextHolder.getAll();
        Map<String, String> mdcMap = MDC.getCopyOfContextMap();
        List<CompletableFuture<T>> futures = taskList.parallelStream().map(task -> {
            SlsBizLogger.getLogMap("getSubTask").success();
            return CompletableFuture.supplyAsync(
                    SupplierWrapper.of(() -> {
                        try {
                            SlsContextHolder.putAll(map);
                            if (Objects.nonNull(mdcMap)) {
                                MDC.setContextMap(mdcMap);
                            }
                            return task.execute();
                        } finally {
                            SlsContextHolder.clear();
                        }
                    }), executorService);
        }).collect(Collectors.toList());
        return futures.stream().map(CompletableFuture::join).collect(Collectors.toList());
    }

在实际运行过程中，通过日志查询某一次请求，发现有15条对应的日志。

image.png

而在skywalking中没有那么多，只看到了8条。

image.png

2、原因定位

2.1 traceId 跨进程传递原理说明

笔者的情况是在多线程中发送HttpClient请求，那么就需要看一下这个traceId是如何传递的。仔细研读了一下代码。

2.1.1 发送traceId

查询 apm-httpClient-4.x-plugin 的源码，找到其中对traceId传递的代码：

CarrierItem next = contextCarrier.items();
while (next.hasNext()) {
    next = next.next();
    httpRequest.setHeader(next.getHeadKey(), next.getHeadValue());
}

这里看到会在请求的 header 中增加对应的sw8这个header。 具体的header值的处理如下代码：

String serialize(HeaderVersion version) {
    if (this.isValid(version)) {
        return StringUtil.join(
            '-',
            "1",
            Base64.encode(this.getTraceId()),
            Base64.encode(this.getTraceSegmentId()),
            this.getSpanId() + "",
            Base64.encode(this.getParentService()),
            Base64.encode(this.getParentServiceInstance()),
            Base64.encode(this.getParentEndpoint()),
            Base64.encode(this.getAddressUsedAtClient())
        );
    }
    return "";
}

实际的效果：

image.png

2.1.2 接收还原traceId

按照RestController的处理逻辑，对应的代码是在 org.apache.skywalking.apm.plugin.spring.mvc.commons.interceptor.AbstractMethodInterceptor

final HttpServletRequest httpServletRequest = (HttpServletRequest) request;
CarrierItem next = contextCarrier.items();
while (next.hasNext()) {
    next = next.next();
    next.setHeadValue(httpServletRequest.getHeader(next.getHeadKey()));
}

这里先看一下items这个方法：

/**
 * @return the list of items, which could exist in the current tracing context.
 */
public CarrierItem items() {
    SW8ExtensionCarrierItem sw8ExtensionCarrierItem = new SW8ExtensionCarrierItem(extensionContext, null);
    SW8CorrelationCarrierItem sw8CorrelationCarrierItem = new SW8CorrelationCarrierItem(
        correlationContext, sw8ExtensionCarrierItem);
    SW8CarrierItem sw8CarrierItem = new SW8CarrierItem(this, sw8CorrelationCarrierItem);
    return new CarrierItemHead(sw8CarrierItem);
}

可以看到这个next会是 org.apache.skywalking.apm.agent.core.context.SW8CarrierItem，它的 setHeadValue 方法，具体的代码逻辑如下：

@Override
public void setHeadValue(String headValue) {
    carrier.deserialize(headValue, ContextCarrier.HeaderVersion.v3);
}

/**
 * Initialize fields with the given text.
 *
 * @param text carries {@link #traceSegmentId} and {@link #spanId}, with '|' split.
 */
ContextCarrier deserialize(String text, HeaderVersion version) {
    if (text == null) {
        return this;
    }
    if (HeaderVersion.v3.equals(version)) {
        String[] parts = text.split("-", 8);
        if (parts.length == 8) {
            try {
                // parts[0] is sample flag, always trace if header exists.
                this.traceId = Base64.decode2UTFString(parts[1]);
                this.traceSegmentId = Base64.decode2UTFString(parts[2]);
                this.spanId = Integer.parseInt(parts[3]);
                this.parentService = Base64.decode2UTFString(parts[4]);
                this.parentServiceInstance = Base64.decode2UTFString(parts[5]);
                this.parentEndpoint = Base64.decode2UTFString(parts[6]);
                this.addressUsedAtClient = Base64.decode2UTFString(parts[7]);
            } catch (IllegalArgumentException ignored) {

            }
        }
    }
    return this;
}

经过上述的处理，traceId等链路信息就已经还原为 contextCarrier，接下来就看一下这个内容是怎么存放到ThreadLocal的。

这里的核心代码如下：

String operationName = this.buildOperationName(method, httpServletRequest.getMethod(),
                                               (EnhanceRequireObjectCache) objInst.getSkyWalkingDynamicField());
AbstractSpan span = ContextManager.createEntrySpan(operationName, contextCarrier);

关键就是createEntrySpan方法，最终会调用 org.apache.skywalking.apm.agent.core.context.ContextManager#getOrCreate。

这一步关键就是初始化 CONTEXT 这个 ThreadLocal 对象。

private static ThreadLocal<AbstractTracerContext> CONTEXT = new ThreadLocal<AbstractTracerContext>();

/**
 * Extract the carrier to build the reference for the pre segment.
 *
 * @param carrier carried the context from a cross-process segment. Ref to {@link AbstractTracerContext#extract(ContextCarrier)}
 */
@Override
public void extract(ContextCarrier carrier) {
    TraceSegmentRef ref = new TraceSegmentRef(carrier);
    this.segment.ref(ref);
    this.segment.relatedGlobalTrace(new PropagatedTraceId(carrier.getTraceId()));
    AbstractSpan span = this.activeSpan();
    if (span instanceof EntrySpan) {
        span.ref(ref);
    }

    carrier.extractExtensionTo(this);
    carrier.extractCorrelationTo(this);
}

这里就是往ThreadLocal里面填充具体的信息了。

2.2 skywalking的多线程解决方案

skywalking其实也提供了，具体可以参考 skywalking.apache.org/docs/skywal…

参考了官方文档，业务开发代码已经是使用 SupplierWrapper。

在org.apache.skywalking.apm.toolkit.activation.trace.CallableOrRunnableConstructInterceptor 构建的时候，会执行如下逻辑：

public void onConstruct(EnhancedInstance objInst, Object[] allArguments) {
    if (ContextManager.isActive()) {
        objInst.setSkyWalkingDynamicField(ContextManager.capture());
    }
}

这里会将当前的链路对象，保存在EnhanceInstance中。

在多线程的具体逻辑执行之前会还原链路跟踪信息。

public void beforeMethod(EnhancedInstance objInst, Method method, Object[] allArguments, Class<?>[] argumentsTypes,
    MethodInterceptResult result) throws Throwable {
    ContextManager.createLocalSpan("Thread/" + objInst.getClass().getName() + "/" + method.getName());
    ContextSnapshot cachedObjects = (ContextSnapshot) objInst.getSkyWalkingDynamicField();
    if (cachedObjects != null) {
        ContextManager.continued(cachedObjects);
    }
}

2.3 链路信息丢失的具体原因

通过上述分析，代码大体上没有问题，那么就需要进一步debug看看问题出在哪里。 在debug类 org.apache.skywalking.apm.toolkit.activation.trace.CallableOrRunnableConstructInterceptor的时候，发现isActive 返回的是false。 说明它没有获取到当前线程的链路上下文信息，这个就很奇怪了。那么我们打印一下线程对比看看是不是线程变了。

image.png

组装并行SupplierWrapper数组的线程信息如下：

image.png

实际执行代码的线程，

image.png

可以看到组装的日志里面，有一个对应的线程是主线程 http-noi-8080-exec-2，另外一个就是ForkJoinPool.commonPool-worker-1。

那么原因到此就定位到了，就是由于使用了 parallelStream 进行组装。它里面会使用forkJoinPool的线程池，会出现新的线程，这个线程里面没有任何链路信息。

3、解决方案

那么既然知道原因了，解决方案就很容易了。

3.1 自行管理链路上下文传递

简单来说就是自行处理上下文，如何还原均自行控制。

ContextSnapshot snapshot = null;
if (ContextManager.isActive()) {
    snapshot = ContextManager.capture();
}
ContextSnapshot finalSnapshot = snapshot;
List<CompletableFuture<T>> futures = taskList.parallelStream().map(task -> {
    if (Objects.nonNull(finalSnapshot)) {
        ContextManager.createLocalSpan("parallelExecutor");
        ContextManager.continued(finalSnapshot);
    }
    return CompletableFuture.supplyAsync(
            SupplierWrapper.of(() -> {
                try {
                    return task.execute();
                } finally {
                    SlsContextHolder.clear();
                }
            }), executorService);
}).collect(Collectors.toList());

image.png

3.2 改成串行stream方法

List<CompletableFuture<T>> futures = taskList.stream()

这个最简单，封装逻辑均会在主线程里面完成。

3.3 最终选择了第二种方案

由于这里的封装逻辑耗时几乎可以忽略，采用并行完全没有必要，改成串行即可。

avatar
文章
阅读
粉丝