以前编程不喜欢对每个功能、重要的方法进行日志的格式化输出，即使要输出，也没按照规范进行输出。前段时间，随着我们平
台用户量不断增加，出现些问题。当用户遇到问题，就给我们客服打电话。然后客服毫无疑问就来找我们。当我们接收到这样问题的时候，
我们首先要定位是什么原因造成的。当时就是因为自己方法中输出的日志很少，而且不规范，所以根本找不到具体原因，虽然最后问题解
决了，但是花费很多不必要的时间。
那么我们怎样使用好日志这一利器呢？
1.写好日志：
我们先来看一下
糟糕的日志
打印：
@ResponseBody
@RequestMapping(value =
"unbind.do", method = RequestMethod.POST)
public Object unbind(String bankId, String memberId) {
if (StringUtils.isBlank(bankId) || StringUtils.isBlank(memberId)) {
return
new Result(
false,
"解绑参数不合法！");
try {
authPayTwoService.unbind(bankId, memberId);
}
catch (AppException e) {
LOG.info(
"认证支付2.0(unbind)失败：{}",e);
return
new Result(
false, e.getMessage());
}
catch (Exception e) {
LOG.info(
"认证支付2.0(unbind)]失败：{}", e);
return
new Result(
false,
"解绑银行卡失败，请重试");
return
new Result(
true,
"解绑银行卡成功！");
@ResponseBody
@RequestMapping(value =
"unbind.do", method = RequestMethod.POST)
public Object unbind(String bankId, String memberId) {
LOG.info(
"[解绑银行卡--认证支付2.0][params:bankId=" + bankId +
",memberId="
+ memberId +
"]");
if (StringUtils.isBlank(bankId) || StringUtils.isBlank(memberId)) {
return
new Result(
false,
"解绑参数不合法！");
try {
authPayTwoService.unbind(bankId, memberId);
}
catch (AppException e) {
LOG.error(
"[解绑银行卡--认证支付2.0(unbind)-mas][error：{}",e);
return
new Result(
false, e.getMessage());
}
catch (Exception e) {
LOG.error(
"[解绑银行卡--认证支付2.0(unbind)][error：{}",e);
return
new Result(
false,
"解绑银行卡失败，请重试");
return
new Result(
true,
"解绑银行卡成功！");
"http-saoma%2F192.168.6.162-8097-132" daemon prio=
10 tid=
0x00002aaab88e4800 nid=
0x2c8e runnable [
0x0000000045274000]
java.lang.Thread.State: BLOCKED
at java.lang.Throwable.getStackTraceElement(Native Method)
at java.lang.Throwable.getOurStackTrace(Throwable.java:
591)
- locked <
0x00000007691390d0> (a java.lang.Throwable)
at java.lang.Throwable.getStackTrace(Throwable.java:
582)
at sun.reflect.GeneratedMethodAccessor29.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:
25)
at java.lang.reflect.Method.invoke(Method.java:
597)
at org.apache.log4j.spi.LocationInfo.<init>(LocationInfo.java:
139)
at org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:
253)
at org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert(PatternParser.java:
500)
at org.apache.log4j.helpers.PatternConverter.format(PatternConverter.java:
65)
at org.apache.log4j.PatternLayout.format(PatternLayout.java:
506)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:
310)
at org.apache.log4j.DailyRollingFileAppender.subAppend(DailyRollingFileAppender.java:
369)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:
162)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:
251)
- locked <
0x0000000780fb1e00> (a org.apache.log4j.DailyRollingFileAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:
66)
at org.apache.log4j.Category.callAppenders(Category.java:
206)
- locked <
0x00000007800020a0> (a org.apache.log4j.spi.RootLogger)
at org.apache.log4j.Category.forcedLog(Category.java:
391)
at org.apache.log4j.Category.log(Category.java:
856)
at org.slf4j.impl.Log4jLoggerAdapter.error(Log4jLoggerAdapter.java:
497)
我们定位org.apache.log4j.spi.LocationInfo类的代码如下：
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也没有了。看来程序的性能和日志的输
