IT博客汇
  • 首页
  • 精华
  • 技术
  • 设计
  • 资讯
  • 扯淡
  • 权利声明
    • 登录 注册

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

    Stupid ET发表于 2014-07-10 18:40:00
    love 0

    今天智平在群里发了一个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主循环中指令的解释，会看到其中会有优化。其中就有PREDICT和fast_next_opcode2，当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源码剖析》↩

    PermaLink: http://everet.org/python-signal-global-var.html
    Tags: Python


沪ICP备19023445号-2号
友情链接