Java高并发查看日志_在高并发的情况下小小的日志打印会严重影响到性能。

2.良好的日志输出格式

最近测试同事采用两百并发对项目进行测试。

格式优化前：

经过测试查看每秒的并发量平均只有110多如下图：

通过查看jvm 虚拟机发现很多日志线程出现BLOCKED，如下：

"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.(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类的代码如下：

String s;

// Protect against multiple access to sw.

synchronized(sw) {

t.printStackTrace(pw);

s = sw.toString();

sw.getBuffer().setLength(0);

}

//System.out.println("s is ["+s+"].");

int ibegin, iend;

// Given the current structure of the package, the line

// containing "org.apache.log4j.Category." should be printed just

// before the caller.

// This method of searching may not be fastest but it's safer

// than counting the stack depth which is not guaranteed to be

// constant across JVM implementations.

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也没有了。看来程序的性能和日志的输