文件IO导致dds write接口block的分析

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.哪位大神好的方法，还请赐教，不慎感激!