python3logging详解_pythonlogging详解及⾃动添加上下⽂信
息
之前写过⼀篇⽂章⽇志的艺术(The art of logging)，提到了输出⽇志的时候记录上下⽂信息的重要性，我认为上下⽂信息包括：
when：log事件发⽣的时间
where：log事件发⽣在哪个模块(⽂件、函数)
how important：log 事件的紧急程度
who：事件产⽣者的唯⼀标识
what：具体的事件内容，以及其他所必须的上下⽂信息
其中，when、where、how important都很容易通过logging框架⾃动包含，但是who(事件⽣产者的唯⼀标识)就不能框架⾃动填充了。⽐如在服务器端，同时有⼤量的⽤户，如果⽇志缺乏⽤户唯⼀标识，如(User can not login)，那么可以说这样的⽇志是毫⽆意义的。特别是当线上出问题的时候，⽽且是偶发的问题的时候，⽇志往往是查问题的唯⼀途径，如果这个时候⽇志信息不充分，那就很让⼈抓狂了。
虽然在团队中强调过很多次，但是很多同事还是会输出毫⽆意义的log，也曾试过静态代码检查或者运⾏时分析，不过都不太优雅，于是希望能够⾃动添加⼀些重要的上下⽂信息，⽐如⽤户唯⼀标识。
虽然每天都在打log，但事实上我以前也没有深度了解过python logging模块，于是借着这个机会，仔细看了⼀下logging⽂档与源码。
这⾥补充⼀句，虽然⽹上有很多⽂章介绍python logging模块，但还是建议直接看官⽅资料，顺序如下：tutorial、api document、cookbook、源码
初识python logging
logging模块是python官⽅提供的、标准的⽇志模块。看代码的话是借鉴了许多log4j中的概念和思想。
logging模块包括以下⼏⼤组件：
Loggers expose the interface that application code directly uses.
Handlers send the log records (created by loggers) to the appropriate destination.
Filters provide a finer grained facility for determining which log records to output.
Formatters specify the layout of log records in the final output.
下⾯结合⼀个更完整的例⼦来逐个介绍。example1.py
1 importlogging
2 classContextFilter(logging.Filter):
3 deffilter(self, record):
4 record.userid = '123'
5 returnTrue6
7
8 if __name__ == '__main__':9 #create logger
10 logger = Logger('simple_example')11 logger.setLevel(logging.DEBUG)12
13 #create console handler and set level to debug
14 ch =logging.StreamHandler()15 ch.setLevel(logging.DEBUG)16 #create formatter for console handler
17 formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')18 #add formatter to console handler
19 ch.setFormatter(formatter)20
21 #create file handler and set level to warn
22 fh = logging.FileHandler('spam.log')23 fh.setLevel(logging.WARN)24 #create formatter for file handler
25 formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(userid)s - %(message)s')26 #add formatter to file handler
27 fh.setFormatter(formatter)28 #add context filter to file handler
29 fh.addFilter(ContextFilter())30
31 #add ch、fh to logger
32 logger.addHandler(ch)33 logger.addHandler(fh)34
35 #'application' code
36 logger.debug('debug message')37 logger.info('info message')38 logger.warn('warn message %s', 'args')39
<('error message')itical('critical message')
console输出结果：
2018-06-10 10:44:32,342 - simple_example - DEBUG - debug message
2018-06-10 10:44:32,342 - simple_example - INFO - info message
2018-06-10 10:44:32,342 - simple_example - WARNING - warn message args
2018-06-10 10:44:32,342 - simple_example - ERROR - error message
2018-06-10 10:44:32,342 - simple_example - CRITICAL - critical message
⽂件内容：
2018-06-10 10:44:32,342 - simple_example - WARNING - 123 - warn message args
2018-06-10 10:44:32,342 - simple_example - ERROR - 123 - error message
2018-06-10 10:44:32,342 - simple_example - CRITICAL - 123 - critical message
logging模块解析
logger
logger是直接提供给应⽤程序使⽤的接⼝。⼀般来说，logging的其他⼏个组件(Handler、Filter、Formatter)都是在初始化Logger的时候使⽤。
logger提供了以下API(部分、重要的)：
Logger.setLevel(level)
Sets the threshold for this logger to level. Logging messages which are less severe than level will be ignored.
Logger.isEnabledFor(lvl)
Indicates if a message of severity lvl would be processed by this logger.
Logger.debug(msg, *args, **kwargs)
Logs a message with level DEBUG on this logger.
Logger.info(msg, *args, **kwargs)
Logs a message with level INFO on this logger.
Logger.warning(msg, *args, **kwargs)
Logs a message with level WARNING on this logger. same as Logger.warn
python新手代码(msg, *args, **kwargs)
Logs a message with level ERROR on this logger.
Logs a message with level CRITICAL on this logger. same as Logger.fatal
Logger.addFilter(filter)
Adds the specified filter filter to this logger.
Removes the specified filter filter from this logger.
Logger.addHandler(hdlr)
Adds the specified handler hdlr to this logger.
Removes the specified handler hdlr from this logger.
logger实例
Logger对象不是通过实例化Logger⽽来的，都是通过 _logger(name) 获得⼀个与name关联的logger对象，logging内部会维护这个映射关系，⽤同样的name反复调⽤Logger，事实上返回的是同⼀个对象。
Multiple calls to getLogger() with the same name will always return a reference to the same Logger object.
logger有⼀个⽗⼦关系，⽐如：
1 a_logger = Logger('A’)
2 ab_logger = Logger('A.B’)
通过name的层次关系就可以看出a_logger是ab_logger的parent。这个⽗⼦关系是会影响到⽇志的输出的，后⾯介绍logging流程的时候可以看到。不过我并没有使⽤过这种层级关系，所以本⽂也不会展开介绍。
log level
log level即⽇志的重要等级，意味着不同的紧急程度，不同的处理⽅式。python logging中，包含以下log level：
上表也给出了什么时候使⽤什么级别的Log level的建议。
只有当写⽇志时候的log level⼤于等于logger的level阈值(通过setLevel设置)时，⽇志才可能被输出。
⽐如example1.py中，输出到⽂件时，debug message、info message并没有输出，因为file handler的logger level是
warning，DEBUG和INFO都⼩于WARNING。
FIlter && Handler
从logger中Filter、Handler相关的接⼝可以看到⼀个logger可以包含多个handler，多个Filter
在example1.py中，logger对象指定了两个handler，第14⾏的StreamHandler，以及第16⾏的FileHandler。
Handler
Handler定义了如何处理⼀条⽇志，是本地打印，还是输出到⽂件，还是通过⽹络发送。
可以这么理解，⽇志代表的是⼀个事件(event)，输出⽇志的应⽤程序是⽣产者，⽽handler是消费者，消费者可以有多个。
Handler有以下API：
Handler.setLevel(level)
Sets the threshold for this handler to level. Logging messages which are less severe than level will be ignored.
Handler.setFormatter(fmt)
Sets the Formatter for this handler to fmt.
Handler.addFilter(filter)
Adds the specified filter filter to this handler.
Removes the specified filter filter from this handler.
对于上述API，⾸先setFormatter表明了⽇志的格式，这⾥是“set”，⽽不是“add”，这个很好理解。其次，Handler有⼀些与Logger 相同的函数：setLevel、addFilter、removeFilter。为啥要⽤相同的API，在tutorial中是这样介绍的：
Why are there two setLevel() methods? The level set in the logger determines which severity of messages it will pass to its handlers. The level set in each handler determines which messages that handler will send on.
但个⼈认为这个解释很牵强，我觉得在handler(⽇志事件的消费者)指定过滤条件更合理、更直观。在⽣产者添加logLevel的⽬的只是为了开发调试⽅便：开发的时候通过debug输出调试信息，开发的时候设置⾼于DEBUG的log level来避免输出这些调试信息。
python logging提供了⼤量的实⽤的Handler，可以写到标准输出、⽂件、linux syslog、邮件、远程服务器。
Formatter
responsible for converting a LogRecord to (usually) a string which can be interpreted by either a human or an external system
可以看到，Formatter将LogRecord输出成字符串。应⽤程序每输出⼀条⽇志的时候，就会创建⼀个LogRecord对象。看看上述例⼦：
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
logger.warn('warn message %s', 'args')
对应输出：
2018-06-10 10:44:32,342 - simple_example - WARNING - warn message args
可以看到，Formatter指定了输出了格式与内容，在logger.warn的两个输⼊参数组成了formatter中的%(message)s ，⽽formatter中的%(asctime) 等则是在⽣成LogRecord填充
以下是默认提供的属性：
如果⼀个handler没有指定Formatter，那么默认的formatter就是  logging.Formatter('%(message)s')  ，在上⾯的例⼦中，对于warn 这条⽇志，那么输出结果是warn message args
Filter
Filters can be used by Handlers and Loggers for more sophisticated filtering than is provided by levels.
filter(record)
Is the specified record to be logged? Returns zero for no, nonzero for yes. If deemed appropriate, the record may be modified in-place by this method.
Filter提供的是⽐log level更精确的过滤控制，只有当Filter.filter函数返回True的时候，这条⽇志才会被输出。
由于Filter.filter函数的参数是LogRecord实例，那么可以修改LogRecord的属性。在example1.py 第25⾏    formatter =
logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(userid)s - %(message)s')  file formatter中指定了属性% (userid)s， 但userid并不在Formatter的属性列表中，这个userid其实就是通过⾃定义的ContextFilter来实现的，在ContextFilter.filter 中，给record对象添加了userid属性。后⾯还会细讲。
官⽅给出了很多例⼦，都是通过Filter来修改LogRecord的内容，来输出⼀些上下⽂信息(contextual information)。但是我觉得这是⼀个不好的设计，顾名思义，Filter应该只做过滤的事情，理论上不应该修改输⼊，builtin filter函数就是这样的。
logging流程
从上述的介绍中可以看出，应⽤层打印的⼀条⽇志，需要经过很多步才能最终落地；既受到logger(⽣产者)的log level、Filter过滤，⼜要受到Handler(消费者)的log level、Filter过滤。
tutorial中给出了⼀个完整的流程图：
logging性能
lazy logging
在⽇志的艺术(The art of logging)⼀⽂中提到了lazy logging，即避免过早求值，把字符串的格式化推迟。但对于下⾯的语句
logger.debug('Message with %s, %s', expensive_func1(), expensive_func2())
虽然不会过早的字符串格式化(format)，但是expensive_func1、expensive_func2这两个函数⼀定会调⽤，不管⽇志是否会被输出。如何避免调⽤这两个函数，解决办法是这样的
iflogger.isEnabledFor(logging.DEBUG):
logger.debug('Message with %s, %s', expensive_func1(),
expensive_func2())
即先判断是否能够输出DEBUG等级的log，然后再调⽤logger.debug，这样就避免了调⽤expensive_func1、expensive_func2这两个函数
在这⾥，除了优化性能，还有⼀个好处就是让代码的意图更加明显(explicit)，如果expensive_func是有副作⽤(side affect)，即会改变某些内部状态，那么⽤这样的代码能更清楚表达expensive_func不⼀定会被调⽤。当然，写在⽇志⾥⾯的表达式不应该有任何副作⽤、函数也应该是pure function。
性能开关
python logging模块的性能是较差的，不仅仅是Python语⾔的问题，更多的是logging模块的实现问题。
前⾯提到，应⽤程序的每⼀条⽇志都会⽣成⼀个LogRecord对象，然后Formatter将其转换成string，怎么转化的呢，其实核⼼就⼀句代码  s = self._fmt % record.__dict__  self是Formatter实例，_fmt即初始化Formatter时传⼊的参数，record即LogRecord实例。由于LogRecord不知道Formatter需要⽤到哪些属性，所以⼲脆计算出所有的属性(见图⼀)，这是eager evaluation，lazy evaluation应该更适合。
也许Formatter只⽤到了%(message)s 属性，即只需要对logger.debug的输⼊参数求值即可，但是Log
Record还是会去反复计算线程id、进程id、应⽤程序的调⽤信息(⽂件、函数、⾏号)，这些都是很耗的操作。
对于部分确定不会⽤到的属性，可以通过开关关掉：
What you don’t want to collectHow to avoid collecting it
Information about where calls were made from.
Set logging._srcfile to None. This avoids calling sys._getframe(), which may help to speed up your code in environments like PyPy (which can’t speed up code that uses sys._getframe()).
Threading information.
Set logging.logThreads to 0.
Process information.
Set logging.logProcesses to 0.
通过下⾯的代码测试(注释第3到6⾏)，关掉之后有25%左右的性能提升

版权声明：本站内容均来自互联网，仅供演示用，请勿用于商业和其他非法用途。如果侵犯了您的权益请与我们联系QQ:729038198，我们将在24小时内删除。