本文同步发布于字节话云公众号。
背景
前段时间老的 MacBook 到了退休的年纪,听了好友的安利换了基于 Apple M1 的 MacBook,在运行一个项目时发现原本能正常执行的任务在新笔记本上就一直是进行中,由此展开了一段 Bug 调试之旅。
初步探索
有如下几点信息:
- Python 版本为
2.7.10 +
,eventlet 版本为v0.21.0
。 - 造成这个问题的直接原因是代码中使用了
eventlet.sleep
,一旦当前协程执行到了 sleep 语句,eventlet
在切出协程后就不会再切回来 - 使用 py-spy 观察进程发现,看到形如下方的调用信息:
%Own %Total OwnTime TotalTime Function (filename:line)
0.00% 0.00% 0.010s 0.010s run (eventlet/hubs/hub.py:334)
可以初步判定问题出在 sleep 上,由于项目逻辑过于复杂不便调试,不如写个最小化测试代码来验证猜想。
复现问题
既然怀疑问题出在 sleep 上,并且认为 eventlet
在 sleep 后不会切换协程,不妨在一个协程池中开两个协程,每个协程不断输出和 sleep,那么就有如下代码:
import eventlet
def echo(name):
while True:
print(name)
eventlet.sleep(2)
def main():
p = eventlet.GreenPool()
p.spawn(echo, 'foo')
p.spawn(echo, 'bar')
p.waitall()
if __name__ == '__main__':
main()
运行后,在依次输出 foo
和 bar
后,就不再继续输出了。
调试和分析
既然输出了 foo
和 bar
,就说明在执行第一个 echo
协程输出 foo
并进入 sleep 后并没阻塞 eventlet
的调度,所以 eventlet
才能调度到第二个 echo
协程输出 bar
。但是为什么两个协程 sleep 后都不会再次被调度了?既然前面通过 py-spy 监控进程调用栈发现一直在调用 eventlet/hubs/hub.py
,不妨查看并调试此文件中的 run
逻辑。
def run(self, *a, **kw):
"""Run the runloop until abort is called.
"""
# accept and discard variable arguments because they will be
# supplied if other greenlets have run and exited before the
# hub's greenlet gets a chance to run
if self.running:
raise RuntimeError("Already running!")
try:
self.running = True
self.stopping = False
while not self.stopping:
while self.closed:
# We ditch all of these first.
self.close_one()
self.prepare_timers()
if self.debug_blocking:
self.block_detect_pre()
self.fire_timers(self.clock())
if self.debug_blocking:
self.block_detect_post()
self.prepare_timers()
wakeup_when = self.sleep_until()
if wakeup_when is None:
sleep_time = self.default_sleep()
else:
sleep_time = wakeup_when - self.clock()
if sleep_time > 0:
self.wait(sleep_time)
else:
self.wait(0)
else:
self.timers_canceled = 0
del self.timers[:]
del self.next_timers[:]
finally:
self.running = False
self.stopping = False
在这段代码中,我们可以看到对 sleep 的相关处理(第23\~31行),获取协程要被唤醒的时间并减去当前时间,如果超过0说明还需要等一段时间,反之就唤醒。实测发现 self.clock()
返回的时钟数值有问题。
此处的 clock
也就是 eventlet/support/monotonic.py
中的 monotonic()
函数,用于返回单调递增的时钟数(每加1即经过1秒)。此函数在 macOS 上,相关实现如下:
if sys.platform == 'darwin': # OS X, iOS
# See Technical Q&A QA1398 of the Mac Developer Library:
# <https://developer.apple.com/library/mac/qa/qa1398/>
libc = ctypes.CDLL('/usr/lib/libc.dylib', use_errno=True)
class mach_timebase_info_data_t(ctypes.Structure):
"""System timebase info. Defined in <mach/mach_time.h>."""
_fields_ = (('numer', ctypes.c_uint32),
('denom', ctypes.c_uint32))
mach_absolute_time = libc.mach_absolute_time
mach_absolute_time.restype = ctypes.c_uint64
timebase = mach_timebase_info_data_t()
libc.mach_timebase_info(ctypes.byref(timebase))
ticks_per_second = timebase.numer / timebase.denom * 1.0e9
def monotonic():
"""Monotonic clock, cannot go backward."""
t = mach_absolute_time()
return mach_absolute_time() / ticks_per_second
monotonic()
函数调用 mach/mach_time.h
的 mach_absolute_time()
系统函数并经过系数处理得到最终的时钟数,这里的处理方式和 mach_absolute_time() / timebase.numer * timebase.denom / 1.0e9
等价,然而这个算法是错误的。
正确的表达式应该是 mach_absolute_time() * timebase.numer / timebase.denom / 1.0e9
,可参照 monotonic.py 的实现。将此实现修改后,再运行测试代码, eventlet
就能够正常进行 sleep 和调度了。
为什么错误的逻辑在 Intel 芯片上运行正常?
mach_timebase_info_data_t
中的 numer
和 denom
分别是时钟数缩放因子的分子和分母,在 Intel 芯片上固定都是 1。这也就意味着 number / denom
和 denom / number
的结果一样,换句话说,即使缩放因子表达式写反了,计算出的结果也不会有所变化。
但在 M1 芯片上,分子和分母并不相等, numer
是大于 denom
的,使用错误的缩放因子 denom / number
会导致计算出的结果小于正确值,也就意味着真实时间过去1秒时,计算出的时间只过去0.000x秒,那么eventlet
就会认为还没达到需要唤醒的时间而继续等待,从而造成卡死的假象。
关于此问题的修复,eventlet
在 v0.24.0
版本中引入了第三方库 monotonic.py 解决了这个问题。
总结
使用 Apple M1 开发程序的真的都是勇士,由于 CPU 架构和 Intel 不同,极有可能出现非预期的问题。一旦出现问题,基本思路就是先观察现象,使用诸如 py-spy 的工具去进一步看看进程在做什么,然后尝试复现和调试,逐步从上层到底层分析代码,定位问题。