用 decorator 計時

最近讀 open source project 時看到的小技巧, 稍加改寫如下:

def log_it(function):
    def wrapper(*args, **kwargs):
        start = time.time()
        try:
            return function(*args, **kwargs)
        finally:
            stop = time.time()
            logging.debug('%s: %.3fs' % (function.__name__, stop - start))
    return wrapper

# usage
@log_it
def some_function(...):
   ...

如此一來 call some_function 時就會記錄它的執行時間到 log file 裡。之前沒想過 finally 可以這麼用, 配上 decorator 太簡潔啦。先存下 function 的傳回值, 寫入 log 再回傳也可做到同樣效果, 不過當 function 丟出 exception 時, 就沒記到時間。而上面的寫法仍然會 log 時間。若要區別 function 是否有正常執行完, 得在 try 和 finally 之間加個 except:, 做完該做的事再執行 raise 將 exception 重丟出去。