https://blog.csdn.net/kobejayandy/article/details/17335215
html
作一个苦逼的Java攻城师, 咱们除了关心系统的架构这种high level的问题, 还须要了解一些语言的陷阱, 异常的处理, 以及日志的输出, 这些"鸡毛蒜皮"的细节. 这篇文章是JCP成员, Tomasz Nurkiewicz(http://nurkiewicz.blogspot.com/ )总结的10条如何正确使用日志的技巧(参见原文). 跟那篇"java编程最差实践"同样, 也是针对一些细节的, 由于日志是咱们排查问题, 了解系统情况的重要线索. 我以为对咱们日常coding很是有借鉴意义. 因此转换成中文, 加深一下印象, 也做为本身工做的一个参考.java
1)选择正确的Log开源框架
在代码中为了知道程序的行为的状态, 咱们通常会打印一条日志:
- log.info("Happy and carefree logging");
在全部的日志框架中, 我认为最好的是SLF4J. 好比在Log4J中咱们会这样写:
- log.debug("Found " + records + " records matching filter: '" + filter + "'");
而在SLF4J中咱们会这样写:
- log.debug("Found {} records matching filter: '{}'", records, filter);
从可读性和系统效率来讲, SLF4J(
http://logback.qos.ch/ )比Log4J都要优秀(Log4J涉及到字符串链接和toString()方法的调用). 这里的{}带来的另外一个好处, 咱们在尽可能不损失性能的状况, 没必要为了避免同的日志输出级别, 而加上相似isDebugEnabled()判断.
SLF4J只是各类日志实现的一个接口抽象(facade), 而最佳的实现是Logback, 相对于Log4J的同门兄弟(皆出自Ceki Gülcü之手), 它在开源社区的活跃度更高.
最后要推荐的是Perf4J(
http://perf4j.codehaus.org/ ). 用一句话来归纳就是:
若是把log4j看作System.out.println()的话, 那么Perf4J就是System.currentTimeMillis()
Perf4J能够帮助咱们更方便的输出系统性能的日志信息. 而后借助其余报表工具将日志以图表的形式加以展示, 从而方便咱们分析系统的性能瓶颈. 关于Perf4J的使用能够参考它的开发者指南(
http://perf4j.codehaus.org/devguide.html).
下面是一份关于日志jar包依赖的pom.xml参考模板:
- <repositories>
- <repository>
- <id>Version99</id>
- <name>Version 99 Does Not Exist Maven repository</name>
- <layout>default</layout>
- <url>http://no-commons-logging.zapto.org/mvn2</url>
- </repository>
- </repositories>
-
-
- <dependency>
- <groupId>org.slf4j</groupId>
- <artifactId>slf4j-api</artifactId>
- <version>1.5.11</version>
- </dependency>
- <dependency>
- <groupId>ch.qos.logback</groupId>
- <artifactId>logback-classic</artifactId>
- <version>0.9.20</version>
- </dependency>
- <dependency>
- <groupId>org.slf4j</groupId>
- <artifactId>jul-to-slf4j</artifactId>
- <version>1.5.11</version>
- </dependency>
- <dependency>
- <groupId>org.slf4j</groupId>
- <artifactId>log4j-over-slf4j</artifactId>
- <version>1.5.11</version>
- </dependency>
- <dependency>
- <groupId>org.slf4j</groupId>
- <artifactId>jcl-over-slf4j</artifactId>
- <version>1.5.11</version>
- </dependency>
- <dependency>
- <groupId>commons-logging</groupId>
- <artifactId>commons-logging</artifactId>
- <version>99.0-does-not-exist</version>
- </dependency>
下面是测试代码:
- SLF4JBridgeHandler.install();
-
- org.apache.log4j.Logger.getLogger("A").info("Log4J");
- java.util.logging.Logger.getLogger("B").info("java.util.logging");
- org.apache.commons.logging.LogFactory.getLog("C").info("commons-logging");
- org.slf4j.LoggerFactory.getLogger("D").info("Logback via SLF4J");
上面的代码, 不管你采用哪一个log框架输出日志, 底层采用的都是logback, 至于为何, 能够看这里(
http://www.slf4j.org/legacy.html), 另外这里为了在classpath里面不引入common-logging, 用了一个小技巧, 就是将依赖版本设置为99.0-does-not-exist, 关于这种用法的说明能够看这里(
http://day-to-day-stuff.blogspot.com/2007/10/announcement-version-99-does-not-exist.html), 不过log4j的做者认为最简单的作法就是直接去掉对common-logging的依赖, 相关内容能够看这里的说明(
http://www.slf4j.org/faq.html#excludingJCL)
2) 理解正确的日志输出级别
不少程序员都忽略了日志输出级别, 甚至不知道如何指定日志的输出级别. 相对于System.out来讲, 日志框架有两个最大的优势就是能够指定输出类别(category)和级别(level). 对于日志输出级别来讲, 下面是咱们应该记住的一些原则:
ERROR:系统发生了严重的错误, 必须立刻进行处理, 不然系统将没法继续运行. 好比, NPE, 数据库不可用等.
WARN:系统能继续运行, 可是必须引发关注. 对于存在的问题通常能够分为两类: 一种系统存在明显的问题(好比, 数据不可用), 另外一种就是系统存在潜在的问题, 须要引发注意或者给出一些建议(好比, 系统运行在安全模式或者访问当前系统的帐号存在安全隐患). 总之就是系统仍然可用, 可是最好进行检查和调整.
INFO:重要的业务逻辑处理完成. 在理想状况下, INFO的日志信息要能让高级用户和系统管理员理解, 并从日志信息中能知道系统当前的运行状态. 好比对于一个机票预订系统来讲, 当一个用户完成一个机票预订操做以后, 提醒应该给出"谁预订了从A到B的机票". 另外一个须要输出INFO信息的地方就是一个系统操做引发系统的状态发生了重大变化(好比数据库更新, 过多的系统请求).
DEBUG:主要给开发人员看, 下面会进一步谈到.
TRACE: 系统详细信息, 主要给开发人员用, 通常来讲, 若是是线上系统的话, 能够认为是临时输出, 并且随时能够经过开关将其关闭. 有时候咱们很难将DEBUG和TRACE区分开, 通常状况下, 若是是一个已经开发测试完成的系统, 再往系统中添加日志输出, 那么应该设为TRACE级别.
以上只是建议, 你也能够创建一套属于你本身的规则. 可是一套良好的日志系统, 应该首先是能根据状况快速灵活的调整日志内容的输出.
最后要提到的就是"臭名昭著"的is*Enabled()条件, 好比下面的写法:
- if(log.isDebugEnabled())
- log.debug("Place for your commercial");
这种作法对性能的提升几乎微乎其微(前面在提到SLF4J的时候已经说明), 并且是一种过分优化的表现. 极少状况下须要这样写, 除非构造日志信息很是耗性能. 最后必须记住一点: 程序员应该专一于日志内容, 而将日志的输出的决定权交给日志框架去非处理.
3) 你真的知道log输出的内容吗?
对于你输出的每一条log信息, 请仔细检查最终输出的内容是否存在问题, 其中最重要的就是避免NPE, 好比想下面这样:
- log.debug("Processing request with id: {}", request.getId());
这里咱们可否保证request不为null? 除了NPE以外, 有时候咱们可能还须要考虑, 是否会致使OOM? 越界访问? 线程饥饿(log是同步的)? 延迟初始化异常? 日志打爆磁盘等等. 另一个问题就是在日志中输出集合(collection), 有时候咱们输出的集合内容多是由Hibernate从数据库中取出来的, 好比下面这条日志信息:
- log.debug("Returning users: {}", users);
这里最佳的处理方式是仅仅输出domain对象的id或者集合的大小(size), 而对Java来讲, 不得不要吐槽几句, 要遍历访问集合中每个元素的getId方法很是繁琐. 这一点Groovy就作的很是简单(users*.id), 不过咱们能够借助Commons Beanutils工具包来帮咱们简化:
- log.debug("Returning user ids: {}", collect(users, "id"));
这里的collect方法的实现以下:
- public static Collection collect(Collection collection, String propertyName) {
- return CollectionUtils.collect(collection, new BeanToPropertyValueTransformer(propertyName));
- }
不过不幸的是, 在给Commons Beanutils提了一个patch(BEANUTILS-375
https://issues.apache.org/jira/browse/BEANUTILS-375)以后, 并无被接受:(
最后是关于toString()方法. 为了让日志更容易理解, 最好为每个类提供合适的toString()方法. 这里能够借助ToStringBuilder工具类. 另一个就是关于数组和某些集合类型. 由于数组是使用的默认的toString方法. 而某些集合没有很好的实现toString方法. 对于数组咱们可使用JDK的Arrays.deepToString()方法(
http://docs.oracle.com/javase/6/docs/api/java/util/Arrays.html#deepToString%28java.lang.Object[]%29).
4) 当心日志的反作用
有时候日志或多或少的会影响系统的行为, 好比最近碰到的一个状况就是在某些条件下, Hibernate会抛出LazyInitializationException. 这是由于某些输出日志致使延迟初始化的集合在session创建时被加载. 而在某些场景下当提升日志输出级别时, 问题就会消失.
另外一个反作用就是日志致使系统运行愈来愈慢. 好比不恰当的使用toString方法或者字符串链接, 使得系统出现性能问题, 曾经碰到的一个现象, 某个系统每隔15分钟重启一次, 这个主要是执行log输出出现线程饥饿致使, 通常状况下, 若是一个系统一小时内生成的日志有几百MB的时候, 就要当心了.
而若是由于日志输出自己的问题致使正常的业务逻辑被中断, 那就更严重了. 好比下面这种代码, 最好不要这样写:
- try {
- log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())
- } catch(NullPointerException e) {}
5) 日志信息应该简洁且可描述
通常, 每一条日志数据会包括描述和上下文两部分, 好比下面的日志:
- log.debug("Message processed");
- log.debug(message.getJMSMessageID());
-
- log.debug("Message with id '{}' processed", message.getJMSMessageID());
第一条只有描述, 第二条只有上下文, 第三条才算完整的一条日志, 还有下面这种日志:
- if(message instanceof TextMessage)
-
- else
- log.warn("Unknown message type");
在上面的警告日志中没有包含实际的message type, message id等信息, 只是代表程序有问题, 那么是什么致使了问题呢? 上下文是什么? 咱们什么都不知道.
另一个问题就是在日志中加上一个莫名其妙的内容, 即所谓的"magic log". 好比有些程序员会在日志中随手敲上"&&&!#"这样一串字符, 用来帮助他们定位.
一个日志文件中的内容应该易读, 清晰, 可描述. 而不要使用莫名其妙的字符, 日志要给出当前操做作了什么, 使用的什么数据. 好的日志应该被当作文档注释的一部分.
最后一点, 切记不要在日志中包含密码和我的隐私信息!
6) 正确的使用输出模式
log输出模式能够帮助咱们在日志中增长一些清晰的上下文信息. 不过对添加的信息仍是要多加当心. 好比说, 若是你是每小时输出一个文件, 这样你的日志文件名中已经包含了部分日期时间信息, 所以就不必在日志中再包含这些信息. 另外在多线程环境下也不要在本身在日志中包含线程名称, 由于这个也能够在模式中配置.
根据个人经验, 一个理想的日志模式将包含下列信息:
- 当前时间(不须要包含日志, 精确到毫秒)
- 日志级别(若是你关心这个)
- 线程名称
- 简单的日志名(非全限定名的那种)
- 日志描述信息
好比像下面这个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>
千万不要在日志信息中包含下列内容:
- 文件名
- 类名(我想这个应该是全限定名吧)
- 代码行号
还有下面这种写法也是要避免的:
由于程序员知道, 在日志模式中会指定行号, 所以他就能够根据日志输的行号出判断指定的方法是否被调用了(好比这里多是authenticate()方法, 进而判断登陆的用户已经通过了验证). 另外, 你们也要清楚一点, 在日志模式中指定类名, 方法名以及行号会带来严重的性能问题. 下面是我针对这个作的一个简单的测试, 配置以下:
- <appender name="CLASS_INFO" class="ch.qos.logback.core.OutputStreamAppender">
- <encoder>
- <pattern>%d{HH:mm:ss.SSS} %-5level [%thread][%class{0}.%method
:%line][%logger{0}] %m%n
</
pattern
>
</
encoder
>
<
outputStream
class=
"org.apache.commons.io.output.NullOutputStream"
/>
</
appender
>
<
appender
name=
"NO_CLASS_INFO"
class=
"ch.qos.logback.core.OutputStreamAppender"
>
<
encoder
>
<
pattern
>%d{HH:mm:ss.SSS} %-5level [%thread][LoggerTest.testClassInfo
- :30][%logger{0}] %m%n</pattern>
- </encoder>
- <outputStream class="org.apache.commons.io.output.NullOutputStream"/>
- </appender>
下面是测试代码:
- import org.junit.Test;
- import org.perf4j.StopWatch;
- import org.perf4j.slf4j.Slf4JStopWatch;
- import org.slf4j.Logger;
- import org.slf4j.LoggerFactory;
-
- public class LoggerTest {
-
- private static final Logger log = LoggerFactory.getLogger(LoggerTest.class);
- private static final Logger classInfoLog = LoggerFactory.getLogger("CLASS_INFO");
- private static final Logger noClassInfoLog = LoggerFactory.getLogger("NO_CLASS_INFO");
-
- private static final int REPETITIONS = 15;
- private static final int COUNT = 100000;
-
- @Test
- public void testClassInfo() throws Exception {
- for (int test = 0; test < REPETITIONS; ++test)
- testClassInfo(COUNT);
- }
-
- private void testClassInfo(final int count) {
- StopWatch watch = new Slf4JStopWatch("Class info");
- for (int i = 0; i < count; ++i)
- classInfoLog.info("Example message");
- printResults(count, watch);
- }
-
- @Test
- public void testNoClassInfo() throws Exception {
- for (int test = 0; test < REPETITIONS; ++test)
- testNoClassInfo(COUNT * 20);
- }
-
- private void testNoClassInfo(final int count) {
- StopWatch watch = new Slf4JStopWatch("No class info");
- for (int i = 0; i < count; ++i)
- noClassInfoLog.info("Example message");
- printResults(count, watch);
- }
-
- private void printResults(int count, StopWatch watch) {
- log.info("Test {} took {}ms (avg. {} ns/log)", new Object[]{
- watch.getTag(),
- watch.getElapsedTime(),
- watch.getElapsedTime() * 1000 * 1000 / count});
- }
-
- }
在上面的测试代码中, CLASS_INFO日志输出了1500万次, 而NO_CLASS_INFO输出了3亿次. 后者采用一个静态的文原本取代日志模式中的动态类信息.
从下面的对比图能够看出, 直接在日志模式中指定类名的日志比使用反射动态获取类名的要快13倍(平均输出每条日志耗时:8.8 vs 115微秒). 对于一个java程序员来讲, 一条日志耗时100微秒是能够接受的. 这也就是说, 一个后台应用其中1%的时间消耗在了输出日志上. 所以咱们有时候也须要权衡一下, 每秒100条日志输出是不是合理的.
最后要提到的是日志框架中比较高级的功能: Mapped Diagnostic Context. MDC(
http://www.slf4j.org/api/org/slf4j/MDC.html )主要用来简化基于thread-local的map参数管理. 你能够往这个map中增长任何key-value内容, 而后在随后的日志输出中做为模式的一部分, 与当前线程一块儿输出.
7) 给方法的输入输出加上日志
当咱们在开发过程当中发现了一个bug, 通常咱们会采用debug的方式一步步的跟踪, 直到定位到最终的问题位置(若是能经过写一个失败的单元测试来暴露问题, 那就更帅了^_^). 可是若是实际状况不容许你debug时, 好比在客户的系统上几天前出现的bug. 若是你没有详细的日志的话, 你能找到问题的根源么?
若是你能根据一些简单的规则来输出每一个方法的输入和输出(参数和返回值). 你基本上能够扔掉调试器了. 固然针对每个方法加上日志必须是合理的: 访问外部资源(好比数据库), 阻塞, 等待等等, 这些地方能够考虑加上日志. 好比下面的代码:
- public String printDocument(Document doc, Mode mode) {
- log.debug("Entering printDocument(doc={}, mode={})", doc, mode);
- String id =
- log.debug("Leaving printDocument(): {}", id);
- return id;
- }
由于在方法调用先后加上了日志, 咱们能够很是方便的发现代码的性能问题, 甚至找出死锁和线程饥饿(starvation)等严重问题:这种状况下都只有输入(entering)日志, 不会有输出(leaving)日志. 若是方法名类名使用得当, 那么输出的日志信息也将会很是赏心悦目. 由于你能够根据日志完整了解系统的运行状况, 所以分析问题的时候, 也将变得更加垂手可得. 为了减小日志代码, 也能够采用简单的AOP来作日志输出. 可是也要当心, 这种作法可能产生大量的日志.
对于这种日志, 通常采用DEBUG/TRACE级别. 当某些方法的调用很是频繁, 那么大量的日志输出将会影响到系统的性能, 此时咱们能够提升相关类的日志级别或者干脆去掉日志输出. 不过通常状况下, 仍是建议你们多输出一些日志. 另外也能够将日志当作一种单元测试. 输出的日志将像单元测试同样, 会覆盖到整个方法的执行过程. 没有日志的系统是不可想象的. 所以经过观察日志的输出将是咱们了解系统是在正确的运行仍是挂了的惟一方式.
8) 用日志检查外部系统
这里是针对前面的一种场景: 若是你的系统须要和其余系统通讯, 那么须要考虑是否须要用日志记录这种交互. 通常状况下, 若是一个应用须要与多个系统进行集成, 那么诊断和分析问题将很是困难. 好比在最近的一个项目中, 因为咱们在Apache CXF web服务上完整的记录了消息数据(包括SOAP和HTTP头信息), 使得咱们在系统集成和测试阶段很是happy.
若是经过ESB的方式来多个系统进行集成, 那么能够在总线(bus)上使用日志来记录请求和响应. 这里能够参考Mules(
http://www.mulesoft.org/)的<log-component/>(
http://www.mulesoft.org/documentation/display/MULE2USER/Configuring+Components).
有时候与外部系统进行通讯产生的大量日志可能让咱们没法接受. 另外一方面, 咱们但愿打开日志临时进行一下测试, 或者在系统出现问题的时候咱们但愿打开短暂的输出日志. 这样咱们能够在输出日志和保证系统性能之间取得一个平衡. 这里咱们须要借助日志日别. 好比像下面的这样作:
- Collection<Integer> requestIds =
-
- if(log.isDebugEnabled())
- log.debug("Processing ids: {}", requestIds);
- else
- log.info("Processing ids size: {}", requestIds.size());
在上面的代码中, 若是日志级别配置为DEBUG, 那么将但应全部的requestIds信息. 可是若是咱们配置INFO级别, 那么只会输出requestId的数量. 不过就像咱们前面提到的日志的反作用那样, 若是在INFO级别下requestIds为null将产生NullPointerException.
9) 正确输出异常日志
对于日志输出的第一条原则就是不要用日志输出异常, 而是让框架或者容器去处理. 记录异常本不该该是logger的工做. 而许多程序员都会用日志输出异常, 而后可能返回一个默认值(null, 0或者空字符串). 也可能在将异常包装一下再抛出. 好比像下面的代码这样:
- log.error("IO exception", e);
- throw new MyCustomException(e);
这样作的结果可能会致使异常信息打印两次(抛出的地方打一次, 捕获处理的地方再打一次).
可是有时候咱们确实但愿打印异常, 那么应该如何处理呢? 好比下面对NPE的处理:
- try {
- Integer x = null;
- ++x;
- } catch (Exception e) {
- log.error(e);
- log.error(e, e);
- log.error("" + e);
- log.error(e.toString());
- log.error(e.getMessage());
- log.error(null, e);
- log.error("", e);
- log.error("{}", e);
- log.error("{}", e.getMessage());
- log.error("Error reading configuration file: " + e);
- log.error("Error reading configuration file: " + e.getMessage());
- log.error("Error reading configuration file", e);
- }
上面的代码, 正确输出异常信息的只有G和L, A和B甚至不能在SLF4J中编译经过, 其余的都会丢失异常堆栈信息或者打印了不恰当的信息. 这里只要记住一条, 在日志中输出异常信息, 第一个参数必定是一个字符串, 通常都是对问题的描述信息, 而不能是异常message(由于堆栈里面会有), 第二个参数才是具体的异常实例.
注: 对于远程调用类型的服务抛出的异常,必定要注意实现序列化, 不然在客户端将抛出NoClassDefFoundError异常, 而掩盖了真实的异常信息
10) 让日志易读,易解析
对日志感兴趣的能够分为两类:
- 人(好比程序员)
- 机器(系统管理员写的shell脚本)
日志的内容必须照顾到这两个群体. 引用鲍勃大叔"Clean Code(
http://www.amazon.com/Clean-Code-Handbook-Software-Craftsmanship/dp/0132350882)"一书的话来讲:日志应该像代码同样可读而且容易理解.
另外一方面, 若是一个系统每小时要输出几百MB甚至上G的日志, 那么咱们须要借助grep, sed以及awk来分析日志. 若是可能, 咱们应该让日志尽量的被人和机器理解. 好比, 避免格式化数字, 使用日志模式则能够方便用正则表达式进行识别. 若是没法兼顾, 那么能够将数据用两种格式输出, 好比像下面这样:
- log.debug("Request TTL set to: {} ({})", new Date(ttl), ttl);
-
-
- final String duration = DurationFormatUtils.formatDurationWords(durationMillis, true, true);
- log.info("Importing took: {}ms ({})", durationMillis, duration);
-
上面的日志, 既照顾了计算机("ms after 1970 epoch"这种时间格式), 又能更好的让人能理解("1 day 10 hours 17 minutes 36 seconds") . 另外, 这里顺便广告一下DurationFormatUtils(
http://commons.apache.org/lang/api-release/org/apache/commons/lang/time/DateFormatUtils.html), 一个很是不错的工具:)