转载

logback官方文档阅读笔记(三)

前言

logback官方文档

本文关于官方文档第二章: Architecture

第二章篇幅较长,分了多篇笔记,本文为关于第二章的笔记的第二篇。第一篇请见: logback官方文档阅读笔记(二)

正文

The ability to selectively enable or disable logging requests based on their logger is only part of the picture. Logback allows logging requests to print to multiple destinations. In logback speak, an output destination is called an appender. Currently, appenders exist for the console, files, remote socket servers, to MySQL, PostgreSQL, Oracle and other databases, JMS, and remote UNIX Syslog daemons.

More than one appender can be attached to a logger.

The addAppender method adds an appender to a given logger. Each enabled logging request for a given logger will be forwarded to all the appenders in that logger as well as the appenders higher in the hierarchy. In other words, appenders are inherited additively from the logger hierarchy. For example, if a console appender is added to the root logger, then all enabled logging requests will at least print on the console. If in addition a file appender is added to a logger, say_L_, then enabled logging requests for_L_and_L_'s children will print on a file_and_on the console. It is possible to override this default behavior so that appender accumulation is no longer additive by setting the additivity flag of a logger to false.

The rules governing appender additivity are summarized below.

Appender Additivity:

The output of a log statement of logger L will go to all the appenders in L and its ancestors. This is the meaning of the term "appender additivity".

However, if an ancestor of logger L , say P , has the additivity flag set to false, then L 's output will be directed to all the appenders in L and its ancestors up to and including P but not the appenders in any of the ancestors of P .

Loggers have their additivity flag set to true by default.

Since the root logger stands at the top of the logger hierarchy, the additivity flag does not apply to it.

为日志记录器添加输出器

本段主要讲明了以下几点:

一个输出器,即 Appender 类可以用来指明一个输出目标。

一个日志记录器,即 Logger 类可以通过设置输出器来设定被允许(等级上达成条件)记录的日志往哪里输出。

因为日志记录器存在层级,低层级的日志记录器的日志输出,也会引起其父级日志记录器的日志输出请求,被允许的请求亦会调动父级日志记录器的输出器向输出目标输出。上述行为可通过设置 addivity 属性控制。

More often than not, users wish to customize not only the output destination but also the output format. This is accomplished by associating a layout with an appender. The layout is responsible for formatting the logging request according to the user's wishes, whereas an appender takes care of sending the formatted output to its destination. The PatternLayout , part of the standard logback distribution, lets the user specify the output format according to conversion patterns similar to the C language printf

function.

For example, the PatternLayout with the conversion pattern "%-4relative [%thread] %-5level %logger{32} - %msg%n" will output something akin to:

176 [main] DEBUG manual.architecture.HelloWorld2 - Hello world.

The first field is the number of milliseconds elapsed since the start of the program. The second field is the thread making the log request. The third field is the level of the log request. The fourth field is the name of the logger associated with the log request. The text after the '-' is the message of the request.

简单引入 PatternLayout

这段话最重要的内容就是“用户定制输出的格式通过关联一个布置器(layout)到一个输出器上来实现”。这一内容值得细读,它表明布置器是与输出器关联而不是与日志记录器关联,同时一个日志记录器可以有多个输出器。

之后举了一个例子讲了一下布置器(layout)的输出格式(pattern)的写法。但很恶心的是,没有讲清楚如何为输出器关联布置器,如何为布置器设置模式,下一节就是另一个话题了。

日志记录器的类似C占位符的格式化输出

Parameterized logging

Given that loggers in logback-classic implement the SLF4J's Logger interface , certain printing methods admit more than one parameter. These printing method variants are mainly intended to improve performance while minimizing the impact on the readability of the code.

这里说日志记录器 Logger 的打印(输出)方法实现了SLF4J要求的可以接收处理多个参数的能力。这一能力可以提高性能并尽可能不破坏可读性,怎么回事呢,继续往下看。

这里也有一个很恼人的地方,所谓'certain printing methods',在超链接过去的API文档中搜索print,根本没有。结合下文才能反应过来,其实在日志系统或者说slf4j或者说logback中,所谓的print就是指 info(..) , debug(...) 这样的方法。

logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i])); incurs the cost of constructing the message parameter, that is converting both integer i and entry[i] to a String, and concatenating intermediate strings. This is regardless of whether the message will be logged or not.
One possible way to avoid the cost of parameter construction is by surrounding the log statement with a test. Here is an example.
if(logger.isDebugEnabled()) {   logger.debug("Entry number: " + i + " is " + String.valueOf(entry[i])); } This way you will not incur the cost of parameter construction if debugging is disabled for logger. On the other hand, if the logger is enabled for the DEBUG level, you will incur the cost of evaluating whether the logger is enabled or not, twice: once in debugEnabled and once in debug. In practice, this overhead is insignificant because evaluating a logger takes less than 1% of the time it takes to actually log a request.
Better alternative There exists a convenient alternative based on message formats. Assuming entry is an object, you can write:
Object entry = new SomeObject();  logger.debug("The entry is {}.", entry); Only after evaluating whether to log or not, and only if the decision is positive, will the logger implementation format the message and replace the '{}' pair with the string value of entry. In other words, this form does not incur the cost of parameter construction when the log statement is disabled.
The following two lines will yield the exact same output. However, in case of a disabled logging statement, the second variant will outperform the first variant by a factor of at least 30.
logger.debug("The new entry is "+entry+"."); logger.debug("The new entry is {}.", entry); A two argument variant is also available. For example, you can write:
logger.debug("The new entry is {}. It replaces {}.", entry, oldEntry); If three or more arguments need to be passed, an Object[] variant is also available. For example, you can write:
Object[] paramArray = {newVal, below, above}; logger.debug("Value {} was inserted between {} and {}.", paramArray);

这一段主要介绍了允许占位符化输出(到这里为止唯一)的好处——避免日志记录器中不够格的输出中的字符串拼接的资源浪费。

After we have introduced the essential logback components, we are now ready to describe the steps that the logback framework takes when the user invokes a logger's printing method. Let us now analyze the steps logback takes when the user invokes the info()

method of a logger named_com.wombat_.

1. Get the filter chain decision

If it exists, the TurboFilter chain is invoked. Turbo filters can set a context-wide threshold, or filter out certain events based on information such as Marker , Level , Logger , message, or the Throwable that are associated with each logging request. If the reply of the filter chain is FilterReply.DENY , then the logging request is dropped. If it is FilterReply.NEUTRAL , then we continue with the next step, i.e. step 2. In case the reply is FilterReply.ACCEPT , we skip the next and directly jump to step 3.

2. Apply the basic selection rule

At this step, logback compares the effective level of the logger with the level of the request. If the logging request is disabled according to this test, then logback will drop the request without further processing. Otherwise, it proceeds to the next step.

3. Create a LoggingEvent object

If the request survived the previous filters, logback will create a ch.qos.logback.classic.LoggingEvent object containing all the relevant parameters of the request, such as the logger of the request, the request level, the message itself, the exception that might have been passed along with the request, the current time, the current thread, various data about the class that issued the logging request and the MDC . Note that some of these fields are initialized lazily, that is only when they are actually needed. The MDC is used to decorate the logging request with additional contextual information. MDC is discussed in a subsequent chapter .

4. Invoking appenders

After the creation of a LoggingEvent object, logback will invoke the doAppend() methods of all the applicable appenders, that is, the appenders inherited from the logger context.

All appenders shipped with the logback distribution extend the AppenderBase abstract class that implements the doAppend method in a synchronized block ensuring thread-safety. The doAppend() method of AppenderBase also invokes custom filters attached to the appender, if any such filters exist. Custom filters, which can be dynamically attached to any appender, are presented in a separate chapter .

5. Formatting the output

It is responsibility of the invoked appender to format the logging event. However, some (but not all) appenders delegate the task of formatting the logging event to a layout. A layout formats the LoggingEvent instance and returns the result as a String. Note that some appenders, such as the SocketAppender , do not transform the logging event into a string but serialize it instead. Consequently, they do not have nor require a layout.

6. Sending out the LoggingEvent

After the logging event is fully formatted it is sent to its destination by each appender.

流程图

logback试图输出一条日志记录的六个过程

本段条理清晰地讲明了logback实现下,试图输出一条日志记录的六个过程。

在本段中,引入了过滤器Filter的概念,值得细读。实际上,继续学习或从使用经验来看,过滤器Filter的重要程度完全不输于之前提到的logback实现依赖的三大主力——输出器Appender,日志记录器Logger,布置器Layout。

同时,细读会发现在阶段一和阶段四均出现了过滤器Filter,目前仅能从文本中获知,一阶段的Filter筛选时权力和范围都更大,而四阶段更多的是对一个输出挑挑拣拣筛一筛。同时带来一些疑问:两者是否为同一个类?第四阶段中Filter的响应和第一阶段中的响应如何?

另外,在第四阶段中的超链接点进去,会发现是官方文档第七篇。也就是说官方文档第七篇主要讲的是阶段四的Filter而不是阶段一的。

Performance

One of the often-cited arguments against logging is its computational cost. This is a legitimate concern as even moderately-sized applications can generate thousands of log requests. Much of our development effort is spent measuring and tweaking logback's performance. Independently of these efforts, the user should still be aware of the following performance issues.

1. Logging performance when logging is turned off entirely

You can turn off logging entirely by setting the level of the root logger to Level.OFF, the highest possible level. When logging is turned off entirely, the cost of a log request consists of a method invocation plus an integer comparison. On a 3.2Ghz Pentium D machine this cost is typically around 20 nanoseconds.

However, any method invocation involves the "hidden" cost of parameter construction. For example, for some logger x writing,

x.debug("Entry number: " + i + "is " + entry[i]);

incurs the cost of constructing the message parameter, i.e. converting both integer i and entry[i] to a string, and concatenating intermediate strings, regardless of whether the message will be logged or not.

The cost of parameter construction can be quite high and depends on the size of the parameters involved. To avoid the cost of parameter construction you can take advantage of SLF4J's parameterized logging:

x.debug("Entry number: {} is {}", i, entry[i]);

This variant will not incur the cost of parameter construction. Compared to the previous call to the debug() method, it will be faster by a wide margin. The message will be formatted only if the logging request is to be sent to attached appenders. Moreover, the component that formats messages is highly optimized.

Notwithstanding the above placing log statements in tight loops, i.e. very frequently invoked code, is a lose-lose proposal, likely to result in degraded performance. Logging in tight loops will slow down your application even if logging is turned off, and if logging is turned on, will generate massive (and hence useless) output.

2. The performance of deciding whether to log or not to log when logging is turned on.

In logback, there is no need to walk the logger hierarchy. A logger knows its effective level (that is, its level, once level inheritance has been taken into consideration) when it is created. Should the level of a parent logger be changed, then all child loggers are contacted to take notice of the change. Thus, before accepting or denying a request based on the effective level, the logger can make a quasi-instantaneous decision, without needing to consult its ancestors.

3. Actual logging (formatting and writing to the output device)

This is the cost of formatting the log output and sending it to its target destination. Here again, a serious effort was made to make layouts (formatters) perform as quickly as possible. The same is true for appenders. The typical cost of actually logging is about 9 to 12 microseconds when logging to a file on the local machine. It goes up to several milliseconds when logging to a database on a remote server.

Although feature-rich, one of the foremost design goals of logback was speed of execution, a requirement which is second only to reliability. Some logback components have been rewritten several times to improve performance.

本段内容其实没有什么意义。主要说自己logback在性能做了很多努力使其性能强劲。

唯一可以让使用者动手操作的就只有接受占位符的输出能力,在这节之前就已经讲解。

原文  https://segmentfault.com/a/1190000020743995
正文到此结束
Loading...