记一次fclose导致的性能问题

背景

最近在做功率分析仪的研发，这玩意儿就是个大号的万用表，可以测量用电器的各项电气参数，比如电压、电流、功率，等等。

有款产品一直存在一个性能问题，就是上位机通过USB连接下位机时，下位机上报的测量值经常丢失。下位机应用看应用日志，发现经常有两条日志间隔2s左右，但间隔的位置不固定，用top命令查看CPU占用率，也没有特别高的进程。

我查看驱动日志syslog，没发现任何报错，哪怕是超时报错也没有。但是在应用代码调用write系统调用的前后加日志，发现确实有write耗时200ms的时候，这是不正常的，所以我就接下来这个故障单。

定位丢包问题

理清应用框架

首先了解清楚应用的软件架构

上面就是涉案进程：

1. power进程是下位机应用的主控进程，负责启动其他进程，并做全局初始化配置
2. DSP进程采集传感器的原始数据，处理后将结果写入cdev（字符型设备文件）；data进程主动读取cdev并将数据写入shm（共享内存）
3. 上位机周期（300ms）下发“上报测量数据”这样的VISA指令，scpi进程通过USBTMC协议从USB口收到指令后，再根据SCPI标准(IEEE 488.2)对其解析，然后通知power进程获取数据
4. power进程读取shm，将结果数据压缩，再通过domain socket发送给scpi进程
5. scpi进程再通过USBTMC将压缩数据返回给上位机

最小系统法，卸载USB驱动

为了定位问题在哪，必须先将排查范围逐渐缩小

这样上位机彻底不再跟下位机有交互了，应用日志2s没打印的现象（即卡顿）显著减少，但仍然有，且长时间运行后卡顿频率又上来了！

看来跟驱动无关，是软件问题，但是软件怎么能卡2s呢？不像是死锁，进程能恢复。

查看top命令，发现排名前4的进程是power (13%)、dsp (12%)和2个loglimit (均为11%)，前2个好理解，后2个进程loglimit我看了下代码，就是干的日志转储工作，为啥也会占用11%的CPU？

分析loglimit

loglimit程序的第一个参数是日志缓冲区的大小，第二个参数是日志转储的目标文件，如果缓冲区满，则覆写日志文件。
代码非常简单，去掉错误检查等内容后，如下

#include <stdio.h>
#include <errno.h>
#include <string.h>
#include <stdlib.h>
#include <time.h>
#include <sys/time.h>

#define MAX_BUFF_SIZE (1024*10)

int main(int argc, char** argv)
{
    int limit = atof(argv[1]) * 1000.0f;

        char bak_name[512];
        sprintf(bak_name, "%s.bak", argv[2]);

    FILE* fp = fopen(argv[2], "r+");
    fseek(fp, 0, SEEK_END);

    while (1)
    {
        static char buffer[MAX_BUFF_SIZE];

        if (fgets(buffer, sizeof(buffer), stdin))
        {
            if (ftell(fp) >= limit)
            {
                fclose(fp);
                rename(argv[2], bak_name);
                fp = fopen(argv[2], "w");
            }

            struct timeval tv;

            gettimeofday(&tv, NULL);
            fprintf(fp, "[%s.%.6ld] %s", FormatTime(tv.tv_sec), tv.tv_usec, buffer);
        }
        else
        {
            break;
        }
    }

    return 0;
}

它的调用也很简单，就是将应用进程的标准输出通过管道重定向到自己的标准输入

./F260_DSP_APP.elf | ./loglimit 50024 /var/log/dsp.log& 
./PowerAnalyzer  | ./loglimit 10024 /var/log/f262.log

这样应用就不用操心日志的事情了。思路很好，但loglimit如果在转储时卡顿，例如fclose就会触发sync调用，即磁盘同步。fclose的manpage里有提示

NOTES
       Note that fclose() flushes only the user-space buffers provided by the C library.  To ensure that the data is physically stored on disk the kernel buffers must be
       flushed too, for example, with sync(2) or fsync(2).

继续最小系统法，屏蔽掉loglimit

将loglimit屏蔽

./F260_DSP_APP.elf > /dev/null &
./PowerAnalyzer > /dev/null

结果卡顿消失了！

看来确实是loglimit在主线程里调用sync，导致卡顿2s，没有及时清空日志缓冲，进而导致应用进程卡在写缓冲上（write是阻塞式的）

规避loglimit的低性能

负责power的同事将日志重定向QT框架，但是负责DSP的同事就惨了，他没有QT可用，只能是注释掉一部分日志后，继续带着loglimit用

重新启用USB

重启USB后，上位机又能跟下位机通信了，而且丢包频率大幅下降。

回顾为啥应用卡顿会导致丢包？

做足功课（浏览了USB 2.0规范前8章，通读了USBTMC规范和驱动源码）后，觉得驱动日志有问题，因为驱动会等待write 40ms，如果没完成就会告警超时，但驱动日志里找不到超时告警。

定位为啥write耗时异常但驱动没有超时告警

给USBTMC驱动加更多的定位日志，发现有些日志没有打印出来，但流程明显跑过了，怀疑是日志丢失，于是查看日志缓冲大小，只有16KB，考虑到驱动日志真的很多，于是临时将其扩展成1MB，这下日志看全了，也看到了偶尔发生的超时告警——原来看不到告警是因为告警被覆盖了！

原因藏在第一个出现的异常里！

寻找第一次超时发生时，应用和驱动的交互情况，原来故事是这样的

1. 上位机发出scpi指令后，会立即发送读取scpi处理结果的请求
2. 驱动在收到scpi指令后，就立即将指令内容写到tmc设备文件，并通知应用tmc设备可读，然后等待应用写入待上报数据
3. 应用读取出scpi命令，解析并执行，突然卡在某条日志的打印处了（见上一节）
4. 驱动等待40ms超时，于是回了个NAK给上位机
5. 上位机丢包

至于后面为啥write会耗时300ms，已经没有追究的意义了。

总结

如果loglimit能将if (ftell(fp) >= limit)的分支放到子线程处理，则不会阻塞主线程的stdin读取流程，进而不会堵塞应用进程的日志输出流程，进而不会导致驱动等待应用write超时。

1. 日志系统并不像看上去那样简单，心存敬畏吧！
2. 就像定位编译错误时要从第一个错误开始，定位运行时异常也要从第一个异常开始。