当你的软件在生产中太慢时,你如何才能找出问题的根源?
改善生产可观察性的一个常见起点是记录,最好是基于跟踪的记录(简称跟踪)。例如,OpenTelemetry标准以及与之配合的库和后端服务可以帮助你收集指标、日志和跟踪。追踪--包括进程内和进程间的追踪--是其中最普遍的,对识别和调试问题(包括性能问题)非常有用。
但还有另一种方法来寻找性能问题,即在生产中使用基于采样的剖析。虽然剖析通常是在开发过程中离线使用,但你也可以在生产中使用它来寻找性能瓶颈,用新一代的连续剖析工具。
那么,基于跟踪的日志和剖析之间有什么区别?你应该使用哪一种--你是只需要一种,还是两种都需要?找到生产中的性能问题的最快方法是什么?
跳到我们的结论:基于跟踪的日志和剖析实际上给了你不同的信息。一旦你的软件足够复杂,你很可能会同时需要这两种方法。
在这篇文章中,你会了解到。
- 基于跟踪的日志和剖析究竟意味着什么。
- 两者的优势和劣势。
- 为什么你可能希望两者都在生产中运行。
一个缓慢的程序
想象一下,你安装了一个由别人维护的第三方库,该库提供了一个函数,可以接收两个列表,并且只返回第一个列表中的项目,而不是第二个。
>>> from thirdpartylibrary import items_only_in_first
>>> items_only_in_first([1, 2, 3, 4], [4, "a", 1])
[2, 3]
我们有一个小程序,使用这个第三方库。
from thirdpartylibrary import items_only_in_first
import sys
def task1():
import time
time.sleep(1)
def make_data(length):
return list(range(length))
def task2(input_length):
result = items_only_in_first(
make_data(100_000), make_data(input_length)
)
return len(result)
def main():
task1()
task2(int(sys.argv[1]))
if __name__ == '__main__':
main()
这个程序中最慢的部分是什么,为什么?
使用统计分析来发现性能问题
统计分析以一定的时间间隔对你的程序的运行代码进行抽样,并告诉你程序在那个特定的时间正在做什么。基本上,它运行一个这样的循环。
- 睡眠一下。
- 记录程序在这个时间点上正在做什么。
- 转到第1步。
任何运行缓慢的代码都更有可能被采样,因此更有可能出现在最后的跟踪中。重要的是,记录在任何特定时刻运行的代码是剖析器的工作,而不是你的工作:你不需要做任何额外的工作来获得这些信息。
有了剖析器,我们可以找到我们的例子的性能瓶颈,而根本不需要改变代码。我们将使用Sciagraph性能剖析器来查看程序正在做什么;它是为在生产中运行而设计的,但你也可以使用它进行离线剖析。
该程序被调用两次,有两种不同的输入大小;--trial ,使用Sciagraph的免费试用模式,这对我们的目的来说已经足够了。
$ pip install sciagraph
$ python -m sciagraph --trial run myprogram.py 1_000
...
The report was stored in sciagraph-result/2022-08-09T18-11-25.198672Z
...
$ python -m sciagraph --trial run myprogram.py 10_000
...
The report was stored in sciagraph-result/2022-08-09T18-11-29.223568Z
...
由此产生的分析报告包括以下第一次运行的时间线图。
而第二次运行的图表。
请注意,第二次运行,输入量为10,000,运行时间要长得多。3.8秒而不是1.2秒。在这个特殊的例子中,我们知道长度输入造成了差异,因为我们在命令行上给出了不同的输入。
在真实的软件中,输入可能被深埋在一个输入文件中,一个HTTP响应,或者一些其他的计算结果,这些都不会显示在剖析报告中;剖析通常集中在函数上,而不是输入或变量上。为了了解输入对性能的影响,我们需要求助于日志记录,最好是追踪。
使用跟踪来发现性能问题
日志给我们提供了一组不同于剖析的信息:特别是,我们可以记录函数参数、结果、变量和其他运行时信息。而且,日志信息的时间戳可以用来确定一些代码运行了多长时间。
像常规的日志记录一样,基于跟踪的日志记录或跟踪也可以用来确定你的代码中哪些部分是慢的。但是,追踪比普通日志更能让你获得这些信息。
- 追踪不是孤立的事实陈述--"某事发生了!","其他事发生了!"--而是记录有始有终的跨度或行动。
- 跨度建立了一棵树:它们可以包含其他的跨度,并且可以跨线程或进程追踪,甚至跨多台计算机追踪。你可以想象一下,追踪一个请求,从浏览器到网络服务器,再到后台服务,最后到数据库,然后再一路返回。 追踪有始有终,这也是追踪比普通日志更好的原因之一:跨度的经过时间会自动给你相关代码的运行时间。让我们看一个例子,我将使用Eliot库来演示,主要是因为它比OpenTelemetry更简单,但其原理更普遍。
为了使用Eliot添加基于跟踪的日志,我们将添加。
- 一些模板,告诉它将日志输出到
out.log。 - 一个
log_call装饰器,当它被调用时启动span/action,记录输入,并在函数返回时完成span。Eliot还有其他的API,但这个简单的API对我们的例子来说已经足够了。
结果。
from eliot import to_file, log_call
from thirdpartylibrary import items_only_in_first
import sys
to_file(open("eliot.log", "a"))
@log_call
def task1():
# ...
# ...
@log_call
def task2(input_length):
# ...
@log_call
def main():
# ...
# ...
请注意,与剖析不同,我们必须手动添加日志/跟踪,而且我们必须决定对代码的哪些部分进行注释。我们从上面的剖析中知道,make_data() 不是瓶颈,所以没有必要给它添加追踪,但是缺乏这种信息,我们就必须做出判断。
我们可以运行该程序,然后用一个叫作 eliot-tree.
$ python myprogram.py
$ ls eliot.log
eliot.log
$ eliot-tree eliot.log 10_000
9a6512cd-7c5b-46ba-bb44-e8b8d83e3b45
└── __main__.main/1 ⇒ started 15:40:21Z ⧖ 3.062s
├── __main__.task1/2/1 ⇒ started 15:40:21Z ⧖ 1.001s
│ └── __main__.task1/2/2 ⇒ succeeded 15:40:22Z
│ └── result: None
├── __main__.task2/3/1 ⇒ started 15:40:22Z ⧖ 2.060s
│ ├── input_length: 10000
│ └── __main__.task2/3/2 ⇒ succeeded 15:40:24Z
│ └── result: 90000
└── __main__.main/4 ⇒ succeeded 15:40:24Z
└── result: None
这在某些方面与我们从剖析器中得到的信息相同--我们可以看到函数调用其他函数,以及耗费了多少时间。但也有一些关键的区别。
- **我们只有那些我们明确添加了跟踪的函数的信息。**例如,没有关于
thirdpartylibrary的信息,尽管我们从剖析中知道它很慢。 - **在积极的一面,我们有关于输入和输出的信息。**具体来说,我们可以看到
task2()是和input_length: 10000一起调用的,并返回90000。
不管输入长度来自哪里--命令行、一些第三方输入文件、HTTP响应--它最终都会被记录在日志中。然后,我们可以在输入长度和运行时间之间进行关联,最好是使用比eliot-tree 更复杂的用户界面,并发现input_length ,运行时间越长,就越大。
剖析与跟踪:功能比较
让我们总结一下到目前为止我们所学到的东西,并更明确地说明每种方法的局限性和优势。
你需要做多少工作?
- **剖析。**只要在剖析器下运行你的程序,就可以了。
- **追踪。**你需要对你希望最终出现在日志中的每个函数和代码块进行检测。
你能得到第三方库的信息吗?
- **剖析。**是的,它们和你代码中的函数没有区别;所有相关的东西都会被记录下来。
- **追踪。**由于需要手动检测,获取第三方的信息可能很困难,特别是对于内部细节和不太动态的语言。
OpenTelemetry和其他追踪库倾向于为常见的库提供自动监测支持,重点是Web框架、数据库等东西。在某些领域,这可能已经足够了;在其他领域,如科学计算或数据科学,你不太可能在覆盖率方面得到很大的改善。
函数多久被记录一次?
- **剖析。**任何运行时间足够长的函数都会被记录下来,但由于使用了抽样,快速和不经常运行的函数不会显示在剖析报告中。
- **追踪。**所有的函数调用都可以被记录下来......只要你对它们进行了工具化。在实践中,一旦你扩大规模(例如大型网络应用程序),也会使用采样,因为否则数据会不堪重负。
变量、输入和返回值是否被记录?
- **剖析。**没有。
- **追踪。**是的,如果你选择记录它们的话。
找到并解决我们的性能问题
回到我们的例子,从追踪中我们知道输入大小影响了task1() 的速度。看上面的剖析图,我们可以看到慢的代码是在第三方库中,尤其是这一行。
return [item for item in first if item not in second]
稍微思考一下就会发现,如果第二个参数是一个列表,这个函数是二次函数;它将在O(F * S) ,其中F 和S 分别是first 和second 的长度。
将代码改为使用set ,当输入长度较大时,该函数会以O(F + S) 的时间运行,从而使其运行速度大大加快。
second = set(second)
return [item for item in first if item not in second]
(这个例子是基于Mercurial版本控制系统中一个真实的、意外的错误。)
剖析还是跟踪?两者都要!
如果你想找到性能问题,在生产中进行剖析是非常有用的。日志或跟踪只能告诉你被检测到的代码;剖析可以检查所有正在运行的代码,不管是你的还是第三方的。
追踪对于发现性能问题真的有必要吗?在日志中看到输入的大小是一个有用的提示,但在实践中,你可能仅仅从剖析中就能找出性能问题。然而,在其他情况下,性能问题可能更难识别,跟踪会有帮助。另一方面,跟踪给你提供了从剖析中不可能得到的调试信息:如果你有足够的日志覆盖率,你可以发现逻辑错误和其他问题。
简而言之,在你的生产环境中,你同时需要跟踪和剖析:它们给你不同的信息,有时是互补的,有时是单独有用。
如果你想要跟踪。
- Eliot对小型Python应用程序很有用;我不建议将它用于任何大规模的应用。
- OpenTelemetry被一个巨大的生态系统所支持,还有许多可视化和存储后端,如Honeycomb、LightStep和开源的Jaegar。
对于生产中的剖析。