数据库‖超万亿规模的Hadoop NameNode性能故障排查过程分享

随着国内互联网行业的发展，万亿规模的超大集群虽然已不像几年前那么凤毛麟角，但是也并不多见，尤其是涉及超万亿规模的超大集群性能故障排查的机会就更加稀少。

而这次我所进行的超万亿规模的Hadoop NameNode性能故障排查也是在我创业几年以来所遇到的集群规模最大，耗时最长，排查工作量最大，头发掉的最多，最终都不得不求助于大牛的一次经历。

因此在问题解决之后，我也第一时间将这次的整个排查过程记录下来进行总结，希望能给看到的各位同学有所帮助。下面，enjoy：

• • -

起 因

事情的起因是由于近日客户反馈使用我们数据库的效果突然变差，之前秒级响应的数据查询与检索，现在却总是在“转圈”，卡住不动了。因为是突然发生的现象，已经在现场的同事先排除了业务变动，但是并未发现问题。作为自己创立公司后第一个接到的万亿数据体量的大项目，我自身也非常重视，马上第一时间奔赴现场。

这里先容介绍一下该平台架构，底层采用hadoop进行分布式存储，中间数据库采用的录信LSQL，数据实时导入采用kafka进行。每天的数据规模是500亿，数据存储周期为90天，一共有4000多张数据表，其中最大的单表数据规模近2万亿条记录，总数据规模将近5万亿，存储空间占8PB。

数据平台支撑的基本使用主要包括数据的全文检索、多维查询，以及地理位置检索、数据碰撞等操作。也会有部分业务涉及数据的统计和分析，会有极少量的数据导出与多表关联操作。

• • -

经 过

①****Before the day：初步定位问题

话说我在创业之前在腾讯做Hermes系统，每日接入的实时数据量就已经达到了3600亿/天，之后更是达到了每日近万亿条数据的实时导入。为了不显得那么凡尔赛，我只想说，我和梁启超在北大演讲时的心情一样：我对超大集群没什么了解，但是还是有那么一点喽！面对当前每日500-1000亿规模的系统，我在考虑是不是买票的时候把当天的回程票也买了......

为了快速定位问题，还没出发之前我就跟现场要了一些日志和jstack，初步定位是hadoop NameNode的瓶颈，而NN的优化我们此前也做了很多次，别无其他，唯手熟尔。

下图为当时堆栈的分析情况，估计在座诸位看了都会信心满满，这很明显就是hadoop卡顿。

②First Day：尝试调整log4j

到现场的第一天，依然是风和日丽，心情继续保持美丽。

我到现场后第一件事情就是不断的抓hadoop Namenode的堆栈Jstack。从中得到的结论是问题确实是卡顿在NN上。此处NN是一个全局锁，所有的读写操作都在排序等待，详情如下图所示：

1. 卡在哪里

这个锁的等待个数竟然长达1000多个，不卡才怪呢，我们再细看一下，当前拥有这个锁的线程在做什么？

2. 问题分析

很明显，在记录log上存在瓶颈，阻塞的时间太久。

1) 记录的log4j不应该加【%L】，它会创建Throwable对象，而这个在java里是一个重对象。

2) 日志记录太频繁，刷盘刷不动。

1. log4j有全局锁，会影响吞吐量。

3. 调整方案

1) 客户的hadoop版本采用的是2.6.0版本，该版本的hadoop，在日志处理上存在诸多问题，故我们将官方明确表示存在问题的patch打了进来

https://issues.apache.org/jir... 因日志原因导致nn慢

https://issues.apache.org/jir... 将日志记录到锁外，避免卡锁

https://issues.apache.org/jir... processIncrementalBlockReport 导致的记录日志问题，严重影响NN性能

2) 禁用namenode所有info级别的日志

观察发现当有大量日志输出的时候，全局锁会阻塞NN。

目前修改方式是屏蔽到log4j的日志输出，禁用namenode所有info级别的日志。

3) log4j 的日志输出去掉【%L】参数

这个参数会为了得到行号而创建new Throwable对象，这个对象对性能影响很大，大量创建会影响吞吐量。

4) 启用异步审计日志

dfs.namenode.audit.log.async 设置为true，将审计日志改为异步。

4. 优化效果

优化之后，确实因log4j导致的卡顿问题不存在了，但hadoop的吞吐量依然卡，仍旧卡在lock上。

③Second Day：优化du，排查解决所有卡顿

接着昨天的工作：

1. 在解决了log4j的问题后，继续抓jstack，抓到如下位置：

2. 通过代码进行分析，发现确实此处有锁，证实此处会引起所有访问阻塞：

3. 继续深入研读代码，发现受如下参数控制：

（2.6.5版本这个默认值是5000，已经不存在这个问题了）

这个参数的核心逻辑是，如果配置上大于零的值，它会间隔一定文件数量，释放锁，让别的程序得以继续执行，该问题只会在hadoop2.6.0的版本里存在，之后的版本里已经对此做了修复。

4. 解决办法

1) 打上官方patch：

https://issues.apache.org/jir...

2) lsql内部移除所有关于hadoop du的使用

5. 为什么要打patch

2.6.5版本中，可以自己定义休眠时间，默认休眠时间为500ms，而2.6.0休眠时间为1ms,我担心太短，会出现问题。

继续按照原先思路，排查所有的jstack 。将所有涉及卡顿的地方都一一解决掉，至此hadoop通过jstack已经抓不到任何的活动线程，但是依然卡顿在读写锁的切换上，这说明：

1.namenode内部的每个函数已经最优，jstack基本抓不到了；

2.堆栈调用只能看到近1000个读写锁在不断切换，说明nn的请求并发非常高，多线程之间锁的上下文切换已经成为了主要瓶颈。

所以当下主要思路应该落在如何减少NN的调用频率上面。

④Third Day：尽可能减少NN请求频率

为了减少NN的请求频率，尝试了多个方法：

1. 启用录信数据库lsql的不同表不同分片功能

考虑到现场有4000多张表，每张表有1000多个并发写入分片，有可能是同时写入的文件数太多，导致的nn请求频率太高，故考虑将那些小表，进行分片合并，写入的文件数量少了，请求频率自然而然就降低了。

2. 与现场人员配合，清理不必要的数据，减少hadoop集群的压力。清理后hadoop集群的文件块数由将近2亿，降低到1.3亿，清理力度足够大。

3. 调整一系列与NN有关交互的心跳的频率：如blockmanager等相关参数。

4. 调整NN内部锁的类型：由公平锁调整为非公平锁。

本次调整涉及的参数有：

• dfs.blockreport.intervalMsec 由21600000L调整为259200000L (3天)，全量心跳
• dfs.blockreport.incremental.intervalMsec 增量数据心跳由0改为300，尽量批量一次上报 （老版本无该参数）
• dfs.namenode.replication.interval 由3秒调整为60秒，减少心跳频率
• dfs.heartbeat.interval 心跳时间由默认3秒调整为60秒，减少心跳频率
• dfs.namenode.invalidate.work.pct.per.iteration 由0.32调整为0.15 (15%个节点)，减少扫描节点数量

本次调整涉及的堆栈：

最终结果卡顿问题依然存在。本人已经黔驴技穷，人已经懵了，不知道该如何处理。

⑤Fourth Day：无计可施，考虑建立分流机制

拖着已经连续熬了三个晚上的疲惫身躯，第四天一早就跟公司和客户汇报排查具体情况，也直接说了已经没有任何的思路。希望能启用B方案：

1.启用hadoop联邦方案，靠多个namenode解决当下问题；

2.立即修改录信lsql数据库，在一个lsql数据库内适配hadoop多集群方案，也就是搭建两个完全一样的集群，录信数据库启动600个进程，300个进程请求旧集群，300个进程分流到新集群，以达到减轻压力的目的。

家里（公司）的意见是先回去睡觉，头脑清醒时再做决定。

客户这边建议继续排查，因为系统已经稳定运行一年多了，没道理突然就不行了，还是希望深入研究一下。

就像是系统故障大部分一次重启就能解决，我决定先睡会，期待醒了之后问题能够迎刃而解。
睡醒之后，走投无路的我只好求助于老同事高高，高高是我以前在腾讯时专门负责HDFS的大牛，他对hadoop的精通程度堪比我熟知各类防脱发窍门，而且上万台大集群的优化经验，可遇而不可求，我想如果他也不能点播一二，恐怕就没人搞得定了，我也不必白费力气。

高高首先询问了集群的基本情况，并给我多项有效建议。最让我振奋的是根据高高的分析，我们的集群绝对没有达到性能的上限。

⑥The last day：对调用NN的锁的每个函数进行分析

这次没有直接看jmx信息，担心结果不准确。采用的是btrace这个工具，排查具体是哪个线程频繁给NN加锁，导致NN负载如此之高。

花费了3个小时分析，最终令人惊喜的是发现processIncrementalBlockReport这个线程请求频率非常高，远远高于其他线程。而这个线程不是datanode （dn）节点增量心跳的逻辑吗？为什么频率如此之高？心跳频率我不是都改掉了吗？难道都没生效么？

仔细查看hadoop代码，发现这个逻辑确实有问题，每次写数据和删数据都会立即调用，而我设置的那些心跳参数在客户的这个版本的hadoop集群里并没有这方面优化，设置了也没用，于是紧急在网上寻找patch的方法，最终找到了这个，它不仅仅解决了心跳频率的问题，还解决了加锁频率问题，通过减少锁的使用次数，从而减少上下文切换的次数，进而提升nn的吞吐量。

迅速打上此patch,  明显发现NN吞吐量上来了，而且不仅仅是访问NN不卡了，实时kafka的消费速度也一下子由原先的每小时处理40亿，上升至每小时处理100亿，入库性能也跟着翻倍。打上patch后，此问题得到了根本的解决。

究其根本原因在于HDFS NameNode内部的单一锁设计，使得这个锁显得极为的“重”。持有这个锁需要付出的代价很高。每个请求需要拿到这个锁，然后让NN 去处理这个请求，这里面就包含了很激烈的锁竞争。因此一旦NN的这个锁被一些大规模的导入/删除操作,容易使NameNode一下子处理大量请求，其它用户的任务会马上受到影响。这次patch的主要作用就是增量汇报的锁修改为异步的锁——让删除、上报等操作不影响查询。

具体详细描述与改法参考这里：

https://blog.csdn.net/android...

• • -

总 结

最后，针对于这次性能故障的排查，我从问题成因和解决建议两个方面总结一下：

①问题成因

系统之前一直运行平稳，突然出现的问题的原因主要是因为以下几个：

1.用户删除了大量文件，造成hadoop压力增大

• 近期硬盘快要满了，集中清理了一批数据
• 最近hadoop不稳定，集中释放了一大批文件

2. 近期明显的日常数据量暴增对hadoop调优后，重入数据，按日志进行数据条数统计，最近的数据规模增加很多

3.消费数据积压

本次调优过程中，由于数据积压了很多天，导致kafka一直在满速消费数据。而在满速消费的情况下，会对nn造成较大的冲击。

4.快照和mover对hadoop造成的冲击

• 清理快照的时候，释放了大量的数据块，造成数据的删除
• mover新增了大量的数据块，致使系统删除了大量的ssd上的文件块。且因节点数增多，心跳频繁，瞬时都进行processIncrementalBlockReport对nn造成较大的压力

②我的几点建议

1.Never give up easily！

在排查的第四天，在尝试过多种解决方案之后，我也想过要放弃，并且认为这次的性能故障是无解的。在这种时候我们不妨多与同事，哪怕是以前的同事领导讨论讨论，也许会带来不一样的思路和启发，要相信群体的智慧！

2.一定要了解的hadoop原理，这也是本次hadoop调优的关键点

（1） 当我们在HDFS中删除文件时：namenode只是把目录入口删掉，然后把需要删除的数据块记录到pending deletion blocks列表。当下一次datanode向namenode发送心跳时，namenode再把删除命令和这个列表发送到datanode端，所以这个pending deletion blocks列表很长很长，导致了timeout。

（2）当我们导入数据时：客户端会将数据写入到datanode里，而datanode在接到数据块后，会立即调processIncrementalBlockReport给NN汇报，写入数据量越多，越频繁，机器数量越多，进程越多，调用NN就会越频繁。所以本次的异步锁patch，在这里才会有效果。

3.最关键的一点：千万不要使用hadoop2.6.0这个版本！！！

用hadoop官方的话来讲，别的版本都是存在a few of bug，而这个版本存在a lot of bug，所以回去后第一件事要督促客户尽快升级换版本。

PS：如果你还想让你的Hadoop性能更上一层楼，建议选择更新至Hadoop3.2.1版本，且启用联邦模式，为此我们已经整理好了可能会遇到的问题及注意事项。
如果你还想再一次突破性能瓶颈，我们也准备好了教你如何提升router的性能瓶颈的实践文章。
微信公众号搜索“录信数软”即可第一时间获取技术实践干货。