TB总站现网频繁GC堆栈资源不释放问题定位

发布时间 2023-09-15 17:13:06作者: heroinss

dump的文件在现网,暂无截图,从现网看,很多的forkjoin和future的对象,GC后依旧很多,几十万个,把堆占满了

日志里频繁打印

2023-09-11 11:20:39,899 [DefaultTransportService-18-2] WARN  o.t.s.t.m.s.GatewaySessionHandler - [4c053877-6bc6-4a94-9584-54e8e0472e03] Failed to process device connect command: 三香广场-assets-16号两开电动风阀
java.util.concurrent.TimeoutException: null
    at org.thingsboard.server.queue.common.DefaultTbQueueRequestTemplate.setTimeoutException(DefaultTbQueueRequestTemplate.java:163)
    at org.thingsboard.server.queue.common.DefaultTbQueueRequestTemplate.lambda$tryCleanStaleRequests$0(DefaultTbQueueRequestTemplate.java:132)
    at java.base/java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1603)
    at org.thingsboard.server.queue.common.DefaultTbQueueRequestTemplate.tryCleanStaleRequests(DefaultTbQueueRequestTemplate.java:128)
    at org.thingsboard.server.queue.common.DefaultTbQueueRequestTemplate.fetchAndProcessResponses(DefaultTbQueueRequestTemplate.java:117)
    at org.thingsboard.server.queue.common.DefaultTbQueueRequestTemplate.mainLoop(DefaultTbQueueRequestTemplate.java:101)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:829)

 

2023-09-11 11:14:22,585 [tb-core-notifications-consumer-38-thread-1] INFO  o.t.s.s.q.p.AbstractConsumerService - [a8866a40-f76d-11ec-be1b-f1ecc841c59e][DEVICE][71f9f423-25ec-11ee-b96e-bfe39a004bd2] Received Lifecycle event: UPDATED

错误日志定位

错误日志在类中有两个位置会打印,onconnect这个方法是不可能的,因为总转接收的topic不会有,连接topic的,只可能在下图的位置打印

 

 

这是一个回调超时的错误,因为不知道是什么触发的(猜测是由发送消息触发的,物联网的频繁GC导致类数量庞大,多半是即时消息引发,因为连接相对来说数量是比较少的,而且连接的断开和建立,一般都会有日志打印)

那就查看这个方法的调用,看看源头是哪里

 

简单来说,就是查看设备在不在这个网关session的map里,如果不在,加了一把共享锁,去调用上图的方法

 

 

 

 

 

上图这个方法的调用非常多,如下图,几乎所有的消息和连接,都会调用这个方法

 

没有全部列举

 

举个例子,从这些方法名也可以看出,上报的属性和时序消息都会触发这些消息,证实了所有的消息都会触发打印错误日志。那接下来就看看为什么getDeviceCreationFuture这个方法会频繁打印日志,这个方法的最主要的工作

 

 

 

那超时肯定是调用process引起的,看看这个方法

 

 

查看send方法,

 

 

这个方法有一个超时时间,默认是10s,预测超时是由这个引起的,因为所有的回调都没有添加withTimeout处理,那就看看这个方法调用的sendToRequestTemplate

 

这个类里还放了一个一直运行的线程,可以看一下,大致就是这个运行线程就是取request队列对应的response队列里的元素,拿出来,处理后,就将结果塞给回调

然后回遍历request队列,将所有超时的请求,塞一个timeOut的异常给回调,触发了日志打印里的Failed to process device connect command;至此,已经定位出了打印错误日志的原因

 

 

 

 

 

走到template命名格式的,就差不多到底了,再看send

 

走到这里已经走到thingsboard的队列处理核心了

 

可以看出对称性,生产和消费都是成对出现,看看DefaultTbQueueResponseTemplate,在init里起了一个一直跑的现成,用来处理请求

 

 

设备状态信息频繁打印定位

日志打印的地方

 

 

回到打印错误日志的地方,这里查询出来设备名称,就会放到map,如果map有了,压根就不会走到这个方法来,那就是map里的方法名被不断添加和删除,或者转发子站和总站断连,不断触发网关新建上下文,要重新给网关下的设备建立这个map

根据现网dump的数据量,不太可能是网关,一共60个子站,子站转发的机制是1s重试,断连的前提是先链接上了,又断开了,不可能出现几十万个对象。大概率还是消息触发。还是顺接上面的请求处理,既然超时了,那肯定是处理请求 有问题,可能处理请求的时候触发了什么操作, 引发了map删除了设备。

 

 

DefaultTbQueueResponseTemplate处理请求,调用handle,看一下这个方法

 

进入对应分支

 

 

这个方法就是这次现网问题的原因,这个一个获取不到则创建的方法,所以先加了一个重入锁,这个方法里的find或者save方法,都是调用dao的

如果device==null,就要去find设备profile,如果不为null,会走一个判断设备从属网关是否变更的判断,如果变更,也会做save和onupdate的操作

看下onDeviceUpdate方法,从这个方法的内容能猜想到,现网频繁打印更新日志,应该和红框内的方法有关系,而且目前的配置确实是有问题的,同一个子站的消息,通过两个topic发送给总站,也就是说,一个设备对应到两个网关,很可能就是这个原因导致了设备频繁切换广播状态变化,而且从属变化,也很可能是devices的map里被频繁清空,又频繁写入的原因,因为一个设备在两个网关下频繁切换。接下来看代码验证猜想

看一看广播方法

 

 

 

其中的send方法调用和之前一样

 

根据这个目录,很明显,下边两个类就是选种类生产消息的消费者,因为现场日志来自core的线程池,看一看DefaultTbCoreConsumerService

 

它继承了打印错误日志的虚类,且线程名一样

 

 

这个方法监听时间

 

 

查看父类的处理

 

 

这个方法调用就到了日志打印的地方,至此,重复打印更新日志的原因也知道了。最后也是最重要的,定位在哪里触发了网关删除设备的信息,导致map不断被写入又清空。

 

同一个设备从属的两个网关上下文不断增加和移除设备信息定位

可以明确也是监听广播后删除的,这个代码量多,不知道是哪里触发的,但是map的移除方法只有一处,那就逆推吧

 

调用处,以下几个调用都排除了其他调用可能了

 

调用处

 

找到根源,一个不停的线程从核心的msg里取数据

 

 

这边怎么查根源就没啥思路了,那就把poll的的类研究一下,这个队列很类似生产者,消费者的订阅模式,那就看下消费的订阅了什么topic,看看能不能找到对应的生产者

 

订阅topic,查了下,选择太多,不是很容易看出来的

 

那就看下接收到msg会在哪些地方产生把,红框是和消费者端的动作一致的

 

看这个代码意思,是找对地方了,现在的问题就是一个设备因为从属于两个网关发送消息,导致在总站有了两个session,但是一个设备应该是只有一个session的

 

 

调用上面代码的源码,到这里就找到了devices的map里设备信息会被反复删除和放入的原因。