Python打印函数用时的两种方法--类的构造析构函数与函数装饰器

在安卓审计项目里，我们使用python脚本来对APK进行扫描检测，为了统计每一步操作的耗时情况编写了一个简单的类，并通过下面的方式使用：

#coding:utf-8

import time

class TimeRecorder:
    def __init__(self, name):
        print(name + u"开始")
        self.name = name
        self.startTime = time.time()
    def __del__(self):
        print(u"{0}结束，耗时：{1}".format(self.name, time.time() - self.startTime))

def scan1():
    t = TimeRecorder(scan1.func_name)
    time.sleep(1)
    return 1

print scan1()

运行后打印输出：

scan1开始

scan1结束，耗时：1.0

1

主要利用了类的构造函数和异构函数，实际上在scan1函数里创建的 TimeRecorder对象并没有真实使用，需要统计耗时的函数开始都要声明一个 TimeRecorder 对象，虽然也比较简单，但是使用者有时会莫名其妙。

在学习了python的装饰器后，便有了更好的设计，让装饰器来统一调用即可，实现方式如下：

# 函数装饰器，让函数打印耗时
def deco(func):
    def _deco():
        t = TimeRecorder(func.func_name)
        return func()
    return _deco

@deco
def scan2():
    time.sleep(1)
    return 2

print scan2()

TimeRecorder 对象不变，使用时调用者函数代码不变，只需要在前面那个@装饰器即可。

运行输出：

scan2开始

scan2结束，耗时：1.0

2

---

Python装饰器（decorator）在实现的时候，有一些细节需要被注意。例如，被装饰后的函数其实已经是另外一个函数了（函数名等函数属性会发生改变）。这样有时候会对程序造成一些不便，例如笔者想对unittest框架中的一些函数添加自定义的decorator，添加后由于函数名和函数的doc发生了改变，对测试结果有一些影响。
所以，Python的functools包中提供了一个叫wraps的decorator来消除这样的副作用。写一个decorator的时候，最好在实现之前加上functools的wrap，它能保留原有函数的名称和docstring。

在上面的例子中，如果打印scan2的函数名：

print scan2.func_name

会发现输出的是_deco
这显然会影响开发者的使用习惯和判断，怎么办呢？
这个时候就需要functools.wraps
from functools import wraps
def decorator2(func):
    @wraps(func)
    def wrapper(*args, **kwargs):
        t = TimeRecorder(func.func_name)
        return func(*args, **kwargs)
    return wrapper

@decorator2
def scan3():
    u"""扫描APK的权限。。。。"""
    time.sleep(1)
    return 3

print scan3.func_name, scan3.func_doc
print scan3()
运行输出：
   
   

    
    scan3 扫描APK的权限。。。。
   
   
   
   

    
    scan3开始
   
   
   
   

    
    scan3结束，耗时：0.0
   
   
   
   

    
    3
   
   
这个时候函数名和文档描述就是正确的了。
  
  

   
   

  
  
  
  

   
   

    
    

     
     

    
    
   
   
   
   

    
    

   
   
   
   

    
    

   
   
   
   
2017.02.20更新
  
  

"""
时间记录的函数和装饰器
"""
class TimeRecorder:
    def __init__(self, name):
        print(name + u" start")
        self.name = name
        self.startTime = time.time()
    def __del__(self):
        print(u"%s end, time used: %.1f s", self.name, time.time() - self.startTime)

"""
def scan1():
    t = TimeRecorder(scan1.func_name)
    time.sleep(1)
    return 1

print scan1()
"""


# 函数装饰器，让函数打印耗时
def logtime(func):
    def wrapper(*args, **kwargs):
        print(func.func_name + u" start")
        startTime = time.time()
        ret = func(*args, **kwargs)
        print(u"%s end, time used: %.1f s", func.func_name, time.time() - startTime)
        return ret
    return wrapper

# 指定一个名称
def logtimewithname(name = None):
    def wrapper(func):
        def wrapper2(*args, **kwargs):
            _name = name
            if name is None:
                _name = func.func_name
            else:
                _name = name
            print(_name + u" start")
            startTime = time.time()
            res = func(*args, **kwargs)
            print(u"%s end, time used: %.1f s", _name, time.time() - startTime)
            return res
        return wrapper2
    return wrapper

用法：

@logtime
def scan1(p1, p2):
    time.sleep(1)
    return 1
print scan1(1, 2)

# @logtimewithname()
@logtimewithname(u"扫描")
def scan2(p1, p2):
    time.sleep(1)
    return 2

print scan2(1, 2)