0%

Python中使用signal带来的怪异问题

今天智平在群里发了一个signal的考题考大家,就是下面程序是什么输出:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
import signal
import sys

count = 0

def signal_handler(signum, frame):
global count
count = -1
print 'sig', count

def main():
signal.signal(signal.SIGALRM, signal_handler)
signal.setitimer(signal.ITIMER_REAL, 1, 1)
global count
while True:
for line in sys.stdin:
count += 1
print count

if __name__ == "__main__":
main()

然后执行tail -f /home/logs/nginx/access.log | python a.py

问输出是 1,2,3,4,5,-1,6,7,8… 这样, 还是1,2,3,4,5,-1,0,1,2…

我们经过测试,是第一种情况。非常奇葩。

伟大的大神叠哥说道:

count += 1 有 read count、plus 1、store count 三步,会不会是因为实现上的什么原因,那个signal_handler总是插入到这三个操作中间去执行了?

因为,发现在count += 1 前面加一条无意义的赋值语句,结果就符合预期了。就输出1,2,3,4,5,-1,0,1,2…

1
2
3
4
5
while True:
for line in sys.stdin:
x = count
count += 1
print count

为啥加上x = count,输出就变了呢?我觉得大神叠哥一语道出了问题的本质,于是想去求证一下是否真的如此:signal_handler总是插入到这三个操作中间去执行。

我们来看字节码

我们首先来看看signal_handler的字节码:

1
2
3
4
5
6
7
8
9
10
11
In [8]: dis.dis(signal_handler)
3 0 LOAD_CONST 1 (-1)
3 STORE_GLOBAL 0 (count)

4 6 LOAD_CONST 2 ('sig')
9 PRINT_ITEM
10 LOAD_GLOBAL 0 (count)
13 PRINT_ITEM
14 PRINT_NEWLINE
15 LOAD_CONST 0 (None)
18 RETURN_VALUE

然后我们再看看两个程序main()的字节码。这里列出字节码主要供下一节参考使用,现在可以不用太仔细看。

非预期的程序

我们看看输出1,2,3,4,5,-1,6,7,8…的字节码

1
2
3
4
5
6
7
8
def main():
signal.signal(signal.SIGALRM, signal_handler)
signal.setitimer(signal.ITIMER_REAL, 1, 1)
global count
while True:
for line in sys.stdin:
count += 1
print count
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
In [4]: dis.dis(main)
2 0 LOAD_GLOBAL 0 (signal)
3 LOAD_ATTR 0 (signal)
6 LOAD_GLOBAL 0 (signal)
9 LOAD_ATTR 1 (SIGALRM)
12 LOAD_GLOBAL 2 (signal_handler)
15 CALL_FUNCTION 2
18 POP_TOP

3 19 LOAD_GLOBAL 0 (signal)
22 LOAD_ATTR 3 (setitimer)
25 LOAD_GLOBAL 0 (signal)
28 LOAD_ATTR 4 (ITIMER_REAL)
31 LOAD_CONST 1 (1)
34 LOAD_CONST 1 (1)
37 CALL_FUNCTION 3
40 POP_TOP

# while True:
5 41 SETUP_LOOP 45 (to 89)
>> 44 LOAD_GLOBAL 5 (True)
47 POP_JUMP_IF_FALSE 88

# for line in sys.stdin:
6 50 SETUP_LOOP 32 (to 85)
53 LOAD_GLOBAL 6 (sys)
56 LOAD_ATTR 7 (stdin)
59 GET_ITER
>> 60 FOR_ITER 21 (to 84)
63 STORE_FAST 0 (line)
# count += 1
7 66 LOAD_GLOBAL 8 (count)
69 LOAD_CONST 1 (1)
72 INPLACE_ADD
73 STORE_GLOBAL 8 (count)
# print count
8 76 LOAD_GLOBAL 8 (count)
79 PRINT_ITEM
80 PRINT_NEWLINE
81 JUMP_ABSOLUTE 60 # 这里回到偏移60的指令
>> 84 POP_BLOCK
>> 85 JUMP_ABSOLUTE 44
>> 88 POP_BLOCK
>> 89 LOAD_CONST 0 (None)
92 RETURN_VALUE

预期输出的程序

我们再来看看1,2,3,4,5,-1,0,1,2…的程序的字节码:

1
2
3
4
5
6
7
8
9
def main():
signal.signal(signal.SIGALRM, signal_handler)
signal.setitimer(signal.ITIMER_REAL, 1, 1)
global count
while True:
for line in sys.stdin:
x = count
count += 1
print count
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
In [6]: dis.dis(main)
2 0 LOAD_GLOBAL 0 (signal)
3 LOAD_ATTR 0 (signal)
6 LOAD_GLOBAL 0 (signal)
9 LOAD_ATTR 1 (SIGALRM)
12 LOAD_GLOBAL 2 (signal_handler)
15 CALL_FUNCTION 2
18 POP_TOP

3 19 LOAD_GLOBAL 0 (signal)
22 LOAD_ATTR 3 (setitimer)
25 LOAD_GLOBAL 0 (signal)
28 LOAD_ATTR 4 (ITIMER_REAL)
31 LOAD_CONST 1 (1)
34 LOAD_CONST 1 (1)
37 CALL_FUNCTION 3
40 POP_TOP
# while True:
5 41 SETUP_LOOP 51 (to 95)
>> 44 LOAD_GLOBAL 5 (True)
47 POP_JUMP_IF_FALSE 94
# for line in sys.stdin:
6 50 SETUP_LOOP 38 (to 91)
53 LOAD_GLOBAL 6 (sys)
56 LOAD_ATTR 7 (stdin)
59 GET_ITER
>> 60 FOR_ITER 27 (to 90)
63 STORE_FAST 0 (line)
# x = count
7 66 LOAD_GLOBAL 8 (count)
69 STORE_FAST 1 (x)
# count += 1
8 72 LOAD_GLOBAL 8 (count)
75 LOAD_CONST 1 (1)
78 INPLACE_ADD
79 STORE_GLOBAL 8 (count)
# print count
9 82 LOAD_GLOBAL 8 (count)
85 PRINT_ITEM
86 PRINT_NEWLINE
87 JUMP_ABSOLUTE 60
>> 90 POP_BLOCK
>> 91 JUMP_ABSOLUTE 44
>> 94 POP_BLOCK
>> 95 LOAD_CONST 0 (None)
98 RETURN_VALUE

增加调试代码

有了程序的字节码后,我们需要打印一下程序的执行流程,来深入看看究竟发生了啥事。我们可以先下载Python 2.7.3的源代码回来,然后修改:

首先打印处理的字节码,我们打开Python/ceval.c,在下面PyEval_EvalFrameEx中的swtich (opcode),前面加上printf("[opcode: %d]\n", opcode);来打印处理的opcode。

然后我们修改一下signalmodule模块,在处理signal的时候,打印一条log。我们打开Modules/signalmodule.c,在其中的PyErr_CheckSignals里面的result = PyEval_CallObject(Handlers[i].func, arglist);语句前加上printf("-> call signal handler\n");,这样就可以在调用signal handler的时候打印一条log。

然后就是编译Python了。编译完,我们就用编译好的Python来做实验!Yeah~

打印程序执行流程

接下来,我们就执行这怪异的程序,我们先来看看输出1,2,3,4,5,-1,6,7,8…这个不符合预期的程序的字节码处理流程[1]

非预期版本的执行流程

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
[opcode: 113 JUMP_ABSOLUTE] 
[opcode: 93 FOR_ITER]

[opcode: 116 LOAD_GLOBAL]
[opcode: 100 LOAD_CONST]
[opcode: 55 INPLACE_ADD]
[opcode: 97 STORE_GLOBAL]

[opcode: 116 LOAD_GLOBAL]
[opcode: 71 PRINT_ITEM]
[opcode: 72 PRINT_NEWLINE]
[opcode: 113 JUMP_ABSOLUTE]

[opcode: 93 FOR_ITER]
[opcode: 116 LOAD_GLOBAL] # 将count压入栈

-> call signal handler
[opcode: 100 LOAD_CONST] # 这里进入到了signal_handler
[opcode: 97 STORE_GLOBAL] # count = -1
[opcode: 100 LOAD_CONST]
[opcode: 71 PRINT_ITEM]
[opcode: 116 LOAD_GLOBAL]
[opcode: 71 PRINT_ITEM]
[opcode: 72 PRINT_NEWLINE]
[opcode: 100 LOAD_CONST]
[opcode: 83 RETURN_VALUE]

[opcode: 100 LOAD_CONST] # 回到main
[opcode: 55 INPLACE_ADD] # 将之前栈顶的count+1,存到全局中的count
[opcode: 97 STORE_GLOBAL]

[opcode: 116 LOAD_GLOBAL]
[opcode: 71 PRINT_ITEM]
[opcode: 72 PRINT_NEWLINE]
[opcode: 113 JUMP_ABSOLUTE]

经过几十秒后,我们可以看到,除了第一次外,后续的signal handler,都在同一个地方被调用的:

1
2
3
4
[opcode: 93 FOR_ITER]       
[opcode: 116 LOAD_GLOBAL] # 将count压入栈

-> call signal handler

这里解释器刚刚将全局的count压入栈,就切换到signal handler处理。

所以这里可以出现问题的原因就很明显了。在main()中,已经将全局的count压入栈,而切换到signal_handler中,修改了全局的count为-1,也是无意义的。因为切回到main()的时候,是操作的是栈顶部的count副本,栈顶+1后,将栈顶的值又写入全局的count中,就把signal_handler设置的count=-1给覆盖了。所以就会一直递增下去。

可预测版本的执行流程

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
[opcode: 113 JUMP_ABSOLUTE] 
[opcode: 93 FOR_ITER]

[opcode: 116 LOAD_GLOBAL]
[opcode: 125 STORE_FAST]
[opcode: 116 LOAD_GLOBAL]
[opcode: 100 LOAD_CONST]
[opcode: 55 INPLACE_ADD]
[opcode: 97 STORE_GLOBAL]
[opcode: 116 LOAD_GLOBAL]
[opcode: 71 PRINT_ITEM]
[opcode: 72 PRINT_NEWLINE]
[opcode: 113 JUMP_ABSOLUTE]

[opcode: 93 FOR_ITER]
[opcode: 116 LOAD_GLOBAL] # 将全局count压入栈顶

-> call signal handler
[opcode: 100 LOAD_CONST] # 进入signal handler
[opcode: 97 STORE_GLOBAL]
[opcode: 100 LOAD_CONST]
[opcode: 71 PRINT_ITEM]
[opcode: 116 LOAD_GLOBAL]
[opcode: 71 PRINT_ITEM]
[opcode: 72 PRINT_NEWLINE]
[opcode: 100 LOAD_CONST]
[opcode: 83 RETURN_VALUE]

[opcode: 125 STORE_FAST] # 回到main(), x = 栈顶
[opcode: 116 LOAD_GLOBAL] # 又将全局count压入栈,此时的全局的count是-1
[opcode: 100 LOAD_CONST] # 继续压入1
[opcode: 55 INPLACE_ADD] # 栈顶的两个值求和,count+1
[opcode: 97 STORE_GLOBAL] # 将栈顶的值写到全局count中,此时全局count为0

[opcode: 116 LOAD_GLOBAL]
[opcode: 71 PRINT_ITEM]
[opcode: 72 PRINT_NEWLINE]
[opcode: 113 JUMP_ABSOLUTE]

我们可以看到,返回main()后,x是旧值,不过在count += 1的时候,又重新从全局字典中读取了count,所以此时的count是正确的。

于是这就解释了上述两程序的怪异行为。

新的疑问

于是这里又引入了一个新的疑问,为什么每次signal handler都在同一个指令后触发?嗯,这个我们就需要去看看Python解释器的实现。我们首先看看signal是怎么触发的。

signal

我们打开Modules/signalmodule.c,这个是signal模块的实现。

1
2
3
4
5
6
7
8
9
10
11
12
13
static void
trip_signal(int sig_num)
{
Handlers[sig_num].tripped = 1;
if (is_tripped)
return;
/* Set is_tripped after setting .tripped, as it gets
cleared in PyErr_CheckSignals() before .tripped. */
is_tripped = 1;
Py_AddPendingCall(checksignals_witharg, NULL);
if (wakeup_fd != -1)
write(wakeup_fd, "\0", 1);
}

其中,当signal触发的时候,我们看到,Python解释器不是马上调用我们的signal handler,而是调用Py_AddPendingCall,将我们回调加到pendingcalls中,然后让主线程在适当的时机调用。最后会调用到PyErr_CheckSignals,然后在里面根据不同的signal选择不同的handler来调用。

什么时候signal handler被调用?

刚刚我们看到,signal触发的时候,会调用Py_AddPendingCall会事件处理加到pendingcalls中(Py_AddPendingCall除了会将函数放到pendingcall队列中,还会将_Py_Ticker设置为0,以通知主线程尽快执行pendingcalls。)。那么pendingcalls中的函数什么时候调用呢?

我们首先来到Python解释器的核心函数PyEval_EvalFrameEx(在Python/ceval.c),看到其中有调用Py_MakePendingCalls,这个里面调用了pendingcalls。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
PyObject *
PyEval_EvalFrameEx(PyFrameObject *f, int throwflag)
{
// ...

for (;;) {
if (--_Py_Ticker < 0) {
_Py_Ticker = _Py_CheckInterval;
Py_MakePendingCalls();
}

fast_next_opcode:
opcode = NEXTOP();

switch (opcode) {
PREDICTED_WITH_ARG(FOR_ITER);
case FOR_ITER:
// ....
PREDICT(STORE_FAST);
// ...
continue;
PREDICTED_WITH_ARG(STORE_FAST);
case STORE_FAST:
v = POP();
SETLOCAL(oparg, v);
goto fast_next_opcode;

// case ...
}
} /* main loop */

// ...

return retval;
}

也就是每次循环开的时候,当_Py_Ticker < 0的时候,就会调用Py_MakePendingCalls,里面会调用我们pending的signal handler。

那么为啥都是那个时刻调用呢?

我可以告诉你,这个真的是纯属巧合。不过为啥在下面三条指令后,触发signal handler的概率那么高呢?

1
2
3
[opcode: 93 FOR_ITER]       ; PREDICT(STORE_FAST); goto fast_next_opcode; 下面还有一条STORE_FAST指令,不过没打印出来
[opcode: 116 LOAD_GLOBAL] # 取出全局变量
-> call signal handler

如果我们仔细去看PyEval_EvalFrameEx主循环中指令的解释,会看到其中会有优化。其中就有PREDICTfast_next_opcode[2],当PREDICT下一条指令成功的时候,会直接goto到下一条指令的处理代码,就不会回到主循环的开头。而fast_next_opcode,也跳过了延迟任务的检查。

而我们上面三个指令的执行,是通过加速,中间都是直接goto执行下一条,一直没有回到主循环开始,所以就没有机会检查_Py_Ticker和执行Py_MakePendingCalls

也就是说,这三条指令执行的过程中,是可以当做一个整体,中间是不会有机会执行Py_MakePendingCalls,所以只有当执行完LOAD_GLOBAL的时候,才会回到循环开头。

而这段连续的时间,因为sys.stdin迭代器的操作相对非常长,所以signal在这段时间触发设置_Py_Ticker为0的概率最大。所以就造成了signal handler好像都在同一个地方执行的假象。

再验证!

既然是巧合,那么就是说,输出1,2,3,4,5,-1,6,7,8…的程序,其实还是有可能在signal handler成功重置计数咯?

于是我将第一个程序放置在那里跑,跑了好久,当计数记到40多万的时候,终于计数重置为0了。也就是说,之前能够连续计数,这个纯属巧合,只是偶然signal_handler都在同一个错误的地方执行。

不过智平童鞋竟然能够恰好写出如此神奇的代码,说明rp十分之高!!

因为时间仓促,语言可能有些混乱,还请见谅。

最后,还是非常佩服伟大的叠哥大神一语道破天机!!


  1. 输出的字节码指令是数字,还需要另外翻译一下,如果你用Emacs,可以使用这个gist,会自动翻译上面输出的opcode。如果不是,可以自己根据源码中的opcode.py修改一下。 ↩︎

  2. 更多解释可以自己看源码和《Python源码剖析》 ↩︎