故事背景
嘀嘀嘀~，生產事故，內存泄漏！
昨天下午，突然收到運維的消息，分部某系統生產環境內存泄漏了，幫忙排查一下。
排查過程
第一步，要日志
分部給到的異常日志大概是這樣（鑒於公司規定禁止截圖禁止拍照禁止外傳任何信息，下面是我網上找到一張類似的報錯）：
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，當檢測到兩者同時存在時，直接讓程序起不來不是更好嘛；
目前在准備Netty專欄，老鐵們等着我。