首页 / 问题 / 正文

如何排查/绕过似乎与GIL相关的锁定问题

6 投票
1 回答
3840 浏览
提问于 2025-04-16 14:44

有两个线程之间出现了一个不太明显的死锁问题，这似乎和全局解释器锁（Global Interpreter Lock，简称GIL）或者其他一些“幕后锁”有关，我现在不知道该怎么继续排查了。如果有任何消除死锁的建议，我会非常感激。

这个问题在一段较大的代码中会偶尔出现，感觉有点随机。代码完全是用Python写的，Python版本是2.6.5（在Linux上）。经过几个小时的排查，我把死锁发生的情况缩小到了以下几点：

  1. 程序只有两个正在运行的线程
  2. 这两个线程同时调用一个被单个threading.RLock保护的方法
  3. 线程1通过acquire()获得了锁（还有其他一些锁）
  4. 线程2调用了acquire()，确认正在等待这个锁
  5. 线程1可以用print()向控制台打印内容，但它被一个简单的非阻塞库调用锁住了

第5点中的问题调用是unicode.encode，这个调用应该是非阻塞的。在线程1中，线程锁住的位置会（如预期）打印'A'和'B'：

print('A')
print('B')

然而，下面的代码只会打印'A'，然后线程就被阻塞了：

print('A')
u'hello'.encode('utf8') # This dummy (non-blocking) call locks up Thread 1
print('B')

这让我完全搞不懂。两个线程之间并不存在逻辑上的死锁条件。线程1被一个非阻塞的库调用锁住，而这个调用并没有干扰到线程2，线程2只是静静地在等待获取RLock。我能想到的线程1被阻塞的唯一原因就是它在等待GIL。

有没有什么想法可以进一步排查这个问题，或者有什么方法可以控制或操作GIL的运行作为解决方案？

编辑：为了回应samplebias（谢谢你的回复），我补充了一些信息。我在获取跟踪信息时遇到了一些问题，因为这个问题似乎对任何可能打乱两个线程之间时序的事情非常敏感。不过在只使用-f选项运行strace后，经过几次迭代，我终于得到了一个跟踪。

线程1包含这三个调试语句，应该会向控制台打印两行'CHECK_IN'和'CHECK_TEST'：

print('CHECK IN')#DEBUG
u'hello'.encode('utf8')
print('CHECK TEST')#DEBUG

这是strace的最后一页：

8605  mmap2(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb753d000
8605  mmap2(NULL, 8392704, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb6d3c000
8605  mprotect(0xb6d3c000, 4096, PROT_NONE) = 0
8605  clone(child_stack=0xb753c494, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb753cbd8, {entry_number:6, base_addr:0xb753cb70, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}, child_tidptr=0xb753cbd8) = 8606
8606  set_robust_list(0xb753cbe0, 0xc <unfinished ...>
8605  futex(0xa239138, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
8606  <... set_robust_list resumed> )   = 0
8606  futex(0xa239138, FUTEX_WAKE_PRIVATE, 1) = 1
8605  <... futex resumed> )             = 0
8606  gettimeofday( <unfinished ...>
8605  futex(0xa272398, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
8606  <... gettimeofday resumed> {1301528807, 326496}, NULL) = 0
8606  futex(0xa272398, FUTEX_WAKE_PRIVATE, 1) = 1
8605  <... futex resumed> )             = 0
8606  futex(0xa272398, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
8605  gettimeofday( <unfinished ...>
8606  <... futex resumed> )             = 0
8605  <... gettimeofday resumed> {1301528807, 326821}, NULL) = 0
8606  futex(0xa272398, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
8605  futex(0xa272398, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
8606  <... futex resumed> )             = -1 EAGAIN (Resource temporarily unavailable)
8605  <... futex resumed> )             = 0
8606  gettimeofday( <unfinished ...>
8605  futex(0xa272398, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
8606  <... gettimeofday resumed> {1301528807, 326908}, NULL) = 0
8606  futex(0xa272398, FUTEX_WAKE_PRIVATE, 1) = 1
8605  <... futex resumed> )             = 0
8606  futex(0xa272398, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
8605  futex(0xa1b0d70, FUTEX_WAIT_PRIVATE, 0, NULL <unfinished ...>
8606  <... futex resumed> )             = 0
8606  stat64("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2225, ...}) = 0
8606  fstat64(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 1), ...}) = 0
8606  mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6d3b000
8606  write(1, "CHECK IN\n", 9)         = 9
8606  futex(0xa115270, FUTEX_WAIT_PRIVATE, 0, NULL

在程序锁住之前，这三行代码的输出仅为：

CHECK IN

所以strace显示线程1（#8606）写入了'CHECK_IN'字符串，当到达unicode.encode调用时进入了一个等待状态，永远没有返回。

顺便说一下，我在所有模块中做了一些未来导入，以保持与一些较新Python约定的一致性……

from __future__ import print_function, unicode_literals

……但我看不出这些会有什么影响，尤其是因为u'hello'字符串被明确调用为一个unicode字符串。

多线程 调试 线程 死锁 全局解释器锁 非阻塞 strace RLock

1 个回答

3

我在Python的源代码里找不到任何会导致unicode.encode()卡住的原因，而我写的测试程序运行得很正常。你提到线程1获取了多个锁，难道你没有排除这些锁是导致卡住的原因吗？

下面的测试案例在你的环境中也出现同样的卡住情况吗？

import time
import threading

def worker(tid):
    _lock.acquire()
    if not tid:
        # wait for rest of threads to enter acquire
        time.sleep(0.5)    
    print('%d: A' % tid)
    u'hello'.encode('utf-8')
    print('%d: B' % tid)
    _lock.release()

def start(tid):
    th = threading.Thread(target=worker, args=(tid,))
    th.start()
    return th

_num = 2
_lock = threading.RLock()
workers = [start(n) for n in range(_num)]
while all(w.isAlive() for w in workers):
    time.sleep(1)

输出：

0: A
0: B
1: A
1: B

你也可以在你的程序上运行strace，这样可以找出进程卡住的地方。例如，使用上面的脚本：

% strace -fTr -o trace.out python lockup.py

这里的-o trace.out选项是告诉strace把输出写入一个文件。你可以不加这个选项，strace会直接打印到错误输出中。

trace.out的内容应该会显示程序所做的所有系统调用，每一行前面会有线程ID和系统调用之间的相对时间。每行的末尾会显示在那个系统调用中花费的时间。我已经把最后几个系统调用和对应的Python代码做了注释：

# thread 0 time.sleep(0.5) completes
24778      0.500124 <... select resumed> ) = 0 (Timeout) <0.500599>
# preparing to print()
24778      0.000071 fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 0), ...}) = 0 <0.000017>
24778      0.000058 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f8fe90a6000 <0.000018>
# print("0: A\n")..
24778      0.000079 write(1, "0: A\n", 5) = 5 <0.000023>
24778      0.000106 write(1, "0: B\n", 5) = 5 <0.000056>
# thread 0 _lock.release()
24778      0.000114 futex(0xe0f3c0, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000024>
24778      0.000108 madvise(0x7f8fe7266000, 8368128, MADV_DONTNEED) = 0 <0.000030>
# thread 0 exit
24778      0.000072 _exit(0)            = ?
# thread 1 _lock.acquire()
24779      0.000050 <... futex resumed> ) = 0 <0.500774>
# thread 1 print("1: A\n") and so on..
24779      0.000052 write(1, "1: A\n", 5) = 5 <0.000026>
24779      0.000086 write(1, "1: B\n", 5) = 5 <0.000026>
24779      0.000099 madvise(0x7f8fe6a65000, 8368128, MADV_DONTNEED) = 0 <0.000024>
24779      0.000064 _exit(0)            = ?
24777      0.499956 <... select resumed> ) = 0 (Timeout) <1.001138>
24777      0.000132 rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7f8fe8c7c8f0}, {0x4d9a90, [], SA_RESTORER, 0x7f8fe8c7c8f0}, 8) = 0 <0.000025>
# main thread process exit
24777      0.002349 exit_group(0)       = ?
回答于 2025-04-16 由 Python大师
分享 举报

撰写回答