以前编程不喜欢对每个功能、重要的方法进行日志的格式化输出，即使要输出，也没按照规范进行输出。前段时间，随着我们平
台用户量不断增加，出现些问题。当用户遇到问题，就给我们客服打电话。然后客服毫无疑问就来找我们。当我们接收到这样问题的时候，
我们首先要定位是什么原因造成的。当时就是因为自己方法中输出的日志很少，而且不规范，所以根本找不到具体原因，虽然最后问题解
决了，但是花费很多不必要的时间。
那么我们怎样使用好日志这一利器呢？
1.写好日志：
我们先来看一下糟糕的日志打印：
[java] view plain copy
1. @ResponseBody
2. @RequestMapping(value = "unbind.do", method = RequestMethod.POST)
3. public Object unbind(String bankId, String memberId) {
4.
5. if (StringUtils.isBlank(bankId) || StringUtils.isBlank(memberId)) {
6. return new Result(false, "解绑参数不合法！");
7. }
8. try {
9. authPayTwoService.unbind(bankId, memberId);
10. catch (AppException e) {
11. "认证支付2.0(unbind)失败：{}",e);
12. return new Result(false, e.getMessage());
13. catch (Exception e) {
14. "认证支付2.0(unbind)]失败：{}", e);
15. return new Result(false, "解绑银行卡失败，请重试");
16. }
17. return new Result(true, "解绑银行卡成功！");
18. }
上面代码是严格不符合规范的，每个公司都有自己的打印要求。首先日志的打印必须是以logger.error、logger.warn或logger.info
的方式打印出来。日志打印格式应包含[系统来源] 错误描述 [关键信息]，日志信息要能打印出能看懂的信息，有前因和后果。方法的入参和
出参也要考虑打印出来。
好的日志格式打印：
[java] view plain copy
1. @ResponseBody
2. @RequestMapping(value = "unbind.do", method = RequestMethod.POST)
3. public Object unbind(String bankId, String memberId) {
4. "[解绑银行卡--认证支付2.0][params:bankId=" + bankId + ",memberId="
5. "]");
6. if (StringUtils.isBlank(bankId) || StringUtils.isBlank(memberId)) {
7. return new Result(false, "解绑参数不合法！");
8. }
9. try {
10. authPayTwoService.unbind(bankId, memberId);
11. catch (AppException e) {
12. "[解绑银行卡--认证支付2.0(unbind)-mas][error：{}",e);
13. return new Result(false, e.getMessage());
14. catch (Exception e) {
15. "[解绑银行卡--认证支付2.0(unbind)][error：{}",e);
16. return new Result(false, "解绑银行卡失败，请重试");
17. }
18. return new Result(true, "解绑银行卡成功！");
19. }
从上面的代码可以很轻松的定位方法、传入的参数及异常是调用接口抛出的异常还是系统级的异常。
2.良好的日志输出格式
最近测试同事采用两百并发对项目进行测试。
格式优化前：
经过测试查看每秒的并发量平均只有110多如下图：
通过查看jvm 虚拟机发现很多日志线程出现BLOCKED，如下：
[java] view plain copy
1. "http-saoma%2F192.168.6.162-8097-132" daemon prio=10 tid=0x00002aaab88e4800 nid=0x2c8e runnable [0x0000000045274000]
2. java.lang.Thread.State: BLOCKED
3. at java.lang.Throwable.getStackTraceElement(Native Method)
4. 591)
5. 0x00000007691390d0> (a java.lang.Throwable)
6. 582)
7. at sun.reflect.GeneratedMethodAccessor29.invoke(Unknown Source)
8. 25)
9. 597)
10. 139)
11. 253)
12. 500)
13. 65)
14. 506)
15. 310)
16. 369)
17. 162)
18. 251)
19. 0x0000000780fb1e00> (a org.apache.log4j.DailyRollingFileAppender)
20. 66)
21. 206)
22. 0x00000007800020a0> (a org.apache.log4j.spi.RootLogger)
23. 391)
24. 856)
25. 497)我们定位org.apache.log4j.spi.LocationInfo类的代码如下：
[java] view plain copy
1. String s;
2. // Protect against multiple access to sw.
3. synchronized(sw) {
4. t.printStackTrace(pw);
5. s = sw.toString();
6. sw.getBuffer().setLength(0);
7. }
8. //System.out.println("s is ["+s+"].");
9. int ibegin, iend;
10.
11. // Given the current structure of the package, the line
12. // containing "org.apache.log4j.Category." should be printed just
13. // before the caller.
14.
15. // This method of searching may not be fastest but it's safer
16. // than counting the stack depth which is not guaranteed to be
17. // constant across JVM implementations.
18. ibegin = s.lastIndexOf(fqnOfCallingClass);
从上面可以看出在该方法中用了synchronized锁，然后又通过打印堆栈来获取行号。那么肯定会影响到性能的，我们通过看
此时log4j.properties日志文件配置的输出格式为：
%d %-5p %c:%L [%t] - %m%n
很明显就是%l输出行号的问题，那么我们把%l去掉结果会不会好很多呢？
把log4j.properties文件中输出格式改为：
%d %-5p %c [%t] - %m%n
输出格式优化后：
再看每秒的并发量如下图：
从图中我们可以看出并发量提高了40多，同时jvm线程日志中java.lang.Thread.State: BLOCKED也没有了。看来程序的性能和日志的输
