聊一聊Python装饰器的代码执行顺序

为什么写这篇文章？

---

起因是QQ群里边有人提了一个问题：之前导入模块只需要1~2秒，为什么现在变成需要2~3分钟？

我的第一感觉是：是不是导入的模块顶层代码里边，做了什么耗时的事情。隔了一天，他的问题解决了，下边是按照他的代码写了一个类似的例子：

import time

def set_log(func):
    def wrap(*args, **kwargs):
        return func(*args, **kwargs)
    time.sleep(4)
    return wrap

@set_log
def demo():
    pass

为什么导入这个模块的时候，会运行time.sleep(4)，明明没有调用demo函数呀？这就要从Python装饰器代码的执行顺序说起了。

简单介绍下装饰器

---

在正式开始之前，先简单科普一下Python的装饰器，装饰器可以对已有的函数，添加额外的功能，甚至于完全改变函数的执行效果。举个例子，现在想统计几个函数的执行耗时，函数是这样的：

import time
import random

def a_func():
    time.sleep(random.randint(1, 5))

当然，我们可以这么写

def a_func():
    start_time = time.time()
    time.sleep(random.randint(1, 5))
    print("cost time: {}".format(time.time() - start_time))

这样带来的问题是代码的可维护性不佳，尤其你有多个函数需要计算耗时的时候，万一某天突然想去掉这些统计代码呢~

所以像这种有切面需求的场景，装饰器是一个非常漂亮的设计。

def cost_time(func):
    def wrap(*args, **kwargs):
        start_time = time.time()
        result = func(*args, **kwargs)
        print("cost time: {}".format(time.time() - start_time))
        return result
    return wrap

@cost_time
def a_func():
    time.sleep(random.randint(1, 5))

只需要对统计耗时的函数挂上一个装饰器，结果就自动出来，无需改动之前的代码，非常方便。

Python也支持带参数的装饰器，比如刚刚的cost_time加入一个报警机制，如果函数执行耗时大于1秒，就发出警告。

def cost_time(warn=1):
    def wrap(func):
        def _wrap(*args, **kwargs):
            start_time = time.time()
            result = func(*args, **kwargs)
            cost = time.time() - start_time
            print("cost time: {}".format(cost))
            if cost > warn:
                print("warning, cost time is {} !!!".format(cost))
            return result
        return _wrap
    return wrap

@cost_time()
def a_func():
    time.sleep(random.randint(1, 5))

a_func()

执行结果：

cost time: 3.0002505779266357
warning, cost time is 3.0002505779266357 !!!

Python装饰器代码的执行顺序

---

回到我们的主题，首先把刚刚的例子加入一些打印：

import time

print("准备编写装饰器")

def set_log(func):
    print("装饰器顶层代码")
    def wrap(*args, **kwargs):
        print("装饰器内层代码")
        return func(*args, **kwargs)
    # time.sleep(4)
    print("准备返回wrap对象")
    return wrap

print("准备编写demo函数")

@set_log
def demo():
    print("正在运行demo函数")

if __name__ == '__main__':
    print("准备运行demo函数")
    demo()

运行结果是：

准备编写装饰器
准备编写demo函数
装饰器顶层代码
准备返回wrap对象
准备运行demo函数
装饰器内层代码
正在运行demo函数

所以在运行demo函数之前，已经做了：

• 准备编写装饰器
• 准备编写demo函数
• 装饰器顶层代码
• 准备返回wrap对象

也就是说，就算你没有运行demo函数，只是导入了这个模块，上边的这4件事情，都是会一一执行的。

是不是有点懵？

让我们从头开始，梳理一遍这个过程。

Python的代码是从上往下依次执行的，所以当你导入这个模块，第一句运行的代码就是

import time

然后就来到了

print("准备编写装饰器")

接着是来到了set_log装饰器函数的定义

def set_log(func):

需要注意的时候，在这里Python只运行了函数的定义语句，对于函数内部的执行，是直接跳过去的，并没有运行。

继续往下，来到了

print("准备编写demo函数")

---

此时重点来了，到了demo函数的定义了

@set_log
def demo():
    print("正在运行demo函数")

因为代码从上往下依次运行的机制，Python解释器首先到了@set_log这句代码，@这个符号是Python提供的语法糖，它本质上是为了简化了装饰器的写法，上边的写法等于

def demo():
    print("正在运行demo函数")
demo = set_log(demo)

于是Python开始执行set_log装饰器，来完成对demo函数的修饰。

def set_log(func):
    print("装饰器顶层代码")
    def wrap(*args, **kwargs):
        print("装饰器内层代码")
        return func(*args, **kwargs)
    # time.sleep(4)
    print("准备返回wrap对象")
    return wrap

首先来到的是

print("装饰器顶层代码")

然后是装饰器内部wrap函数的定义，同样是，只运行了定义语句，跳过函数的内部执行代码

 def wrap(*args, **kwargs):

然后来到了打印“准备返回wrap对象”，以及返回wrap对象，要注意，在返回了wrap函数对象后，此时demo函数，其实已经被替换成了wrap函数对象。

print("准备返回wrap对象")
return wrap

完成了对demo函数的修饰后，代码也来到了最后的调用demo函数的部分

if __name__ == '__main__':
    print("准备运行demo函数")
    demo()

---

新的重点来了~

上边说到，在装饰器内部返回了wrap对象后，demo已经被替换成了wrap函数对象了。
也就说说，运行 demo()，其实就是运行wrap()

def wrap(*args, **kwargs):
    print("装饰器内层代码")
    return func(*args, **kwargs)

所以代码来到了wrap的函数内部，首先当然就是打印了“装饰器内层代码”。接下来是

return func(*args, **kwargs)

这里的func是不是很眼熟？我们回去看看set_log装饰器的定义：

def set_log(func):
    print("装饰器顶层代码")
    def wrap(*args, **kwargs):
        print("装饰器内层代码")
        return func(*args, **kwargs)
    # time.sleep(4)
    print("准备返回wrap对象")
    return wrap

func就是我们一开始传给set_log装饰器修饰的demo函数，还记得上边写的，装饰器的两种写法吗？

@set_log
def demo():
    pass

#  等同于：

def demo():
    pass
demo = set_log(demo) 

于是代码进入到了demo函数的内部去了~

def demo():
    print("正在运行demo函数")

执行完毕，最终搞定，一个装饰器的代码执行顺序就是这么走过来的。

---

最后，再来一个多重+带参数的装饰器的复杂一点的例子~

print("准备编写装饰器")

def set_log_first(func):
    print("set_log_first装饰器顶层代码")

    def wrap(*args, **kwargs):
        print("set_log_first装饰器内层代码")
        return func(*args, **kwargs)

    print("set_log_first准备返回wrap对象")
    return wrap

def set_log_second(times=1):
    print("set_log_second装饰器顶层代码")

    def wrap(func):
        print("set_log_second装饰器中间层代码")

        def _wrap(*args, **kwargs):
            print("set_log_second装饰器内层代码")
            return func(*args, **kwargs)

        print("set_log_second准备返回中间层的_wrap对象")
        return _wrap

    print("set_log_second准备返回顶层的wrap对象")
    return wrap

print("准备编写demo函数")

@set_log_first
@set_log_second()
def demo():
    print("正在运行demo函数")

if __name__ == '__main__':
    print("准备运行demo函数")
    demo()

输出是~

准备编写装饰器
准备编写demo函数
set_log_second装饰器顶层代码
set_log_second准备返回顶层的wrap对象
set_log_second装饰器中间层代码
set_log_second准备返回中间层的_wrap对象
set_log_first装饰器顶层代码
set_log_first准备返回wrap对象
准备运行demo函数
set_log_first装饰器内层代码
set_log_second装饰器内层代码
正在运行demo函数

这里理解的重点就是，下边的两个写法是等价的

@set_log_first
@set_log_second()
def demo():
    print("正在运行demo函数")

# 等价于
demo = set_log_first(set_log_second()(demo))

---

装饰器是不是很好玩呢？