skywalking 引起 spring-cloud-gateway 的内存溢出 skywalking的bug

801 阅读4分钟

本文已参与「新人创作礼」活动,一起开启掘金创作之路。

大家好,我是烤鸭:

   又是个线上问题记录,这次坑惨了,开源软件也不是万能的,还是要做好压测和灰度。

问题

上游反馈大量超时,不止某一个服务,查看服务没有问题,猜测是网络或者环境问题。

想到网关接入了skywaling(已接入24小时),回滚后问题消失。

堆内存在某个时间点后上升且无法回收。

3.png

Full GC 时间变得特别长...这个就是上游超时的原因

2.png

环境

cloud版本

<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-gateway</artifactId>
<version>2.2.3.RELEASE</version>

skywalking 版本

<artifactId>java-agent-sniffer</artifactId>
<groupId>org.apache.skywalking</groupId>
<version>8.9.0</version>

复现

说实话,当时我本地起了,压测了一天,并没有出现OOM的情况,事实证明,还是量不够大。

后来同事找到了病根(下面两种情况原因是一样的)

  1. TracingContext中的activeSpanStack在某些场景下没有清空,就是下面这个。

4.png

或者是

  1. IgnoredTracerContext的 stackDepth 不等于0

14.png

最终的结果都是 ContextManager.Context/RuntimeContext 未清空,导致内存泄露

6.png

调试

可以参考这篇文章 www.jianshu.com/p/ba9254f38…

因为我只想调试网关相关包,把下载失败的包和编译失败的包都注释掉了,再在网关项目的导入module。

导入完了,结构如下图,该注释的注释,能编译打包就行。

5.png

断点打在 gateway-2.1.x-plugin的几个拦截器,可以看到debug成功

7.png

源码解析

剩下就跟着代码一步一步走了。

几个拦截器的顺序是 NettyRoutingFilterInterceptor -> HttpClientFinalizerSendInterceptor -> HttpClientFinalizerResponseConnectionInterceptor

可以看到 NettyRoutingFilterInterceptor 初次进入会执行 ContextManager.createLocalSpan

创建span对象(全链路用到的流转对象,感兴趣的可以看看谷歌的dapper blog.csdn.net/ruizhikai_z…)

@Override
public void beforeMethod(EnhancedInstance objInst, Method method, Object[] allArguments, Class<?>[] argumentsTypes,
                         MethodInterceptResult result) throws Throwable {
    ServerWebExchange exchange = (ServerWebExchange) allArguments[0];
    EnhancedInstance enhancedInstance = getInstance(exchange);
​
    AbstractSpan span = ContextManager.createLocalSpan("SpringCloudGateway/RoutingFilter");
    if (enhancedInstance != null && enhancedInstance.getSkyWalkingDynamicField() != null) {
        ContextManager.continued((ContextSnapshot) enhancedInstance.getSkyWalkingDynamicField());
    }
    span.setComponent(SPRING_CLOUD_GATEWAY);
}

createLocalSpan,这里的两个实现,是否忽略trace,由于我引入了

apm-trace-ignore-plugin-8.9.0.jar 这个包,实现会走 ignore的,也就是复现里的第二种情况

7.png

这个方法里有一个栈深度 stackDepth 字段,只要创建span就会自增,删除span就会自减。

@Override
public AbstractSpan createLocalSpan(String operationName) {
    stackDepth++;
    return NOOP_SPAN;
}
​
@Override
public boolean stopSpan(AbstractSpan span) {
    stackDepth--;
    if (stackDepth == 0) {
        ListenerManager.notifyFinish(this);
    }
    return stackDepth == 0;
}

一般来说的话,方法的Interceptor的 beforeMethod 会执行

ContextManager.createLocalSpan();

afterMethod 会执行

AbstractSpan span = ContextManager.activeSpan();
ContextManager.stopSpan(span);

但是很多中间件的某些场景都是异步的,尤其网关是响应式的,所以入口和出口也可能在不同的类里。

比如网关的 createLocalSpan 是在 NettyRoutingFilterInterceptor

而 stopSpan 是在 HttpClientFinalizerSendInterceptor

再看下上面的 stopSpan 方法的调用的地方

stopSpan 方法返回值是根据 stackDepth 是否为0来的,如果 stackDepth != 0,返回false

9.png

那这种就有点危险了,如果有方法触发了 createLocalSpan 而后续没有执行 stopSpan 就会出现内存无法回收。

比如只执行了 NettyRoutingFilterInterceptor 而没有执行 HttpClientFinalizerSendInterceptor

网关异常代码

这种问题很长时间都没有人反馈,说明还是小众的。主要是我们写的不规范也有一定的原因。(不要问,问就是开源全锅)

public class CorsResponseHeaderFilter implements GlobalFilter{
    @Override
    public Mono<Void> filter(ServerWebExchange exchange, GatewayFilterChain chain) {
        return chain.filter(exchange).then(Mono.defer(() -> {
            exchange.getResponse().getHeaders().entrySet().stream()
                    .filter(kv -> !CollectionUtils.isEmpty(kv.getValue()))
                    .filter(kv -> (
                            kv.getKey().equals(HttpHeaders.ACCESS_CONTROL_ALLOW_ORIGIN)
                                    || kv.getKey().equals(HttpHeaders.ACCESS_CONTROL_ALLOW_CREDENTIALS)
                                    || kv.getKey().equals(HttpHeaders.ACCESS_CONTROL_ALLOW_METHODS)
                                    || kv.getKey().equals(HttpHeaders.ACCESS_CONTROL_ALLOW_HEADERS)
                                    || kv.getKey().equals(HttpHeaders.ACCESS_CONTROL_MAX_AGE)))
                    .forEach(kv -> {
                        kv.setValue(new ArrayList<String>() {
                            {
                                add(kv.getValue().get(0));
                            }
                        });
                    });
            return chain.filter(exchange);
        }));
    }
​
}

这段代码主要是解决网关跨域的问题,记得有一些后台页面对返回的头有限制,所以做了这个逻辑处理,过滤一些响应头和指定格式。

乍一看没啥问题,问题就出现在 Mono.defer,一般我们使用的多的是Mono.just。

看一下官方文章这俩有啥区别 projectreactor.io/docs/core/r…

简单介绍一下常用的api:

Mono.just 饿汉式:立即执行

10.png

Mono.defer 懒汉式:发布之后,等待订阅者来执行(有延迟)

11.png

Mono.create 完全自主控制:发布之后,自己添加/移除监听器,并且手动写回调

12.png

问题解决

饶了一大圈,在本应该skywalking 的gateway inteceptor 走完了之后,stackDepth 为0。

而 Mono.defer 操作,又进入了 NettyRoutingFilterInterceptor,执行了 createLocalSpan,stackDepth ++,再之后的CONTEXT就无法remove了,造成内存泄漏。

访问两次之后就会出现这种情况了。

13.png

同事已经给修了。

github.com/apache/skyw…

同一个链路上 ServerWebExchange.getAttributes() 是一直有的,进入的时候放一次,再次进入判断一下如果是同一个链路的话,就不再执行后面的代码了

总结

开源项目就是有这样的魅力,发现其中问题,再fix提交。

不过线上运行也确实是坑啊,之前有别的网关已经接过了,没问题,就直接上了。

但是每个网关项目本身也不一样,一个小小的过滤器有这么大的能量。

额外说一句,一定要灰度!!!