新版Ansible速度慢问题排查及解决过程

前段时间负责升级及维护公司中控机ansible，碰到一个问题觉得有点意思，遂记录一下

Ansible速度慢问题排查

中控机新版Ansible上线后，碰到一个棘手的问题：大部分SRE反馈新版速度非常慢。经过几天的调试、排查、分析、解决后，将过程整理如下：

发现问题

通过time 命令发现新版Ansible在目标机器上执行 ls 命令需要8秒的时间，个别机器需要13秒

可以看到，在某台机器上，执行一项ls命令的时间去到了13秒之多。

初次解决

发现修改Ansible配置文件的 [become] 项会使时间缩短到4、5秒。

该项是在目标机器上先用sudo命令切换下用户。

于是修改配置文件添加 [become] 项。

引发新问题

修改 [become] 项后，经某位同学反馈，某些产品线下的机器由于不存在sudo命令，在这些机器上会执行失败。

所以该解决方式存在问题不能使用。

问题分析

问题又回到原点，重新对新版Ansible速度慢的问题进行排查。

使用 strace 分析

查看strace日志发现有大量的select等待，从12189行一直到33950行。应该是在执行某项操作时长时间阻塞。

Ansible debug

使用Ansible调试，发现在目标机器上执行AnsiballZ_command.py文件时花费了大量的时间。

问题初显

找到 AnsiballZ_command.py

这个 AnsiballZ_command.py 是什么文件？为什么会消耗大量的时间，有没有什么办法获取到这个文件？

通过查阅Ansible官方文档，发现存在一项配置：Ansible_KEEP_REMOTE_FILES

开启这项配置可保留发送到目标机器上的文件。

结合 Ansible debug，到目标机器上找到AnsiballZ_command.py

查看AnsiballZ_command.py内容

发送到目标机器上的AnsiballZ_command.py都大同小异，我们看一看下内容：

我们发现文件执行该文件保存一段base64编码，该编码为实际运行的文件的zip压缩包。

我们按照上图修改，获取到zip文件并解压。

该目录结构：

文件执行分析

目录有了，文件有了，如何分析呢？

我们按照 AnsiballZ_command.py 的内容，编写一个Python文件test.py：

然后通过cProfile分析该文件生成的result.out.

再编写一个pstat.py。

运行pstat.py 查看输出。

可以看到文件一共执行7.007秒，{posix.read} 一项占用了6.882秒。这应该就是Ansible执行速度慢的罪魁祸首。

对比旧版

然后我们对比下旧版Ansible的输出，旧版Ansible与新版Ansible差异很大，但是可以看到旧版也是在目标机器上执行一个文件 – command。

剩下的大同小异，只不过旧版没有zip压缩并base64编码，也没有目录，所有代码都集成在一起。

旧版输出：

旧版相似的调用有红框标出，但没有更有价值的信息了，因为新旧两版代码差别太大，几乎不存在什么参考性了。

于是在这又卡住了。

对比其他机器

似乎一筹莫展了，又突然想起开发时我在个人云主机上跑过Ansible，速度只有两秒多，版本也是2.9.2，可以拿来对比下。

剩下的又是大同小异，以下是输出结果：

可以看到与中控机新版输出大同小异，然而却少了{posix.read} 这一项，时间就缩短到了0.34秒。

然后我又测试了我家里的物理机，虚拟机，以及其他云主机以及VPS。时间均在0.5秒一下。

我在开发中控机的新版Ansible时，这块的代码没有改动过，是什么原因导致同一套代码在公司的机器上和其他机器上出现了截然不同的速度差异？

代码分析

接下来分析代码层面。

发现新版 Ansible_command_payload.zip 这块的代码，集中位于Ansible/lib/ 下的module_utils与modules目录内，modules/command.py 会调用 module_utils/basic.py 内 run_command() 函数。

这块代码新版更改较多，但依稀可以找到旧版的大致结构，于是在目标机器里的Ansible_command_payload目录下，将旧版的 run_command() 函数替换到新版，并在新版的调用上做了相应的兼容修改，然后测试。

运行速度缩短到0.015秒！！！

测试在目标机器上可行，然后修改中控机测试机的新版Ansible，发现速度也缩短到了4秒的时间！！！

看来新版Ansible的问题解决了。

后续

到上一步已经解决了问题，但是目前还是用旧版的代码，最终的问题也还没找到，后续Ansible升级的话还是会头大。

换回新版 run_command() 函数，继续调试，修改，发现 run_command() 是调用subprocess.Popen() 执行命令，而且 {posix.read} 是出现在Python 的自有库 subprocess.py 文件下的 _execute_child() 函数里，一步一步寻找，发现了 MAXFD = os.sysconf(“SC_OPEN_MAX”)

当 subprocess.Popen() 的参数 close_fds 设置为True时，在子进程执行前强制关闭所有除 stdin，stdout和stderr外的文件；然而 close_fds=True时会读取 os.sysconf(‘SC_OPEN_MAX’)的值：

从3开始迭代并依次关闭fd，这个值是系统定义的，由于是公司机器，系统安装时统一设置，因而在公司机器上这个值都是10485760，所以速度会非常慢非常慢。(这块也是由于Python实现的不太好导致管道阻塞) 。而旧版Ansible close_fds 默认是False，所以不存在此问题。

好奇的同学可以继续深入，为什么Python实现的不太好导致管道阻塞，挺有意思的。

Ansible执行sudo有一个会切换到一般用户的过程，过程中会将这一数值重置为一般用户所设定的值，在公司机器上的一般用户这个值是150240，还未达到管道阻塞的程度，所以会很快，也是设置 [become]变快的原因。

Ansible配置文件内未找到相关配置项，所以将调用 run_command() 所在 basic.py 文件修改后分离出来，以外挂的形式通过配置文件定义，避免Ansible hook，便于维护。

另外gathering facts慢也是这个问题，针对相关文件进行修改并外挂。gathering facts 的时间也同样缩短至5、6秒。

与旧版速度差异

目前与旧版相比，新版速度仍旧会慢些，这是由于新版Ansible的连接机制所决定的。

新版Ansible执行过程：

旧版Ansible执行过程：

可以看到新版Ansible 在目标机器上执行 ls 命令需要6次登陆操作，而旧版至有3次登陆。官方的考量应该是这样易于代码维护且可扩展性更强。