- 浏览: 8887 次
- 性别:
- 来自: 北京
最新评论
Our latest JCP partner, Tomasz Nurkiewicz, has submitted a number of posts describing the basic principles of proper application logging. I found them quite interesting, thus I decided to aggregate them in a more compact format and present them to you. So, here are his suggestions for clean and helpful logs:
(NOTE: The original posts have been slightly edited to improve readability)
我们最近的JCP(JAVA code Geek) 小伙伴们已经写了很多描述程序合理记录日志的基本原则,我发现它们非常有趣,所以我决定把他们写的总结成一个更紧凑合理的格式给大家,下面是一些他们关于日志的一些建议:
1) Use the appropriate tools for the job
Many programmers seem to forget how important is logging an application’s behavior and its current activity. When somebody puts:
1)使用合适的工具
许多程序员好像忘了在系统中记录程序的行为和系统当前的活动,当有人写到:
log.info("Happy and carefree logging");
happily somewhere in the code, he probably doesn’t realize the importance of application logs during maintenance, tuning and failure identification. Underestimating the value of good logs is a terrible mistake.
In my opinion, SLF4J is the best logging API available, mostly because of a great pattern substitution support:
他可能没有意识到程序日志在维护,调优,错误标识的重要性,低估了记录好日志的重要性是一个可怕的错误。
我认为,SLF4J是现有最好的日志API,主要是因为它强大的模式替换。
log.debug("Found {} records matching filter: '{}'", records, filter);
In Log4j you would have to use:
如果用log4j你会写到:
log.debug("Found " + records + " records matching filter: '" + filter + "'");
This is not only longer and less readable, but also inefficient because of extensive use of string concatenation. SLF4J adds a nice {} substitution feature. Also, because string concatenation is avoided and toString() is not called if the logging statement is filtered, there is no need for isDebugEnabled() anymore. BTW, have you noticed single quotes around filter string parameter?
这不紧长,不容易阅读,而且效率地下因为大量的字符串的拼接。SLF4J 添加了一个漂亮的{}符号来置换变量的功能。而且,如果日志被过滤的话就不会对字符串进行拼接和调用toString()方法,isDebugEnabled()这个方法就没有用处了。顺便,你注意到filter字符串两边的单括号了吗?
SLF4J is just a façade. As an implementation I would recommend the Logback framework, already advertised, instead of the well established Log4J. It has many interesting features and, in contrary to Log4J, is actively developed.
SLF4J紧紧是个入门,就使用而言,我会推荐 Logback 框架,而不是log4j。它有很多有趣的功能而且和Log4j相反,它正在被活跃的开发当中。
The last tool to recommend is Perf4J. To quote their motto:
Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()
最后要推荐的是Perf4j,引用他们的座右铭:
如果Log4j是System.out.println(),Perf4J 就是 System.currentTimeMillis()
I’ve added Perf4J to one existing application under heavy load and seen it in action in few other. Both administrators and business users were impressed by the nice graphs produced by this simple utility. Also we were able to discover performance flaws in no time. Perf4J itself deserves its own article, but for now just check their Developer Guide.
我已经讲Perf4J用到了一个负载较重的项目当中观察它的表现。管理员和商业客户都都这个小工具产生的漂亮的图表印象深刻。
Additionally, note that Ceki Gülcü (founder of the Log4J, SLF4J and Logback projects) suggested a simple approach to get rid ofcommons-logging dependency (see his comment).
此外,留意Ceki Gülcü ( Log4J, SLF4J and Logback 项目的创始人) 一个简单的摆脱commons-logging 依赖(see his comment).的建议。
2) Don’t forget, logging levels are there for you
2)不要忘记日志的级别
Every time you make a logging statement, you think hard which logging level is appropriate for this type of event, don’t you? Somehow 90% of programmers never pay attention to logging levels, simply logging everything on the same level, typically INFO or DEBUG. Why? Logging frameworks have two major benefits over System.out., i.e. categories and levels. Both allow you to selectively filter logging statements permanently or only for diagnostics time. If you really can’t see the difference, print this table and look at it every time you start typing “log.” in your IDE:
每次你写一个log的时候,你很难决定那个级别对这个日志比较合适,对吗?不管怎样,90%的程序员从来不关心日志的级别,简单的用同样的日志级别打印日志,通常是INFO或者DEBUG,为什么呢?日志框架跟System.out相比有两个主要的好处,一个是分类,一个是级别。两者都允许你设置filter来过滤日志。
ERROR – something terribly wrong had happened, that must be investigated immediately. No system can tolerate items logged on this level. Example: NPE, database unavailable, mission critical use case cannot be continued.
ERROR-一些严重的错误发生的时候,必须马上研究原因的日志。没有任何系统能够忍受这种级别的日志。例如:数据库不能访问,关键流程失败。
WARN – the process might be continued, but take extra caution. Actually I always wanted to have two levels here: one for obvious problems where work-around exists (for example: “Current data unavailable, using cached values”) and second (name it: ATTENTION) for potential problems and suggestions. Example: “Application running in development mode” or “Administration console is not secured with a password”. The application can tolerate warning messages, but they should always be justified and examined.
WARN—— 进程可以持续,但是需要引起注意。事实上,我总是想用两种级别在这:一种是明显的但是有应急方案的问题。(例如:“当前数据不可用,可以使用缓存的数据”)第二种是可能有潜在错误。例如:程序运行在开发模式。管理控制台没有密码保护。
INFO – Important business process has finished. In ideal world, administrator or advanced user should be able to understand INFO messages and quickly find out what the application is doing. For example if an application is all about booking airplane tickets, there should be only one INFO statement per each ticket saying “[Who] booked ticket from [Where] to [Where]“. Other definition of INFO message: each action that changes the state of the application significantly (database update, external system request).
INFO- 重要的业务流程已经完成。理想的话,管理员和高级用户以你更改能够理解INFO 的日志输出并且能够快速的找出应用程序正在做什么。例如如果程序是关于预定机票的话,对每一个预定的机票应该输出“谁”预定了机票从“哪儿”到“哪儿”。其他一些INFO日志:每一个改变应用程序状态的重要动作都应该记录(数据库更新,外部系统请求等)
DEBUG – Developers stuff. I will discuss later what sort of information deserves to be logged.
DEBUG - 开发者的东西。后面我会谈到什么想的信息应该被记录
TRACE – Very detailed information, intended only for development. You might keep trace messages for a short period of time after deployment on production environment, but treat these log statements as temporary, that should or might be turned-off eventually. The distinction between DEBUG and TRACE is the most difficult, but if you put logging statement and remove it after the feature has been developed and tested, it should probably be on TRACE level.
TRACE --所有的详细信息,紧紧为了开发。项目部署之后短时间之内可能会打开这些信息,但是最后必须得关闭这些日志的输出。DEBUG和TRACE的确不容易区分,但是如果你想在开发的时候打出一些日志,开发完成之后删除它,你应该选择TRACE。
The list above is just a suggestion, you can create your own set of instructions to follow, but it is important to have some. My experience is that always everything is logged without filtering (at least from the application code), but having the ability to quickly filter logs and extract the information with proper detail level, might be a life-saver.
上面这些是我的一些建议,你可以根据自己的需要简历自己的使用原则。我的经验是总是打印所有的日志,但是能够快速的过滤和摘取需要的日志。
The last thing worth mentioning is the infamous is*Enabled() condition. Some put it before every logging statement:
最后值得提一提是Enabled() 选项,有些总是把他放到输出日志的前面:
if(log.isDebugEnabled())
log.debug("Place for your commercial");
Personally, I find this idiom being just clutter that should be avoided. The performance improvement (especially when using SLF4Jpattern substitution discussed previously) seems irrelevant and smells like a premature optimization. Also, can you spot the duplication? There are very rare cases when having explicit condition is justified – when we can prove that constructing logging message is expensive. In other situations, just do your job of logging and let logging framework do its job (filtering).
就我个人二千,我发现这样的写法只能造成混乱,应该避免使用。
3) Do you know what you are logging?
3)你知道你在打什么日志吗?
Every time you issue a logging statement, take a moment and have a look at what exactly will land in your log file. Read your logs afterwards and spot malformed sentences. First of all, avoid NPEs like this:
每次你打印日志的时候,花点时间看看你的日志文件会真正的输出什么,首先不要这么写:
log.debug("Processing request with id: {}", request.getId());
Are you absolutely sure that request is not null here?
Another pitfall is logging collections. If you fetched collection of domain objects from the database using Hibernate and carelessly log them like here:
你确定request不是null ?
另一个陷阱是打印集合。如果你用Hibernate从数据库查询记录存在集合里并输出到日志:
log.debug("Returning users: {}", users);
SLF4J will call toString() only when the statement is actually printed, which is quite nice. But if it does… Out of memory error, N+1 select problem, thread starvation (logging is synchronous!), lazy initialization exception, logs storage filled completely – each of these might occur.
SLF4J只有输出日志的时候才会调用toString()。但是,如果它内存溢出了,N+1 select 问题,线程饥饿,延迟加载,日志会自动填满。
It is a much better idea to log, for example, only ids of domain objects (or even only size of the collection). But making a collection of ids when having a collection of objects having getId() method is unbelievably difficult and cumbersome in Java. Groovy has a great spread operator (users*.id), in Java we can emulate it using the Commons Beanutils library:
一个好的记录日志的方法是,比如紧紧打印对象的ID,或着紧紧是集合的SIZE。但是当你得到一个对象的集合每次来调用getId()来得到id的集合会很不方便。Groovy有一个好的框架可以使用(users*.id),java中我们可以用Commons Beanutils :
log.debug("Returning user ids: {}", collect(users, "id"));
Where collect() method can be implemented as follows:
collect()方法可以这么实现:
public static Collection collect(Collection collection, String propertyName) {
return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));
}
The last thing to mention is the improper implementation or usage of toString(). First, create toString() for each class that appears anywhere in logging statements, preferably using ToStringBuilder (but not its reflective counterpart). Secondly, watch out for arrays and non-typical collections. Arrays and some strange collections might not have toString() implemented calling toString() of each item. UseArrays #deepToString JDK utility method. And read your logs often to spot incorrectly formatted messages.
最后要提的是toString()不正确的使用方法和实现。首先,创建一个toString()方法为每一个出现在日志输出语句的class中。可以使用
ToStringBuilder 。第二,小心那些数组和非典型的集合。数组和一些集合可能没有实现toString()方法。可以使用Arrays #deepToString JDK工具方法,并且经常读下你的日志,找出不合理的地方。
4) Avoid side effects
4)避免副作用
Logging statements should have no or little impact on the application’s behavior. Recently a friend of mine gave an example of a system that threw Hibernates’ LazyInitializationException only when running on some particular environment. As you’ve probably guessed from the context, some logging statement caused lazy initialized collection to be loaded when session was attached. On this environment the logging levels were increased and collection was no longer initialized. Think how long would it take you to find a bug without knowing this context?
输出日志的语句应该对系统没有或者有很小行为上的影响。有一个朋友提供了一个系统在一些情况下会抛出Hibernates’ LazyInitializationException 异常的例子。或许你已经猜到,一些日志输出语句导致了延迟加载的集合被加载。在这种情况下,当调整日志级别的时候就不会有这种问题,但是如果不知道这中情况的话你得花多上时间去找这个bug呢?
Another side effect is slowing the application down. Quick answer: if you log too much or improperly use toString() and/or string concatenation, logging has a performance side effect. How big? Well, I have seen server restarting every 15 minutes because of a thread starvation caused by excessive logging. Now this is a side effect! From my experience, few hundreds of MiB is probably the upper limit of how much you can log onto disk per hour.
另一个副作用是会让系统变得很慢。答案:如果你打印太多日志或者错误的使用toString() 或者字符串拼接,输出日志就会有负面影响。多大呢?我看过服务器没15分钟重启一次就是应为大量日志导致的线程饥饿。
Of course if logging statement itself fails and causes business process to terminate due to exception, this is also a huge side effect. I have seen such a construct to avoid this:
当然如果打印日志的语句 本身导致业务流程终端抛出异常,这也是一个很大的负面影响。我看到过这么写去避免这种问题的:
try {
log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())
}
This is a real code, but please make the world a bit better place and don’t do it, ever.
还真有人这么写,不过为了让世界更美好还是别这么写的好啊
5) Be concise and descriptive
5)简洁并具有描述性
Each logging statement should contain both data and description. Consider the following examples:
每一个日志输出语句应该都包含数据和描述,看一下下面的例子:
log.debug("Message processed");
log.debug(message.getJMSMessageID());
log.debug("Message with id '{}' processed", message.getJMSMessageID());
Which log would you like to see while diagnosing failure in an unknown application? Believe me, all the examples above are almost equally common. Another anti-pattern:
当你调试系统错误的时候你更喜欢看到哪中日志呢?相信我,上面的例子非常常见。另一个反面的例子:
if(message instanceof TextMessage)
//...
else
log.warn("Unknown message type");
Was it so hard to include thee actual message type, message id, etc. in the warning string? I know something went wrong, but what? What was the context?
在日志里加上消息类型,消息ID就这么难吗?我知道程序发生了错误,但是在什么环境下发生的呢?
A third anti-pattern is the “magic-log”. Real life example: most programmers in the team knew that 3 ampersands followed by exclamation mark, followed by hash, followed by pseudorandom alphanumeric string log means “Message with XYZ id received”. Nobody bothered to change the log, simply someone hit the keyboard and chose some unique “&&&!#” string, so that it can be easily found by himself.
第三个反面的日志模式是“魔术日志”。真实的例子,好多team中的程序员用一些特殊的符号,比如&!#来标识“收到了消息”,这样他自己就能方便的找到。
As a consequence, the whole logs file looks like a random sequence of characters. Somebody might even consider that file to be a validPerl program. Instead, a log file should be readable, clean and descriptive. Don’t use magic numbers, log values, numbers, ids and include their context. Show the data being processed and show its meaning. Show what the program is actually doing. Good logs can serve as a great documentation of the application code itself.
结果是,日志看起来就像是一些随机的字符串。一些人还会以为是一个Perl程序呢。相反,一个日志文件应该很容易的被阅读,整洁并具有描述性。不要使用那些神秘的字符,要记录那些值,数字,id,还有上下文环境。记录那些数据正在被处理,还有这些数据的意思。记录程序正在做什么。好的日志能够作为程序代码一个好的文档。
Did I mention not to log passwords and any personal information? Don’t!
我提到不要记录密码信息和任何私人的信息了吗?千万不要这么做啊,会死人的!
6) Tune your pattern
6)调整你的日志格式
Logging pattern is a wonderful tool, that transparently adds a meaningful context to every logging statement you make. But you must consider very carefully which information to include in your pattern. For example, logging date when your logs roll every hour is pointless as the date is already included in the log file name. On the contrary, without logging the thread name you would be unable to track any process using logs when two threads work concurrently – the logs will overlap. This might be fine in single-threaded applications – that are almost dead nowadays.
日志格式一个很好的工具,他很明显的为没一条日志添加了一个有意思的上下文环境。但是你必须细心的考虑到哪些日志应该应用你的日志格式。例如:当你的日志每一个小时生成一个文件的时候你在日志里记录时间是没有意义的,因为文件名中已经有时间了。相反,当2个线程并发执行的时候你没有记录线程的名字你是不能跟踪每一个线程的活动的-日志会有重叠。单线程的程序没有这个问题——但是貌似现在很少有单线程的系统啊
From my experience, the ideal logging pattern should include (of course except the logged message itself): current time (without date, milliseconds precision), logging level, name of the thread, simple logger name (not fully qualified) and the message. In Logback it is something like:
跟我我的经验,理想的日志模式应该包括:当前的时间(排除日期,毫秒的精度),日志的级别,线程名,日志名,还有消息内容。在 Logback 中:
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%logger{0}] %m%n</pattern>
</encoder>
</appender>
You should never include file name, class name and line number, although it’s very tempting. I have even seen empty log statements issued from the code:
你不应该包含文件名,类名和行数尽管它很诱人。我看见过代码中空的日志记录语句:
log.info("");
because the programmer assumed that the line number will be a part of the logging pattern and he knew that “If empty logging message appears in 67th line of the file (in authenticate() method), it means that the user is authenticated”. Besides, logging class name, method name and/or line number has a serious performance impact.
因为程序员以为行数会是日志的一部分,他知道,“如果日志出现在67行,意味着这个用户验证通过”。此外,在日志中记录类名,方法名或者行数会对程序性能有很大的影响。
A somewhat more advanced feature of a logging frameworks is the concept of Mapped Diagnostic Context. MDC is simply a map managed on a thread-local basis. You can put any key-value pair in this map and since then every logging statement issued from this thread is going to have this value attached as part of the pattern.
一个更高级的日志框架的功能是 MDC的概念,它是一个简单的基于线程的map。你可以放任务key-value对到这个map,然后所有的日志跟这个线程有关的就会有他的值来作为日志的一部分。MDC用法参见:http://logback.qos.ch/manual/mdc.html
7) Log method arguments and return values
7)日志方法的参数和返回值
When you find a bug during development, you typically run a debugger trying to track down the potential cause. Now imagine for a while that you can’t use a debugger. For example, because the bug manifested itself on a customer environment few days ago and everything you have is logs. Would you be able to find anything in them?
当你开发的时候发现一个bug,你会debug一下看一看有什么潜在的问题。考虑一下,如果不能使用debug功能。例如:这个bug在客户环境几天之前发生,你就只能看log了。你能在log里找到你要的信息吗?
If you follow the simple rule of logging each method input and output (arguments and return values), you don’t even need a debugger any more. Of course, you must be reasonable but every method that: accesses external system (including database), blocks, waits, etc. should be considered. Simply follow this pattern:
如果你遵循简单的规则,记录每一个方法的输入和输出(参数和返回值),你甚至都不需要去debug了。当然,你应该合理并且每一个方法:访问外部系统(包括数据库),block,等待。。。都应该考虑。看下下面的格式:
public String printDocument(Document doc, Mode mode) {
log.debug("Entering printDocument(doc={}, mode={})", doc, mode);
String id = //Lengthy printing operation
log.debug("Leaving printDocument(): {}", id);
return id;
}
Because you are logging both the beginning and the end of method invocation, you can manually discover inefficient code and even detect possible causes of deadlocks and starvation – simply by looking after “entering” without corresponding “leaving”. If your methods have meaningful names, reading logs would be a pleasure. Also, analyzing what went wrong is much simpler, since on each step you know exactly what has been processed. You can even use a simple AOP aspect to log a wide range of methods in your code. This reduces code duplication, but be careful, since it may lead to enormous amount of huge logs.
因为你在记录方法调用的开始和结束,你就能够发现效率地下的代码和发现可能的线程死锁和线程饥饿---简单的看下“entering”之后有没有“leaving”被打印出来。如果你的方法有一个有意义的名字,读Log的时候会很方便。而且,分析什么是发生了错误会很简单,因为你知道每一步都在处理什么。你甚至可以使用简单的AOP面向横切面的方式去记录你代码中的各种方法。这样会减少代码重复,但是小心,这回产生大量的日志。
You should consider DEBUG or TRACE levels as best suited for these types of logs. And if you discover some method are called too often and logging might harm performance, simply decrease logging level for that class or remove the log completely (maybe leaving just one for the whole method invocation?) But it is always better to have too much rather than too few logging statements. Treat logging statements with the same respect as unit tests – your code should be covered with logging routines as it is with unit tests. No part of the system should stay with no logs at all. Remember, sometimes observing logs rolling by is the only way to tell whether your application is working properly or hangs forever.
你应该考虑用DEBUG或者TRACE 对于这种类型的日志。还有,如果你发现一些方法被调用比较频繁并且会影响性能,可以降低日志的级别或者直接删除这条日志。但是一般日志多总是会比日志少要好。单元测试的日志应该同样的别对待---你的代码里应该充斥着日志输出的代码,测试代码也一样。没有一个系统应该不输出日志。请记住,观察滚动的日志有时候会是判断程序正常或者被挂唯一的方式。
8) Watch out for external systems
8)关注那些外部系统
This is the special case of the previous tip: if you communicate with an external system, consider logging every piece of data that comes out from your application and gets in. Period. Integration is a tough job and diagnosing problems between two applications (think two different vendors, environments, technology stacks and teams) is particularly hard. Recently, for example, we’ve discovered that logging full messages contents, including SOAP and HTTP headers in Apache CXF web services is extremely useful during integration and system testing.
跟之前的建议相比,这是一个特殊的例子:如果你跟一个外部的系统有交互,一定要考虑用日志记录从你系统进入和流出的数据。集成是一项困难的工作并且在两个不通厂家不同环境的系统中诊断系统问题就更困难了。目前,例如:我们讨论到记录所有的Apache CXF 消息体包括SOAP和HTTP 头在集成和系统测试中是非常有用的。
This is a big overhead and if performance is an issue, you can always disable logging. But what is the point of having a fast, but broken application, that no one can fix? Be extra careful when integrating with external systems and prepare to pay that cost. If you are lucky and all your integration is handled by an ESB, then the bus is probably the best place to log every incoming request and response. See for example Mules’ log-component.
这是一个很大的开销,如果遇到性能问题可以关闭日志。但是如果一个运行很快但是崩溃的时候没法修复有什么用呢?当跟外部系统集成的时候一定要小心。
Sometimes the amount of information exchanged with external systems makes it unacceptable to log everything. On the other hand during testing and for a short period of time on production (for example when something wrong is happening), we would like to have everything saved in logs and are ready to pay performance cost. This can be achieved by carefully using logging levels. Just take a look at the following idiom:
有些时候与外部系统大量的信息使得记录全部不能被接受,另一方面,在测试阶段或者系统上线后短时间之内(例如系统出问题了)我们希望能够看到所有的日志记录并且做好性能问题的准备。我们可以利用日志级别去做这件事,看一下下面的例子:
Collection<Integer> requestIds = //...
if(log.isDebugEnabled())
log.debug("Processing ids: {}", requestIds);
else
log.info("Processing ids size: {}", requestIds.size());
If this particular logger is configured to log DEBUG messages, it will print the whole requestIds collection contents. But if it is configured to print INFO messages, only the size of collection will be outputted. If you are wondering why I forgot about isInfoEnabled() condition, go back to tip #2. One thing worth mentioning is that requestIds collection should not be null in this case. Although it will be logged correctly as null if DEBUG is enabled, but big fat NullPointerException will be thrown if logger is configured to INFO. Remember my lesson about side effects in tip #4?
如果日志配置成DEBUG级别,会打印所有的请求的集合信息。如果配置成INFO,只会打印集合的SIZE。
9) Log exceptions properly
9)合理的记录异常信息
First of all, avoid logging exceptions, let your framework or container (whatever it is) do it for you. There is one, ekhem, exception to this rule: if you throw exceptions from some remote service (RMI, EJB remote session bean, etc.), that is capable of serializing exceptions, make sure all of them are available to the client (are part of the API). Otherwise the client will receive NoClassDefFoundError: SomeFancyException instead of the “true” error.
首先,避免写异常信息的日志,让框架活着容器来做这件事。记录异常的一条规则:如果你抛出的异常要给远端的服务器,例如(RMI,EJB),可以讲异常序列化保证你的异常被其他的客户端收到,否则客户端将收到NoClassDefFoundError
Logging exceptions is one of the most important roles of logging at all, but many programmers tend to treat logging as a way to handle the exception. They sometimes return default value (typically null, 0 or empty string) and pretend that nothing has happened. Other times they first log the exception and then wrap it and throw it back:
记录异常日志是记录日志中最重要的,但是好多程序员将日志作为处理异常的方式。他们有时候返回缺省值(null,0或者空字符)假装什么都没发生。有时候他们首先打印出日志然后抛出去
log.error("IO exception", e);
throw new MyCustomException(e);
This construct will almost always print the same stack trace two times, because something will eventually catch MyCustomException and log its cause. Log, or wrap and throw back (which is preferable), never both, otherwise your logs will be confusing.
But if we really do WANT to log the exception? For some reason (because we don’t read APIs and documentation?), about half of the logging statements I see are wrong. Quick quiz, which of the following log statements will log the NPE properly?
上面的语句将会打印2次同样的Log,但是有时候将会捕获自己定义的异常并且记录下来。遇到异常是记录日志,封装然后再跑出去呢?不要两个都做,否则日志会很乱。
但是如果我们想记录这些异常应该怎么做呢?看下下面的例子那一个更合适呢?
try {
Integer x = null;
++x;
} catch (Exception e) {
log.error(e); //A
log.error(e, e); //B
log.error("" + e); //C
log.error(e.toString()); //D
log.error(e.getMessage()); //E
log.error(null, e); //F
log.error("", e); //G
log.error("{}", e); //H
log.error("{}", e.getMessage()); //I
log.error("Error reading configuration file: " + e); //J
log.error("Error reading configuration file: " + e.getMessage()); //K
log.error("Error reading configuration file", e); //L
}
Surprisingly, only G and preferably L are correct! A and B don’t even compile in SLF4J, others discard stack traces and/or print improper messages. For example, E will not print anything as NPE typically doesn’t provide any exception message and the stack trace won’t be printed as well. Remember, the first argument is always the text message, write something about the nature of the problem. Don’t include exception message, as it will be printed automatically after the log statement, preceding stack trace. But in order to do so, you must pass the exception itself as the second argument.
令人惊奇的是,只有G和L是正确的。在SLF4J中A和B编译不通过,其他的不会打印异常调用栈的信息或者打印一些不合理的消息。例如,E将不会提供任何异常信息包括调用栈信息。
10) Logs easy to read, easy to parse
10) 日志要容易阅读,容易解析
There are two groups of receivers particularly interested in your application logs: human beings (you might disagree, but programmers belong to this group as well) and computers (typically shell scripts written by system administrators). Logs should be suitable for both of these groups. If someone looking from behind your back at your application logs sees (source Wikipedia):
有两种人会对你的系统日志感兴趣:人类(你可能不同意,但是程序员也属于这类人)和计算机(尤其是系统管理员写的shell脚本)。日志应该对这两组人都试用。
then you probably have not followed my tips. Logs should be readable and easy to understand just like the code should.
On the other hand, if your application produces half GB of logs each hour, no man and no graphical text editor will ever manage to read them entirely. This is where old-school grep, sed and awk come in handy. If it is possible, try to write logging messages in such a way, that they could be understood both by humans and computers, e.g. avoid formatting of numbers, use patterns that can be easily recognized by regular expressions, etc. If it is not possible, print the data in two formats:
日志应该容易被阅读和理解,应该和你的代码一样。
另一方面,如果你的程序每小时500M的之日,没有人并且没有文本编辑器能够编辑这个文档,这个时候我们要用grep,sed,awk了。如果可以,日志应该同时被人和计算机理解,使用能够被正则表达式解析的格式等,如果不能,那就用这两种方式:
log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);
// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)
final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);
log.info("Importing took: {}ms ({})", durationMillis, duration);
//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds)
Computers will appreciate “ms after 1970 epoch” time format, while people would be delighted seeing “1 day 10 hours 17 minutes 36 seconds” text. BTW take a look at DurationFormatUtils,nice tool.
计算机会很欢迎 “ms after 1970 epoch”格式,人们会很高兴看到“1 day 10 hours 17 minutes 36 seconds“格式。看一DurationFormatUtils一个很好的工具。
That’s all guys, a “logging tips extravaganza” from our JCP partner, Tomasz Nurkiewicz. Don’t forget to share!
原文地址:
http://www.javacodegeeks.com/2011/01/10-tips-proper-application-logging.html
(NOTE: The original posts have been slightly edited to improve readability)
我们最近的JCP(JAVA code Geek) 小伙伴们已经写了很多描述程序合理记录日志的基本原则,我发现它们非常有趣,所以我决定把他们写的总结成一个更紧凑合理的格式给大家,下面是一些他们关于日志的一些建议:
1) Use the appropriate tools for the job
Many programmers seem to forget how important is logging an application’s behavior and its current activity. When somebody puts:
1)使用合适的工具
许多程序员好像忘了在系统中记录程序的行为和系统当前的活动,当有人写到:
log.info("Happy and carefree logging");
happily somewhere in the code, he probably doesn’t realize the importance of application logs during maintenance, tuning and failure identification. Underestimating the value of good logs is a terrible mistake.
In my opinion, SLF4J is the best logging API available, mostly because of a great pattern substitution support:
他可能没有意识到程序日志在维护,调优,错误标识的重要性,低估了记录好日志的重要性是一个可怕的错误。
我认为,SLF4J是现有最好的日志API,主要是因为它强大的模式替换。
log.debug("Found {} records matching filter: '{}'", records, filter);
In Log4j you would have to use:
如果用log4j你会写到:
log.debug("Found " + records + " records matching filter: '" + filter + "'");
This is not only longer and less readable, but also inefficient because of extensive use of string concatenation. SLF4J adds a nice {} substitution feature. Also, because string concatenation is avoided and toString() is not called if the logging statement is filtered, there is no need for isDebugEnabled() anymore. BTW, have you noticed single quotes around filter string parameter?
这不紧长,不容易阅读,而且效率地下因为大量的字符串的拼接。SLF4J 添加了一个漂亮的{}符号来置换变量的功能。而且,如果日志被过滤的话就不会对字符串进行拼接和调用toString()方法,isDebugEnabled()这个方法就没有用处了。顺便,你注意到filter字符串两边的单括号了吗?
SLF4J is just a façade. As an implementation I would recommend the Logback framework, already advertised, instead of the well established Log4J. It has many interesting features and, in contrary to Log4J, is actively developed.
SLF4J紧紧是个入门,就使用而言,我会推荐 Logback 框架,而不是log4j。它有很多有趣的功能而且和Log4j相反,它正在被活跃的开发当中。
The last tool to recommend is Perf4J. To quote their motto:
Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()
最后要推荐的是Perf4j,引用他们的座右铭:
如果Log4j是System.out.println(),Perf4J 就是 System.currentTimeMillis()
I’ve added Perf4J to one existing application under heavy load and seen it in action in few other. Both administrators and business users were impressed by the nice graphs produced by this simple utility. Also we were able to discover performance flaws in no time. Perf4J itself deserves its own article, but for now just check their Developer Guide.
我已经讲Perf4J用到了一个负载较重的项目当中观察它的表现。管理员和商业客户都都这个小工具产生的漂亮的图表印象深刻。
Additionally, note that Ceki Gülcü (founder of the Log4J, SLF4J and Logback projects) suggested a simple approach to get rid ofcommons-logging dependency (see his comment).
此外,留意Ceki Gülcü ( Log4J, SLF4J and Logback 项目的创始人) 一个简单的摆脱commons-logging 依赖(see his comment).的建议。
2) Don’t forget, logging levels are there for you
2)不要忘记日志的级别
Every time you make a logging statement, you think hard which logging level is appropriate for this type of event, don’t you? Somehow 90% of programmers never pay attention to logging levels, simply logging everything on the same level, typically INFO or DEBUG. Why? Logging frameworks have two major benefits over System.out., i.e. categories and levels. Both allow you to selectively filter logging statements permanently or only for diagnostics time. If you really can’t see the difference, print this table and look at it every time you start typing “log.” in your IDE:
每次你写一个log的时候,你很难决定那个级别对这个日志比较合适,对吗?不管怎样,90%的程序员从来不关心日志的级别,简单的用同样的日志级别打印日志,通常是INFO或者DEBUG,为什么呢?日志框架跟System.out相比有两个主要的好处,一个是分类,一个是级别。两者都允许你设置filter来过滤日志。
ERROR – something terribly wrong had happened, that must be investigated immediately. No system can tolerate items logged on this level. Example: NPE, database unavailable, mission critical use case cannot be continued.
ERROR-一些严重的错误发生的时候,必须马上研究原因的日志。没有任何系统能够忍受这种级别的日志。例如:数据库不能访问,关键流程失败。
WARN – the process might be continued, but take extra caution. Actually I always wanted to have two levels here: one for obvious problems where work-around exists (for example: “Current data unavailable, using cached values”) and second (name it: ATTENTION) for potential problems and suggestions. Example: “Application running in development mode” or “Administration console is not secured with a password”. The application can tolerate warning messages, but they should always be justified and examined.
WARN—— 进程可以持续,但是需要引起注意。事实上,我总是想用两种级别在这:一种是明显的但是有应急方案的问题。(例如:“当前数据不可用,可以使用缓存的数据”)第二种是可能有潜在错误。例如:程序运行在开发模式。管理控制台没有密码保护。
INFO – Important business process has finished. In ideal world, administrator or advanced user should be able to understand INFO messages and quickly find out what the application is doing. For example if an application is all about booking airplane tickets, there should be only one INFO statement per each ticket saying “[Who] booked ticket from [Where] to [Where]“. Other definition of INFO message: each action that changes the state of the application significantly (database update, external system request).
INFO- 重要的业务流程已经完成。理想的话,管理员和高级用户以你更改能够理解INFO 的日志输出并且能够快速的找出应用程序正在做什么。例如如果程序是关于预定机票的话,对每一个预定的机票应该输出“谁”预定了机票从“哪儿”到“哪儿”。其他一些INFO日志:每一个改变应用程序状态的重要动作都应该记录(数据库更新,外部系统请求等)
DEBUG – Developers stuff. I will discuss later what sort of information deserves to be logged.
DEBUG - 开发者的东西。后面我会谈到什么想的信息应该被记录
TRACE – Very detailed information, intended only for development. You might keep trace messages for a short period of time after deployment on production environment, but treat these log statements as temporary, that should or might be turned-off eventually. The distinction between DEBUG and TRACE is the most difficult, but if you put logging statement and remove it after the feature has been developed and tested, it should probably be on TRACE level.
TRACE --所有的详细信息,紧紧为了开发。项目部署之后短时间之内可能会打开这些信息,但是最后必须得关闭这些日志的输出。DEBUG和TRACE的确不容易区分,但是如果你想在开发的时候打出一些日志,开发完成之后删除它,你应该选择TRACE。
The list above is just a suggestion, you can create your own set of instructions to follow, but it is important to have some. My experience is that always everything is logged without filtering (at least from the application code), but having the ability to quickly filter logs and extract the information with proper detail level, might be a life-saver.
上面这些是我的一些建议,你可以根据自己的需要简历自己的使用原则。我的经验是总是打印所有的日志,但是能够快速的过滤和摘取需要的日志。
The last thing worth mentioning is the infamous is*Enabled() condition. Some put it before every logging statement:
最后值得提一提是Enabled() 选项,有些总是把他放到输出日志的前面:
if(log.isDebugEnabled())
log.debug("Place for your commercial");
Personally, I find this idiom being just clutter that should be avoided. The performance improvement (especially when using SLF4Jpattern substitution discussed previously) seems irrelevant and smells like a premature optimization. Also, can you spot the duplication? There are very rare cases when having explicit condition is justified – when we can prove that constructing logging message is expensive. In other situations, just do your job of logging and let logging framework do its job (filtering).
就我个人二千,我发现这样的写法只能造成混乱,应该避免使用。
3) Do you know what you are logging?
3)你知道你在打什么日志吗?
Every time you issue a logging statement, take a moment and have a look at what exactly will land in your log file. Read your logs afterwards and spot malformed sentences. First of all, avoid NPEs like this:
每次你打印日志的时候,花点时间看看你的日志文件会真正的输出什么,首先不要这么写:
log.debug("Processing request with id: {}", request.getId());
Are you absolutely sure that request is not null here?
Another pitfall is logging collections. If you fetched collection of domain objects from the database using Hibernate and carelessly log them like here:
你确定request不是null ?
另一个陷阱是打印集合。如果你用Hibernate从数据库查询记录存在集合里并输出到日志:
log.debug("Returning users: {}", users);
SLF4J will call toString() only when the statement is actually printed, which is quite nice. But if it does… Out of memory error, N+1 select problem, thread starvation (logging is synchronous!), lazy initialization exception, logs storage filled completely – each of these might occur.
SLF4J只有输出日志的时候才会调用toString()。但是,如果它内存溢出了,N+1 select 问题,线程饥饿,延迟加载,日志会自动填满。
It is a much better idea to log, for example, only ids of domain objects (or even only size of the collection). But making a collection of ids when having a collection of objects having getId() method is unbelievably difficult and cumbersome in Java. Groovy has a great spread operator (users*.id), in Java we can emulate it using the Commons Beanutils library:
一个好的记录日志的方法是,比如紧紧打印对象的ID,或着紧紧是集合的SIZE。但是当你得到一个对象的集合每次来调用getId()来得到id的集合会很不方便。Groovy有一个好的框架可以使用(users*.id),java中我们可以用Commons Beanutils :
log.debug("Returning user ids: {}", collect(users, "id"));
Where collect() method can be implemented as follows:
collect()方法可以这么实现:
public static Collection collect(Collection collection, String propertyName) {
return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));
}
The last thing to mention is the improper implementation or usage of toString(). First, create toString() for each class that appears anywhere in logging statements, preferably using ToStringBuilder (but not its reflective counterpart). Secondly, watch out for arrays and non-typical collections. Arrays and some strange collections might not have toString() implemented calling toString() of each item. UseArrays #deepToString JDK utility method. And read your logs often to spot incorrectly formatted messages.
最后要提的是toString()不正确的使用方法和实现。首先,创建一个toString()方法为每一个出现在日志输出语句的class中。可以使用
ToStringBuilder 。第二,小心那些数组和非典型的集合。数组和一些集合可能没有实现toString()方法。可以使用Arrays #deepToString JDK工具方法,并且经常读下你的日志,找出不合理的地方。
4) Avoid side effects
4)避免副作用
Logging statements should have no or little impact on the application’s behavior. Recently a friend of mine gave an example of a system that threw Hibernates’ LazyInitializationException only when running on some particular environment. As you’ve probably guessed from the context, some logging statement caused lazy initialized collection to be loaded when session was attached. On this environment the logging levels were increased and collection was no longer initialized. Think how long would it take you to find a bug without knowing this context?
输出日志的语句应该对系统没有或者有很小行为上的影响。有一个朋友提供了一个系统在一些情况下会抛出Hibernates’ LazyInitializationException 异常的例子。或许你已经猜到,一些日志输出语句导致了延迟加载的集合被加载。在这种情况下,当调整日志级别的时候就不会有这种问题,但是如果不知道这中情况的话你得花多上时间去找这个bug呢?
Another side effect is slowing the application down. Quick answer: if you log too much or improperly use toString() and/or string concatenation, logging has a performance side effect. How big? Well, I have seen server restarting every 15 minutes because of a thread starvation caused by excessive logging. Now this is a side effect! From my experience, few hundreds of MiB is probably the upper limit of how much you can log onto disk per hour.
另一个副作用是会让系统变得很慢。答案:如果你打印太多日志或者错误的使用toString() 或者字符串拼接,输出日志就会有负面影响。多大呢?我看过服务器没15分钟重启一次就是应为大量日志导致的线程饥饿。
Of course if logging statement itself fails and causes business process to terminate due to exception, this is also a huge side effect. I have seen such a construct to avoid this:
当然如果打印日志的语句 本身导致业务流程终端抛出异常,这也是一个很大的负面影响。我看到过这么写去避免这种问题的:
try {
log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())
}
This is a real code, but please make the world a bit better place and don’t do it, ever.
还真有人这么写,不过为了让世界更美好还是别这么写的好啊
5) Be concise and descriptive
5)简洁并具有描述性
Each logging statement should contain both data and description. Consider the following examples:
每一个日志输出语句应该都包含数据和描述,看一下下面的例子:
log.debug("Message processed");
log.debug(message.getJMSMessageID());
log.debug("Message with id '{}' processed", message.getJMSMessageID());
Which log would you like to see while diagnosing failure in an unknown application? Believe me, all the examples above are almost equally common. Another anti-pattern:
当你调试系统错误的时候你更喜欢看到哪中日志呢?相信我,上面的例子非常常见。另一个反面的例子:
if(message instanceof TextMessage)
//...
else
log.warn("Unknown message type");
Was it so hard to include thee actual message type, message id, etc. in the warning string? I know something went wrong, but what? What was the context?
在日志里加上消息类型,消息ID就这么难吗?我知道程序发生了错误,但是在什么环境下发生的呢?
A third anti-pattern is the “magic-log”. Real life example: most programmers in the team knew that 3 ampersands followed by exclamation mark, followed by hash, followed by pseudorandom alphanumeric string log means “Message with XYZ id received”. Nobody bothered to change the log, simply someone hit the keyboard and chose some unique “&&&!#” string, so that it can be easily found by himself.
第三个反面的日志模式是“魔术日志”。真实的例子,好多team中的程序员用一些特殊的符号,比如&!#来标识“收到了消息”,这样他自己就能方便的找到。
As a consequence, the whole logs file looks like a random sequence of characters. Somebody might even consider that file to be a validPerl program. Instead, a log file should be readable, clean and descriptive. Don’t use magic numbers, log values, numbers, ids and include their context. Show the data being processed and show its meaning. Show what the program is actually doing. Good logs can serve as a great documentation of the application code itself.
结果是,日志看起来就像是一些随机的字符串。一些人还会以为是一个Perl程序呢。相反,一个日志文件应该很容易的被阅读,整洁并具有描述性。不要使用那些神秘的字符,要记录那些值,数字,id,还有上下文环境。记录那些数据正在被处理,还有这些数据的意思。记录程序正在做什么。好的日志能够作为程序代码一个好的文档。
Did I mention not to log passwords and any personal information? Don’t!
我提到不要记录密码信息和任何私人的信息了吗?千万不要这么做啊,会死人的!
6) Tune your pattern
6)调整你的日志格式
Logging pattern is a wonderful tool, that transparently adds a meaningful context to every logging statement you make. But you must consider very carefully which information to include in your pattern. For example, logging date when your logs roll every hour is pointless as the date is already included in the log file name. On the contrary, without logging the thread name you would be unable to track any process using logs when two threads work concurrently – the logs will overlap. This might be fine in single-threaded applications – that are almost dead nowadays.
日志格式一个很好的工具,他很明显的为没一条日志添加了一个有意思的上下文环境。但是你必须细心的考虑到哪些日志应该应用你的日志格式。例如:当你的日志每一个小时生成一个文件的时候你在日志里记录时间是没有意义的,因为文件名中已经有时间了。相反,当2个线程并发执行的时候你没有记录线程的名字你是不能跟踪每一个线程的活动的-日志会有重叠。单线程的程序没有这个问题——但是貌似现在很少有单线程的系统啊
From my experience, the ideal logging pattern should include (of course except the logged message itself): current time (without date, milliseconds precision), logging level, name of the thread, simple logger name (not fully qualified) and the message. In Logback it is something like:
跟我我的经验,理想的日志模式应该包括:当前的时间(排除日期,毫秒的精度),日志的级别,线程名,日志名,还有消息内容。在 Logback 中:
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%logger{0}] %m%n</pattern>
</encoder>
</appender>
You should never include file name, class name and line number, although it’s very tempting. I have even seen empty log statements issued from the code:
你不应该包含文件名,类名和行数尽管它很诱人。我看见过代码中空的日志记录语句:
log.info("");
because the programmer assumed that the line number will be a part of the logging pattern and he knew that “If empty logging message appears in 67th line of the file (in authenticate() method), it means that the user is authenticated”. Besides, logging class name, method name and/or line number has a serious performance impact.
因为程序员以为行数会是日志的一部分,他知道,“如果日志出现在67行,意味着这个用户验证通过”。此外,在日志中记录类名,方法名或者行数会对程序性能有很大的影响。
A somewhat more advanced feature of a logging frameworks is the concept of Mapped Diagnostic Context. MDC is simply a map managed on a thread-local basis. You can put any key-value pair in this map and since then every logging statement issued from this thread is going to have this value attached as part of the pattern.
一个更高级的日志框架的功能是 MDC的概念,它是一个简单的基于线程的map。你可以放任务key-value对到这个map,然后所有的日志跟这个线程有关的就会有他的值来作为日志的一部分。MDC用法参见:http://logback.qos.ch/manual/mdc.html
7) Log method arguments and return values
7)日志方法的参数和返回值
When you find a bug during development, you typically run a debugger trying to track down the potential cause. Now imagine for a while that you can’t use a debugger. For example, because the bug manifested itself on a customer environment few days ago and everything you have is logs. Would you be able to find anything in them?
当你开发的时候发现一个bug,你会debug一下看一看有什么潜在的问题。考虑一下,如果不能使用debug功能。例如:这个bug在客户环境几天之前发生,你就只能看log了。你能在log里找到你要的信息吗?
If you follow the simple rule of logging each method input and output (arguments and return values), you don’t even need a debugger any more. Of course, you must be reasonable but every method that: accesses external system (including database), blocks, waits, etc. should be considered. Simply follow this pattern:
如果你遵循简单的规则,记录每一个方法的输入和输出(参数和返回值),你甚至都不需要去debug了。当然,你应该合理并且每一个方法:访问外部系统(包括数据库),block,等待。。。都应该考虑。看下下面的格式:
public String printDocument(Document doc, Mode mode) {
log.debug("Entering printDocument(doc={}, mode={})", doc, mode);
String id = //Lengthy printing operation
log.debug("Leaving printDocument(): {}", id);
return id;
}
Because you are logging both the beginning and the end of method invocation, you can manually discover inefficient code and even detect possible causes of deadlocks and starvation – simply by looking after “entering” without corresponding “leaving”. If your methods have meaningful names, reading logs would be a pleasure. Also, analyzing what went wrong is much simpler, since on each step you know exactly what has been processed. You can even use a simple AOP aspect to log a wide range of methods in your code. This reduces code duplication, but be careful, since it may lead to enormous amount of huge logs.
因为你在记录方法调用的开始和结束,你就能够发现效率地下的代码和发现可能的线程死锁和线程饥饿---简单的看下“entering”之后有没有“leaving”被打印出来。如果你的方法有一个有意义的名字,读Log的时候会很方便。而且,分析什么是发生了错误会很简单,因为你知道每一步都在处理什么。你甚至可以使用简单的AOP面向横切面的方式去记录你代码中的各种方法。这样会减少代码重复,但是小心,这回产生大量的日志。
You should consider DEBUG or TRACE levels as best suited for these types of logs. And if you discover some method are called too often and logging might harm performance, simply decrease logging level for that class or remove the log completely (maybe leaving just one for the whole method invocation?) But it is always better to have too much rather than too few logging statements. Treat logging statements with the same respect as unit tests – your code should be covered with logging routines as it is with unit tests. No part of the system should stay with no logs at all. Remember, sometimes observing logs rolling by is the only way to tell whether your application is working properly or hangs forever.
你应该考虑用DEBUG或者TRACE 对于这种类型的日志。还有,如果你发现一些方法被调用比较频繁并且会影响性能,可以降低日志的级别或者直接删除这条日志。但是一般日志多总是会比日志少要好。单元测试的日志应该同样的别对待---你的代码里应该充斥着日志输出的代码,测试代码也一样。没有一个系统应该不输出日志。请记住,观察滚动的日志有时候会是判断程序正常或者被挂唯一的方式。
8) Watch out for external systems
8)关注那些外部系统
This is the special case of the previous tip: if you communicate with an external system, consider logging every piece of data that comes out from your application and gets in. Period. Integration is a tough job and diagnosing problems between two applications (think two different vendors, environments, technology stacks and teams) is particularly hard. Recently, for example, we’ve discovered that logging full messages contents, including SOAP and HTTP headers in Apache CXF web services is extremely useful during integration and system testing.
跟之前的建议相比,这是一个特殊的例子:如果你跟一个外部的系统有交互,一定要考虑用日志记录从你系统进入和流出的数据。集成是一项困难的工作并且在两个不通厂家不同环境的系统中诊断系统问题就更困难了。目前,例如:我们讨论到记录所有的Apache CXF 消息体包括SOAP和HTTP 头在集成和系统测试中是非常有用的。
This is a big overhead and if performance is an issue, you can always disable logging. But what is the point of having a fast, but broken application, that no one can fix? Be extra careful when integrating with external systems and prepare to pay that cost. If you are lucky and all your integration is handled by an ESB, then the bus is probably the best place to log every incoming request and response. See for example Mules’ log-component.
这是一个很大的开销,如果遇到性能问题可以关闭日志。但是如果一个运行很快但是崩溃的时候没法修复有什么用呢?当跟外部系统集成的时候一定要小心。
Sometimes the amount of information exchanged with external systems makes it unacceptable to log everything. On the other hand during testing and for a short period of time on production (for example when something wrong is happening), we would like to have everything saved in logs and are ready to pay performance cost. This can be achieved by carefully using logging levels. Just take a look at the following idiom:
有些时候与外部系统大量的信息使得记录全部不能被接受,另一方面,在测试阶段或者系统上线后短时间之内(例如系统出问题了)我们希望能够看到所有的日志记录并且做好性能问题的准备。我们可以利用日志级别去做这件事,看一下下面的例子:
Collection<Integer> requestIds = //...
if(log.isDebugEnabled())
log.debug("Processing ids: {}", requestIds);
else
log.info("Processing ids size: {}", requestIds.size());
If this particular logger is configured to log DEBUG messages, it will print the whole requestIds collection contents. But if it is configured to print INFO messages, only the size of collection will be outputted. If you are wondering why I forgot about isInfoEnabled() condition, go back to tip #2. One thing worth mentioning is that requestIds collection should not be null in this case. Although it will be logged correctly as null if DEBUG is enabled, but big fat NullPointerException will be thrown if logger is configured to INFO. Remember my lesson about side effects in tip #4?
如果日志配置成DEBUG级别,会打印所有的请求的集合信息。如果配置成INFO,只会打印集合的SIZE。
9) Log exceptions properly
9)合理的记录异常信息
First of all, avoid logging exceptions, let your framework or container (whatever it is) do it for you. There is one, ekhem, exception to this rule: if you throw exceptions from some remote service (RMI, EJB remote session bean, etc.), that is capable of serializing exceptions, make sure all of them are available to the client (are part of the API). Otherwise the client will receive NoClassDefFoundError: SomeFancyException instead of the “true” error.
首先,避免写异常信息的日志,让框架活着容器来做这件事。记录异常的一条规则:如果你抛出的异常要给远端的服务器,例如(RMI,EJB),可以讲异常序列化保证你的异常被其他的客户端收到,否则客户端将收到NoClassDefFoundError
Logging exceptions is one of the most important roles of logging at all, but many programmers tend to treat logging as a way to handle the exception. They sometimes return default value (typically null, 0 or empty string) and pretend that nothing has happened. Other times they first log the exception and then wrap it and throw it back:
记录异常日志是记录日志中最重要的,但是好多程序员将日志作为处理异常的方式。他们有时候返回缺省值(null,0或者空字符)假装什么都没发生。有时候他们首先打印出日志然后抛出去
log.error("IO exception", e);
throw new MyCustomException(e);
This construct will almost always print the same stack trace two times, because something will eventually catch MyCustomException and log its cause. Log, or wrap and throw back (which is preferable), never both, otherwise your logs will be confusing.
But if we really do WANT to log the exception? For some reason (because we don’t read APIs and documentation?), about half of the logging statements I see are wrong. Quick quiz, which of the following log statements will log the NPE properly?
上面的语句将会打印2次同样的Log,但是有时候将会捕获自己定义的异常并且记录下来。遇到异常是记录日志,封装然后再跑出去呢?不要两个都做,否则日志会很乱。
但是如果我们想记录这些异常应该怎么做呢?看下下面的例子那一个更合适呢?
try {
Integer x = null;
++x;
} catch (Exception e) {
log.error(e); //A
log.error(e, e); //B
log.error("" + e); //C
log.error(e.toString()); //D
log.error(e.getMessage()); //E
log.error(null, e); //F
log.error("", e); //G
log.error("{}", e); //H
log.error("{}", e.getMessage()); //I
log.error("Error reading configuration file: " + e); //J
log.error("Error reading configuration file: " + e.getMessage()); //K
log.error("Error reading configuration file", e); //L
}
Surprisingly, only G and preferably L are correct! A and B don’t even compile in SLF4J, others discard stack traces and/or print improper messages. For example, E will not print anything as NPE typically doesn’t provide any exception message and the stack trace won’t be printed as well. Remember, the first argument is always the text message, write something about the nature of the problem. Don’t include exception message, as it will be printed automatically after the log statement, preceding stack trace. But in order to do so, you must pass the exception itself as the second argument.
令人惊奇的是,只有G和L是正确的。在SLF4J中A和B编译不通过,其他的不会打印异常调用栈的信息或者打印一些不合理的消息。例如,E将不会提供任何异常信息包括调用栈信息。
10) Logs easy to read, easy to parse
10) 日志要容易阅读,容易解析
There are two groups of receivers particularly interested in your application logs: human beings (you might disagree, but programmers belong to this group as well) and computers (typically shell scripts written by system administrators). Logs should be suitable for both of these groups. If someone looking from behind your back at your application logs sees (source Wikipedia):
有两种人会对你的系统日志感兴趣:人类(你可能不同意,但是程序员也属于这类人)和计算机(尤其是系统管理员写的shell脚本)。日志应该对这两组人都试用。
then you probably have not followed my tips. Logs should be readable and easy to understand just like the code should.
On the other hand, if your application produces half GB of logs each hour, no man and no graphical text editor will ever manage to read them entirely. This is where old-school grep, sed and awk come in handy. If it is possible, try to write logging messages in such a way, that they could be understood both by humans and computers, e.g. avoid formatting of numbers, use patterns that can be easily recognized by regular expressions, etc. If it is not possible, print the data in two formats:
日志应该容易被阅读和理解,应该和你的代码一样。
另一方面,如果你的程序每小时500M的之日,没有人并且没有文本编辑器能够编辑这个文档,这个时候我们要用grep,sed,awk了。如果可以,日志应该同时被人和计算机理解,使用能够被正则表达式解析的格式等,如果不能,那就用这两种方式:
log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);
// Request TTL set to: Wed Apr 28 20:14:12 CEST 2010 (1272478452437)
final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);
log.info("Importing took: {}ms ({})", durationMillis, duration);
//Importing took: 123456789ms (1 day 10 hours 17 minutes 36 seconds)
Computers will appreciate “ms after 1970 epoch” time format, while people would be delighted seeing “1 day 10 hours 17 minutes 36 seconds” text. BTW take a look at DurationFormatUtils,nice tool.
计算机会很欢迎 “ms after 1970 epoch”格式,人们会很高兴看到“1 day 10 hours 17 minutes 36 seconds“格式。看一DurationFormatUtils一个很好的工具。
That’s all guys, a “logging tips extravaganza” from our JCP partner, Tomasz Nurkiewicz. Don’t forget to share!
原文地址:
http://www.javacodegeeks.com/2011/01/10-tips-proper-application-logging.html
相关推荐
《Linux系统管理员手册》是为Linux系统新手提供的一份详尽的系统管理指南,由Lars Wirzenius撰写,经过赵炯与gohigh@sh163.net的翻译,适用于0.6.1版。这份手册不仅是对Linux系统基础知识的全面介绍,还深入探讨了...
- **事件日志**:记录系统操作的历史记录。 - **文件操作**:包括文件复制、移动、删除等基本操作。 - **FileNet软件管理**:管理安装和配置FileNet软件。 - **索引数据库管理**:维护索引数据库的工具。 - **单文档...
首先,驱动程序是计算机硬件与操作系统之间的桥梁,它翻译并执行硬件设备的指令,使得操作系统能够理解和控制硬件。对于佳能MP288打印机来说,驱动程序是必不可少的,因为它允许电脑识别和配置打印机,执行打印任务...
- **选择规则**:记录日志时,会根据 Logger 的级别以及消息的级别来判断是否应该记录这条日志。 ##### 2.2.4 获取 Logger 通过 `LoggerFactory.getLogger()` 方法获取 Logger 实例。 ##### 2.2.5 Appender 和 ...
例如,当你连接一个打印机时,打印机驱动程序允许操作系统发送打印命令并接收设备的反馈。 Kernel Detective v1.3.0 的汉化版本对于中国用户来说是个好消息,因为它消除了语言障碍,使非英文熟练的用户也能方便地...
因此,本书在阐述时,对部分代码进行了局部重构,简化了异常处理和日志打印,以便更加直接地展示问题的本质,这样做不会影响读者理解TensorFlow的主要行为特征,同时也有利于掌握系统的工作原理。为了简化计算图的...
#### 二十一、系统日志管理 - **日志查询**:支持按用户、模块、时间等多种条件查询日志记录。 - **日志类型**:区分不同类型的日志,如登录日志、操作日志等。 #### 二十二、模块(菜单)管理 - **模块定义**:...
- **打印指南:**说明如何获取和打印纸质版手册。 #### 二、安装篇 **2.1 如何获得KDevelop** - **官方渠道:**指导用户通过官方网站下载软件。 - **第三方平台:**列出了一些可信的第三方平台,便于用户获取。 *...
Burleson 编写,turner 翻译为中文版,内容涵盖了 Unix 命令、服务器环境、进程管理、内存和 CPU 管理、服务器监控、文件管理和磁盘管理等重要主题。 #### 二、构建 Unix 命令 本书首先介绍了如何构建 Unix 命令,...
37. **--sysinfo**:打印系统诊断信息,有助于调试和性能优化。 38. **--upgrade**:如果需要,升级数据库。 39. **Replication 参数**: - **--fastsync**:用于从已有的数据快照快速启动从库。 - **--...
### 编写优质无错C程序的核心技巧与实践 ...通过遵循书中的原则和建议,我们可以构建出更加健壮、可靠且易于维护的软件系统。无论是对于初学者还是经验丰富的开发者来说,这本书都是不可或缺的宝贵资源。
- 一个简单的模块,仅包含打印消息到内核日志的功能。 - 使用`printk()`函数实现。 - **编译模块**: - 需要配置内核支持模块编译。 - 使用`make`命令编译模块。 - **模块文档**: - 模块应该包含必要的文档,...
如果以商业方式出版或分发此书,建议向作者及Linux文档项目(Linux Documentation Project, LDP)捐赠、支付版税或提供印刷副本作为支持。 #### 三、章节概览 - **前言**:简要介绍了本书的编写背景和目的。 - **第...
在Linux和Unix系统中,文本处理是一项常见的需求。其中,`sed`(stream editor)和`awk`是两款非常强大的文本处理工具,它们不仅功能强大而且极其灵活。本文将详细介绍这两款工具的基础知识以及一些高级用法,帮助...
《你必须知道的495个C语言问题》是一份由Steve Summit编写的详尽的C语言编程指南,经过朱群英和孙云的翻译,修订版为0.9.4,出版于2005年6月23日。这份文档通过一系列问题解答的形式,覆盖了C语言的基础到高级概念,...