Kafka-4614问题复盘 (MappedByteBuffer未关闭导致慢磁盘访问)
上面提到的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的值。
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方法发出的。
$ grep 0x1ecab /tmp/jstack.dump
"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007ff278d0c800 nid=0x1ecab in Object.wait() [0x00007ff17da11000]
$ 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
- 索引文件仅仅被VFS(虚拟文件系统)标记为“已删除”。由于对应的映射对象没有被清除，所以依然有引用指向该文件，故物理文件块仍然在磁盘上
- Kafka的索引对象OffsetIndex在JVM中变为不可达，此时可以被GC收集器回收
- GC线程开始工作清除MappedByteBuffer对象，并执行对应的删除映射操作
- OffsetIndex对象通常都会在堆上保留很长时间(因为日志段文件通常都会保留很长时间)，所以该对象应该早就被提升到老年代了
- OffsetIndex.delete()操作将文件标记为“已删除”，VFS稍后会更新inode缓存
- 由于G1收集器是以region为单位收集的，且它通常都会挑选包含了最多“垃圾”的region进行收集，所以包含mmap对象的region通常都不属于这类region，从而有可能很长时间都不会被收集
- 在没有被收集的这段时间内，inode缓存被更新，正式把标记为“已删除”的那个索引文件元数据信息“踢出”缓存
- 最终当GC开始回收mmap对象并调用munmap时，内核就需要执行物理删除IO操作。但此时，该索引文件的元数据信息已经从缓存中被剔除，因此文件系统就必须要从磁盘中读取这些信息。而同一时刻Kafka磁盘正在用于高速写操作(producer还在飞速运行着)，所以读磁盘操作就遭遇竞争从而拉长整体GC时间。对Kafka broker来说，表现为所有Kafka线程全部暂停，极大地拉长了请求的平均响应时间
那条粗线代表bug的修复点。如图所示，在那之后请求的平均响应时间非常稳定，再也没有毛刺的现象出现，这足以说明这次修复是有效的。纵观整个bug的修复过程，Yuto对于Kafka索引文件机制、JVM GC和操作系统VFS都有很深的造诣，我自己也在这个过程中学到了很多东西。今总结出来以供大家讨论。最后贴一份Kafka committer Ijuma关于此bug的评论，足见此问题的分量：
