java開發的微信公眾號服務端生產環境中的兩個大坑
摘要: 我們開發的公眾號，由於將功能開發完畢後，未對服務進行壓力測試，因此用到的元件中的引數值全是預設的，服務上線後一段時間執行得倒沒什麼問題，隨著服務得訪問量增加，一些多執行緒併發的問題就逐步暴露出來了，有的問題還非常嚴重。
背景
本文的背景是一個用java開發的微信公眾號服務端的業務應用，使用的java開發包是weixin-java-tools。該系統的部署結構式nginx+10個tomcat例項的叢集。
上線一段時間後，業務運營人員在微信公眾號上做了幾個活動，系統的訪問量增加了一些。就陸陸續續暴露了一些問題，而這些問題的造成的危害還非常大，其中有2個tomcat例項執行一段時間後就會無法提供服務了。下面就詳細介紹這個問題。
問題描述
某天我們的程式設計師小馬經常接到幾個簡訊報警說是2臺tomcat例項無法提供服務了，他就只能重啟伺服器，但是過幾十分鐘後，又會出現這樣的問題，他只能痛苦得一遍一遍得重啟tomcat伺服器，最終實在是鬱悶就找到我幫他一起看看到底是什麼原因。
檢視jvm監控
我經過檢視監控後，檢視到了這樣的異常現象。
說明一下：上圖中的tomcat的執行緒最大數配置的是1000，因此這個tomcat已經達到了最大執行緒數（其中多餘的執行緒是jvm自啟動的一些執行緒以及應用程式其它的程式碼啟動的一些執行緒）。而圖中出現的拐點是因為小馬哥重啟了tomcat，但是過段時間又會逐步上升。
檢視執行緒棧列表
檢視其它的正常的tomcat執行緒比較穩定，它們的執行緒數都在一個穩定狀態，而這些tomcat是負載均衡的狀態，它們的訪問量應該是差不多的，因此這2個tomcat的執行緒如此之多，不是因為訪問量太高，肯定還有其它的願意，因此使用jstack將執行緒棧匯出來，發現有大量的BLOCKED和WAITING狀態的執行緒。
BLOCKED狀態執行緒
"http-1601-1000" daemon prio=10 tid=0x00007fb6709b1000 nid=0x673d waiting for monitor entry [0x00007fb604b0b000]
java.lang.Thread.State: BLOCKED (on object monitor)
at me.chanjar WAITING狀態執行緒
"http-1601-381" daemon prio=10 tid=0x00007f1fe827f800 nid=0x27f5 waiting on condition [0x00007f1fa03c1000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000007f9843b10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987)
at org.apache.http.pool.PoolEntryFuture.await(PoolEntryFuture.java:133)
at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:282)
at org.apache.http.pool.AbstractConnPool.access$000(AbstractConnPool.java:64)
at org.apache.http.pool.AbstractConnPool$2.getPoolEntry(AbstractConnPool.java:177)
at org.apache.http.pool.AbstractConnPool$2.getPoolEntry(AbstractConnPool.java:170)
at org.apache.http.pool.PoolEntryFuture.get(PoolEntryFuture.java:102)
at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:244)
at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:231)
at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:173)
at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:195)
at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:86)
at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:108)
at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:106)
at me.chanjar.weixin.common.util.http.SimpleGetRequestExecutor.execute(SimpleGetRequestExecutor.java:36)
at me.chanjar.weixin.common.util.http.SimpleGetRequestExecutor.execute(SimpleGetRequestExecutor.java:20)
at com.jd.ql.cun.web.wx4jsdk.JdWxTestSupportMpServiceImpl.oauth2getAccessTokenExtension(JdWxTestSupportMpServiceImpl.java:91)
at com.jd.ql.cun.web.controller.WeixinSecurityController.getOpenId(WeixinSecurityController.java:111)問題分析及解決
BLOCKED狀態執行緒
根據執行緒中的資訊找打鎖住行所在的原始碼，繼續追蹤該行的原始碼如下：
public String getJsapiTicket(boolean forceRefresh) throws WxErrorException {
if (forceRefresh) {
wxMpConfigStorage.expireJsapiTicket();
}
if (wxMpConfigStorage.isJsapiTicketExpired()) {
synchronized (globalJsapiTicketRefreshLock) {
if (wxMpConfigStorage.isJsapiTicketExpired()) {
String url = "https://api.weixin.qq.com/cgi-bin/ticket/getticket?type=jsapi";
String responseContent = execute(new SimpleGetRequestExecutor(), url, null);
JsonElement tmpJsonElement = Streams.parse(new JsonReader(new StringReader(responseContent)));
JsonObject tmpJsonObject = tmpJsonElement.getAsJsonObject();
String jsapiTicket = tmpJsonObject.get("ticket").getAsString();
int expiresInSeconds = tmpJsonObject.get("expires_in").getAsInt();
wxMpConfigStorage.updateJsapiTicket(jsapiTicket, expiresInSeconds);
}
}
}
return wxMpConfigStorage.getJsapiTicket();
}在程式碼“synchronized (globalJsapiTicketRefreshLock) {“處使用了synchronized 同步鎖，對全域性共享物件globalJsapiTicketRefreshLock進行了加鎖操作，主要是防止多個執行緒同時對jsapiTicket進行更新操作。
既然大量的執行緒阻塞在該處，那說明有的執行緒在執行同步塊中的程式碼非常慢，而其它的執行緒都在等待該執行緒釋放鎖，因此越來越多的執行緒都阻塞該處。問題就出在該程式碼處。繼續分析該處程式碼發現了一個比較嚴重的坑，描述如下：
- accessToken的機制是每個7200毫秒會過期，並且若重新獲取則上次獲取的會過期。
- 本系統是在10個tomcat例項的叢集環境下面。
- 本系統中的accessToken是儲存在記憶體中的，多個tomcat叢集的值無法共享。
- 多個tomcat叢集都會經常獲取，因此導致accessToken經常過期。
- 獲取accessToken介面的呼叫次數有限制，每日2000次。
- 若達到介面獲取上線，則無法獲取accessToken，導致獲取accessToken始終失敗。
- 程式碼塊中有失敗重試預設3次的機制，而且每次衝時候會暫停執行緒1秒，且暫停時間每次增加一倍。
- 因此會某個執行緒會在該處執行時間非常長，導致鎖長期被佔用，其它執行緒阻塞時間較長。
解決方案
重新實現accessToken和jsApiTicket儲存方案，將其儲存在共享的redis服務上。
修改上線後，BLOCKED執行緒消失了，但是依舊有很多WAITING狀態的執行緒，因此繼續分析該狀態的程式碼。
WAITING狀態執行緒
分析執行緒棧中的程式碼”at org.apache.http.pool.PoolEntryFuture.await(PoolEntryFuture.java:133)”經過檢視原始碼發現是因為呼叫微信api使用了java的元件httpclient，如本文中專案使用的是httpclient4.3.5。
而httpclient為了複用http連線，使用了連線池技術，該處的等待執行緒就是在等待從連線池中獲得連線，那有可能是連線池中連線不夠，或者某些執行緒佔用連線時間過長導致的。因此繼續檢視程式碼和查詢相關httpClient連線配置文件得出如下結論：
httpclient連線配置全部為預設
本專案中的httpclient的連線配置全部使用預設配置。使用HttpClients.createDefault();建立預設的httpclient物件，全部使用預設值。
httpclient連線的配置，參考了張開濤的部落格：http://jinnianshilongnian.iteye.com/blog/2089792
連線池配置不合理
maxConnTotal和maxConnPerRoute
maxConnTotal是連線池總的最大連線數，用的是預設值20.
maxConnPerRoute是每個路由最大連線數，本專案都是連線微信伺服器，因此就是預設為2的值，而這對於生產環境併發較高確實不合適。
http網路連線配置不合理
httpclient的請求配置都沒有配置，使用預設配置資訊。
this.connectionRequestTimeout = -1;
this.connectTimeout = -1;
this.socketTimeout = -1;
都是使用的系統預設時間值，而這個值是一個比較大的值，對於生產環境來說是不合適的。
因此這些值對於生產環境來說均為不合理的值，因此我根據自己的生產環境的實際情況配置如下：
weixin.mp.httpclient.socketTimeout=2000
weixin.mp.httpclient.connectTimeout=2000
weixin.mp.httpclient.connectionRequestTimeout=500
weixin.mp.httpclient.maxConnPerRoute=300
weixin.mp.httpclient.maxConnTotal=300微信呼叫介面統計
平均耗時都要300毫秒。
總結
- 預設配置值一定不是最優的，有時候在正好碰到惡劣環境下反而是致命的問題。
- 微信介面的效能比較差，尤其是當伺服器與微信api的網路通訊較差的時候，會是較大的問題。
- 微信的accessToken和jspApiTicket在叢集環境下一定要共享儲存。
- 涉及到網路通訊的連線超時一定要設定且不能太大。
- 生產環境解決問題需要有儘量多的日誌、監控、各種資源的使用情況的資訊。