spring websocket效能調優
由於之前的排版較混亂,現重新整理髮布
TProfiler工具
TProfiler是一個可以在生產環境長期使用的效能分析工具。它同時支援剖析和取樣兩種方式,記錄方法執行的時間和次數,生成方法熱點、物件建立熱點、執行緒狀態分析等資料,為查詢系統性能瓶頸提供資料支援。
TProfiler在JVM啟動時把時間採集程式注入到位元組碼中,整個過程無需修改應用原始碼.執行時會把資料寫到日誌檔案,一般情況下每小時輸出的日誌小於50M。
業界同類開源產品都不是針對大型Web應用設計的,對效能消耗較大不能長期使,TProfiler解決了這個問題。目前TProfiler已應用於淘寶的核心Java前端系統。
定位效能瓶頸
線上客服觸屏版使用了websocket,下圖是websocket訊息傳送的流程圖
(檢視原圖)
根據業務流程,選取關鍵程式碼對其進行跟蹤取樣,在使用Tprofiler時需要設定profiler.properties,部分資訊如下,其中includePackageStartsWith是指定哪些包需要受到監控。
includePackageStartsWith = org.springframework.messaging.simp.broker;org.springframework.messaging.support;com.alibaba.dubbo.rpc.proxy;net.dwade.livechat.dubbo.service;net.dwade.livechat.touch.client.controller.stomp
excludePackageStartsWith = com.taobao.sketch;org.apache;com.taobao
在 jvm 啟動引數中新增-javaagent:/path/tprofiler.jar -Dprofile.properties=/path/profile.properties,然後重啟應用。
Tprofiler實踐
需要檢視Tprofiler的資料,需要先執行flushMethod操作,將記憶體中的資料寫入日誌檔案中,其中50001是Tprofiler的埠,由profiler.properties指定:
java -cp /dwade/tomcat/tomcat_touch_test/bin/TProfiler/tprofiler-1.0 .1.jar com.taobao.profile.client.TProfilerClient 10.112.172.125 50001
然後對執行緒和方法呼叫進行統計,其中tsampler.log是資料樣本,stat-method.log、stat-thread.log是統計輸出檔案。
java -cp /dwade/tomcat/tomcat_touch_test/bin/TProfiler/tprofiler-1.0.1.jar com.taobao.profile.analysis.SamplerLogAnalysis tsampler.log stat-method.log stat-thread.log
再對熱點方法和物件進行統計,其中tprofiler.log、tmethod.log是資料樣本,top-method.log、top-object.log是統計輸出檔案。
java -cp /dwade/tomcat/tomcat_touch_test/bin/TProfiler/tprofiler-1.0.1.jar com.taobao.profile.analysis.ProfilerLogAnalysis tprofiler.log tmethod.log top-method.log top-object.log
最後得到stat-method.log、stat-thread.log、top-method.log、top-object.log
TProfiler資料分析
執行緒資料分析
檢視stat-thread.log,可以得到執行緒的狀態統計資料,比如哪些執行緒經常出現阻塞,哪些執行緒比較繁忙、哪些執行緒比較空閒等。下面是部分資料:
3562 New I/O client worker #1-19 RUNNABLE 6187
3196 LiveChat-WebSocketSessionManagerThread-7 WAITING 6187
21219 clientInboundChannel-2728 TIMED_WAITING 38
……
23458 clientInboundChannel-2769 BLOCKED 32
……
由上述資料可知,clientInboundChannel-*執行緒經常出現阻塞,再結合tsampler.log中的執行緒棧資訊,或者使用jstack命令,很快就可以找到該執行緒阻塞的原因。如下圖所示,在DefaultSubscriptionRegistry.java的第269行出現阻塞:
在getSubscriptions方法中,如果result為null,則出現synchronized鎖,因為在accessCache中獲取不到資料,為什麼呢?因為使用的updateCache的value是LinkedMultiValueMap,如果當前size大於cacheLimit,則將最少訪問的資料刪除。程式碼如下所示:
private class DestinationCache {
/** Map from destination -> <sessionId, subscriptionId> for fast look-ups */
private final Map<String, LinkedMultiValueMap<String, String>> accessCache =
new ConcurrentHashMap<String, LinkedMultiValueMap<String, String>>(DEFAULT_CACHE_LIMIT);
/** Map from destination -> <sessionId, subscriptionId> with locking */
@SuppressWarnings("serial")
private final Map<String, LinkedMultiValueMap<String, String>> updateCache =
new LinkedHashMap<String, LinkedMultiValueMap<String, String>>(DEFAULT_CACHE_LIMIT, 0.75f, true) {
@Override
protected boolean removeEldestEntry(Map.Entry<String, LinkedMultiValueMap<String, String>> eldest) {
if (size() > getCacheLimit()) {
accessCache.remove(eldest.getKey());
return true;
}
else {
return false;
}
}
};
public LinkedMultiValueMap<String, String> getSubscriptions(String destination, Message<?> message) {
LinkedMultiValueMap<String, String> result = this.accessCache.get(destination);
if (result == null) {
synchronized (this.updateCache) {
result = new LinkedMultiValueMap<String, String>();
for (SessionSubscriptionInfo info : subscriptionRegistry.getAllSubscriptions()) {
for (String destinationPattern : info.getDestinations()) {
if (getPathMatcher().match(destinationPattern, destination)) {
for (Subscription subscription : info.getSubscriptions(destinationPattern)) {
result.add(info.sessionId, subscription.getId());
}
}
}
}
if (!result.isEmpty()) {
this.updateCache.put(destination, result.deepCopy());
this.accessCache.put(destination, result);
}
}
}
return result;
}
// other code......
}
熱點方法分析
檢視stat-method.log,可以看到在取樣期間目標方法被呼叫的次數,主要是關注哪些方法用的較多,下面是部分資料:
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) 77921
org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108) 64885
org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:44) 64885
org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:163) 64861
org.jboss.netty.channel.socket.nio.SelectorUtil.select(SelectorUtil.java:38) 64861
org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:32) 50518
org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:104) 50518
org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:86) 26948
org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:32) 26948
top方法資料分析
檢視top-method.log,可以看到目標方法在取樣期間的呼叫總時長、呼叫次數、平均耗時,下面是部分資料:
net/dwade/livechat/cache/ClientCache:getClientBySessionId:111 120647 9 1051500
net/dwade/livechat/cache/ChatSessionCache:getSessionById:45 105245 9 991919
net/dwade/livechat/cache/MessageCache:saveMessage:122 39860 22 871732
net/dwade/livechat/cache/MessageCache:getMessageById:64 36666 16 596621
net/dwade/livechat/cache/ChatRequestCache:getChatRequest:128 85844 6 477680
整理後的資料如下:
touch-client應用
dubbo應用
效能調優
關於tomcat等中介軟體的優化,這裡不再重複,請另行參考相關的帖子。
減少執行緒BLOCKED
線上程資料分析章節中,我們分析了spring websocket的高併發場景下的執行緒阻塞問題。專案中,我們使用了spring預設的訊息代理,在SimpleBrokerMessageHandler中有一個致命的弱點,就是使用了DefaultSubscriptionRegistry,而在這個裡面又使用了DestinationCache,這是一個基於LinkedHashMap實現的LRU快取策略,如果快取大小超過了cacheLimit值,則會去將原有舊的資料清理掉,並且再次讀取的時候仍然會去讀取所有的訂閱地址直到找到符合條件的,涉及到寫的部分,都加了synchronized重量級鎖,所以在壓測的過程中這一塊的執行緒BLOCK也是相對較頻繁的,程式的併發效能下降。目前,專案中還未使用訊息中介軟體,後續如果接入訊息中介軟體,對應用系統的效能將會有很大提高。
有以下3種優化方案:
1. 增大cacheLimit值,擴大快取資料量,減少頻繁加鎖;
2. 使用spring的BeanPostProcessor,改變SimpleBrokerMessageHandler的subscriptionRegistry實現類,這個方案難度比較大而且還有一定的風險,需要經過嚴格的測試;
3. 使用訊息中介軟體,spring會將訂閱操作交給訊息中介軟體處理,這樣便可以避免這個問題。
dubbo程式碼優化
dubbo日誌輸出
因為dubbo預設使用的log4j日誌實現,但是專案裡面使用的是logback,導致dubbo框架內部的日誌無法輸出(包括ERROR日誌),不方便後續定位問題,以下日誌是非常重要的:
1. com.alibaba.dubbo.rpc.RpcException: Invoke remote method timeout
2. c.a.d.c.t.s.AbortPolicyWithReport - [DUBBO] Thread pool is EXHAUSTED!
解決辦法:在tomcat的啟動指令碼中加下以下jvm引數:-Ddubbo.application.logger=slf4j
cache優化
在top方法資料分析裡面,我們得到了dubbo服務的方法執行耗時的統計資料:
MessageCache.getUnreadMessages()、ChatRequestCache.getChatRequest()、ChatSessionCache.getSessionById()等,這些方法有一個共同點就是大量使用了hget方法,其中ChatRequestCache.getChatRequest()使用了20+次hget呼叫reids取值,部分程式碼如下所示:
@Override
public ChatRequest getChatRequest(String requestId){
String key = CacheConstants.ChatRequestCacheKey.PREFIX_CHAT_REQUEST+requestId;
if(cache.exists(key)){
ChatRequest chatRequest = new ChatRequest();
chatRequest.setId(requestId);
chatRequest.setClientId(cache.hget(key,"clientId"));
chatRequest.setFromUserId(cache.hget(key,"fromUserId") );
chatRequest.setToUserId(cache.hget(key,"toUserId") );
String creationTime = cache.hget(key,"creationTime");
if(!StringUtils.isEmpty(creationTime)){
chatRequest.setCreationTime(DateUtil.str2Date(creationTime,DateUtil.YYYYMMDDHHMMSSSSS));
}
chatRequest.setWorkgroupId(cache.hget(key,"workgroupId"));
String endTime = cache.hget(key,"endTime");
if(!StringUtils.isEmpty(endTime)){
chatRequest.setEndTime(DateUtil.str2Date(endTime,DateUtil.YYYYMMDDHHMMSSSSS ));
}
// 此處省略10行hget程式碼......
return chatRequest;
}
return null;
}
因為會涉及多次資料傳輸,所以這個方法的效能較差。而JedisCluster中提供了hmset、hmget的api,如下圖所示。但是考慮到hmset在併發情況下會有執行緒安全問題,hset方法可以先不改造,並且目前是讀多寫少的場景。也就是說,將多個hget方法改造成一個hmget,一次性獲取多個欄位值,從而提升查詢效能。
JVM調優
為了提高系統的吞吐量,減少GC停頓時間,採用並行回收機制,同時為了減輕老年代GC壓力,將更多的物件預留在新生代,設定了較大的新生代大小,並且提高了新生代觸發GC的域值。
MEM_ARGS="-server -Xmx3550m -Xms3550m -Xmn2g -XX:PermSize=64m -XX:MaxPermSize=128m -XX:TargetSurvivorRatio=80 -XX:+UseParNewGC -XX:ParallelGCThreads=16 -XX:+UseConcMarkSweepGC"
JAVA_OPTS="-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/dwade/livechat/log/jvm/touch-test.dump -Ddubbo.application.logger=slf4j $JAVA_OPTS $MEM_ARGS"
可以使用監控工具對主機資源進行監控,也可以使用常用的一些命令,比如top。另外還需要對GC活動進行監控,使用jstat –gcutil命令可以粗粒度地瞭解GC活動,也可以使用VisualVM進行視覺化監控。