Kafka-4614問題復盤 (MappedByteBuffer未關閉導致慢磁盤訪問)

　　很早之前就想動筆就這個kafka bug總結一番了，只是這個問題既不是本人發現，也不是自己動手修復，終歸是底氣不足，故而一直耽擱下來。怎奈此問題實在是含金量十足，又恰逢最近有人詢問Kafka 0.10.2都有哪些提升，我終究還是決定給這個bug寫點東西了。

 

事先聲明：這是一個日本人(下稱Yuto)開的bug，其對問題的描述、定位、探查、分析、驗證以及結論都堪稱完美，令人印象深刻。自該issue報出的第一天起我便全程追蹤其進度，整個過程甚覺受益良多，今總結出來希望對自己及各位讀者都有所幫助。值得一提的是，我只會寫出親自驗證了的結論，對於該issue中闡述的一些未經驗證的觀點，不會顯式強調。有興趣的讀者可以查看issue原文自己去判斷。附上bug地址： https://issues.apache.org/jira/browse/KAFKA-4614

 

環境背景

操作系統：CentOS 6

內核版本：2.6.32-xx

文件系統：XFS

Java版本：1.8.0_66

GC:            G1

Kafka版本：0.10.0.1

 

問題描述

　　生產環境中有一半左右的PRODUCE請求平均響應時間是1ms，99%請求的響應時間指標是10ms，但有時99%請求響應時間指標會飆升至100ms~500ms，且絕大多數情況下時間都花在了“Remote”部分，即意味着是由於備份機制慢造成的。另外，每天都會在不同的broker上穩定地觀察到3~5次，同時伴隨着Remote的增加，Total和RequestQueue也會相應地增加，就像下圖這樣：

 　　上面提到的Remote、Total和RequestQueue分別表示RemoteTimeMs、TotalTimeMs和RequestQueueTimeMs這3個JMX指標，即副本備份時間(設置了acks=-1)、請求處理總時間以及請求在隊列中的等待時間。具體來說，remote time就是leader broker等待所有follower副本拉取消息的時間。顯然，只有在acks=-1下才會有remote time；RequestQueueTimeMs指客戶端發過來的PRODUCE請求在broker端的請求隊列中待的時間，由於請求隊列是使用阻塞隊列實現的，所以如果該值過大的話，說明broker端負載過大，需要增大請求隊列的大小，即增加參數queued.max.requests的值。

 　　另外，在上述三個指標飆升的同時還觀測到broker所在磁盤的讀操作指標也跟着飆升。

 

定位問題

　　接下來Yuto開始分析了：按說PRODUCE請求應該只會寫磁盤，為什么磁盤的讀操作指標會這么高呢？另外生產環境中的consumer幾乎沒有太多滯后，consumer請求的消息數據幾乎全部命中操作系統的頁緩存，為什么還會"狂"讀磁盤呢？看來目前的主要問題就是要弄明白是哪個線程在讀磁盤。於是Yuto使用了SystemTap，stap腳本如下

global target_pid = KAFKA_PID global target_dev = DATA_VOLUME probe ioblock.request { if (rw == BIO_READ && pid() == target_pid && devname == target_dev) { t_ms = gettimeofday_ms() + 9 * 3600 * 1000 // timezone adjustment
     printf("%s,%03d:  tid = %d, device = %s, inode = %d, size = %d\n", ctime(t_ms / 1000), t_ms % 1000, tid(), devname, ino, size) print_backtrace() print_ubacktrace() } }

　　不了解SystemTap也沒關系，上面的腳本就是打印Kafka進程讀磁盤時內核態和用戶態的棧trace，輸出如下：

Thu Dec 22 17:21:39 2016,209: tid = 126123, device = sdb1, inode = -1, size = 4096 0xffffffff81275050 : generic_make_request+0x0/0x5a0 [kernel]
0xffffffff81275660 : submit_bio+0x70/0x120 [kernel]
0xffffffffa036bcaa : _xfs_buf_ioapply+0x16a/0x200 [xfs]
0xffffffffa036d95f : xfs_buf_iorequest+0x4f/0xe0 [xfs]
0xffffffffa036db46 : _xfs_buf_read+0x36/0x60 [xfs]
0xffffffffa036dc1b : xfs_buf_read+0xab/0x100 [xfs]
0xffffffffa0363477 : xfs_trans_read_buf+0x1f7/0x410 [xfs]
0xffffffffa033014e : xfs_btree_read_buf_block+0x5e/0xd0 [xfs]
0xffffffffa0330854 : xfs_btree_lookup_get_block+0x84/0xf0 [xfs]
0xffffffffa0330edf : xfs_btree_lookup+0xbf/0x470 [xfs]
0xffffffffa032456f : xfs_bmbt_lookup_eq+0x1f/0x30 [xfs]
0xffffffffa032628b : xfs_bmap_del_extent+0x12b/0xac0 [xfs]
0xffffffffa0326f34 : xfs_bunmapi+0x314/0x850 [xfs]
0xffffffffa034ad79 : xfs_itruncate_extents+0xe9/0x280 [xfs]
0xffffffffa0366de5 : xfs_inactive+0x2f5/0x450 [xfs]
0xffffffffa0374620 : xfs_fs_clear_inode+0xa0/0xd0 [xfs]
0xffffffff811affbc : clear_inode+0xac/0x140 [kernel]
0xffffffff811b0776 : generic_delete_inode+0x196/0x1d0 [kernel]
0xffffffff811b0815 : generic_drop_inode+0x65/0x80 [kernel]
0xffffffff811af662 : iput+0x62/0x70 [kernel]
0x37ff2e5347 : munmap+0x7/0x30 [/lib64/libc-2.12.so]
0x7ff169ba5d47 : Java_sun_nio_ch_FileChannelImpl_unmap0+0x17/0x50 [/usr/jdk1.8.0_66/jre/lib/amd64/libnio.so]

　　關於這段輸出，Yuto並沒有給出過多的解釋。不過我特意標紅了第一行和最后兩行：

• 第一行中最重要的就是tid信息，即線程ID。我們需要記下這個ID：126123

• 最后這兩行告訴我們目前Kafka進程下某個讀磁盤的線程正在執行munmap系統調用試圖刪除某段地址空間的內存映射。雖然進程結束時該映射會被自動取消，但如果只是在程序中關閉了文件部署符(file descriptor)——比如調用File.close()，那么這段映射是不會自動被移除的。被標紅的第二行顯示出了是哪段Java代碼執行的這個系統調用。從輸出中我們已知是由Java的FileChannelImpl的unmap方法發出的。

　　我們平時可能用到FileChannel的機會比較多，知道可以利用它來操作文件，但如果查詢JDK官網API的話，你會發現它實際上是個抽象類，也就是說底層的實現是由子類提供的——這個子類就是這里面的sun.nio.ch.FileChannelImpl。從包名來看，這並不是對外開放的Java類，應該是JVM內部的類。實際上，該類用到的一些其他類其實並不是所有JVM都有的，所以不鼓勵用戶直接使用這個類。

 

分析原因

　　Okay，既然我們已經知道Kafka進程下的某個線程正在執行大量讀磁盤操作，並且是在運行mnumap操作。那么下面該如何定位問題呢？Yuto想到了jstack dump，相關輸出如下：

$ grep 0x1ecab /tmp/jstack.dump
"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007ff278d0c800 nid=0x1ecab in Object.wait() [0x00007ff17da11000]

　　為什么是這一行？因為126123（還記得吧？就是剛才得到的線程ID）的16進制就是0x1ecab，即上面輸出中的nid (native thread ID)。同時，還可以看到這個線程的名字是Reference Handler——這個線程就是Finalizer線程。當某個對象被標記為不可達之后，JVM會再給它一次機會讓它重新關聯上其他的對象從而“逃脫”被GC的命運，在這個過程中JVM會將該對象放入到一個特定的隊列中，並由一個特定的Finalizer線程去查看這個對象是否真的不再被使用了。這個線程就是Reference Handler。在這里我們只需要知道這是個GC線程就可以了。

 　　 問題的定位似乎更進一步了！ 我們已經知道是因為GC線程導致的讀操作從而引發的請求變慢。那么接下來查詢一下GC日志便順理成章了：

$ grep --text 'Total time for which application threads were stopped' kafkaServer-gc.log  | grep --text '11T01:4' | perl -ne '/^(.*T\d{2}:\d{2}).*stopped: ([0-9\.]+)/; $h{$1} += $2 * 1000; END { print "$_ = $h{$_}\n" for sort keys %h }'
2017-01-11T01:40 = 332.0601
2017-01-11T01:41 = 315.1805
2017-01-11T01:42 = 318.4317
2017-01-11T01:43 = 317.8821
2017-01-11T01:44 = 302.1132
2017-01-11T01:45 = 950.5807 # << 這里非常耗時
2017-01-11T01:46 = 344.9449
2017-01-11T01:47 = 328.936
2017-01-11T01:48 = 296.3204
2017-01-11T01:49 = 299.2834

 從上面的輸出中 可以看出GC STW的時間非常抖動，特別是有一段時間內的停頓耗時異常地高，再一次證明Kafka broker端請求處理能力的下降是因為GC的原因導致的。

 　　 其實問題梳理到這里，理論上已經可以丟給Kafka團隊去讓他們去解決了，但日本人的嚴謹實在是令人佩服。這位Yuto先生並沒有停下腳步，而是繼續開始追查更深入的原因。還記得之前我們說過的munmap嗎? 我們可以沿着這條路繼續追查下去。

 　　 首先，Kafka代碼中哪部分用到了映射內存文件呢？答案就是索引文件！Kafka日志的索引文件都是使用MappedByteBuffer來實現的。后台日志刪除線程會定期刪除過期日志及其對應的索引文件。0.10.2之前的代碼就是簡單調用File.delete()把底層索引文件刪除掉，但這樣做其實並沒有刪除映射的內存區域。事實上，當調用完File.delete之后，下面情況會依次發生：

1. 索引文件僅僅被VFS(虛擬文件系統)標記為“已刪除”。由於對應的映射對象沒有被清除，所以依然有引用指向該文件，故物理文件塊仍然在磁盤上
2. Kafka的索引對象OffsetIndex在JVM中變為不可達，此時可以被GC收集器回收
3. GC線程開始工作清除MappedByteBuffer對象，並執行對應的刪除映射操作

　　關於第三點，我們已經可以從之前的jstack dump中得到驗證。jstack清晰地表明就是由GC線程來執行munmap的。okay，搞清楚了這些， 現在的問題就要弄明白為什么munmap需要花費這么長的時間？以下就是Yuto的分析：

1. OffsetIndex對象通常都會在堆上保留很長時間(因為日志段文件通常都會保留很長時間)，所以該對象應該早就被提升到老年代了
2. OffsetIndex.delete()操作將文件標記為“已刪除”，VFS稍后會更新inode緩存
3. 由於G1收集器是以region為單位收集的，且它通常都會挑選包含了最多“垃圾”的region進行收集，所以包含mmap對象的region通常都不屬於這類region，從而有可能很長時間都不會被收集
4. 在沒有被收集的這段時間內，inode緩存被更新，正式把標記為“已刪除”的那個索引文件元數據信息“踢出”緩存
5. 最終當GC開始回收mmap對象並調用munmap時，內核就需要執行物理刪除IO操作。但此時，該索引文件的元數據信息已經從緩存中被剔除，因此文件系統就必須要從磁盤中讀取這些信息。而同一時刻Kafka磁盤正在用於高速寫操作(producer還在飛速運行着)，所以讀磁盤操作就遭遇競爭從而拉長整體GC時間。對Kafka broker來說，表現為所有Kafka線程全部暫停，極大地拉長了請求的平均響應時間

驗證

　　不得不說，上面的這幾點分析實在太精彩了。后面Yuto為了驗證這一套分析結果還特意寫了一段Java程序來模擬這個問題。由於代碼太長，我就不貼了，具體思想就是使用dd命令先讓磁盤忙起來，然后運行Java程序模擬mapped文件被刪除並從VFS的inode緩存中被移除的情況，最后成功地復現了這個問題。SystemTap腳本輸出和jstack結果都證明了GC線程執行這個邏輯花費了大量的時間。而原因就是因為VFS正在從磁盤中讀取文件元數據信息。

 

問題解決

　　 其實講到這里該問題的解決辦法已然清晰明了了——就是在刪除索引文件的同時還取消對應的內存映射，刪除mapped對象。不過令人遺憾的是，Java並沒有特別好的解決方案——令人有些驚訝的是，Java沒有為MappedByteBuffer提供unmap的方法，該方法甚至要等到Java 10才會被引入，詳見JDK的這個bug： JDK-4724038   不過Java倒是提供了內部的“臨時”解決方案——DirectBuffer.cleaner().clean() 切記這只是臨時方法，畢竟該類在Java9中就正式被隱藏了，而且也不是所有JVM廠商都有這個類。

　　還有一個解決辦法就是顯式調用System.gc()，讓gc趕在cache失效前就進行回收。不過坦率地說，這個方法弊端更多：首先顯式調用GC是強烈不被推薦使用的，其次很多生產環境甚至禁用了顯式GC調用，所以這個辦法最終沒有被當做這個bug的解決方案。

 

結語

　　最后這個bug的修復幾乎得到了所有Kafka主要committer的贊揚，其結果也非常喜人，以下是Yuto先生的反饋：

 　　那條粗線代表bug的修復點。如圖所示，在那之后請求的平均響應時間非常穩定，再也沒有毛刺的現象出現，這足以說明這次修復是有效的。縱觀整個bug的修復過程，Yuto對於Kafka索引文件機制、JVM GC和操作系統VFS都有很深的造詣，我自己也在這個過程中學到了很多東西。今總結出來以供大家討論。最后貼一份Kafka committer Ijuma關於此bug的評論，足見此問題的分量：