???????在項目發(fā)展初期,可能由于數(shù)據(jù)量和用戶訪問量的原因,系統(tǒng)不會出現(xiàn)性能問題,但是隨著項目發(fā)展,數(shù)據(jù)量發(fā)生具體變化,系統(tǒng)訪問量也不斷增多,此時對代碼的優(yōu)化就顯得迫在眉睫。本文首先講解如何使用perf4j和aop定期的完成相關(guān)日志的統(tǒng)計,其次講解了如何使用ThreadLocal變量記錄一個請求從開始到結(jié)束過程中所產(chǎn)生的調(diào)用鏈,并且記錄相關(guān)方法的調(diào)用時間,最后將演示如何使用shell腳本對生成的日志文件進行處理,并生成性能統(tǒng)計報告。
???????perf4j是一種日志統(tǒng)計工具,其不僅可以進行日志的實時統(tǒng)計,也可以進行定時匯總統(tǒng)計。實時統(tǒng)計主要是記錄項目運行過程中的一些消息日志,以便后續(xù)排查問題;而定時匯總統(tǒng)計則可用于對方法調(diào)用時間進行匯總,并且perf4j能夠進行計算每個時間間隔內(nèi)所有方法的最小調(diào)用時間,最大調(diào)用時間,平均調(diào)用時間,調(diào)用次數(shù)以及調(diào)用方差。這里主要講解如何使用perf4j進行定時時間統(tǒng)計,如下是在log4j.xml中對service方法進行時間統(tǒng)計的配置:
<!-- 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對應(yīng),level表示打印info及以上級別的日志,appender-ref則配置了日志的相關(guān)打印策略,如:打印時間,日志文件目錄以及日志文件的生成策略等。如下是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會將一段時間內(nèi)StopWatch的信息匯總到一個獨立的GroupedTimeingStatistics日志信息,然后把這個信息傳遞給下游的appender。TimeSlice配置了間隔多長時間進行一次日志統(tǒng)計,默認是30s,這里配置為每10s進行一次日志統(tǒng)計。appender-ref則指定了日志統(tǒng)計方式,如下是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表示每天產(chǎn)生一個新的日志文件,DatePattern則指定了新產(chǎn)生的日志文件的文件名格式,F(xiàn)ile主要指定了當前日志文件的存放路徑。如此log4j.xml配置完成。
???????性能日志統(tǒng)計與項目的主業(yè)務(wù)流程無關(guān),并且其是針對整個某一層(controller,service和dao等)的請求進行的,因而使用spring的aop進行統(tǒng)計再好不過了。這里需要說明的是,perf4j中使用的是StopWatch進行日志的記錄,StopWatch中需要為每次調(diào)用分配一個tag,其會將在指定時間段內(nèi)的tag進行分組,并且為每一組數(shù)據(jù)進行次數(shù),最小,最大值以及平均值等的統(tǒng)計。因此這里的tag其實可以理解為service層的每個方法,StopWatch會自動為每個方法進行性能統(tǒng)計。如下是使用aop統(tǒng)計性能日志的代碼:
@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()里面省略了部分與實際項目相關(guān)的路徑,讀者可根據(jù)實際情況進行配置。@Aspect表示當前類是一個切面類,@Around則定義了具體的切點位置,STOP_WATCH_LOGGER_NAME與log4j.xml中配置的名稱相同。從代碼里可以看出,我們是將"類型.方法名"作為tag進行分組統(tǒng)計。由此,使用perf4j進行定時性能統(tǒng)計的相關(guān)代碼已經(jīng)完成,如下是項目實際運行過程中的日志記錄:

???????在項目運行過程中,僅僅進行日志的打印還是不夠的,我們需要定期對日志進行統(tǒng)計匯總,以查找消耗時間過長的方法,并且分析相關(guān)方法是否需要進行優(yōu)化,如下日志進行按照最大消耗時間降序排序的shell腳本:
#!/bin/bash
file_name=$1
echo "" | awk '
{
printf("%-70s %10s %10s %10s %3s\n", "interface", "avg_time", "min_time", "max_time", "count");
}
'
awk '
{
# printf("%-70s %s %s\n", "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\n", method_str, $2, $3, $4, $6);
}
}
' $file_name | sort -k 6 -r -n | more
????????同理,我們也可以按照調(diào)用次數(shù)進行排序,這里只需要將上述腳本中“sort -k 6 -r -n”部分的6改為4即可,該數(shù)字表示按照哪一列進行排序。如下是按照最大時間降序排序的示例:

???????正常情況下,上述日志統(tǒng)計方式已經(jīng)能夠協(xié)助排查大部分問題了,比如某個請求過程中所有service和dao方法的時長記錄,找出消耗時長最長的方法并進行優(yōu)化。但是在生產(chǎn)環(huán)境,我們發(fā)現(xiàn)上述方式還不能完全定位相關(guān)性能問題,主要原因有如下幾點:
- 為了展示內(nèi)容的清晰,service方法和dao方法一般會分文件存放,這就導(dǎo)致無法直觀的查看service和dao方法調(diào)用的嵌套關(guān)系(從上述日志排版方式可以看出,即使放到同一個文件中也無法查看嵌套關(guān)系);
- 核心請求的調(diào)用方法非常多,并且由于service嵌套的原因,如果某個內(nèi)層方法調(diào)用時長較長,會導(dǎo)致外層方法調(diào)用時長都較長;
- 由于統(tǒng)計的是時間段內(nèi)的所有方法調(diào)用,因而會將這段時間內(nèi)所有請求的記錄都進行匯總,無法定位某次請求某個方法的調(diào)用記錄;
- 由于項目中使用了一些其他同事提供的第三方j(luò)ar包(如es搜索),這些jar包的方法調(diào)用并不在定義的切點范圍內(nèi),因而無法定位其性能消耗。
???????為了處理上述問題,我們實際上希望以另一種方式進行日志統(tǒng)計,并且希望實現(xiàn)兩個目標:
- 可選擇性查看某次請求的調(diào)用棧信息;
- 日志展示時能夠以層次分明的方式進行展示,從而定位消耗時長最長的某幾個方法。
???????針對上述兩個目標,我們使用aop和ThreadLocal對方法調(diào)用的相關(guān)棧軌跡進行了記錄,并且記錄其調(diào)用時間,并且編寫了相關(guān)shell腳本進行日志的統(tǒng)計打印。如下是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>
???????我們首先定義了一個優(yōu)先級最高的攔截器PerformanceInterceptor,用于記錄每次請求從開始到結(jié)束所進行的所有時間調(diào)用,其主要代碼如下:
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),該方法用于記錄每次方法調(diào)用開始或者結(jié)束的時間點,用于后續(xù)統(tǒng)計使用;SiteContextUtil.printMethodInvokeChain()方法則主要是對記錄的時間點信息進行統(tǒng)計,并打印到日志文件中。另外,我們使用try...catch語句將統(tǒng)計的時間進行匯總的過程包裝起來,以避免該統(tǒng)計過程中處理不可預(yù)知的錯誤,從而影響主要業(yè)務(wù)功能。如下是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<>(); // 記錄沒有配對的節(jié)點
while (!chain.isEmpty()) {
Node method = chain.poll();
Node pair = notPaired.peek();
if (null == pair) { // 為空說明是最開始進行的遍歷
notPaired.push(method);
continue;
}
// 比較當前鏈中彈出的元素與未配對的元素的類型,如果是同一類型,
// 說明都是退出點元素,繼續(xù)將其push進入未配對類型中
if (method.type == pair.type) {
notPaired.push(method);
continue;
}
// 鏈表中的最后一個元素與未配對鏈表的最后一個元素是不同類型的,說明其是同一
// 方法的進入點和退出點,配對成功,這里記錄該方法的消耗時間,如果小于200ms則不記錄該方法
long cost = pair.time - method.time;
notPaired.poll();
if (cost < 200) {
continue;
}
// 對于配對的方法以“方法名|開始時間|結(jié)束時間|消耗時間”的格式進行記錄
String result = method.method + "|" + method.time + "|" + pair.time + "|" + cost + "|";
resultChain.addFirst(result);
}
// 將所有的方法消耗記錄以上述格式都放在同一個字符串中,以防止日志打印時將其分開而無法其調(diào)用方
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;
}
}
???????由于每次方法的調(diào)用都有進方法的時間點和出方法的時間點,該時間差也即該方法的調(diào)用時長,并且我們需要考慮的問題還有方法的嵌套調(diào)用,遞歸調(diào)用等問題,因而實際的調(diào)用過程是非常復(fù)雜的,這里我們處理方法調(diào)用鏈的思路是在每個方法的調(diào)用前記錄一個時間,并且記錄該時間點是方法進入點還是退出點,然后處理過程和棧非常類似,每次添加一個時間點元素即是一次push操作,如上述logTime()方法,而對記錄的處理過程則是從棧進行pop元素,并且進行時間點的配對的操作(一個方法可能調(diào)用多次,因而一個退出點需要和正確的進入點進行配對),為如下是記錄進入或退出點的枚舉類:
public enum PerformanceType {
START, END
}
???????這里需要說明的是,在生成調(diào)用記錄的過程中,由于一次請求的方法調(diào)用鏈是非常長的,而有的方法,比如僅僅只是一次dao查詢,其消耗的時間可能不到1ms,這種類型因而我們對其進行了過濾,而只統(tǒng)計方法消耗時長超過200ms的方法;另外,我們在攔截器中進行了判斷,如果一次請求的消耗時間不超過2s,我們也會對其進行過濾。如此我們則完成了方法統(tǒng)計的相關(guān)方法,接下來則是通過aop產(chǎn)生各個方法的基本記錄點,這里我們以service,dao和第三方j(luò)ar包的入口方法為例展示其代碼的編寫。
- 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;
}
}
- 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;
}
}
- 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 + ")";
}
// 略去其余方法
}
???????這里我們就完成了使用調(diào)用鏈的方式對方法性能進行統(tǒng)計的功能,下圖展示了某次性能調(diào)用時間過長的日志:

???????通過該日志我們還不能直觀的看出此次調(diào)用過程中具體是哪幾個方法調(diào)用時間過長,因此我們編寫了該日志分析的shell腳本。腳本編寫的基本思路如下:
- 對每個方法都往前遍歷,當找到第一個方法滿足當前方法的開始時間比該方法的大,結(jié)束時間比該方法的小,那么說明當前方法就是該方法的子方法,也即被該方法直接或間接調(diào)用了;
- 為了展示層次結(jié)構(gòu),使用一個數(shù)組記錄之前已經(jīng)處理完成的每個方法的縮進空格數(shù);
- 在開始對當前方法往前遍歷之前,默認當前方法為前一個方法的子方法,也即比該方法多兩個空格,遍歷開始之后每當當前方法不滿足一次第一條的時候當前方法的空格數(shù)減2(每個縮進數(shù)目為2);
- 傳入一個數(shù)目,標識要處理的慢請求日志的條數(shù),也即將產(chǎn)生的樹形結(jié)構(gòu)的數(shù)目。
???????根據(jù)上述縮進的思路,我們編寫的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\n" "${tag}" ${perfs[i+1]} ${perfs[i+2]} ${perfs[i+3]}
${perfs[i+3]}`
done
done < line_tmp.log
???????這里說明一下,這是本人第一次寫shell腳本處理解析日志,其中可能有一些高手看著不順眼的地方,大家可以忽略不計,如果大家感興趣,也可以按照上述思路自己重寫該腳本(話說第一次寫腳本,其中各種錯誤,而且還涉及到一定的算法,有點時候都不知道自己寫的語法對不對,各種心塞)。下圖展示了使用上述腳本解析出的慢請求的效果:

???????上圖展示了三種典型的調(diào)用情形,對于第一個次請求,可以看到,前三個方法中第一個方法占用226ms,而底層的search(ListingQuery)方法占用205ms,由此可看出其是搜索部分占用時長較高;對于第二次請求,第二個方法的結(jié)束時間比第一個方法的要高,說明這兩個方法并沒有嵌套關(guān)系,處于并行狀態(tài),而第二個方法最主要是search(ListingQuery)方法占用時間較長;對于第三次請求,仔細觀察第一個方法,其占用時長2473ms,而第二個到第四個方法的結(jié)束時間都比前一個方法要高,并且都在第一個方法內(nèi),說明第二三四個方法是并行調(diào)用,并且都是由第一個方法調(diào)用的,另外可以觀察到,第一個方法的調(diào)用時長差不多正好是第二三四個方法的調(diào)用時長的和。
???????在項目中,我們使用了Nginx進行負載均衡,并且在Nginx中配置了如果某次請求超過2s則會給主要技術(shù)負責(zé)人發(fā)送報警短信(這也是我們前面設(shè)置只打印時長超過2s的日志的原因)。在某次上線完成之后我們發(fā)現(xiàn)報警短信發(fā)送非常頻繁,并且都是和主要業(yè)務(wù)相關(guān),剛開始我們以為是和搜索服務(wù)造成的,因為之前經(jīng)常出現(xiàn)搜索服務(wù)查詢時間比較長的問題。后來我們使用該腳本解析了線上最近100次滿請求的日志,解析結(jié)果如下:

???????從該圖片可以看出,根節(jié)點是大多是SysArgService.getGlobalSysArg()和WebsiteConfigService.getConfigs()方法,因而初步判斷可以排除是搜索服務(wù)調(diào)用時間過長的問題,大致可以猜測出是數(shù)據(jù)庫服務(wù)不穩(wěn)定造成的。繼續(xù)看這兩個方法的上一節(jié)點,其為ListingInfoServiceImpl.transformListingInfos()方法,通過具體業(yè)務(wù)知道,該方法是一個循環(huán)調(diào)用,每次調(diào)用過程中都會調(diào)用一次SysArgService.getGlobalSysArg()和WebsiteConfigService.getConfigs()方法?;谶@個猜測,我們查看了使用perf4j產(chǎn)生的dao方法調(diào)用統(tǒng)計,按照降序排序之后結(jié)果如下:

???????從圖中可以看出,SysArgService.getGlobalSysArg()和WebsiteConfigService.getConfigs()這兩個方法的調(diào)用次數(shù)非常大,10s之內(nèi)可以產(chǎn)生1w多次調(diào)用,因而這里可以確認的就是系統(tǒng)服務(wù)較為緩慢的原因就是這兩個方法被循環(huán)調(diào)用了,但是比較奇怪的是ListingInfoServiceImpl.transformListingInfos()在最近幾次上線都沒有進行過修改,而偏偏這次出現(xiàn)了這個問題,后來我們查看了使用show processlist查看了數(shù)據(jù)庫的進程情況,發(fā)現(xiàn)有兩條binlog的復(fù)制記錄,由此我們可以基本確認,造成服務(wù)性能較低主要有兩個原因:①數(shù)據(jù)庫正在進行數(shù)據(jù)同步,造成數(shù)據(jù)庫資源不足;②代碼中有循環(huán)調(diào)用,造成方法調(diào)用時間過長。