Python记录日志与性能

Question

我在一个程序中使用Python的Logger。

这个程序是解决一个NP难题的求解器，因此需要进行多次深度迭代。

我的问题是，Logger是否会对程序的性能产生影响，是否有更好的记录信息的方法能够保持性能。

- PeCosta

Answer 1

根据您的日志记录器配置和程序生成的日志数量，日志记录可以成为性能瓶颈，因为Logger操作会阻塞程序。例如，从响应时间慢的NFS服务器直接记录到NFS文件时，可能会出现此情况。在这种情况下改善性能的一种可能方法是切换到使用能够缓冲和批处理日志记录操作的日志服务器 - 阻塞将仅限于与日志服务器的通信，而不是（慢速）日志文件访问，这对于性能更好。

- Dan Cornilescu

Answer 2

我使用了两个不同的日志文件，获得了非常好的使用体验。

1. server.log文件是为操作员准备的，仅接收重要的消息，通常是INFO、WARNING、ERROR和CRITICAL级别的消息。
2. debug.log文件是供开发人员分析错误的，它包含了在ERROR发生前一段时间内线程中最多100条DEBUG消息。

对于第二个文件，我使用了本地线程环形缓冲区，仅在程序检测到错误时才将其写入文件。因此，server.log文件保持较小，但开发人员可以获取足够的调试信息以后续分析问题。如果没有问题发生，则两个文件都为空，从而不会影响性能。当然，缓冲区需要一些内存和一点CPU计算能力，但这是可以接受的。

以下是我在Odoo（一个Python应用程序）中使用的示例实现：

import logging, collections, time

class LogBuffer(logging.Handler):
    """Buffer debug messages per thread and write them out when an error (or warning) occurs"""

    def __init__(self, target_handler, threshold, max_buffered_messages, max_buffer_seconds):
        logging.Handler.__init__(self, logging.DEBUG)
        self.tread_buffers = dict()  # stores one buffer for each thread (key=thread number)
        self.target_handler = target_handler
        self.threshold = threshold
        self.max_buffered_messages = max_buffered_messages
        self.last_check_time = time.time()
        self.max_buffer_seconds = max_buffer_seconds

    def emit(self, record):
        """Do whatever it takes to actually log the specified logging record."""

        # Create a thread local buffer, if not already exists
        if record.thread not in self.tread_buffers:
            thread_buffer = self.tread_buffers[record.thread] = collections.deque()
        else:
            thread_buffer = self.tread_buffers[record.thread]

        # Put the log record into the buffer
        thread_buffer.append(record)

        # If the buffer became to large, then remove the oldest entry
        if len(thread_buffer) > self.max_buffered_messages:
            thread_buffer.popleft()

        # produce output if the log level is high enough
        if record.levelno >= self.threshold:
            for r in thread_buffer:
                self.target_handler.emit(r)
            thread_buffer.clear()

        # remove very old messages from all buffers once per minute
        now = time.time()
        elapsed = now - self.last_check_time
        if elapsed > 60:
            # Iterate over all buffers
            for key, buffer in list(self.tread_buffers.items()):
                # Iterate over the content of one buffer
                for r in list(buffer):
                    age = now - r.created
                    if age > self.max_buffer_seconds:
                        buffer.remove(r)
                # If the buffer is now empty, then remove it
                if not buffer:
                    del self.tread_buffers[key]
            self.last_check_time = now

以下是创建/配置此类记录器的示例：

import logging
from . import logbuffer

"""
    Possible placeholders for the formatter:

    %(name)s            Name of the logger (logging channel)
    %(levelno)s         Numeric logging level for the message (DEBUG, INFO,
                        WARNING, ERROR, CRITICAL)
    %(levelname)s       Text logging level for the message ("DEBUG", "INFO",
                        "WARNING", "ERROR", "CRITICAL")
    %(pathname)s        Full pathname of the source file where the logging
                        call was issued (if available)
    %(filename)s        Filename portion of pathname
    %(module)s          Module (name portion of filename)
    %(lineno)d          Source line number where the logging call was issued
                        (if available)
    %(funcName)s        Function name
    %(created)f         Time when the LogRecord was created (time.time()
                        return value)
    %(asctime)s         Textual time when the LogRecord was created
    %(msecs)d           Millisecond portion of the creation time
    %(relativeCreated)d Time in milliseconds when the LogRecord was created,
                        relative to the time the logging module was loaded
                        (typically at application startup time)
    %(thread)d          Thread ID (if available)
    %(threadName)s      Thread name (if available)
    %(process)d         Process ID (if available)
    %(message)s         The result of record.getMessage(), computed just as
                        the record is emitted
"""

# Log levels are: CRITICAL, ERROR, WARNING, INFO, DEBUG

# Specify the output format
formatter = logging.Formatter('%(asctime)-15s %(thread)20d %(levelname)-8s %(name)s %(message)s')

# Create server.log
server_log = logging.FileHandler('../log/server.log')
server_log.setLevel(logging.INFO)
server_log.setFormatter(formatter)
logging.root.addHandler(server_log)

# Create debug.log
debug_log = logging.FileHandler('../log/debug.log')
debug_log.setFormatter(formatter)
memory_handler = logbuffer.LogBuffer(debug_log, threshold=logging.ERROR, max_buffered_messages=100, max_buffer_seconds=600)
logging.root.addHandler(memory_handler)

# Specify log levels for individual packages
logging.getLogger('odoo.addons').setLevel(logging.DEBUG)

# The default log level for all other packages
logging.root.setLevel(logging.INFO)

如果这篇文章对您有帮助，请告诉我。关于Python，我是一个非常初级的学习者，但是我已经成功地在Java和C++中运行了同样的程序多年。

- Stefan