别再手动写日志了,用 Python 这个装饰器,自动记录函数调用信息.
写日志这事,做开发的都懂。出了bug,第一反应就是翻日志。日志写得好,定位问题就跟看故事一样清楚。日志写得乱,看半天也找不到头绪。
我自己刚入行那会,每写一个函数,都得手动加几行print。比如这样:
def get_user_info(user_id):
print(f'【开始】获取用户信息,参数:{user_id}')
result = db.query(user_id)
print(f'【结束】获取用户信息,结果:{result}')
return result看起来挺简单?项目一大了,麻烦就来了。每个函数都得手动写开始结束,复制粘贴多了就容易漏。有一次线上出了个性能问题,我排查了三个小时,最后发现是某个调用日志里忘记记录时间戳了。气得我坐在工位上发呆。
后来我醒悟了。这种事应该让代码自己干。Python有个装饰器,专门解决这类问题。你写好一个装饰器,在需要记录日志的函数头上加个@符号就行了。
写一个最简单的:
import functools
import logging
import time
logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(message)s')
logger = logging.getLogger(__name__)
def log_call(func):
@functools.wraps(func)
def wrapper(args, kwargs):
start = time.time()
logger.info(f'调用 {func.__name__},参数:{args}, {kwargs}')
result = func(args, kwargs)
end = time.time()
logger.info(f'{func.__name__} 返回:{result},耗时:{end - start:.2f}秒')
return result
return wrapper用法更简单:
@log_call
def get_user_info(user_id):
这样一来,所有函数调用都会被自动记录。参数、返回值、耗时,清清楚楚。你再也不用满世界找漏掉的print了。
我还加过一些实用功能。比如记录异常:
def log_call(func):
@functools.wraps(func)
def wrapper(args, kwargs):
try:
logger.info(f'调用 {func.__name__}')
result = func(args, kwargs)
logger.info(f'{func.__name__} 成功')
return result
except Exception as e:
logger.error(f'{func.__name__} 异常:{e}')
raise
return wrapper再比如限制日志级别。有些函数调用频繁,全打印出来日志文件会炸。可以加个参数控制:
def log_call(level='INFO'):
def decorator(func):
@functools.wraps(func)
def wrapper(args, kwargs):
getattr(logger, level.lower())(f'调用 {func.__name__}')
return func(args, kwargs)
return wrapper
return decorator这样你可以在热点函数上用@log_call('DEBUG'),只在调试时输出。生产环境可以关闭DEBUG级别。
这套方案我用了快三年,再也没有因为漏写日志而抓狂过。团队里的新人接手项目,也不用先背一遍要在哪里打日志。他们只要记一个规则:需要记录调用的函数,加@log_call就行。
我见过最夸张的一次,同事手动写了200多行日志代码来跟踪一个服务。我花了半小时,用装饰器重构了。同样的效果,代码少了80%。他看了一眼就直接改用了我的方案。
写日志的目的是为了解决问题,不是为了给自己添麻烦。能把重复劳动交给机器的,就不要用手。说白了,我们写代码是为了偷懒。既然能偷懒,干嘛不偷得聪明点?