原文:Freeze your Python with str.encode and threads
当我在sqreen.io Python agent工作的时候,我发现了一个相当讨厌,但是分析起来却挺有意思的bug,它让我深入到Python内部。
我正在写一段代码,它产生一个线程,检索一些JSON,然后存储以用于后续使用。基本上,代码看起来是这样的:
from threading import Thread, Event
class MyThread(Thread):
def __init__(self):
self.event = Event()
def run(self):
data = self.retrieve_json()
self.data = data
self.event.set()
print("Data retrieval done!")
while True:
pass
thread = MyThread()
thread.start()
timeout = thread.event.wait(5)
if timeout is not None:
print("JSON retrieval was too slow")
一切似乎都还好,并且当网络延迟过高的时候,错误信息会正确显示:
$> python2 app.py
Data retrieval done!
接下来,我想将字典键和值从unicode转换成latin-1字符串:
class MyThread(Thread):
def run(self):
data = self.retrieve_json()
# Convert unicode strings into latin1 strings because of WSGI
self.data = {key.encode('latin1'): value.encode('latin1') for (key, value) in data.keys()}
self.event.set()
print("Data retrieval done!")
while True:
pass
我敢肯定,在接收JSON时,你们都做过这种类型的转换,不是吗?
添加这个代码后,无论我提供了什么样子的值,错误信息开始显示超时,从5s到1小时。而更诡异的是,"Data retrieval done!"
信息总是在错误信息之后打印出来:
$> python2 app.py
JSON retrieval was too slow
Data retrieval done!
然而,当我在Python 3上跑的时候,一切如我所预期:
$> python3 app.py
Data retrieval done!
一些非常奇怪的事情一直发生,而我决定调查一下。
我试图找出问题所在,于是有了这个最小化的再现脚本,让我们把它命名为"str_encode_thread.py"
:
import time
import threading
def to_latin_1(event, value):
print(time.time(), "Before encode")
value.encode('latin-1')
print(time.time(), "After encode")
event.set()
print(time.time(), "Event set")
event = threading.Event()
thread = threading.Thread(target=to_latin_1, args=(event, u'42'))
thread.start()
event.wait(10)
如果你用Python 3启动这个脚本,将会看到:
$> python3 str_encode_thread.py
1467046041.643346 Before encode
1467046041.643446 After encode
1467046041.643483 Event set
而用Python 2,你会看到:
$> python2 str_encode_thread.py
(1467046099.495261, 'Before encode')
(1467046099.495937, 'After encode')
(1467046099.495961, 'Event set')
目前一切OK。而当我们尝试导入这个脚本时,好玩的事情来了。如果你用Python 3导入这个脚本,那么一切仍然是正常的:
$> time python3 -c "import str_encode_thread"
1467046239.921475 Before encode
1467046239.921578 After encode
1467046239.921602 Event set
python3 -c "import str_encode_thread" 0,05s user 0,01s system 84% cpu 0,081 total
而用Python 2导入时,我们讨厌的朋友再次出现了:
$> time python2 -c "import str_encode_thread"
(1467046276.826755, 'Before encode')
(1467046286.830485, 'After encode') # <- 10 seconds (╯°□°)╯︵ ┻━┻
(1467046286.830519, 'Event set')
python2 -c "import str_encode_thread" 0,03s user 0,03s system 0% cpu 10,109 total
如果你仔细看看"After encode"
消息,可以看到,它在"Before encode"
消息打印10s之后才打印,这意味着线程莫名其妙被冻结了。
为嘛一个简单的"value.encode('latin1', 'encode')"
会阻塞一个线程呢?
幸好,有一个非常棒的名为faulthandler的包,它在这种情况下非常有用。它可以在unix信号、用户信号或者python错误上展示回溯。从Python 3.3开始,它就是标准库的一部分了,而对于老一点的Python版本,可以用pip进行安装。
本例中,我们将使用dump_traceback_later来看看该线程在哪里阻塞。
带faulthandler的新脚本并没有什么不同 (不要忘了"pip install faulthandler"
):
import time
import threading
import faulthandler
faulthandler.dump_traceback_later(5)
def to_latin_1(event, value):
print(time.time(), "Before encode")
value.encode('latin-1')
print(time.time(), "After encode")
event.set()
print(time.time(), "Event set")
event = threading.Event()
thread = threading.Thread(target=to_latin_1, args=(event, u'42'))
thread.start()
event.wait(10)
让我们运行新的脚本:
time python2 -c "import str_encode_thread"
(1468083195.13011, 'Before encode')
Timeout (0:00:05)!
Thread 0x0000700000401000 (most recent call first):
File "/usr/lib/python2.7/encodings/__init__.py", line 100 in search_function
File "str_encode_thread.py", line 11 in to_latin_1
File "/usr/lib/python2.7/threading.py", line 754 in run
File "/usr/lib/python2.7/threading.py", line 801 in __bootstrap_inner
File "/usr/lib/python2.7/threading.py", line 774 in __bootstrap
Current thread 0x00007fff71258000 (most recent call first):
File "/usr/lib/python2.7/threading.py", line 359 in wait
File "/usr/lib/python2.7/threading.py", line 614 in wait
File "str_encode_thread.py", line 20 in <module>
File "<string>", line 1 in <module>
(1468083205.133041, 'After encode')
(1468083205.133106, 'Event set')
python2 -c "import str_encode_thread" 0,03s user 0,02s system 0% cpu 10,043 total
回溯中我们能看到什么?
主线程"0x00007fff71258000"
在我们模块的第20行阻塞了,在那里是"event.wait(10)"
,这完全正常。
其他线程"0x0000700000401000"
正运行我们模块的第11行"value.encode('latin-1')"
,并且调用内置模块"encoding"
的函数"search_function"
,它冻结了我们的线程。这个函数做了什么,为什么它是阻塞的?
源代码告诉我们,它试图导入一个以"encodings."
开头的模块。
In [1]: import sys
In [2]: before_modules = sys.modules.keys()
In [3]: '42'.encode('latin-1')
Out[3]: '42'
In [4]: after_modules = sys.modules.keys()
In [5]: print("Imported modules", set(after_modules) - set(before_modules))
('Imported modules', set(['encodings.latin_1']))
明白了!"str.encode(X)"
试图导入模块"encodings.X"
。所以修复应该是容易的:在主线程中,使用该函数之前导入该模块,这样就可以了,是吧?
import time
import threading
import encodings.latin_1
def to_latin_1(event, value):
print(time.time(), "Before encode")
value.encode('latin-1')
print(time.time(), "After encode")
event.set()
print(time.time(), "Event set")
event = threading.Event()
thread = threading.Thread(target=to_latin_1, args=(event, u'42'))
thread.start()
event.wait(10)
让我们用python2再试试:
$> time python2 -c "import str_encode_thread"
(1467049098.995541, 'Before encode')
(1467049109.000293, 'After encode')
(1467049109.000324, 'Event set')
python2 -c "import str_encode_thread" 0,03s user 0,02s system 0% cpu 10,054 total
我们仍然有相同的问题!怎么了?
我们知道,"str.encode"
试图导入一个可能冻结我们线程的模块。
在这一点上,我到我最喜欢的IRC频道 (#python-fr)寻求帮助,最终我们找到了原因!
"import module"
做了什么?如果我们相信Python文档,那它基本上做了这些:
import imp
import sys
def __import__(name, globals=None, locals=None, fromlist=None):
# Fast path: see if the module has already been imported.
try:
return sys.modules[name]
except KeyError:
pass
# If any of the following calls raises an exception,
# there's a problem we can't handle -- let the caller handle it.
fp, pathname, description = imp.find_module(name)
try:
return imp.load_module(name, fp, pathname, description)
finally:
# Since we may exit via an exception, close fp explicitly.
if fp:
fp.close()
没有啥特别的:如果已经导入了该模块,那么从"sys.modules"
返回该模块,否则,尝试找到该模块的源文件,加载并返回。
这里也不应该阻塞,但若我们继续看"imp"
模块文档,可以找到一个非常有趣的名为"lock_held"
的函数:
在多线程平台上,执行导入的线程持有一个内部锁,直到导入完成。这个锁阻塞了其他线程进行导入,直到初始导入完成,这反过来阻止其他线程看到由初始线程在完成导入(以及可能有的由此导入触发的其他导入)过程中构建的未完成的模块对象。
真相越来越近……
当搜索"python import lock"
,我们可以迅速找到关于在线程代码中导入的章节,它只是告诉你这是一个可怕的想法,并有可能造成死锁。
让我们总结下我们的发现:
import imp
import time
import threading
def to_latin_1(event, value):
print(time.time(), "Before encode", threading.current_thread().name, imp.lock_held())
value.encode('latin-1')
print(time.time(), "After encode")
event.set()
print(time.time(), "Event set")
event = threading.Event()
thread = threading.Thread(target=to_latin_1, args=(event, u'42'))
thread.start()
event.wait(10)
$> python2 -c "import str_encode_thread"
(1467050582.565935, 'Before encode', 'Thread-1', True)
(1467050592.567373, 'After encode')
(1467050592.567418, 'Event set')
当我们导入我们的模块"str_encode_thread"
时,导入锁由主线程获得,因此当我们的自定义线程试图执行"value.encode('latin-1')"
时,stdlib试图导入"encoding.latin_1"
模块,这会被阻塞,因为导入锁已经在主线程手里。然后,我们通过"event.wait(10)"
阻塞了主线程,接着这两个线程都阻塞了10秒,太糟糕了……当等待超时,"import str_encode_thread"
结束,释放导入锁,从而唤醒了我们的自定义线程。
如果我们没有设置一个最大化的事件超时,我们将永远让Python解释器死锁!
在处理线程时,并无神奇解决方案。如果你手动导入一个模块而无需使用锁,那么你可能不知道发生了什么,但是它只会通过抛出额外有趣的bug来“解决”死锁。
例如,当你调用"time.strptime"
时,它试图以一种不安全的方式导入"_strptime"
模块,这可能会引发一些难以调试的问题,像这个boto问题和对应的Python bug页面。这个问题可以通过在主线程之前"import _strptime"
,这样线程就不会因为锁或者看到一个未完成的模块而阻塞,从而解决。
那为什么在Python 3就一切正常?除了打破你所有的导入名,强制你在代码中到处用".encode"
和`".decode" (这是件好事!)之外,Python 3对导入锁进行了重构,而现在每个模块都处理全局导入锁。现在,你不大可能触发这个问题了。
这可能是一个非常讨厌的问题,但是深入Python的一个鲜为人知的机制却是非常有趣的。
TL;DR: Python 2中,还有一个可重入锁,当该锁由其他线程持有时,如果你的线程试图进行导入,它将阻塞它们。Python 3中,该导入锁现在是每个模块持有的。