项目添加性能监控日志

转载自https://my.oschina.net/zhangxufeng/blog/1542676

性能日志监控目前有一些框架使用，博主是自己实现的一个性能监控日志

   在项目发展初期，可能由于数据量和用户访问量的原因，系统不会出现性能问题，但是随着项目发展，数据量发生具体变化，系统访问量也不断增多，此时对代码的优化就显得迫在眉睫。本文首先讲解如何使用perf4j和aop定期的完成相关日志的统计，其次讲解了如何使用ThreadLocal变量记录一个请求从开始到结束过程中所产生的调用链，并且记录相关方法的调用时间，最后将演示如何使用shell脚本对生成的日志文件进行处理，并生成性能统计报告。

       perf4j是一种日志统计工具，其不仅可以进行日志的实时统计，也可以进行定时汇总统计。实时统计主要是记录项目运行过程中的一些消息日志，以便后续排查问题；而定时汇总统计则可用于对方法调用时间进行汇总，并且perf4j能够进行计算每个时间间隔内所有方法的最小调用时间，最大调用时间，平均调用时间，调用次数以及调用方差。这里主要讲解如何使用perf4j进行定时时间统计，如下是在log4j.xml中对service方法进行时间统计的配置：

<!-- service perf log -->
<logger name="service.perf.logger" additivity="false">
	<level value="info"/>
	<appender-ref ref="CoalescingStatistics_Service"/>
</logger>

       这里name属性用于指定log的名称，其与代码中LogFactory.getLog(name)中的name对应，level表示打印info及以上级别的日志，appender-ref则配置了日志的相关打印策略，如：打印时间，日志文件目录以及日志文件的生成策略等。如下是CoalescingStatistics_Service的具体配置：

<!--service perf log -->
<appender name="CoalescingStatistics_Service"
		  class="org.perf4j.log4j.AsyncCoalescingStatisticsAppender">
	<!-- TimeSlice配置多少时间间隔去做一次汇总写入文件中 默认值是 30000 ms -->
	<param name="TimeSlice" value="10000"/>
	<appender-ref ref="statFileAppender_service"/>
</appender>

       这里AsyncCoalescingStatisticsAppender会将一段时间内StopWatch的信息汇总到一个独立的GroupedTimeingStatistics日志信息，然后把这个信息传递给下游的appender。TimeSlice配置了间隔多长时间进行一次日志统计，默认是30s，这里配置为每10s进行一次日志统计。appender-ref则指定了日志统计方式，如下是statFileAppender_service的具体配置：

<!--service perf log -->
<appender name="statFileAppender_service" class="org.apache.log4j.DailyRollingFileAppender">
	<param name="File" value="${catalina.base}/logs/service_perf/perfStats.log"/>
	<param name="DatePattern" value="'_'yyyy-MM-dd"/>
	<layout class="org.apache.log4j.PatternLayout">
		<param name="ConversionPattern" value="%m%n"/>
	</layout>
</appender>

       DailyRollingFileAppender表示每天产生一个新的日志文件，DatePattern则指定了新产生的日志文件的文件名格式，File主要指定了当前日志文件的存放路径。如此log4j.xml配置完成。

       性能日志统计与项目的主业务流程无关，并且其是针对整个某一层(controller，service和dao等)的请求进行的，因而使用spring的aop进行统计再好不过了。这里需要说明的是，perf4j中使用的是StopWatch进行日志的记录，StopWatch中需要为每次调用分配一个tag，其会将在指定时间段内的tag进行分组，并且为每一组数据进行次数，最小，最大值以及平均值等的统计。因此这里的tag其实可以理解为service层的每个方法，StopWatch会自动为每个方法进行性能统计。如下是使用aop统计性能日志的代码：

@Aspect
public class Perf4jLogAspect {
  private static final String STOP_WATCH_LOGGER_NAME = "service.perf.logger";
  private static final Log STOP_WATCH_LOGGER = LogFactory.getLog(STOP_WATCH_LOGGER_NAME);

  @Around("execution(public * com..*.service..*.*(..))")
  public Object logPer4jLogs(ProceedingJoinPoint pjp) throws Throwable {
    String className = pjp.getSignature().getDeclaringTypeName();
    String methodName = pjp.getSignature().getName();
    String name = className.substring(className.lastIndexOf(".") + 1) + "." + methodName;
    StopWatch stopWatch = new CommonsLogStopWatch(STOP_WATCH_LOGGER);
    Object retVal = pjp.proceed();
    stopWatch.stop(name);

    return retVal;
  }
}

       这里@Around()里面省略了部分与实际项目相关的路径，读者可根据实际情况进行配置。@Aspect表示当前类是一个切面类，@Around则定义了具体的切点位置，STOP_WATCH_LOGGER_NAME与log4j.xml中配置的名称相同。从代码里可以看出，我们是将"类型.方法名"作为tag进行分组统计。由此，使用perf4j进行定时性能统计的相关代码已经完成，如下是项目实际运行过程中的日志记录：

       在项目运行过程中，仅仅进行日志的打印还是不够的，我们需要定期对日志进行统计汇总，以查找消耗时间过长的方法，并且分析相关方法是否需要进行优化，如下日志进行按照最大消耗时间降序排序的shell脚本：

#!/bin/bash

file_name=$1
echo "" | awk '
{
        printf("%-70s %10s %10s %10s %3s
", "interface", "avg_time", "min_time", "max_time", "count");
}
'
awk ' 
{
#       printf("%-70s %s %s
", "interface", "max_time", "count");
        if($1 ~ /com/) {
                len=split($1,arr,".");
                method_str="";
                for(i=len-1;i<=len;++i) {
                        method_str = method_str"."arr[i];
                }
                printf("%-70s %10.2f %10d %10d %3d
", method_str, $2, $3, $4, $6);
        }
}
' $file_name | sort -k 6 -r -n | more

        同理，我们也可以按照调用次数进行排序，这里只需要将上述脚本中“sort -k 6 -r -n”部分的6改为4即可，该数字表示按照哪一列进行排序。如下是按照最大时间降序排序的示例：

       正常情况下，上述日志统计方式已经能够协助排查大部分问题了，比如某个请求过程中所有service和dao方法的时长记录，找出消耗时长最长的方法并进行优化。但是在生产环境，我们发现上述方式还不能完全定位相关性能问题，主要原因有如下几点：

• 为了展示内容的清晰，service方法和dao方法一般会分文件存放，这就导致无法直观的查看service和dao方法调用的嵌套关系（从上述日志排版方式可以看出，即使放到同一个文件中也无法查看嵌套关系）；
• 核心请求的调用方法非常多，并且由于service嵌套的原因，如果某个内层方法调用时长较长，会导致外层方法调用时长都较长；
• 由于统计的是时间段内的所有方法调用，因而会将这段时间内所有请求的记录都进行汇总，无法定位某次请求某个方法的调用记录；
• 由于项目中使用了一些其他同事提供的第三方jar包（如es搜索），这些jar包的方法调用并不在定义的切点范围内，因而无法定位其性能消耗。

       为了处理上述问题，我们实际上希望以另一种方式进行日志统计，并且希望实现两个目标：

• 可选择性查看某次请求的调用栈信息；
• 日志展示时能够以层次分明的方式进行展示，从而定位消耗时长最长的某几个方法。

       针对上述两个目标，我们使用aop和ThreadLocal对方法调用的相关栈轨迹进行了记录，并且记录其调用时间，并且编写了相关shell脚本进行日志的统计打印。如下是log4j.xml中进行的实时记录日志配置：

<logger name="performance.interceptor.logger" additivity="false">
    <level value="info"/>
    <appender-ref ref="performanceLogger"/>
</logger>

<appender name="performanceLogger" class="org.apache.log4j.DailyRollingFileAppender">
    <param name="File" value="${catalina.base}/logs/site/performance.log"/>
    <param name="DatePattern" value="'_'yyyy-MM-dd"/>
    <layout class="com.homethy.lead.sites.util.SiteLogLayout">
    </layout>
</appender>

       我们首先定义了一个优先级最高的拦截器PerformanceInterceptor，用于记录每次请求从开始到结束所进行的所有时间调用，其主要代码如下：

public class PerformanceInterceptor implements HandlerInterceptor {
  private static final Log PERFORMANCE_LOGGER = LogFactory.getLog("performance.interceptor.logger");
  private static final Log SWITCH_LOGGER = LogFactory.getLog(StopWatch.DEFAULT_LOGGER_NAME);
  private static final String STOPWATCH_NAME = "stopWatch";

  @Override
  public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object
      handler) throws Exception {
    long start = System.currentTimeMillis();
    SiteContextUtil.logTime("performanceInterceptor", start, START);
    request.setAttribute("performanceStartTime", start);
    return true;
  }

  @Override
  public void postHandle(HttpServletRequest request, HttpServletResponse response, Object
      handler, ModelAndView model) throws Exception {

  }

  @Override
  public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object
      handler, Exception exception) throws Exception {
    SiteContextUtil.logTime("performanceInterceptor", System.currentTimeMillis(), END);
    long start = (long)request.getAttribute("performanceStartTime");
    try {
      if (System.currentTimeMillis() - start >= 2000) {
        PERFORMANCE_LOGGER.info("request url: " + request.getRequestURL() + "|" + SiteContextUtil.printMethodInvokeChain());
      }
    } catch (RuntimeException e) {
      PERFORMANCE_LOGGER.info("invoke method performance method error, message is: " + e);
    }
  }
}

       这里SiteContextUtil.logTime(String method, Long currentTime, PerformanceType type)，该方法用于记录每次方法调用开始或者结束的时间点，用于后续统计使用；SiteContextUtil.printMethodInvokeChain()方法则主要是对记录的时间点信息进行统计，并打印到日志文件中。另外，我们使用try...catch语句将统计的时间进行汇总的过程包装起来，以避免该统计过程中处理不可预知的错误，从而影响主要业务功能。如下是SiteContextUtil的具体代码：

public class SiteContextUtil {
  private static final Log LOG = LogFactory.getLog(SiteContextUtil.class);
  public static final ThreadLocal<LinkedList<Node>> methodInvokeChain = new ThreadLocal<>();
  
  public static void logTime(String method, Long currentTime, PerformanceType type) {
    Node node = new Node();
    node.method = method;
    node.time = currentTime;
    node.type = type;
    LinkedList<Node> chain = methodInvokeChain.get();
    if (null == chain) {
      chain = new LinkedList<>();
      methodInvokeChain.set(chain);
    }

    chain.push(node);
  }

  public static String printMethodInvokeChain() {
    LinkedList<Node> chain = methodInvokeChain.get();
    if (null == chain) {
      return "empty method invoke chain";
    }

    StringBuilder results = new StringBuilder();
    results.append("method|start|end|cost|");
    LinkedList<String> resultChain = new LinkedList<>();
    LinkedList<Node> notPaired = new LinkedList<>();  // 记录没有配对的节点
    while (!chain.isEmpty()) {
      Node method = chain.poll();
      Node pair = notPaired.peek();
      if (null == pair) {  // 为空说明是最开始进行的遍历
        notPaired.push(method);
        continue;
      }

      // 比较当前链中弹出的元素与未配对的元素的类型，如果是同一类型，
      // 说明都是退出点元素，继续将其push进入未配对类型中
      if (method.type == pair.type) {
        notPaired.push(method);
        continue;
      }

      // 链表中的最后一个元素与未配对链表的最后一个元素是不同类型的，说明其是同一
      // 方法的进入点和退出点，配对成功，这里记录该方法的消耗时间，如果小于200ms则不记录该方法
      long cost = pair.time - method.time;
      notPaired.poll();
      if (cost < 200) {
        continue;
      }

      // 对于配对的方法以“方法名|开始时间|结束时间|消耗时间”的格式进行记录
      String result = method.method + "|" + method.time + "|" + pair.time + "|" + cost + "|";
      resultChain.addFirst(result);
    }

    // 将所有的方法消耗记录以上述格式都放在同一个字符串中，以防止日志打印时将其分开而无法其调用方
    resultChain.forEach(result -> results.append(result));
    return results.subSequence(0, results.length() - 1).toString();
  }

  private static final class Node {
    public String method;
    public Long time;
    public PerformanceType type = PerformanceType.START;
  }
}

       由于每次方法的调用都有进方法的时间点和出方法的时间点，该时间差也即该方法的调用时长，并且我们需要考虑的问题还有方法的嵌套调用，递归调用等问题，因而实际的调用过程是非常复杂的，这里我们处理方法调用链的思路是在每个方法的调用前记录一个时间，并且记录该时间点是方法进入点还是退出点，然后处理过程和栈非常类似，每次添加一个时间点元素即是一次push操作，如上述logTime()方法，而对记录的处理过程则是从栈进行pop元素，并且进行时间点的配对的操作（一个方法可能调用多次，因而一个退出点需要和正确的进入点进行配对），为如下是记录进入或退出点的枚举类：

public enum PerformanceType {
  START, END
}

       这里需要说明的是，在生成调用记录的过程中，由于一次请求的方法调用链是非常长的，而有的方法，比如仅仅只是一次dao查询，其消耗的时间可能不到1ms，这种类型因而我们对其进行了过滤，而只统计方法消耗时长超过200ms的方法；另外，我们在拦截器中进行了判断，如果一次请求的消耗时间不超过2s，我们也会对其进行过滤。如此我们则完成了方法统计的相关方法，接下来则是通过aop产生各个方法的基本记录点，这里我们以service，dao和第三方jar包的入口方法为例展示其代码的编写。

1. service切入

@Aspect
public class Perf4jLogAspect {

  @Around("execution(public * com..*.service..*.*(..))")
  public Object logPer4jLogs(ProceedingJoinPoint pjp) throws Throwable {
    String className = pjp.getSignature().getDeclaringTypeName();
    String methodName = pjp.getSignature().getName();
    String name = className.substring(className.lastIndexOf(".") + 1) + "." + methodName;
    SiteContextUtil.logTime(name, System.currentTimeMillis(), START);
    Object retVal = pjp.proceed();
    SiteContextUtil.logTime(name, System.currentTimeMillis(), END);

    return retVal;
  }
}

2. dao切入

@Intercepts(@Signature(
    type = Executor.class,
    method = "query",
    args = {MappedStatement.class, Object.class, RowBounds.class, ResultHandler.class}
))
public class DaoInterceptor implements Interceptor {

  public Object intercept(Invocation inv) throws InvocationTargetException, IllegalAccessException {
    MappedStatement mappedStatement = (MappedStatement)inv.getArgs()[0];
    String name = mappedStatement.getId();
    String methodName = name.substring(name.lastIndexOf(".") + 1);
    name = name.substring(0, name.lastIndexOf("."));
    String className = name.substring(name.lastIndexOf(".") + 1);
    String fullName = className + "." + methodName;
    SiteContextUtil.logTime(fullName, System.currentTimeMillis(), START);
    Object result = inv.proceed();
    SiteContextUtil.logTime(fullName, System.currentTimeMillis(), END);
    
    return result;
  }
}

3. search jar包

private static class SearchHandler implements MethodInterceptor {
  @Override
  public Object intercept(Object obj, Method method, Object[] args, MethodProxy proxy) throws Throwable {
    switch (method.getName()) {
      case SEARCH:
        return searchMethod(obj, method, args, proxy);
      default:
        return proxy.invokeSuper(obj, args);
    }
  }

  private Object searchMethod(Object obj, Method method, Object[] args, MethodProxy proxy) {
    String tag = getLogTag(proxy);
    long start = System.currentTimeMillis();
    SiteContextUtil.logTime(tag, start, START);
    QueryResult queryResult = invoke(obj, args, proxy);
    long end = System.currentTimeMillis();
    SiteContextUtil.logTime(tag, end, END);
    return queryResult;
  }
  
  private String getLogTag(MethodProxy proxy) {
      String methodName = proxy.getSignature().getName();
      String argNames = getClassNames(proxy.getSignature().getArgumentTypes());
      return methodName + "(" + argNames + ")";
  }
  
  // 略去其余方法
}

       这里我们就完成了使用调用链的方式对方法性能进行统计的功能，下图展示了某次性能调用时间过长的日志：

       通过该日志我们还不能直观的看出此次调用过程中具体是哪几个方法调用时间过长，因此我们编写了该日志分析的shell脚本。脚本编写的基本思路如下：

• 对每个方法都往前遍历，当找到第一个方法满足当前方法的开始时间比该方法的大，结束时间比该方法的小，那么说明当前方法就是该方法的子方法，也即被该方法直接或间接调用了；
• 为了展示层次结构，使用一个数组记录之前已经处理完成的每个方法的缩进空格数；
• 在开始对当前方法往前遍历之前，默认当前方法为前一个方法的子方法，也即比该方法多两个空格，遍历开始之后每当当前方法不满足一次第一条的时候当前方法的空格数减2（每个缩进数目为2）；
• 传入一个数目，标识要处理的慢请求日志的条数，也即将产生的树形结构的数目。

       根据上述缩进的思路，我们编写的shell脚本如下：

#!/bin/bash

lines=$1
fileName=$2

if [ ! $lines ];
then
  echo "lines is empty, use default lines 1000 to calculate relative statistics! "
  lines=1000;
fi

directory=`pwd`
if [ "$fileName" = "" ];
then
  echo "file name is empty, read performance.log from current package! "
  fileName=${directory}/performance.log
fi

`tail -n ${lines} ${fileName} > line_tmp.log`

while read row
do

  line=${row##*request url: }

  OLD_IFS="$IFS"
  IFS="|"
  perfs=($line)
  IFS="$OLD_IFS"

 echo "*************************************************line break*************************************************"
  declare -a array;
  array[5]="";
  for((i=5; i<${#perfs[*]}-2; i=i+4))
  do
    array[i]="";
    for((j=i-4; j>4; j=j-4))
    do
      if [ ${perfs[j+2]} -ge ${perfs[i+2]} ];
      then
        array[i]="${array[j]}""  "
        break;
      fi
    done
    
    tag="${array[i]}""${perfs[i]}"
    printf "%-64s %-16s %-16s %-16s
" "${tag}" ${perfs[i+1]} ${perfs[i+2]} ${perfs[i+3]}
${perfs[i+3]}`
  done
done < line_tmp.log

       这里说明一下，这是本人第一次写shell脚本处理解析日志，其中可能有一些高手看着不顺眼的地方，大家可以忽略不计，如果大家感兴趣，也可以按照上述思路自己重写该脚本（话说第一次写脚本，其中各种错误，而且还涉及到一定的算法，有点时候都不知道自己写的语法对不对，各种心塞）。下图展示了使用上述脚本解析出的慢请求的效果：

       上图展示了三种典型的调用情形，对于第一个次请求，可以看到，前三个方法中第一个方法占用226ms，而底层的search(ListingQuery)方法占用205ms，由此可看出其是搜索部分占用时长较高；对于第二次请求，第二个方法的结束时间比第一个方法的要高，说明这两个方法并没有嵌套关系，处于并行状态，而第二个方法最主要是search(ListingQuery)方法占用时间较长；对于第三次请求，仔细观察第一个方法，其占用时长2473ms，而第二个到第四个方法的结束时间都比前一个方法要高，并且都在第一个方法内，说明第二三四个方法是并行调用，并且都是由第一个方法调用的，另外可以观察到，第一个方法的调用时长差不多正好是第二三四个方法的调用时长的和。

       在项目中，我们使用了Nginx进行负载均衡，并且在Nginx中配置了如果某次请求超过2s则会给主要技术负责人发送报警短信（这也是我们前面设置只打印时长超过2s的日志的原因）。在某次上线完成之后我们发现报警短信发送非常频繁，并且都是和主要业务相关，刚开始我们以为是和搜索服务造成的，因为之前经常出现搜索服务查询时间比较长的问题。后来我们使用该脚本解析了线上最近100次满请求的日志，解析结果如下：

       从该图片可以看出，根节点是大多是SysArgDao.getGlobalSysArg()和WebsiteConfigDao.getConfigs()方法，因而初步判断可以排除是搜索服务调用时间过长的问题，大致可以猜测出是数据库服务不稳定造成的。继续看这两个方法的上一节点，其为ListingInfoServiceImpl.transformListingInfos()方法，通过具体业务知道，该方法是一个循环调用，每次调用过程中都会调用一次SysArgDao.getGlobalSysArg()和WebsiteConfigDao.getConfigs()方法。基于这个猜测，我们查看了使用perf4j产生的dao方法调用统计，按照降序排序之后结果如下：

       从图中可以看出，SysArgDao.getGlobalSysArg()和WebsiteConfigDao.getConfigs()这两个方法的调用次数非常大，10s之内可以产生1w多次调用，因而这里可以确认的就是系统服务较为缓慢的原因就是这两个方法被循环调用了，但是比较奇怪的是ListingInfoServiceImpl.transformListingInfos()在最近几次上线都没有进行过修改，而偏偏这次出现了这个问题，后来我们查看了使用show processlist查看了数据库的进程情况，发现有两条binlog的复制记录，由此我们可以基本确认，造成服务性能较低主要有两个原因：①数据库正在进行数据同步，造成数据库资源不足；②代码中有循环调用，造成方法调用时间过长。