时间监控--Profiler使用方法

一、 概述
Profiler是一个时间统计程序，他通过在程序中埋点，将埋点时间记录入线程变量中以实现革离，最后dump出结果，得出埋点时间树。
二、 Profiler常用方法(Profiler类的静态方法)
 1、Start
当 前线程埋点计时的开始，标识当前埋点的开始时间，每个埋点产生一个Entry，被压入线程变量中的栈中，当start方法被调用时，就是一个时间点栈的开 始，如果start方法被重复调用，则覆盖前面被放入线程变量的栈，每个线程只允许一个栈的存在。该方法的参数标识该Entry信息。
2、 Enter
向线程变量中的栈压入当前埋点信息Profiler.entry("...")，标识当前埋点的开始时间，如果此线程此前未调用start方法，则此方法调用不执行任何操作。
 3、Release
结束栈里当前Entry时间，打上结束时间标识。
 4、GetDuration
获取耗费的总时间，是从start到当前的中时间，如果start的Entry没有被release，则getDuration的结果为-1，所以只有栈的最底层的Entry被release后getDuration得到的数值才有意义。
 5、Dump
当线程内的所有Entry被release后，通过dump的到整个线程内埋点的时间树，列出所有Entry，并统计各自所占用的时间。
 6、Reset
清除当前线程内的计数器栈。当一次调用完成后，在dump出时间树后应该将其清除，并须再次调用start方可重新计时。
三、 Profiler埋点方式
在消息中心项目中主要采用两种埋点方式，一种是业务程序中直接埋入Profiler代码，另一种是利用Spring方法拦截器，将Profiler代码埋入拦截器中。两种方法各有优劣，所以在项目中两种方式综合应用，相互补充。
 1、直接埋点
优点是在业务代码中埋点可以设置任意粒度，能够显示程序中微小范围内的时间变化。
缺点是Profiler耦合进了业务代码，埋点分布于业务程序的各处，不便于阅读和修改，同时由于其要带try{}finally{}块，将业务代码分割的支离破碎，造成业务代码的断层。
用例如下：
  1. public void sendWithChannels(final MessageTaskDO messageTask,    
  2.             final MessageTypeDO messageType,final UserInfoDO userInfo,   
  3.             final int chs) throws MessageException{   
  4.         int channelInt = chs;   
  5.         UserInfoFuture userInfoFuture = null;         
  6.         Profiler.start("TagTask isFinish");   
  7.         try{   
  8.             if (messageTask.getTaskPreStatus() == MessageTaskDO.FALURE_NOTSEND_RETRY   
  9.                     && messageStatusDAO.isFinish(messageTask.getTaskID(), userInfo.getTargetID())){   
  10.                 return;   
  11.             }   
  12.             Profiler.enter("Task Filter");   
  13.             try{   
  14.                 channelInt = getChannelsAfterFilter(messageType, userInfo, channelInt);   
  15.             }finally{   
  16.                 Profiler.release();   
  17.             }   
  18.             Profiler.enter("Task Fill UserInfo");   
  19.             try{   
  20.                 channelInt = getChannelsAfterUInfoFilled(userInfo, userInfoFuture, channelInt);   
  21.             }finally{   
  22.                 Profiler.release();   
  23.             }   
  24.             List<Channel> channels = null;   
  25.             Map<Channel, Integer> channelTemplateId = null;   
  26.             Map<String, String> mapContext = null;   
  27.             Profiler.enter("Task Fill Context");   
  28.             try{   
  29.                 channels = Channel.parseChannels(channelInt);                   
  30.             }finally{   
  31.                 Profiler.release();   
  32.             }   
  33.             Profiler.enter("Task Send with Channels");   
  34.             try{   
  35.                 for (final Channel channel : channels){   
  36.                     final boolean couldSend = true;   
  37.                     String sendToAddress = "";   
  38.                     if (couldSend){   
  39.                         Profiler.enter("send of Channel choose");   
  40.                         if (channel == Channel.WANGWANG){   
  41.                             sendToAddress = userInfo.getUserNick();   
  42.                         }else{   
  43.                             logger.error("MessageTask:" + messageTask.getTaskID() + " is not channel");   
  44.                             continue;   
  45.                         }   
  46.                         final Integer templetId = channelTemplateId.get(channel);   
  47.                         final String replyTo = "taobao@taobao.com";   
  48.                         Profiler.release();                          
  49.                     }   
  50.                 }   
  51.             }finally{   
  52.                 Profiler.release();   
  53.             }   
  54.         }finally{   
  55.             Profiler.release();   
  56.             final String detail = Profiler.dump("Detail: ", "           ");   
  57.             logger.warn(String.format("调用服务：%s的方法%s耗时：%dms，超过预期\n%s\n",   
  58.                     new Object[] {invocation.getThis().getClass().getName(),    
  59.                     invocation.getMethod().getName(),duration, detail }));   
  60.             Profiler.reset();   
  61.         }   
  62.     }  
通过上面代码可以看出，直接埋点虽然可以控制到很小的粒度，但埋点代码混杂于业务代码，将业务代码分割的支离破碎，是一种很不优雅的用法。

 2、Spring拦截器埋点
优点是和业务代码解耦，要统计哪个方法的耗时只需要修改拦截器配置文件和拦截器中的埋点代码即可，和业务代码完全无关。
缺点是埋点粒度只能到方法这个级别，方法内部的耗时统计就无法完成，同时只能拦截Spring Bean的方法，Bean内部间方法调用无法拦截，只能拦截外部调用Bean的方法。
用例如下：

  1. <!-- 自动代理所有的advisor -->  
  2.     <bean id="autoProxyCreator"  
  3.         class="org.springframework.aop.framework.autoproxy.DefaultAdvisorAutoProxyCreator">  
  4.         <property name="proxyTargetClass" value="true"/>  
  5.     </bean>  
  6.     <bean id="interceptorAdvisor"  
  7.         class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">  
  8.         <!-- 业务实现方法名匹配 -->  
  9.        <property name="patterns">  
  10.          <list>  
  11.     <value>com.taobao.messenger.dal.*DAO.*</value>  
  12.     <value>com.taobao.messenger.service.*</value>    
  13.     </list>  
  14.         </property>  
  15.         <property name="advice">  
  16.             <ref bean="interceptorAdvice" />  
  17.         </property>  
  18.     </bean>  
  19.     <bean id="interceptorAdvice"  
  20.      class="com.taobao.messenger.proxy.ProfilerInterceptor">  
  21.     </bean>  
 
  1. public Object invoke(final MethodInvocation invocation) throws Throwable {   
  2.         final String key = invocation.getThis().getClass().getName()   
  3.         +MessageConstants.DOT_SPLIT+invocation.getMethod().getName();   
  4.         boolean resetFlag = false;   
  5.         if(Profiler.getEntry() == null || (key.equals(TagTaskDispatcher.class.getName()   
  6.                 +MessageConstants.DOT_SPLIT+"sendMessage"))){   
  7.             Profiler.start(key);   
  8.             resetFlag = true;   
  9.         }else{   
  10.             Profiler.enter(key);   
  11.         }   
  12.         Object result = null;   
  13.         try{   
  14.             result = invocation.proceed();   
  15.         } finally{   
  16.             Profiler.release();   
  17.             if(resetFlag || (key.equals(TagTaskDispatcher.class.getName()   
  18.                     +MessageConstants.DOT_SPLIT+"sendMessage"))){   
  19.                 try{if(threshold.containsKey(key)){   
  20.                         final Long duration = Profiler.getDuration();   
  21.                         if(duration>threshold.get(key)){   
  22.                             final String detail = Profiler.dump("Detail: ", "           ");   
  23.                             logger.warn(String.format("调用服务：%s的方法%s耗时：%dms，超过预期\n%s\n",   
  24.                                     new Object[] {   
  25.                                     invocation.getThis().getClass().getName(),    
  26.                                     invocation.getMethod().getName(),duration, detail }));   
  27.                         }   
  28.                     }   
  29.                 } finally{   
  30.                     Profiler.reset();   
  31.                 }}   
  32.         }   
  33.         return result;   
  34.     }  

通过上面代码可以看出，Profiler代码和业务代码从表象上看完全无关，从结构上和管理上都比较不错。
四、 Profiler使用中的问题
1、埋点方式的问题
通 过上面埋点方式的分析，两种方式都有自己的优缺点，所以我们采用两种方式综合使用的方针，以Spring拦截器埋点方式为主，在需要被埋点的重要关节，程 序实现的同时尽量将要监控的点放到不通的类里面，被监控的方法粒度尽可能的小，便于配置Spring进行监控。有些相互间关系比较紧密的不容易分割的点和 在debug阶段需要临时监控的点使用直接埋点的方式，进行细粒度的监控，在系统稳定后注释掉临时监控点，保留仍需后续监控的直接埋点，但这种埋点要尽可 能的少。
2、内存泄露的问题
一定要将Profiler.start()方法和Profiler.reset()方法写入 try{}finally{}块中，确保Profiler.reset()方法一定被调用来释放资源，否则如果中间出现异常跳过资源释放操作将引发内存泄 露。同理Profiler.release()方法也应该写入finally块里，跳过虽然不会引发内存泄露，但会导致埋点时间计算错误。这点用 Spring拦截器比较好控制，只要控制住出口和入口就行。
3、时间树输出的问题
在多线程环境下一般在在线程的出口输出时间树即可，在 线程中间（非start方法对应的栈）不要用getDuration获取总耗时，此时只能得到-1,因为getDuration是求最底层Entry的耗 时的，中间状态通常最底层的Entry没被release，没办法获得耗时。
4、方法对
Profiler.start() 和 Profiler.reset()要成对出现，reset()及时释放内存，防止内存泄露；
Profiler.enter() 和 Profiler.release() 要成对出现，release()是时间段结束埋点，内存中打上此enter结束的时间点。

产生结果树如下:

  1. [WARN ] 2009-06-30 15:46:06,517 [TaskExecuteThread- 1-priority-1] [proxy.ProfilerInterceptor] - 调用服 务：com.taobao.messenger.control.impl.DefaultTaskController的方法send耗 时：375ms，超过预期   
  2. Detail: 0 [375ms (219ms), 100%] - com.taobao.messenger.control.impl.DefaultTaskController.send   
  3.            +---47 [0ms] - com.taobao.messenger.dal.ibatis.IbatisMessageTypeDAO.getMessageTypeById   
  4.            `---219 [156ms (16ms), 42%, 42%] - com.taobao.messenger.control.impl.DelegateTaskController.sendWithChannels   
  5.                +---235 [0ms] - TagTask isFinish   
  6.                +---235 [62ms, 40%, 17%] - Task Filter   
  7.                |   `---235 [62ms, 100%, 17%] - com.taobao.messenger.dal.ibatis.IbatisSubscriptionInfoDAO.getUserSubscriptionInfo   
  8.                +---297 [0ms] - Task Fill UserInfo   
  9.                |   `---297 [0ms] - Task fill from UIC   
  10.                +---297 [0ms] - Task Fill Context   
  11.                `---297 [78ms, 50%, 21%] - Task Send with Channels   
  12.                    +---297 [0ms] - send of Channel choose   
  13.                    +---297 [31ms (16ms), 40%, 8%] - render getTempletId   
  14.                    |   `---313 [15ms, 48%, 4%] - com.taobao.messenger.dal.ibatis.IbatisMessageTemplateDAO.getMessageTempletByID   
  15.                    +---328 [47ms, 60%, 13%] - render content   
  16.                    +---375 [0ms] - render subject   
  17.                    +---375 [0ms] - render fill message   
  18.                    +---375 [0ms] - put message into gateway   
  19.                    +---375 [0ms] - send of Channel choose   
  20.                    +---375 [0ms] - render getTempletId   
  21.                    |   `---375 [0ms] - com.taobao.messenger.dal.ibatis.IbatisMessageTemplateDAO.getMessageTempletByID   
  22.                    +---375 [0ms] - render content   
  23.                    +---375 [0ms] - render subject   
  24.                    +---375 [0ms] - render fill message   
  25.                    +---375 [0ms] - put message into gateway   
  26.                    +---375 [0ms] - send of Channel choose   
  27.                    +---375 [0ms] - render getTempletId   
  28.                    |   `---375 [0ms] - com.taobao.messenger.dal.ibatis.IbatisMessageTemplateDAO.getMessageTempletByID   
  29.                    +---375 [0ms] - render content   
  30.                    +---375 [0ms] - render subject   
  31.                    +---375 [0ms] - render fill message   
  32.                    +---375 [0ms] - put message into gateway   
  33.                    +---375 [0ms] - send of Channel choose   
  34.                    +---375 [0ms] - render getTempletId   
  35.                    |   `---375 [0ms] - com.taobao.messenger.dal.ibatis.IbatisMessageTemplateDAO.getMessageTempletByID   
  36.                    +---375 [0ms] - render content   
  37.                    +---375 [0ms] - render subject   
  38.                    +---375 [0ms] - render fill message   
  39.                    `---375 [0ms] - put message into gateway 
posted @ 2011-06-22 19:15  跳刀的兔子  阅读(6842)  评论(1)  编辑  收藏  举报