1.背景
为了快速的完成算法的验证,最近在项目上使用了开源的通信组件fastdds。搞通信中间件的朋友应该都知道这个组件,相对来说,其应用比较广泛,像ros2,cyber等开源库,底层所使用的通信组件就是fastdds(毕竟人家开源,免费而功能全,都是很香的)。之前我们对fastdds做了一些性能测试,完全满足我们的通信要求,因此就通信组件修改为fastdds了。
通信架构:
以上是一个很简单的数据发送-接收-处理的片内数据通信的处理模型,在项目一开始的这个模型我们也测试过(用可能当时测试的比较简单,系统环境不复杂),在fastdds的write接口调用,并不会出现block时间过长的现象,当然也有可能没有注意这个现象,因为测试时候,我们关注更多的是发送周期是否稳定,即发送前一帧与后一帧之间的时间间隔是否稳定。另外,为了确保数据处理的实时性,项目上将数据处理线程设置为RR调度的实时优先级线程。相对应的,数据发送线程会被设置为RR调度的实时优先级,两个线程的优先级相同,不过没有绑核。数据接收线程一开始并没有设置优先级,随着问题的暴露,后来也设置了优先级。
2 问题:
经测试,在调fastdds datawriter类的write接口时,出现block 超过10ms甚至是100ms的线程,这个引起来的问题是:数据处理端无法得到实时的处理,即会出现数据处理时间的不确定性而影响程序的整体逻辑(即算法部分)。
3 排查过程:
3.1 剔除其他模块,保留干净环境
排查多模块程序问题一般逻辑是去除其他模块,得到仅有自己开发模块的一个干净纯粹的调试测试环境。然后以模拟的方式,增加其他模块执行的CPU。在这里我们首先拿掉了算法模块,以写文件的形式模拟算法那块的CPU(其实这种方式不太好,算法部分消耗的有可能仅是CPU,而IO就不仅是CPU消耗了,还有内存以及磁盘)。得到干净环境后,block问题依然能复现。
3.2 增加打印
排查奔溃的问题,可以通过debug的方式或者用coredump方式比较容易,但是像这种非奔溃的接口block问题,我们一般是通过打印日志的方式进行排查(当然有更好的方式,可以在评论区留言,也可以私信我,一起讨论,相互学习一下)。在响应的日志记录点上输出对应的时间戳,通过比对时间戳,来确定发送接口write阻塞的位置。
以下是正常情况下输出的日志,
在发送线程发送数据,一般在很短的时间内接收线程就能够收到数据,在微秒级别,根据统计,一般在100us内接收线程就能够接收数据。另外,接收线程接收完数据并触发数据处理线程的执行也是在微秒级别,有图片看出,从触发到执行,使用了24us的时间。所以正常情况下,整条工作链路使用的时间会比较端,不会占用ms界面的时间。
3.3 异常日志分析1
注:数据发送进程和数据接收进程采用两种日志记录方式,所以打印的风格不一样,在时间戳的单位上就没有统一,
这个是异常日志
1.消息发送的时间戳:1712827172715ms,调用datawriter的write调用接口后的时间戳:1712827176172ms,
2.消息接收线程接收的时间戳:1712827176172367us,即1712827176172.367ms,
那么发送到接收所使用的时间1712827176172.367-1712827172715=3457ms
也就说,发送线程出现了阻塞,而运行前,为发送线程配置了RR调度的实时优先级,所以理论上没有更高优先级抢占的话,正常情况下,不会也不应该出现3s多的,真是离大谱了。这个结果给我的第一反应就是肯定出现了共享资源争夺了(发送线程与接收线程之间,它俩直接使用的fastdds的datasharing通信方式),而且优先级反转了。于是在fastdds write接口的调用流程中,涉及到通信data race的,都加上前后时间的打印☺。
但是这些打印好像并没有出现在日志中。
3.4 异常日志分析2
这个日志看起来有点奇怪,数据处理线程的阻塞导致了数据接收线程的阻塞,数据接收线程的阻塞又导致了发送线程无法退出。感觉好像处于此刻在同一个CPU运行,有点类似以下情况:
这个好像就解释的通了为啥会出现异常的日志打印了,但是为何会出现了数据处理线程的阻塞(该线程每次触发的时候仅是向磁盘上写入1k的文件),后来网上查了一下:有可能是文件描述中的buffer满了,向磁盘中写入脏页的内容而导致阻塞。这个好像也能解释的通。但是算法部分的工作内容应该不是写文件,那集成工程中出现这个问题是原因出现导致的尼?
查看代码。发送进程中日志在向terminal输出时,同时也会向文件中写入日志,是否可能是这个引起的?而接收线程和数据处理线程的日志都是打向终端的。后来将日志修改为统一的方式,同时将数据处理线程的写文件加了一个fsync 同步操作。经过几轮测试后,以上两种情况并没有复现。
4 初步结论
目前的初步的结论是:同步写文件有可能会导致线程阻塞时间比较长,而影响到其他线程的执行。
但是没有直接的证据证明,调试中使用perf工具,抓到了dds发送过程中被切出去的情况,而且是处于运行running状态的情况下:
现在准备退会到异常情况的代码,看能否通过perf抓到内核的直接证据。由于自己对内核的调试不是很熟悉,perf不加指定的进程,产生的数据量有很大。加了之后,又看不出是哪个进程导致切出的。这个Linux内核的编译没有将bpf需要的选项加上去,无法使用bpf_trace.哪位大神好的方法,还请赐教,不慎感激!