目的
打印系统的性能分析日志,用于分析系统性能
一.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