背景

我們這個項目是針對環境監測的，某個展館中配有N個設備和N個顯示屏終端，每個終端根據實際情況顯示不同的檢測數據項。設備端通過UDP方式向服務端上傳數據，服務端通過websocket方式向終端主動推送實時的檢測數據。

發現問題

就在前些天，收到現場實施人員的消息，問我們是不是程序出問題了（估計實施沒有看過如何與程序員溝通的指南），我一口回絕說：怎麼可能！（嘁，程序員都是好面子的，哪有承認自己的程序有BUG的，一定是甲方不會用，誤操作引起的）。後來經過一番溝通，才了解了事情的來龍去脈：現場實施接到甲方的反饋，展館中的屏幕經常會「卡死」（數據不更新），只有在重啟過後才能正常工作，但是過個三五分鐘後屏幕又會卡死。因為甲方一直拿著這個作為理由，對我們的項目拒絕驗收，所以我們需要抓緊解決這個問題。

復現問題

發現問題後，第一時間查看程序日誌，通過日誌可以看到這個展館的設備頻繁的上線、下線

2018-10-09 15:07:11 [cn.com.xx.websocket.UsrSocketServer:51] INFO - xx上線
2018-10-09 15:16:30 [cn.com.xx.websocket.UsrSocketServer:51] INFO - xx上線
2018-10-09 15:16:33 [cn.com.xx.websocket.UsrSocketServer:74] INFO - xx下線
2018-10-09 15:17:00 [cn.com.xx.websocket.UsrSocketServer:74] INFO - xx下線
2018-10-09 15:17:02 [cn.com.xx.websocket.UsrSocketServer:51] INFO - xx上線
2018-10-09 15:17:12 [cn.com.xx.websocket.UsrSocketServer:51] INFO - xx上線
2018-10-09 15:17:17 [cn.com.xx.websocket.UsrSocketServer:74] INFO - xx下線
2018-10-09 15:19:00 [cn.com.xx.websocket.UsrSocketServer:74] INFO - xx下線

然後就是嘗試復現這個問題，因為只有復現了問題，才能針對問題尋找解決辦法。

隨即我在本地、手機、pad上測試，但都無法復現這個問題（復現的流程在後面會詳細解釋），

可是現場那邊一直反饋存在問題，沒辦法，針對這種情況，只能嘗試著各個方面分析、調試，看看是否真的存在問題。

分析問題

依據以往的經驗，推斷可能會有以下幾種原因：

  1. 現場的網路情況有問題，可能網路不穩定（坑）
  2. 設備出問題，無法上傳數據
  3. 程序出BUG了（雖然極不願意接受這種情況，但不得不排除可能會有這種原因）
  • UDP Server出現問題
  • websocket客戶端出現問題
  • websocket服務端出現問題，不能正常推送

tips：至於為什麼第一條會備註「坑」，後面會解釋

解決問題

有了基本的推斷，接下來就是根據推斷逐一排查。

網路問題

因為這種情況有過先例，所以第一反映就是現場網路出現了問題。通過和現場人員溝通，他給出的結論是：現場網路沒問題，通過顯示屏終端可以打開網頁，並且設備的信號燈一直在閃（信號燈閃爍說明正在進行數據傳輸）。

雖然還是懷疑網路出現問題，但從現場人員的反饋來看，應該不是網路問題。

設備問題

前面提到了設備的信號燈一直在工作，並且通過後台查看設備的實時數據也是一直在更新的，因此也就排除了設備的問題。

程序問題

既然上面兩種都已經排除了，那最後一種可能就是程序出BUG了（偶買噶的，小心臟砰砰砰的亂跳~~）。循著這種思路，嘗試著過一遍代碼，看看是不是程序真的出問題了。

UDP Server出現問題

UDP存在的問題主要是：無法正常處理設備上傳的數據。查看日誌後發現了有時候會報內存泄露的異常：

[io.netty.util.internal.logging.Slf4JLogger:171] ERROR - LEAK: ByteBuf.release() was not called before its garbage-collected. See http://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records:
Created at:
io.netty.buffer.AdvancedLeakAwareByteBuf.readBytes(AdvancedLeakAwareByteBuf.java:496)
cn.com.xx.udp.UsrUdpServer$ConsoleHandler.channelRead0(UsrUdpServer.java:114)
cn.com.xx.udp.UsrUdpServer$ConsoleHandler.channelRead0(UsrUdpServer.java:100)
io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1414)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:945)
io.netty.channel.nio.AbstractNioMessageChannel$NioMessageUnsafe.read(AbstractNioMessageChannel.java:93)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
java.lang.Thread.run(Thread.java:748)

根據提示可知，在GC前未調用release釋放資源，查看相關代碼

ByteBuf buf = (ByteBuf) packet.copy().content();
byte[] req = new byte[buf.readableBytes()];

Netty官方Api中說明了如果指定的消息實現了引用計數器，請嘗試手動調用ReferenceCounted.release()釋放。

Try to call ReferenceCounted.release() if the specified message implements ReferenceCounted. If the specified message doesn』t implement ReferenceCounted, this method does nothing.

在代碼中並沒有手動釋放buf，導致內存泄露。添加以下代碼即可解決這一問題

ReferenceCountUtil.release(buf);

扯得多了，話題切換到本文的主題：UDP Server這邊從接收數據到解析、入庫再到推送通知，未發現明顯問題。主要是系統不止服務了這一個展館，還有其他展館也在使用，但是其他展館的數據都是正常的。所以，基本能排除UDPServer的問題。

這個時候我再次向現場確認了網路情況是否正常，得到的結論仍然是確定網路沒問題。好吧…

Websocket客戶端出現問題了

(function ($) {
$.extend({
websocket: {
_this: null,
init: function (options) {
this._this = new WebSocket(host);

this._this.onopen = function (event) {
console.log("與伺服器連接成功...");
}

// 鏈接關閉後，會自動重連，直到網路暢通為止
this._this.onclose = function () {
setTimeout(function () {
// 重連...
}, 5000);
}
}
}
});
})(dwz);

如上（偽代碼），因為我在編寫websocket客戶端時，加上了斷線重連的的邏輯，所以理論上來說，只要斷網後重新聯網，不應該收不到推送的消息，那麼在實施反饋現場網路良好的前提下為什麼總是反覆停止推送？那麼還有什麼原因會造成這種現象呢？百度關鍵詞「websocket卡頓」，網上有說因為ws推送頻率太高，頁面渲染頻繁造成頁面卡頓；還有說是因為設備內存不夠等等，基本都排除掉。沒辦法，前端也發現不出什麼問題，最後就只剩下服務端了。

Websocket服務端出現問題了

首先進行例行檢查，項目的依賴spring-boot-starter-websocket有了，ServerEndpointExporterbean也注入了，@ServerEndpoint註解聲明也是完好的，從@OnOpen中用戶上線、記錄用戶狀態到@OnClose中用戶下線，清除用戶狀態等處理邏輯也是沒問題的。

確認了業務流程正常的情況下，本地啟動前台程序通過鏈接後台服務進行自測。測試結果也是顯示一切正常，server端能正常接收數據並推送數據，client端也能正常接收數據並渲染到頁面上。

看似一切流程都是正常的，但現場那邊還是一直在反饋屏幕卡死的問題。

到這一步我腦海中就已經有個大大的問號了，反覆在問自己：究竟哪兒出問題了？看來僅僅靠瀏覽器端模擬測試並不能復現真實的應用場景，那麼接下來就需要找一台真實的終端機器進行測試。可喜的是確實有一台測試機，可悲的是這台測試機有問題（這是廢話，湊字數用的( ╯□╰ )），沒辦法，最後在自己手機和測試pad機中安裝了線上的應用。經過測試，手機和pad上的程序運行都沒有問題。

What the fuck~!!!

走到這一步還沒找到問題的原因，那就只能仔細分析分析系統日誌了。通過日誌可以看到有時候websocket會報出SocketTimeoutException異常：

2018-10-09 15:30:22 [cn.com.xx.websocket.UsrSocketServer:51] INFO - xx上線
2018-10-09 15:31:12 [cn.com.xx.websocket.UsrSocketServer:74] INFO - xx下線
java.io.IOException: java.net.SocketTimeoutException
at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:315)
at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:250)
at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendString(WsRemoteEndpointImplBase.java:191)
at org.apache.tomcat.websocket.WsRemoteEndpointBasic.sendText(WsRemoteEndpointBasic.java:37)
at cn.com.xx.websocket.UsrSocketServer.sendMessage(UsrSocketServer.java:95)
at cn.com.xx.websocket.UsrSocketServer.sendMessage(UsrSocketServer.java:103)
at cn.com.xx.websocket.UsrSocketServer.sendMessage(UsrSocketServer.java:128)
at cn.com.xx.websocket.UsrSocketServer.updateMessage(UsrSocketServer.java:170)
at cn.com.xx.udp.UsrUdpServer.notifyObserver(UsrUdpServer.java:74)
at cn.com.xx.udp.UsrUdpServer$ConsoleHandler.channelRead0(UsrUdpServer.java:123)
at cn.com.xx.udp.UsrUdpServer$ConsoleHandler.channelRead0(UsrUdpServer.java:100)
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1414)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:945)
at io.netty.channel.nio.AbstractNioMessageChannel$NioMessageUnsafe.read(AbstractNioMessageChannel.java:93)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
Caused by: java.net.SocketTimeoutException
at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:134)
at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1259)
at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:670)
at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:607)
at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:597)
at org.apache.tomcat.websocket.server.WsRemoteEndpointImplServer.doWrite(WsRemoteEndpointImplServer.java:95)
at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:494)
at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:309)
... 26 more

心想，是不是因為這個問題導致的消息推送失敗？那麼先解決這個異常吧。根據異常棧信息，查找WsRemoteEndpointImplBase.sendMessageBlock方法，可以找到這個異常所在的位置，如下：

try {
if (!this.messagePartInProgress.tryAcquire(timeout, TimeUnit.MILLISECONDS)) {
String msg = sm.getString("wsRemoteEndpoint.acquireTimeout");
this.wsSession.doClose(new CloseReason(CloseCodes.GOING_AWAY, msg), new CloseReason(CloseCodes.CLOSED_ABNORMALLY, msg));
throw new SocketTimeoutException(msg);
}
} catch (InterruptedException var13) {
// do something...
}

其中messagePartInProgress定義為：

private final Semaphore messagePartInProgress = new Semaphore(1);

tips: Semaphore信號量，用於控制對某資源訪問的同一時間的並發量。

由上面代碼可以看到，在阻塞模式下發送WebSocket消息時，同一時間段只能有一個線程進行訪問。首先程序通過tryAcquire嘗試在規定的**超時時間[1]**內獲取一個許可，如果獲取不到（有其他線程阻塞住了，未及時釋放信號量。比如：服務端向a客戶端推送數據時a異常關閉鏈接，此時就會被阻塞住），則拋出SocketTimeoutException異常

[1] : tomcat官方文檔中有說明，默認的超時時間是20秒，可以通過org.apache.tomcat.websocket.BLOCKING_SEND_TIMEOUT屬性修改默認的超時時間。

The write timeout used when sending WebSocket messages in blocking mode defaults to 20000 milliseconds (20 seconds). This may be changed by setting the property org.apache.tomcat.websocket.BLOCKING_SEND_TIMEOUT in the user properties collection attached to the WebSocket session. The value assigned to this property should be a Long and represents the timeout to use in milliseconds. For an infinite timeout, use -1.

在源碼中也可以看到對阻塞時間的處理邏輯

private long getBlockingSendTimeout() {
Object obj = this.wsSession.getUserProperties().get("org.apache.tomcat.websocket.BLOCKING_SEND_TIMEOUT");
Long userTimeout = null;
if (obj instanceof Long) {
userTimeout = (Long)obj;
}

return userTimeout == null ? 20000L : userTimeout;
}

既然如此，那我調大一點這個值，讓它延長一些時間，這樣不就能給前面阻塞的線程以足夠釋放的時間了嗎？干！

在@OnOpen中加入如下代碼測試有沒有效果

session.getUserProperties().put( "org.apache.tomcat.websocket.BLOCKING_SEND_TIMEOUT",25000L);

部署、重啟服務然後通知現場人員：重試一下吧！本來信心滿滿的等著現場人員誇我牛逼的時候才發現：理想很豐滿，現實很骨感~~~幾分鐘後現場反饋：然並卵！

由於現場催的越來越緊，再加上我本地一直無法復現這個「BUG」，其實此時我的內心是煩躁的。

這個時候我又想到了另外一種可能：設備兼容性。是否是因為這個展館使用的設備與其他展館的設備不一樣，所以由於設備的兼容問題才造成websocket的異常呢？

通過溝通確認，這個展館的設備確實大部分和其他展館的不同，但是其中的一個設備卻是和其他展館的一樣，但它也出現了這種問題。看來也不是這個原因，因此這個可能也被否定。

到了這個時候，已經找不到其他的原因了，也是到了這一步，又讓我對現場的網路狀況產生了深深的懷疑（雖然已經再三向現場人員確認過了），最後不得已想了一個辦法：讓現場人員用自己的手機開一個熱點進行測試！

結果：最怕空氣突然安靜。問題解決了！當時我的感覺彷佛有幾萬匹草泥馬從我面前呼嘯而過！MMP!

事兒，就是這麼個事兒~~~

反思

事情過去有段時間了，雖然這件問題結束了，但我的心裡卻久久不能平靜。為什麼本來很簡單的一個問題卻要繞這麼大一圈才用了這種最弱智的辦法解決？

原因不過有二：

  1. 現場人員的問題：在沒有明確網路是否穩定的情況下就輕易得出結論。這是因
  2. 我的問題：在心裡明確懷疑網路問題的情況下並沒有太堅持自己的觀點，才造成後面這一步步多餘的操作。這是果

其實我本身的問題，不光光是如上第二條所說，還有就是，如果我當初能考慮多一點，能先讓現場人員完全排除網路的問題，也一樣不會發生後面這些麻煩事。歸根結底：自己做事欠考慮。

總結

吃一塹長一智，這種情況，我不會讓它再發生第二次了。

（tip:這篇文章已經寫完好幾天了，因為中間一些情況，所以到現在才發出來）

作者：慕冬雪鏈接：imooc.com/article/detai來源：慕課網

推薦閱讀：

前端邁進3D時代-three.js高階（3D圖片預覽）

30行Javascript代碼實現圖片懶載入

【前端乾貨整理】金九銀十，offer拿到手軟的秘密都在這兒！

Github上發布一天Star數破4K的項目了解一下

多線程並發的使用、學習與測試

高並發場景下轉移表的處理過程探討

為什麼部分程序員下班後只關顯示器不關電腦？

推薦10個Java方向最熱門的開源項目

學習編程太枯燥？12款助你學編程的免費遊戲

推薦閱讀：

查看原文 >>
相关文章