Java 调整格式日志输出_java

工欲善其事,必先利其器

很多程序员可能都忘了记录应用程序的行为是一件多么重要的事,当遇到多线程环境下高压力导致的并发bug时,你就能体会到记录log的重要性。

有的人很高兴的就在代码里加上了这么句:

log.info("Happy and carefree logging");

他可能都没有意识到应用程序的日志在维护,调优和故障识别中的重要性。我认为slf4j是最好的日志API,最主要是因为它支持一个很棒的模式注入的方式:

log.debug("Found {} records matching filter: '{}'", records, filter);

log4j的话你只能这样:

log.debug("Found " + records + " recordsmatching filter: '" + filter + "'");

这样写不仅更啰嗦和可读性差,而且字符串拼接影响效率(当这个级别并不需要输出的时候)。

slf4j引入了{}注入特性,并且由于避免了每次都进行字符串拼接,toString方法不会被调用,也不再需要加上isDebugEnabled了。slf4j是外观模式的一种应用,它只是一个门面。具体实现的话我推荐logback框架,之前已经做过一次广告了,而不是已经很完备的log4j。它有许多很有意思的特性,和log4j不同的是,它还在积极的开发完善中。

还有一个要推荐的工具是perf4j:

Perf4J is to System.currentTimeMillis() as log4j is to System.out.println()

就好比log4j是System.out.println的一种更好的替换方式一样,perf4j更像是System.currentTimeMillis()的替代。我已经在一个项目中引入了perf4j,并在高负载的情况下观察它的表现。管理员和企业用户都被这个小工具提供的漂亮的图表惊呆了。我们可以随时查看性能问题。perf4j应该专门开一篇文章来讲,现在的话可以先看下它的开发者指南。还有一个Ceki Gülcü(log4j,slf4j和logback工程的创建者)提供了一个简单的方法供我们移除对commons-logging的依赖。

不要忘了日志级别

每次你要加一行日志的时候,你都会想,这里该用哪种日志级别?大概有90%的程序员都不太注意这个问题,都是用一个级别来记录日志,通常不是INFO就是DEBUG。为什么?

日志框架和System.out相比有两大优势:分类和级别。两者可以让你可以选择性的过滤日志,永久的或者只是在排查错误的时候。

ERROR :发生了严重的错误,必须马上处理。这种级别的错误是任何系统都无法容忍的。比如:空指针异常,数据库不可用,关键路径的用例无法继续执行。

WARN :还会继续执行后面的流程,但应该引起重视。其实在这里我希望有两种级别:一个是存在解决方案的明显的问题(比如,"当前数据不可用,使用缓存数据"),另一个是潜在的问题和建议(比如“程序运行在开发模式下”或者“管理控制台的密码不够安全”)。应用程序可以容忍这些信息,不过它们应该被检查及修复。

DEBUG :开发人员关注的事。后面我会讲到什么样的东西应该记录到这个级别。

TRACE :更为详尽的信息,只是开发阶段使用。在产品上线之后的一小段时间内你可能还需要关注下这些信息,不过这些日志记录只是临时性的,最终应该关掉。DEBUG和TRACE的区别很难区分,不过如果你加了一行日志,在开发测试完后又删了它的话,这条日志就应该是TRACE级别的。

上面的列表只是一个建议,你可以根据自己的规则来记录日志,但最好要有一定的规则。我个人的经验是:在代码层面不要进行日志过滤,而是用正确的日志级别能够快速的过滤出想要的信息,这样能节省你很多时间。

最后要说的就是这个臭名昭著的is*Enabled的条件语句了。有的人喜欢把每次日志前加上这个:

if(log.isDebugEnabled())
 log.debug("Place for your commercial");

个人认为,应该避免在代码里加入这个乱哄哄的东西。性能看起来没有什么提升(尤其是用了slf4j之后),更像是过早的优化。还有,没发现这么做有点多余么?很少有时候是明确需要这种显式的判断语句的,除非我们证明构造日志消息本身开销太大。不然的话,该怎么记就怎么记,让日志框架去操心这个吧。

你清楚你在记录什么吗?

每次你写下一行日志,花点时间看看你到底在日志文件里打印了些什么。读一遍你的日志,找出异常的地方。首先,至少要避免空指针异常:

log.debug("Processing request with id: {}", request.getId());

你确认过request不是null了吗?

记录集合也是一个大坑。如果你用Hibernate从数据库里获取领域对象的集合的时候,不小心写成了这样:log.debug("Returning users: {}", users);

slf4j只会在这条语句确实会打印的时候调用toString方法,当然这个很酷。不过如果内存溢出了,N+1选择问题,线程饿死,延迟初始化异常,日志存储空间用完了...这些都有可能发生。最好的方式是只记录对象的ID(或者只记录集合的大小)。不过收集ID需要对每个对象调用getId方法,这个在Java里可真不是件简单的事。Groovy有个很棒的展开操作符(users*.id),在Java里我们可以用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));
}

最后要说的是,toString方法可能没有正确的实现或者使用。

首先,为了记录日志,为每个类创建一个toString的做法比比皆是,最好用 ToStringBuilder来生成(不过不是它的反射实现的那个版本)。

第二,注意数组和非典型的集合。数组和一些另类的集合的toString实现可能没有挨个调用每个元素的toString方法。可以使用JDK提供的Arrays#deepToString方法。经常检查一下你自己打印的日志,看有没有格式异常的一些信息。

避免副作用

日志打印一般对程序的性能没有太大影响。最近我一个朋友在一些特殊的平台上运行的一个系统抛出了Hibernate的LazyInitializationException异常。你可能从这已经猜到了,当会话连接进来的时候,一些日志打印导致延迟初始化的集合被加载。在这种情况下,把日志级别提高了,集合也就不再被初始化了。如果你不知道这些上下文信息,你得花多长时间来发现这个BUG。

另一个副作用就是影响程序的运行速度。快速回答一下这个问题:如果日志打印的过多或者没有正确的使用toString和字符串拼接,日志打印就会对性能产生负面影响。能有多大?好吧,我曾经见过一个程序每15分钟就重启一次,因为太多的日志导致的线程饿死。这就是副作用!从我的经验来看,一小时打印百来兆差不多就是上限了。

当然如果由于日志打印异常导致的业务进程中止,这个副作用就大了。我经常见到有人为了避免这个而这么写:

try {
 log.trace("Id=" + request.getUser().getId() + " accesses " + manager.getPage().getUrl().toString())
} catch(NullPointerException e) {}

这是段真实的代码,但是为了让世界清净点,请不要这么写。

描述要清晰

每个日志记录都会包含数据和描述。看下这个例子:

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"); 

在这个警告日志里加上消息类型,消息ID等等这些难道很困难吗?我是知道发生错误了,不过到底是什么错误?上下文信息是什么?

第三个反面例子是“魔法日志”。一个真实的例子:团队里的很多程序员都知道,3个&号后面跟着!号再跟着一个#号,再跟着一个伪随机数的日志意味着”ID为XYZ的消息收到了”。没人愿意改这个日志,某人敲下键盘,选中某个唯一的”&&&!#”字符串,他就能很快找到想要的信息。

结果是,整个日志文件看起来像一大串随机字符。有人不禁会怀疑这是不是一个perl程序。

日志文件应当是可读性强的,清晰的,自描述的。不要用一些魔数,记录值,数字,ID还有它们的上下文。记录处理的数据以及它的含义。记录程序正在干些什么。好的日志应该是程序代码的一份好的文档。

我有提过不要打印密码还有个人信息吗?相信没有这么傻的程序员。

调整你的格式

日志格式是个很有用的工具,无形中在日志添加了很有价值的上下文信息。不过你应该想清楚,在你的格式中包含什么样的信息。比如说,在每小时循环写入的日志中记录日期是没有意义的,因为你的日志名就已经包含了这个信息。相反的,如果你没记录线程名的话当两个线程并行的工作的时候,你就无法通过日志跟踪线程了——日志已经重叠到一起了。在单线程的应用程序中,这样做没问题,不过那个已经是过去的事儿了。

从我的经验来看,理想的日志格式应当包括(当然除了日志信息本身了):当前时间(无日期,毫秒级精度),日志级别,线程名,简单的日志名称(不用全称)还有消息。在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> 

文件名,类名,行号,都不用列进来,尽管它们看起来很有用。我还在代码里见过空的日志记录:

log.info(""); 因为程序员认为行号会作为日志格式的一部分,并且他知道如果空日志消息出现在这个文件的67行的话,意味着这个用户是认证过的。不仅这样,记录类名方法名,或者行号对性能都有很大的影响。

日志框架的一个比较高级的特性是诊断上下文映射(Mapped Diagnostic Context)。MDC只是一个线程本地的一个map。你可以把任何键值对放到这个map里,这样的话这个线程的所有日志记录都能从这个map里取到相应的信息作为输出格式的一部分。

记录方法的参数和返回值

如果你在开发阶段发现了一个BUG,你通常会用调试器来跟踪具体的原因。现在假设不让你用调试器了,比如,因为这个BUG几天前在用户的环境里出现了,你能拿到的只有一些日志。你能从中发现些什么?

如果你遵循打印每个方法的入参和出参这个简单的原则,你根本不需要调试器。当然每个方法可能访问外部系统,阻塞,等待,等等,这些都应该考虑进来。就参考以下这个格式就好:

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;
}

由于你在方法的开始和结束都记录了日志,所以你可以人工找出效率不高的代码,甚至还可以检测到可能会引起死锁和饥饿的诱因——你只需看一下“Entering”后面是不是没有”Leaving“就明白了。如果你的方法名的含义很清晰,清日志将是一件愉快的事情。同样的,分析异常也更得更简单了,因为你知道每一步都在干些什么。代码里要记录的方法很多的话,可以用AOP切面来完成。这样减少了重复的代码,不过使用它得特别小心,不注意的话可能会导致输出大量的日志。

这种日志最合适的级别就是DEBUG和TRACE了。如果你发现某个方法调用 的太频繁,记录它的日志可能会影响性能的话,只需要调低它的日志级别就可以了,或者把日志直接删了(或者整个方法调用只留一个?)不过日志多了总比少了要强。把日志记录当成单元测试来看,你的代码应该布满了日志就像它的单元测试到处都是一样。系统没有任何一部分是完全不需要日志的。记住,有时候要知道你的系统是不是正常工作,你只能查看不断刷屏的日志。

观察外部系统

这条建议和前面的有些不同:如果你和一个外部系统通信的话,记得记录下你的系统传出和读入的数据。系统集成是一件苦差事,而诊断两个应用间的问题(想像下不同的公司,环境,技术团队)尤其困难。最近我们发现记录完整的消息内容,包括Apache CXF的SOAP和HTTP头,在系统的集成和测试阶段非常有效。

这样做开销很大,如果影响到了性能的话,你只能把日志关了。不过这样你的系统可能跑的很快,挂的也很快,你还无能为力?当和外部系统进行集成的时候,你只能格外小心并做好牺牲一定开销的准备。如果你运气够好,系统集成由ESB处理了,那在总线把请求和响应给记录下来就最好不过了。可以参考下Mule的这个日志组件。

有时候和外部系统交换的数据量决定了你不可能什么都记下来。另一方面,在测试阶段和发布初期,最好把所有东西都记到日志里,做好牺牲性能的准备。可以通过调整日志级别来完成这个。看下下面这个小技巧:

Collection<Integer> requestIds = //...
if(log.isDebugEnabled())
 log.debug("Processing ids: {}", requestIds);
else
 log.info("Processing ids size: {}", requestIds.size()); 

如果这个logger是配置成DEBUG级别,它会打印完整的请求ID的集合。如果它配置成了打印INFO信息的话,就只会输出集合的大小。你可能会问我是不是忘了isInfoEnabled条件了,看下第二点建议吧。这里还有一个值得注意的是ID的集合不能为null。尽管在DEBUG下,它为NULL也能正常打印,但是当配置成INFO的时候一个大大的空指针。还记得第4点建议中提到的副作用吧?

正确的记录异常

首先,不要记录异常,让框架或者容器来干这个。当然有一个例外:如果你从远程服务中抛出了异常(RMI,EJB等),异常会被序列化,确保它们能返回给客户端 (API中的一部分)。不然的话,客户端会收到NoClassDefFoundError或者别的古怪的异常,而不是真正的错误信息。

异常记录是日志记录的最重要的职责之一,不过很多程序员都倾向于把记录日志当作处理异常的方式。他们通常只是返回默认值(一般是null,0或者空字符串),装作什么也没发生一样。还有的时候,他们会先记录异常,然后把异常包装了下再抛出去:

log.error("IO exception", e);
throw new CustomException(e); 

这样写通常会把栈信息打印两次,因为捕获了MyCustomException异常的地方也会再打印一次。日志记录,或者包装后再抛出去,不要同时使用,否则你的日志看起来会让人很迷惑。

如果我们真的想记录日志呢?由于某些原因(大概是不读API和文档?),大约有一半的日志记录我认为是错误的。做个小测试,下面哪个日志语句能够正确的打印空指针异常?

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
}

很奇怪吧,只有G和L(这个更好)是对的!A和B在slf4j下面根本就编译不过,其它的会把栈跟踪信息给丢掉了或者打印了不正确的信息。比如,E什么也不打印,因为空指针异常本身没有提供任何异常信息而栈信息又没打印出来 .记住,第一个参数通常都是文本信息,关于这个错误本身的。不要把异常信息给写进来,打印日志后它会自动出来的,在栈信息的前面。不过想要打印这个,你当然还得把异常传到第二个参数里面才行。

日志应当可读性强且易于解析

现在有两组用户对你的日志感兴趣:我们人类(不管你同不同意,码农也是在这里边),还有计算机(通常就是系统管理员写的shell脚本)。日志应当适合这两种用户来理解。如果有人在你后边看你的程序的日志却看到了这个:

那你肯定没听从我的建议。日志应该像代码一样易于阅读和理解。

另一方面,如果你的程序每小时就生成了半GB的日志,没有谁或者任何图形化的文本编辑器能把它们看完。这时候我们的老家伙们,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) 

计算机看到”ms after 1970 epoch“这样的的时间格式会感谢你的,而人们则乐于看到”1天10小时17分36秒“这样的东西。

总之,日志也可以写得像诗一样优雅,如果你愿意琢磨的话。

以上就是对java 日志调整输出格式的资料整理,有兴趣的朋友可以参考下。

以上是小编为您精心准备的的内容,在的博客、问答、公众号、人物、课程等栏目也有的相关内容,欢迎继续使用右上角搜索按钮进行搜索java
, log
, 输出日志
, 日志输出
日志输出格式
java日志输出格式、java jar 日志输出、java log日志输出、java 输出日志到文件、java输出日志,以便于您获取更多的相关知识。

时间: 2024-11-04 08:27:36

Java 调整格式日志输出_java的相关文章

Java多线程实现同时输出_java

一道经典的面试题目:两个线程,分别打印AB,其中线程A打印A,线程B打印B,各打印10次,使之出现ABABABABA.. 的效果 package com.shangshe.path; public class ThreadAB { /** * @param args */ public static void main(String[] args) { final Print business = new Print(); new Thread(new Runnable() { public v

使用Log4j为项目配置日志输出应用详解以及示例演示的实现分析_java

Log4j组件构成  Log4j由三个重要的组件构成: 1.日志信息的优先级(Logger) 2.日志信息的输出目的地(Appender) 3.日志信息的输出格式(Layout). 概要: 日志信息的优先级从高到低有ERROR.WARN. INFO.DEBUG,分别用来指定这条日志信息的重要程度: 日志信息的输出目的地指定了日志将打印到控制台还是文件中: 而输出格式则控制了日志信息的显示内容. Log4j介绍 Log4j是 Apache的一个开放源代码项目,通过使用Log4j,我们可以控制日志信

请教下关于CXF的JAVA客户端的控制台日志输出问题

问题描述 我在自己做的API中整合了CXF的Webservice调用,没有使用spring配置,但是cxf在调用webservice的时候会在控制台打印出很多日志,影响了我API其他日志的输出,怎样才能把cxf打印到控制台的日志去掉呢?我试了加入自己写的interceptor也没什么效果. 解决方案 解决方案二:学习............解决方案三:1.默认情况下,CXF打印大量令人不悦的日志细节并输出到控制台.CXF使用Java日志记录,因此为避免此输出,您需要设置一个系统属性使其指向一个日

css 、js-网页上的java代码格式像eclipse上输出

问题描述 网页上的java代码格式像eclipse上输出 就是要做到这种效果,是怎么实现的? 解决方案 用〈pre〉标签..... 解决方案二: 看过页面的源码了,直接用 标签就可以吗 解决方案三: 看过页面的源码了,直接用 标签就可以吗

java 实现随机数组输出及求和实例详解_java

java 实现随机数组输出及求和 问题描述: 随机生成10个数,填充一个数组,然后用消息框显示数组内容,接着计算数组元素的和,将结果也显示在消息框中. 设计思路: 使用java.util中的Random类来获取随机数,存入数组后,定义一个String类的对象result,利用for循环存储要输出的数组内容到result并且求和:再利用javax.swing中的JoptionPane类创建消息框进行结果输出. 源代码: import java.util.*; import javax.swing.

tomcat 和 jboss access log 日志输出详解

工作中nginx+jboss/tomcat反向代理集成,想打开后端jboss的access log, 配置在:/home/admin/wdetail/conf/tomcat-server.xml 开启日志将下面内容的注释去掉:            <valve classname="org.apache.catalina.valves.AccessLogValve" <="" div="" style="word-wrap

【原创】日志输出到串口设备导致的问题

问题场景:       测试人员报告,业务 modb 作为 RabbitMQ 的消费者,消费消息的速度非常慢,慢到大约每秒 2 条左右,从而导致 RabbitMQ 的队列中积压了 4000+ 条消息.  排查过程:       先通过 top 命令定位一下  [root@upucore_1 ~]# top -Hp 8177 top - 09:50:33 up 34 min, 8 users, load average: 4.76, 4.32, 3.65 Tasks: 2 total, 0 run

log4j 高手请教 多账户多日志输出

问题描述 有个交易系统,账户定义文件不定多个,格式相同,账号密码等内容不同有个class是处理交易的,每个实例处理一个账户的交易问题:如何让这个class根据账户的不同,把日志输出到账户专用的日志文件中去?因为账户定义文件允许新增删除,所以希望log4j的配置也是动态的,尽量不要写死请把class中的相关设定代码和log4j配置文件的相关设置分别说明一下,多谢了 解决方案 解决方案二:ding..........................解决方案三:我也顶起吧..坐等楼下的答案了...解决

Tomcat控制台日志输出到文件

startup.bat中修改 call "%EXECUTABLE%" start %CMD_LINE_ARGS% 为 call "%EXECUTABLE%" run %CMD_LINE_ARGS%  (>> ..\logs\detailLog.%DATE:~0,10%.log )   这样控制台就不会输出日志文件了,让catalina.bat去决定日志输出在哪里吧 在catalina.bat中 寻找以%ACTION%结尾的四处,每处%ACTION%后面添