ARM应用调试打印的耗时分析

1. 问题背景

在多个微服务子程序调试的时候，发现一个奇怪的问题。在Shell登陆信号机手动启动各个微服务程序的时候，一切都响应正常。但是打包成固件包，上电启动的时候，在应用配置稍微复杂一些的情况下，就会出现频繁的RPC通信超时获取不到信息的情况。

由于每个微服务程序不是直接通过启动脚本启动的，而是通过一个管理微服务的程序间接启动。管理微服务程序（Manager Microservice Program, MMP）通过fork + exec的方式将启动信息传递给子进程，从而作为父进程能够拿到子进程的退出状态。通过这个方式，能够将异常退出的子程序进行重启。

2. 问题分析

2.1 更多的尝试和情况收集

问题背景进一步收集：
RPC通信超时获取并不是必现的，而是跟随着RPC传输的数据量呈现一定的比例关系。当通信的数据量较小的时候，不会出现超时问题。当存在较大的通信数据量时候，超时是必现的。

进一步尝试后，发现以下现象。

问题能够在以下情况中解除：

• 当数据库服务不用MMP间接启动，采用手动输入命令的方式启动，问题解除。

• 当初次上电后，退出管理程序及其监控微服务，手动运行系统中的应用启动脚本，问题解除。

问题不能够在以下情况中解除：

• 在不退出上电启动的管理程序，而通过交互的方式，让管理程序重启启动所有子服务的时候，问题不能解除。

2.2 尝试与直接原因分析

从现象看来，不使用MMP启动的时候，就没问题。但是用了MMP启动就出问题。这一点出发，看起来很明显是MMP的问题。但是将第一次上电启动的MMP退出，手动运行启动脚本却没问题看来，问题应该和MMP没关系。这里唯一的不同在于，上电启动和手动启动。

上电启动和手动启动有什么不同呢？

将上电启动时候的环境变量打印和Shell启动的环境变量打印出来后，

# 串口启动的程序环境变量打印
env:USER=root
env:SHLVL=4
env:LD_LIBRARY_PATH=/home/lib
env:HOME=/
env:OLDPWD=/home
env:LCD_TYPE=
env:TERM=vt102
env:PATH=.:/bin:/sbin:/usr/sbin:/usr/bin:/dav0:/dav1
env:UIMAGE_BOOTP=1
env:SHELL=/bin/sh
env:APP_BOOTP=1
env:PWD=/home/main

# Shell启动的程序环境变量打印
env:USER=hik
env:SSH_CLIENT=10.10.114.23 60539 22
env:SHLVL=3
env:LD_LIBRARY_PATH=/home/lib
env:HOME=/root/
env:OLDPWD=/home
env:SSH_TTY=/dev/pts/0
env:LOGNAME=hik
env:TERM=xterm
env:PATH=.:/bin:/sbin:/usr/bin:/dav0:/dav1:/usr/bin/dvrCmd:/home/app
env:SHELL=/bin/sh
env:PWD=/home/main
env:SSH_CONNECTION=10.10.114.23 60539 10.10.113.223 22

发现对应的TTY是不同的，猜想有可能是连结终端的速率不同造成的问题。注意到，我们的超时服务程序是存在调试打印的，出现超时的那个配置其实调试打印已经在终端上显示了。看了看打印的字符量，大概有11K的字符串。通过增加耗时打印，惊人的发现居然有

ms: 1586

1586 ms，也就是打印11K的字符串居然需要1.5秒耗时，这显然是违反常理的，虽然ARM板子性能不如PC，但也远不止于会这样。

同样的程序手动启动，到相同地方的打印时长。

file[v3/cycleinfo.h]:line[234]:=============== ms: 21

耗时大概在21 ms。

这个现象和之前

• 当初次上电后，退出管理程序及其监控微服务，手动运行系统中的应用启动脚本，问题解除。

这个现象相符，原来问题的直接原因是，上电驱动的程序打印耗时会延迟特别高，耗时在500 - 1500ms左右波动。但是同样的程序，因为手动启动打印耗时低（21 ms），所以RPC服务超时的情况不会产生。

2.3 根因分析

为什么同样的程序用不同的终端启动，差异会如此明显呢？想到串口连接shell的时候，要设置波特率，我们的板子是115200。估计是串口启动的字符串输出速率被这个波特率限制了，而且上电启动的时候，终端对应的tty，很有可能就是这个原因。但是我们ssh连接进去走的是网络，速率远高于115200，所以会快一些。

那么怎么验证这个猜想呢？

用串口连接进板子，然后手动启动相同程序，果然耗时到了

ms: 1001

这个时候猜想和显示保持一致了。

3. 结论

• 程序里面的打印实际上消耗的时间，远远比想象中的要高。所以不要在正式发布的程序中增加打印，会很消耗程序性能。

• 对于时间敏感的接口和程序，调试打印甚至会影响正常业务。