将 localhost”改为 127.0.0.1”如何将我的测试套件速度提高了 18 倍
将“localhost”改为“127.0.0.1”如何将我的测试套件速度提高了 18 倍

我想分享一个关于一行代码的改变如何提高我对软件工程的理解的轶事(有些最近);这是我一生中的一次经历,从此对我的职业道德产生了深远的影响。
如果你想跳过这个故事,简单的解释在最后一节。
背景
所以是 2015 年。我是一名大二刚毕业的 CS 学生,准备跳入学位的后半段。那时我刚刚学会如何构造 B 树,建立了自己的递归下降解析器,并完成了一个软件安全研究项目。看到我的同龄人如此迅速地找到编程工作(只有不到两年的编程经验),我决定我也该找些工作了。
转眼到了下一学期,我找到了一份软件工程的工作,做了一名 QA 实习生。我们实践了许多常见的敏捷实践:我参加了 scrum 会议,完成了用户故事,并记录了缺陷。
该公司在自动化测试方面积累了一些技术债务,因为他们主要产品的许多集成测试需要人工干预。所以他们雇用我的主要目标是在产品的测试套件中尽可能多地自动化回归测试。大多数简单的问题已经自动化了,而较难的问题涉及到一些操作,比如在没有实现 SDK 的情况下点击一系列 UI 按钮,或者将一个物理硬件插入网络并等待它修改网页。
这些集成测试自然要求我投入到整个系统的许多不同的组件中。某一天我会在浏览器中执行 JavaScript,第二天我会嗅探网络上的数据包,第三天我会编写 SQL 查询来检查状态变化。为了测试服务之间的交互,我必须学习每个组件使用的语言,从网络协议到抽象这些底层细节的对象。
在被消防水管喷了几个月后,事情终于开始变得明朗起来。我每天都会来到办公室,调配几个虚拟机,在其中部署 RDP/SSH,执行网络请求,修改一些代码,提交并推送它们,参加一两次会议,然后关门大吉。
问题
当时,QA 团队采用了机器人框架来执行他们所有的集成测试。它做得很好,因为测试可以用商业语言编写,直接翻译成我们在系统中跟踪的验收测试。以下是它的典型外观。
每一行都按顺序执行,缩进的行是单个测试的子方法,执行某种操作或验证步骤。我们使用 Python 驱动程序将这种高级语言翻译成执行这些测试的代码。Python 类可能看起来像这样。
这些 Python 函数将进一步执行 JavaScript/Java/C#/SQL 脚本来测试系统中的各种事件。因此,在执行测试时,我会看到一个方便的可视化结果。屏幕上的每个点代表一个机器人执行的子方法。

我们总共进行了大约 100 次这样的高级测试,在我们的 Windows 虚拟机上执行大约需要 1.5 个小时。当时我没把它放在心上。所以我很乐意用 Robot 框架编写更多的测试,添加新的 Python 函数,到处写一些脚本。但是后来发生了一件让我非常困扰的事情。
QA 团队的一名成员提到,他们看到测试运行得比平时快得多。我转过头去看,是的,事实上,那些点在屏幕上飞来飞去,一些测试在几秒钟内就完成了,而它们通常需要几分钟。我马上问为什么会这样。没有明确的答案,但似乎是在一个具有不寻常环境的虚拟机中运行的测试导致了这种行为。这似乎很无害;虚拟机只是被配置来测试我们的一个非标准生产系统。这怎么能让它们跑得这么快呢?
我进一步恳求道。一个开发人员简单地看了一下,说 Robot 中执行的每一个子方法都不会在一秒钟内完成。这可能意味着某处引入了奇怪的一秒钟延迟(每次测试)。我想看得更远。但是遗憾的是,我没有能力访问原始 VM,我有几件其他事情要做,而且测试代码有几层代码执行:Robot 查找 JSON 配置文件来执行 Python 文件,然后查找第二个 JSON 文件来调用 JavaScript 函数进行远程对话——可以想象调试这些测试有时会非常痛苦。我得到的只是一个日志文件,其中附加了几个关键执行阶段的状态变化。我只是一个勉强能跟上信息过载洪流的新手实习生。就这样了。
一个突破
几个月过去了,我越来越频繁地运行测试套件,以确保它们正常工作。再做一次测试?是时候去喝杯咖啡,逛逛办公室了。我甚至一度尝试将虚拟机数量增加一倍,这样我就可以同时运行两个测试环境,节省了我大量的等待时间。
但我无法摆脱这种感觉。我心想。
这怎么可能呢?我看到的是骗局吗?那些测试是不是什么都没做就提前退出了?或者也许我没有产生幻觉,我浪费了太多时间一遍又一遍地做这些测试。
我终于崩溃了。我知道我应该做这做那,但是我下定决心要找到那个在我皮肤下爬行了几个月的 bug。
所以我设定了两个小时的时间。这场比赛是为了看我是否能找到根本原因,或者永远陷入慢测试综合症。一个实习生的想法:解决这个问题最合理的方法是什么?当然是注释掉代码!在我的脑海中,我在想,如果我删除所有不必要的代码,仍然看到测试运行缓慢,我有一个小得多的搜索区域。
所以我首先跳入 JavaScript 文件。当我这样做的时候,我对自己说:
好了,注释掉那个 block 破坏了所有的机器人测试。不需要这个功能。我不知道这段代码做了什么,但是测试现在会随机失败。呃,测试还是很慢。
然后我想可能是一些奇怪的配置导致了问题。我查看了 JSON 文件,但什么也没找到。
一小时过去了,还有一小时。现在,还有什么代码我没碰过?也许这些 Python 文件。但它们所做的只是调用其他文件中的其他函数。等等,这是什么?
不知道我是不是把这个注释掉?
def __init__(self):# self._sut_path = os.path.join(os.path.dirname(__file__),# ‘..’, ‘sut’, ‘login.py’)# self._status = ‘’
不,测试失败了。这个怎么样?
# self.logger = logging.getLogger(‘localhost’, 3456)# handler = logging.StreamHandler()# formatter = logging.Formatter(‘%(asctime)s %(levelname)-8s %(message)s’)# handler.setFormatter(formatter)# self.logger.addHandler(handler)# self.logger.setLevel(logging.DEBUG)# for f,a in my_funcs:# self.logger.debug(‘Executing ‘ + f ‘ with args ‘ + a)# # …
过不了一秒钟,我看到这个出现在我的屏幕上。

然后最自由的感觉降临在我身上。 砰 !圆点在屏幕上飞舞。我睁大了眼睛。 这个 就是它!我短暂地举起双手,高兴地摇了摇。
我进一步将问题缩减到这一行代码。
self.logger = logging.getLogger(‘localhost’, 3456)
究竟是什么原因会导致日志库在每次测试初始化时暂停一秒钟呢?
我给开发团队发了一封电子邮件,说当我去掉这段代码时,测试运行得非常快。其中一个开发者回复了我。
不知您是否将 localhost 替换为:::1?或者可能是 127.0.0.1 ?
所以代码变成了
self.logger = logging.getLogger(‘::1’, 3456)
不,还是个问题。
然后我试着
self.logger = logging.getLogger(‘127.0.0.1’, 3456)
你瞧,测试进行得非常顺利。我简直不敢相信。
好吧,这是我见过的最奇怪的 特征 。我甚至不…
甚至我也没有。我对这个发现欣喜若狂,所以多巴胺的突然释放分散了我对这个问题的追求和寻找根本原因的注意力。我很高兴看到我在不到两个小时的时间里解决了困扰我几个月的问题。
在提交和修改代码之后,我开始测试新的测试套件。只有 5 分钟。因此,通过改变一些字符(甚至不是 1.0 行代码),测试从 90 分钟运行到 5 分钟,提高了 18 倍。
善后工作
QA 团队和我的经理都对我的发现表示祝贺,并将此记录为缺陷。我可以如此轻松地运行测试,我的生产率也显著提高了。
事后看来,本可以有更好的方法来解决这个问题,但这是我在这个领域缺乏经验的结果,而不是解决问题的能力。一个剖析工具在这里会很有帮助。可惜我当时不知道有这种东西存在。
附注:在那灾难性的一天过后不久,我和 QA 团队基于运行在 Nodejs 之上的 Mochajs 创建了一个新的测试套件。这个想法是去除调试的繁琐和不必要的代码分层,以利于统一的测试界面。它甚至更快,而且 100%可调试!
当时,我只是满足于它被修复,并没有费心去检查为什么会出现这种情况。大约一年后,我离开了公司,甚至不知道是什么导致了这个问题(但是不要害怕,下一节将解释原因!).我知道我应该在离开前更充分地调查这件事。但是我被突如其来的喜悦冲昏了头脑,再加上我们无论如何都要计划替换测试框架的事实。现在,我想我更有可能不会重蹈覆辙。这是一个寻找问题根源的学习机会。结果,这让我成为一个更加细致入微的程序员。
但是我从这整个磨难中学到的最重要的一课是不断挑战现状。当事情看起来不太对的时候,不要自满。花点时间(安全地)探索那些让你头疼的问题。即使有其他事情要做,通过对未知问题的建议解决方案进行实验,也有助于获得一些观点。它可能不会产生即的解决方案,但学习一些起作用的因素可能是值得的。
善后
在写这篇文章的时候,我做了一些调查,看看到底是什么导致了这种奇怪的行为。我登陆这个栈溢出帖子,里面有答案。这个问题是关于 MySQL 的,但在这里仍然适用。
我非常确信这个问题是由 Windows 机器上的 IPv4 和 IPv6 的差异引起的。我依稀记得 QA 团队的虚拟机被配置为在可能的情况下优先使用 IPv6 地址。这意味着对'localhost'的查找解析为 IPv6 字符串'::1’。但是,日志服务器没有绑定到 IPv6 地址,而是绑定到 IPv4 地址。因此,Windows 无法在默认的 1 秒超时窗口中绑定到'::1',从而回退到 IPv4 版本'127.0.0.1’。这无意中成功了,测试在超时后继续。但是这段代码的位置意味着每次测试运行时都会发生这种情况。我们最初看到一个虚拟机运行测试非常快,可能是因为 IPv4 地址'127.0.0.1'是本地主机的默认解析地址。多么令人沮丧。
没有比 127.0.0.1 更好的地方了,嗯?
—
喜欢我的内容?查看我在 https://hyperparticle.com 的博客。



