Logback及Log4J性能测试

最新推荐文章于 2024-09-02 08:55:03 发布

吴帝永

最新推荐文章于 2024-09-02 08:55:03 发布

阅读量1.6k

点赞数

分类专栏： Logback日志框架

本文链接：https://blog.csdn.net/wudiyong22/article/details/78665343

版权

Logback日志框架专栏收录该内容

3 篇文章 0 订阅

订阅专栏

分别从两个方面测试：

1、日志输出的格式对性能的影响，即日志中包含动态方法名和行号对性能的影响

2、日志长度对性能的影响

LogBack测试

本测试在Spring Boot框架基础上进行，日志配置文件logback-spring.xml内容如下：

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 seconds">
	<property name="log.path" value="D:\\log\\eurekaServer\\" />
	<!-- 不带方法名和行号 -->
	<appender name="LOGFILE"
		class="ch.qos.logback.core.rolling.RollingFileAppender">
		<File>${log.path}/eurekaServer.log</File>
		<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
			<fileNamePattern>${log.path}/eurekaServer-%d{yyyyMMdd}.%i.log
			</fileNamePattern>
			<timeBasedFileNamingAndTriggeringPolicy
				class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
				<maxFileSize>50MB</maxFileSize>
			</timeBasedFileNamingAndTriggeringPolicy>
			<maxHistory>60</maxHistory>
			<totalSizeCap>20GB</totalSizeCap>
		</rollingPolicy>
		<layout class="ch.qos.logback.classic.PatternLayout">
			<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%-14.14thread] %-30.30logger{30} - %msg%n </pattern>
		</layout>
	</appender>
	<root level="info">
		<appender-ref ref="LOGFILE" />
	</root>
	<logger name="com.EurekaServer" level="INFO" additivity="false">
		<appender-ref ref="LOGFILE" />
	</logger>
</configuration>

只带行号：

%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%-14.14thread] %-30.30logger{30} %-4line - %msg%n

只带方法名：

%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%-14.14thread] %-30.30logger{30} [%-20.20method] - %msg%n

带方法名和行号：

%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%-14.14thread] %-30.30logger{30} [%-20.20method]:%-4line - %msg%n

因为基于Spring Boot，所以只需在测试类外面加上如下两个注解即可：

@RunWith(SpringRunner.class)
@SpringBootTest

整个测试类内容如下：

import java.util.ArrayList;
import java.util.List;
import org.junit.Ignore;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.perf4j.StopWatch;
import org.perf4j.slf4j.Slf4JStopWatch;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.test.context.junit4.SpringRunner;

@RunWith(SpringRunner.class)
@SpringBootTest
public class EurekaServerApplicationTests {
    Logger log = LoggerFactory.getLogger(EurekaServerApplicationTests.class);  

	@Ignore
	@Test
	public void contextLoads() {
	}

//	@Ignore
	@Test  
    public void logMehodAndLine() throws InterruptedException{  
        StopWatch watch = new Slf4JStopWatch();  
        List<Long> times = new ArrayList<Long>();  
        int n = 10;  
        int size = 1000000;  
        Long totalTime = 0L;  
        for(int i = 0;i<n;i++){  
            watch.start();  
            for(int j = 0;j<size - 1;j++){  
                log.info("Example message");  
            }  
            watch.stop();  
            times.add(i, watch.getElapsedTime());  
            totalTime += watch.getElapsedTime();  
            Thread.sleep(500);  
        }  
        log.info("{}条耗时：{}ms",size,times.toString());  
        log.info("平均每{}条耗时：{}ms",size,totalTime/n);  
    }  
      
    /** 
     * 测试日志长度对时间的影响 
     */  
	@Ignore  
    @Test  
    public void logLength() throws InterruptedException{  
        StopWatch watch = new Slf4JStopWatch();  
        List<Long> times = new ArrayList<Long>();  
        int n = 50;  
        int size = 10000;  
        int length = 1000;  
        StringBuffer info = new StringBuffer();  
        log.info("开始。。。。");
        for(int i = 0;i < n; i++){  
            while(info.length()<(i+1)*length){  
                info.append("a");  
            }  
            String infoStr = info.toString();  
            watch.start();  
            for(int j = 0;j<size - 1;j++){  
                log.info(infoStr);  
            }  
            watch.stop();  
            times.add(i, watch.getElapsedTime());  
            Thread.sleep(500);  
        }  
        for(int i = 0;i < n; i++){  
            log.info("长度为{}时，{}条共耗时：{}ms",(i+1)*length,size,times.get(i));  
        }  
    }  
}

日志输出的格式对性能的影响

包含行号测试结果：

2017-12-17 16:47:28.795 INFO [main ] E.EurekaServerApplicationTests 42 - 1000000条耗时：[55742, 55179, 54539, 55101, 56176, 56494, 56571, 55494, 55828, 56417]ms
2017-12-17 16:47:28.795 INFO [main ] E.EurekaServerApplicationTests 43 - 平均每1000000条耗时：55754ms

包含动态方法名测试结果：

2017-12-17 17:19:46.811 INFO [main ] E.EurekaServerApplicationTests [logMehodAndLine ] - 1000000条耗时：[56293, 55258, 54957, 55100, 55357, 53849, 55144, 55342, 54842, 56428]ms
2017-12-17 17:19:46.811 INFO [main ] E.EurekaServerApplicationTests [logMehodAndLine ] - 平均每1000000条耗时：55257ms

同时包含动态方法名和行号的测试结果：

2017-12-17 17:35:27.582 INFO [main ] E.EurekaServerApplicationTests [logMehodAndLine ]:42 - 1000000条耗时：[59606, 57803, 57607, 57038, 58981, 57819, 58784, 58220, 60550, 57470]ms
2017-12-17 17:35:27.583 INFO [main ] E.EurekaServerApplicationTests [logMehodAndLine ]:43 - 平均每1000000条耗时：58387ms

不包含动态方法名和行号的测试结果：

2017-12-17 17:49:30.144 INFO [main ] E.EurekaServerApplicationTests - 1000000条耗时：[3877, 3425, 3189, 3002, 4061, 3372, 3767, 3138, 4020, 2914]ms
2017-12-17 17:49:30.144 INFO [main ] E.EurekaServerApplicationTests - 平均每1000000条耗时：3476ms

可见，同时包含方法名和行号的时间与只包含方法名或行号差不多，但都比不包含方法名和行号需要的时间多，大概为16倍。

日志长度对性能的影响

以包含方法名和行号、输出到文件为例

测试结果：

n=50、size = 10000、length = 1000时：

2017-12-17 15:35:55.726 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为1000时，10000条共耗时：884ms
2017-12-17 15:35:55.726 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为2000时，10000条共耗时：769ms
2017-12-17 15:35:55.726 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为3000时，10000条共耗时：1009ms
2017-12-17 15:35:55.726 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为4000时，10000条共耗时：1050ms
2017-12-17 15:35:55.726 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为5000时，10000条共耗时：805ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为6000时，10000条共耗时：835ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为7000时，10000条共耗时：956ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为8000时，10000条共耗时：776ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为9000时，10000条共耗时：1016ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为10000时，10000条共耗时：1054ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为11000时，10000条共耗时：1172ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为12000时，10000条共耗时：1189ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为13000时，10000条共耗时：1078ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为14000时，10000条共耗时：1780ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为15000时，10000条共耗时：2187ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为16000时，10000条共耗时：2096ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为17000时，10000条共耗时：2072ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为18000时，10000条共耗时：3175ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为19000时，10000条共耗时：3202ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为20000时，10000条共耗时：3065ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为21000时，10000条共耗时：3867ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为22000时，10000条共耗时：2614ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为23000时，10000条共耗时：3466ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为24000时，10000条共耗时：4425ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为25000时，10000条共耗时：5366ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为26000时，10000条共耗时：6404ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为27000时，10000条共耗时：6481ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为28000时，10000条共耗时：5930ms
2017-12-17 15:35:55.810 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为29000时，10000条共耗时：6752ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为30000时，10000条共耗时：5903ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为31000时，10000条共耗时：6539ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为32000时，10000条共耗时：8695ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为33000时，10000条共耗时：8874ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为34000时，10000条共耗时：10502ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为35000时，10000条共耗时：11454ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为36000时，10000条共耗时：11974ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为37000时，10000条共耗时：11695ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为38000时，10000条共耗时：12955ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为39000时，10000条共耗时：13296ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为40000时，10000条共耗时：13684ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为41000时，10000条共耗时：13281ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为42000时，10000条共耗时：14756ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为43000时，10000条共耗时：14626ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为44000时，10000条共耗时：17325ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为45000时，10000条共耗时：18513ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为46000时，10000条共耗时：21122ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为47000时，10000条共耗时：16580ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为48000时，10000条共耗时：15385ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为49000时，10000条共耗时：16923ms
2017-12-17 15:35:55.826 INFO [main ] E.EurekaServerApplicationTests [logLength ]:75 - 长度为50000时，10000条共耗时：17295ms