故事背景
嘀嘀嘀~，生産事故，記憶體洩漏！
昨天下午，突然收到運維的消息，分部某系統生産環境記憶體洩漏了，幫忙排查一下。
排查過程如下：
第一步，要日志
分部給到的異常日志大概是這樣（鑒于公司規定禁止截圖禁止拍照禁止外傳任何資訊，下面是我網上找到一張類似的報錯）：
LEAK: ByteBuf.release() was not called before it's garbage-collected. See http://netty.io/wiki/reference-counted-objects.html for more information.
Recent access records:
#1:
io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:273)
io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:253)
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:1434)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:965)
io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:646)
io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:581)
io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:498)
io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:460)
io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:884)
java.lang.Thread.run(Thread.java:748)
這一看，不得了了，ByteBuf沒有釋放，導緻記憶體洩漏了。
第二步，看記憶體名額
既然知道了是記憶體洩漏，趕緊讓運維看下記憶體使用情況，特别是堆外記憶體使用情況（因為用了Netty），根據運維回報，堆内記憶體使用正常，堆外記憶體居高不下。
OK，到這裡已經可以很明确地斷言：堆外記憶體洩漏了。
此時，分兩步走，一步是把gateway換成zuul壓測觀察，一步是記憶體洩漏問題排查。
第三步，要代碼
讓分部這個項目的負責人把代碼給到我，我打開一看，傻眼了，就一個簡單的Spring Cloud Gateway項目，裡面還包含了兩個類，一個是AuthFilter用來做權限校驗的，一個是XssFilter用來防攻擊的。
Spring Cloud Gateway使用的是Netty，zuul 1.x使用的是Tomcat，本文來源于工縱耗彤哥讀源碼。
第四步，初步懷疑
快速掃一下各個類的代碼，在XssFilter裡面看到了跟ByteBuf相關的代碼，但是，沒有明顯地ByteBuf沒有釋放的資訊，很簡單，先把這個類屏蔽掉，看看還有沒有記憶體洩漏。
但是，怎麼檢測有沒有記憶體洩漏呢？總不能把這個類删掉，在生産上跑吧。
第五步，參數及監控改造
其實，很簡單，看過Netty源碼的同學，應該比較清楚，Netty預設使用的是池化的直接記憶體實作的ByteBuf，即PooledDirectByteBuf，是以，為了調試，首先，要把池化這個功能關閉。
直接記憶體，即堆外記憶體。
為什麼要關閉池化功能？
因為池化是對記憶體的一種緩存，它一次配置設定16M記憶體且不會立即釋放，開啟池化後不便觀察，除非慢慢調試。
那麼，怎麼關閉池化功能呢？
在Netty中，所有的ByteBuf都是通過一個叫作ByteBufAllocator來建立的，在接口ByteBufAllocator中有一個預設的配置設定器，找到這個預設的配置設定器，再找到它建立的地方，就可以看到相關的代碼了。
public interface ByteBufAllocator {
ByteBufAllocator DEFAULT = ByteBufUtil.DEFAULT_ALLOCATOR;
}
public final class ByteBufUtil {
static final ByteBufAllocator DEFAULT_ALLOCATOR;
static {
// 本文來源于工縱耗彤哥讀源碼
String allocType = SystemPropertyUtil.get(
"io.netty.allocator.type", PlatformDependent.isAndroid() ? "unpooled" : "pooled");
allocType = allocType.toLowerCase(Locale.US).trim();
ByteBufAllocator alloc;
if ("unpooled".equals(allocType)) {
alloc = UnpooledByteBufAllocator.DEFAULT;
logger.debug("-Dio.netty.allocator.type: {}", allocType);
} else if ("pooled".equals(allocType)) {
alloc = PooledByteBufAllocator.DEFAULT;
logger.debug("-Dio.netty.allocator.type: {}", allocType);
} else {
alloc = PooledByteBufAllocator.DEFAULT;
logger.debug("-Dio.netty.allocator.type: pooled (unknown: {})", allocType);
}
DEFAULT_ALLOCATOR = alloc;
}
}
可以看到，是通過io.netty.allocator.type這個參數控制的。
OK，在JVM啟動參數中添加上這個參數，并把它指派為unpooled。
關閉了池化功能之後，還要能夠實時地觀測到記憶體是不是真的有洩漏，這要怎麼做呢？
其實，這個也很簡單，Netty的PlatformDependent這個類會統計所有直接記憶體的使用。
最近一直在研究Netty的源碼，是以，我對Netty的各種細節了解地很清楚，本文來源于工縱耗彤哥讀源碼，最近還在準備，等後面弄完了，開始Netty專欄的創作。
是以，我們隻需要寫一個定時器，定時地把這個統計資訊列印出來就可以了，這裡，我就直接給出代碼了：
@Component
public class Metrics {
@PostConstruct
public void init() {
ScheduledExecutorService scheduledExecutorService = Executors.newSingleThreadScheduledExecutor();
scheduledExecutorService.scheduleAtFixedRate(()->{
System.out.println("used direct memory: " + PlatformDependent.usedDirectMemory());
}, 1, 1, TimeUnit.SECONDS);
}
}
把它扔到跟啟動類同級或下級的目錄就可以了。
到這裡，池化及監控都弄好了，下面就是調試了。
第六步，初步調試
直接運作啟動類，觀察日志。
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
一開始，直接記憶體都很正常，一直是0。
随便發送一個請求，報404了，而且觀察直接記憶體并沒有變化，還是0，說明，随便模拟一個請求還不行，這直接被spring給攔截了，還沒到Netty。
第七步，修改配置
随便一個請求不行， 那隻能模拟正常的請求轉發了，我快速啟動了一個SpringBoot項目，并在裡面定義了一個請求，修改gateway的配置，讓它可以轉發過去：
spring:
cloud:
gateway:
routes:
- id: test
uri: http://localhost:8899/test
predicates:
- Path=/test
第八步，再次調試
修改完配置，同時啟動兩個項目，一個gateway，一個springboot，請求發送，觀察直接記憶體的使用情況：
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 1031
used direct memory: 1031
used direct memory: 1031
果然，記憶體沒有釋放。
第九步，删除XssFilter
為了驗證前面初步懷疑的XssFilter，把它删掉，再次啟動項目，發送請求，觀察直接記憶體的使用。
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 1031
used direct memory: 1031
used direct memory: 1031
問題依然存在，而且，還是跟前面洩漏的一樣大小。
這個是這樣的，Netty是靠猜（guess）來決定每次記憶體配置設定的大小的，這個猜的初始值是1024。
@Override
public ByteBuf allocate(ByteBufAllocator alloc) {
return alloc.ioBuffer(guess());
}
是不是沒想到Netty還有這麼可愛的一面^^，咳咳，跑題了，強行拉回！
然後，這裡還有個7B存儲的是換行符回車符啥的，這7B是不會釋放的，加到一起就是1031。
private static final byte[] ZERO_CRLF_CRLF = { '0', CR, LF, CR, LF };
// 2B
private static final ByteBuf CRLF_BUF = unreleasableBuffer(directBuffer(2).writeByte(CR).writeByte(LF));
// 5B
private static final ByteBuf ZERO_CRLF_CRLF_BUF = unreleasableBuffer(directBuffer(ZERO_CRLF_CRLF.length)
.writeBytes(ZERO_CRLF_CRLF));
嗯，有點意思，既然不是XssFilter的問題，那麼，會不會是AuthFilter的問題呢？
第十步，幹掉AuthFilter
說幹就幹，幹掉AuthFiler，重新開機項目，發送請求，觀察直接記憶體：
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 1031
used direct memory: 1031
used direct memory: 1031
問題還是存在，還是熟悉的記憶體大小。
此時，我的思路已經不順暢了，下面是跑偏之路。
第十一步，思考
在把XssFilter和AuthFilter相繼删除之後，已經隻剩下一個啟動類了，當然，還有一個新加的監控類。
難道是Spring Cloud Gateway本身有問題，咦，我好像發現了新大陸，這要是發現Spring Cloud Gateway有問題，以後又能吹噓一番了（内心YY）。
既然，記憶體配置設定沒有釋放，那我們就找到記憶體配置設定的地方，打個斷點。
通過前面的分析，我們已經知道使用的記憶體配置設定器是UnpooledByteBufAllocator了，那就在它的newDirectBuffer()方法中打一個斷點，因為我們這裡是直接記憶體洩漏了。
第十二步，一步一步調試
按照第十一步的思路，在UnpooledByteBufAllocator的newDirectBuffer()方法中打一個斷點，一步一步調試，最後，來到了這個方法：
// io.netty.handler.codec.ByteToMessageDecoder.channelRead
@Override
public void channelRead(ChannelHandlerContext ctx, Object msg) throws Exception {
if (msg instanceof ByteBuf) {
CodecOutputList out = CodecOutputList.newInstance();
try {
first = cumulation == null;
// 1. 傳回的是msg本身，msg是一個ByteBuf
cumulation = cumulator.cumulate(ctx.alloc(),
first ? Unpooled.EMPTY_BUFFER : cumulation, (ByteBuf) msg);
// 2. 解碼，本文來源于工縱耗彤哥讀源碼
callDecode(ctx, cumulation, out);
} catch (DecoderException e) {
throw e;
} catch (Exception e) {
throw new DecoderException(e);
} finally {
if (cumulation != null && !cumulation.isReadable()) {
numReads = 0;
// 3. 釋放記憶體
cumulation.release();
cumulation = null;
} else if (++ numReads >= discardAfterReads) {
// We did enough reads already try to discard some bytes so we not risk to see a OOME.
// See https://github.com/netty/netty/issues/4275
numReads = 0;
discardSomeReadBytes();
}
int size = out.size();
firedChannelRead |= out.insertSinceRecycled();
// 4. 讀取完out中剩餘的值
fireChannelRead(ctx, out, size);
// 5. 回收out
out.recycle();
}
} else {
ctx.fireChannelRead(msg);
}
}
這中間花了好幾個小時，特别是ChannelPipeLine裡面一不小心就跳過去了，又得重新來過，真的是隻能一步一步來。
這個方法主要是用來把ByteBuf轉換成Message，Message就是消息，可以了解為簡單的Java對象，主要邏輯在上面的代碼中都标示出來了。
可以看到，這裡有個cumulation.release();，它就是釋放記憶體的地方，但是，并沒有釋放掉，在調用這行代碼之前，msg(=cumulation)的引用計數是4，釋放之後是2，是以，還有計數，無法回收。
走完下面的4、5兩步，out都回收了，msg還是沒有被回收，問題肯定是出在這一塊。
一直在這裡糾結，包括decode裡面的代碼都反反複複看了好多遍，這裡沒有釋放的msg裡面的内容轉換之後的對象是DefaultHttpContent，它表示的是Http請求的body，不過這裡是Http請求傳回值的body。
這也是讓我很迷惑的一點，我試了，Http請求的body好像沒有走到這塊邏輯，又反反複複地找Http請求的Body，搞了好久，一直沒有進展。
到晚上9點多的時候，辦公室已經沒什麼人了，燈也關了（疫情期間，每個部門每天隻能去幾個人），我也收拾下回家了。
第十三步，打車回家
在車上的時候，一直在想這個問題，回憶整個過程，會不會是我的方向錯了呢？
Spring Cloud Gateway出來也挺久了，沒聽說有記憶體洩漏的問題啊，此時，我開始自我懷疑了。
不行，我回家得自己寫一個項目，使用Spring Cloud Gateway跑一下試試。
第十四步，寫一個使用Spring Cloud Gateway的項目
到家了，趕緊打開電腦，動手寫了一個使用Spring Cloud Gateway的項目和一個SpringBoot的項目，把監控打開，把池化功能去掉，啟動項目，發送請求，觀察直接記憶體。
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
納尼，阿西巴，到這裡，已經很明确了，不是Spring Cloud Gateway的問題，那是什麼問題呢？
肯定是使用的姿勢不對，不過公司那個項目，也沒有别的什麼東西了，類都被我删完了，隻剩下啟動類了。
哎不對，pom檔案。
打開跳闆機，登入到公司電腦，檢視pom.xml，發現裡面都是SpringBoot或者SpringCloud本身的一些引用。
嗯，不對，有個common包，分部自己寫的common包，點進去，裡面引用了三個jar包，其中，有一個特别紮眼，tomcat！！！！
哎喲我次奧，此時，我真的想罵娘，這都什麼事兒~~
其實，我在删除AuthFilter的時候就應該想到pom的問題的，當時，隻顧着YY Spring Cloud Gateway 可能有bug的問題了，一頭就紮進去了。
我們知道，Spring Cloud Gateway使用的是Netty做為服務端接收請求，然後再轉發給下遊系統，這裡引用tomcat會怎樣呢？還真是一件有趣的事呢。
第十五步，幹掉tomcat
在pom檔案中，把tomcat的jar包排除掉，重新開機項目，發送請求，觀察直接記憶體：
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
used direct memory: 0
哦了，沒有問題了，就是tomcat搗的鬼。
那麼，tomcat是怎麼搗鬼的呢？加了tomcat也能正常的響應請求，請求也能正常的轉發，傳回給用戶端，而且，更可怕的是，内部也确實是使用了Netty進行請求的讀寫響應，真的有點神奇。
第十六步，發現新大陸
為了驗證這個問題，我們還是先退出跳闆機，回到我自己的電腦，在pom中加入tomcat，啟動項目，咦，确實能起得來，好好玩兒~~
難道是tomcat和Netty同時監聽了同一個端口，兩者都起來了？
觀察一下項目啟動日志：
Connected to the target VM, address: '127.0.0.1:52162', transport: 'socket'
. ____ _ __ _ _
/\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
\\/ ___)| |_)| | | | | || (_| | ) ) ) )
' |____| .__|_| |_|_| |_\__, | / / / /
=========|_|==============|___/=/_/_/_/
:: Spring Boot :: (v2.2.6.RELEASE)
2020-05-19 08:50:04.448 INFO 7896 --- [ main] com.alan.test.Application : No active profile set, falling back to default profiles: default
2020-05-19 08:50:04.829 INFO 7896 --- [ main] o.s.cloud.context.scope.GenericScope : BeanFactory id=082e67ca-d4c7-3a8c-b051-e806722fd225
2020-05-19 08:50:04.998 INFO 7896 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
2020-05-19 08:50:05.006 INFO 7896 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
2020-05-19 08:50:05.006 INFO 7896 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.33]
2020-05-19 08:50:05.859 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [After]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Before]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Between]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Cookie]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Header]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Host]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Method]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Path]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [Query]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [ReadBodyPredicateFactory]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [RemoteAddr]
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : 本文來源于工縱耗彤哥讀源碼
2020-05-19 08:50:05.860 INFO 7896 --- [ main] o.s.c.g.r.RouteDefinitionRouteLocator : Loaded RoutePredicateFactory [CloudFoundryRouteService]
2020-05-19 08:50:06.731 INFO 7896 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
2020-05-19 08:50:07.304 INFO 7896 --- [ main] com.alan.test.Application : Started Application in 4.271 seconds (JVM running for 5.0)
發現确實隻啟動了tomcat，那它是怎麼把請求移交給Netty來處理的呢？
第十七步，tomcat -> Netty
學習過NIO相關知識的同學應該知道，NIO将SocketChannel分成了兩種，一種是ServerSocketChannel，一種是SocketChannel，其中，ServerSocketChannel是服務啟動的時候建立的，用來監聽用戶端連接配接的到來，而SocketChannel就表示用戶端與服務端之間的連接配接。
看過NIO源碼的同學又知道，SocketChannel是通過ServerSocketChannel建立出來的。
看過Netty源碼的同學又知道，Netty根據不同的協定又把這些Channel分成了NioXxxChannel、EpollXxxChannel等等，針對每一種協定的Channel同樣分成NioServerSocketChannel、NioSocketChannel等。
而在Windows平台下，預設使用的是NioXxxChannel，而從上可知，NioSocketChannel應該是通過NioServerSocketChannel建立出來的，如果是正常使用Netty，也确實是這樣的。
下圖是正常使用Netty時NioSocketChannel建立時的線程棧：
不過，我們現在的場景是 tomcat + Netty，那又是怎樣的呢？
此時，在NioSocketChannel的構造方法中打一個斷點，發送一個請求，發現斷點到了NioSocketChannel的構造方法中，觀察線程棧的情況（從下往上看）：
可以看到，經過tomcat->spring->reactor->reactor-netty->netty，千轉百回之後，終于建立了NioSocketChannel。
這裡的情況就有點複雜了，後面有時間，我們再詳細分析。
第十八步，記憶體洩漏
從上面可以看出，Tomcat最終把請求的處理交給了Netty，但是為什麼會記憶體洩漏呢？這依然是個問題。
經過我的對比檢測，問題還是出在第十二步的代碼那裡，在使用正常的Netty請求時，在fireChannelRead()的裡面會往NioEventLoop中添加一個任務，叫作MonoSendMany.SendManyInner.AsyncFlush:
final class AsyncFlush implements Runnable {
@Override
public void run() {
if (pending != 0) {
ctx.flush();
}
}
}
這是用來把寫緩沖區的資料真正寫出去的（讀完了寫出去），同時，也會把寫緩沖區的資料清理掉，也就是調用了這個方法用戶端才能收到響應的結果，而使用 tomcat + Netty 的時候，并沒有執行這個任務，資料就發送給了用戶端（猜測可能是通過tomcat的連接配接而不NioSocketChannel本身發送出去的），這是一個遺留問題，等後面再研究下了，現在腦子有點淩亂。
總結
這次生産事件，雖然整個代碼比較簡單，但是還是搞了挺久的，現總結幾個點：
- 不要輕易懷疑開源架構，特别是像Spring這種用的人比較多的，懷疑它容易把自己帶偏，但也不是不要懷疑哈；
- 當無法找到問題的原因的時候，可以考慮休息一下、放松一下，換個思路；
- Spring Cloud Gateway中為什麼能tomcat和Netty可以并存，這是一個問題，應該給官方提一個issue，當檢測到兩者同時存在時，直接讓程式起不來不是更好嘛；
個人公衆号：Java架構師聯盟，每日更新技術好文