目的
打印系统的性能分析日志,用于分析系统性能
一.maven依赖
<dependency> <groupId>com.duowan.common</groupId> <artifactId>duowan-common-log</artifactId> <version>1.0.5</version> </dependency> <dependency> <groupId>com.duowan.common</groupId> <artifactId>duowan-common-util</artifactId> <version>1.0.8</version> </dependency>
二.配置
1.web.xml filter配置
拦截需要性能分析的URL,被拦截的方法启动子任务分析:start(requestURI),release()
<!-- Profiler性能分析Filter --> <filter> <filter-name>ProfilerLoggerFilter</filter-name> <filter-class>com.duowan.common.log.filter.ProfilerLoggerFilter</filter-class> </filter> <filter-mapping> <filter-name>ProfilerLoggerFilter</filter-name> <url-pattern>*.do</url-pattern> </filter-mapping>
2.spring方法拦截器配置
拦截需要性能分析的方法及类,被拦截的方法启动子任务分析:enter(),release()
<bean id="profiledAnnotationPointcutAdvisor" class="com.duowan.common.log.aop.ProfiledAnnotationPointcutAdvisor"/> <!-- 拦截有@Profiled标注的类或者方法 --> <bean id="bean" class="org.springframework.aop.framework.autoproxy.BeanNameAutoProxyCreator"> <property name="proxyTargetClass" value="true"/> <property name="interceptorNames"> <value>profiledAnnotationPointcutAdvisor</value> </property> <property name="beanNames"> <list> <value>userGameServerDao</value> <value>userGameServerService</value> </list> </property> </bean>
三.日志打印结果
1. 日志打印位置
# DWPROJECTNO是环境变量中的配置,profilerLogDir整个配置可以通过System.properties覆盖 profilerLogDir=/data2/log/${DWPROJECTNO}/
2. digest-profiler.log
#动作时间,耗时(单位毫秒),动作ID,成功标志(Y为成功,其它为错误),循环执行次数(loopCount),方法执行结果(resultSize),clientIp 2012-10-16 00:06:20.586,0,UserGameServerBatchCallback|userDataBatchUpdater.init|saveUserGameServerList,Y,1,0, 2012-10-16 00:06:20.591,0,UserGameServerBatchCallback|userDataBatchUpdater.init|saveUserGameServerList,Y,1,0, 2012-10-16 00:06:20.613,0,UserGameServerBatchCallback|userDataBatchUpdater.init|saveUserGameServerList,Y,10,0, 2012-10-16 00:06:20.63,1,UserGameServerBatchCallback|userDataBatchUpdater.init|saveUserGameServerList,Y,13,0, 2012-10-16 00:06:20.642,0,UserGameServerBatchCallback|userDataBatchUpdater.init|saveUserGameServerList,Y,2,0, 2012-10-16 00:06:20.659,1,UserGameServerBatchCallback|userDataBatchUpdater.init|saveUserGameServerList,Y,16,0, 2012-10-16 00:06:20.696,0,UserGameServerBatchCallback|userDataBatchUpdater.init|saveUserGameServerList,Y,1,0,
3. dump-profiler.log
[totalCost:25,555ms (selfCost:25,543ms), all:100% start:0ms ] - UserBatchCallback +---[totalCost:7ms, parent:0%, all:0%, loopCount:10,000, TPS:1,428,571 start:25,543ms ] - userDataBatchUpdater.init +---[totalCost:4ms, parent:0%, all:0%, loopCount:10,000, TPS:2,500,000 start:25,550ms ] - UserBatchCallback.loopProcessVisitable `---[totalCost:1ms, parent:0%, all:0%, loopCount:7,691, TPS:7,691,000 start:25,554ms ] - UserBatchCallback.flush
字段含义
- totalCost: 当前任务总耗时
- selfCost: 当前耗时,将子任务耗时拿开
- parent: 在父任务中所占的耗时比重
- all: 在整个任务中所占的耗时比重
- start: 任务开始至现在的开始时间
- loopCount: 循环变量,用于计算TPS(每秒事务处理量Transaction Per Second)
- TPS: 每秒事务处理量Transaction Per Second
- resultSize: 方法执行的结果集大小
四. API使用
1.最简使用
1 import com.duowan.common.util.Profiler; 2 3 @Test 4 public void test_simple_loop() { 5 int loopCount = 1000000000; 6 Profiler.start("test_simple_loop",loopCount); //开始计时 7 for(int i = 0; i < loopCount; i++) { 8 int a = i * 100; 9 } 10 Profiler.release(); //结束计时 11 12 Profiler.printDump(); //打印日志至控制台 13 }
Profiler.printDump();打印结果
[totalCost:1,750ms, all:100%, loopCount:1,000,000,000, TPS:571,428,571 start:0ms ] - test_simple_loop
2. 子任务的性能分析
1 @Test 2 public void test_loop() { 3 int loopCount = 1000000000; 4 Profiler.start("test_loop_a*100",loopCount); //开始计时 5 for(int i = 0; i < loopCount; i++) { 6 int a = i * 100; 7 } 8 9 testThrowException(); //调用子任务 10 11 Profiler.release(); //结束计时 12 13 Profiler.printDump(); //打印日志至控制台 14 15 } 16 17 private void testThrowException() { 18 int loopCount = 1000000; 19 Profiler.enter("test_throw_exception",loopCount); //进入:子任务计时,如果没有Profiler.start() 该方法将不执行计时操作,不会耗费性能 20 for(int i = 0; i < loopCount; i++) { 21 try { 22 throw new RuntimeException(); 23 }catch(Exception e){ 24 } 25 } 26 Profiler.release(); //结束:子任务计时 27 }
Profiler.printDump();打印结果
[totalCost:4,079ms (selfCost:1,422ms), all:100%, loopCount:1,000,000,000, TPS:703,234,880 start:0ms ] - test_loop_a*100 `---[totalCost:2,657ms, parent:65.1%, all:65.1%, loopCount:1,000,000, TPS:376,364 start:1,422ms ] - test_throw_exception
日志打印API
ProfilerLogger.infoDigestLogAndDump();打印结果 通过这个打印可以打印在日志文件中: digest-profiler.log, dump-profiler.log
2012-10-16 00:06:20.586,4079,test_loop_a*100,Y,0,0, 20