作者介紹

母延年，大數(shù)據(jù)領(lǐng)域數(shù)據(jù)分析處理專家，原騰訊和阿里巴巴大數(shù)據(jù)領(lǐng)域?qū)＜壹?jí)工程師。曾在阿里開源項(xiàng)目Mdrill及騰訊Hermes項(xiàng)目擔(dān)任核心開發(fā)人員。

隨著國(guó)內(nèi)互聯(lián)網(wǎng)行業(yè)的發(fā)展，萬億規(guī)模的超大集群雖然已不像幾年前那么鳳毛麟角，但是也并不多見，尤其是涉及超萬億規(guī)模的超大集群性能故障排查的機(jī)會(huì)就更加稀少。

而這次我所進(jìn)行的超萬億規(guī)模的Hadoop NameNode性能故障排查也是在我創(chuàng)業(yè)幾年以來所遇到的集群規(guī)模最大，耗時(shí)最長(zhǎng)，排查工作量最大，頭發(fā)掉的最多，最終都不得不求助于大牛的一次經(jīng)歷。

因此在問題解決之后，我也第一時(shí)間將這次的整個(gè)排查過程記錄下來進(jìn)行總結(jié)，希望能給看到的各位同學(xué)有所幫助。下面，enjoy：

一、起 因

那是一個(gè)深夜，隨著手機(jī)屏幕的熄滅，這本應(yīng)該是一個(gè)溫暖而甜美的睡夢(mèng)的開始，突然一聲“叮咚”的提示音劃破了這靜謐，隨之而來的是“叮咚、叮咚、叮叮叮叮咚....”借著手機(jī)屏幕的亮光，我模糊的看見了那仿佛怪笑著的綠色人頭標(biāo)識(shí)上的字“你收到了20條微信消息”......

言歸正傳。事情的起因是由于近日客戶反饋錄信數(shù)據(jù)庫LSQL突然性能變差，之前秒級(jí)響應(yīng)的數(shù)據(jù)查詢與檢索，現(xiàn)在卻總是在“轉(zhuǎn)圈”，卡住不動(dòng)了。因?yàn)槭峭蝗话l(fā)生的現(xiàn)象，已經(jīng)在現(xiàn)場(chǎng)的同事先排除了業(yè)務(wù)變動(dòng)，但是并未發(fā)現(xiàn)問題。作為自己創(chuàng)立公司后第一個(gè)接到的萬億數(shù)據(jù)體量的大項(xiàng)目，我自身也非常重視，馬上第一時(shí)間奔赴現(xiàn)場(chǎng)。

這里先容介紹一下該平臺(tái)架構(gòu)，底層采用hadoop進(jìn)行分布式存儲(chǔ)，中間數(shù)據(jù)庫采用的錄信LSQL，數(shù)據(jù)實(shí)時(shí)導(dǎo)入采用kafka進(jìn)行。每天的數(shù)據(jù)規(guī)模是500億，數(shù)據(jù)存儲(chǔ)周期為90天，一共有4000多張數(shù)據(jù)表，其中最大的單表數(shù)據(jù)規(guī)模近2萬億條記錄，總數(shù)據(jù)規(guī)模將近5萬億，存儲(chǔ)空間占8PB。

數(shù)據(jù)平臺(tái)支撐的基本使用主要包括數(shù)據(jù)的全文檢索、多維查詢，以及地理位置檢索、數(shù)據(jù)碰撞等操作。也會(huì)有部分業(yè)務(wù)涉及數(shù)據(jù)的統(tǒng)計(jì)和分析，會(huì)有極少量的數(shù)據(jù)導(dǎo)出與多表關(guān)聯(lián)操作。

二、經(jīng)過

1.Before the day ：初步定位問題

出發(fā)的前一天，晴空萬里，萬里無云，一如我的心情。

話說我在創(chuàng)業(yè)之前在騰訊做Hermes系統(tǒng)，每日接入的實(shí)時(shí)數(shù)據(jù)量就已經(jīng)達(dá)到了3600億/天，之后更是達(dá)到了每日近萬億條數(shù)據(jù)的實(shí)時(shí)導(dǎo)入。為了不顯得那么凡爾賽，我只想說，我和梁?jiǎn)⒊诒贝笱葜v時(shí)的心情一樣：我對(duì)超大集群沒什么了解，但是還是有那么一點(diǎn)嘍！面對(duì)當(dāng)前每日500-1000億規(guī)模的系統(tǒng)，我在考慮是不是買票的時(shí)候把當(dāng)天的回程票也買了......

為了快速定位問題，還沒出發(fā)之前我就跟現(xiàn)場(chǎng)要了一些日志和jstack，初步定位是hadoop NameNode的瓶頸，而NN的優(yōu)化我們此前也做了很多次，別無其他，唯手熟爾。

下圖為當(dāng)時(shí)堆棧的分析情況，估計(jì)在座諸位看了都會(huì)信心滿滿，這很明顯就是hadoop卡頓。

2.First Day：嘗試調(diào)整log4j

到現(xiàn)場(chǎng)的第一天，依然是風(fēng)和日麗，心情繼續(xù)保持美麗。

我到現(xiàn)場(chǎng)后第一件事情就是不斷的抓hadoop Namenode的堆棧Jstack。從中得到的結(jié)論是問題確實(shí)是卡頓在NN上。此處NN是一個(gè)全局鎖，所有的讀寫操作都在排序等待，詳情如下圖所示：

（1）卡在哪里

這個(gè)鎖的等待個(gè)數(shù)竟然長(zhǎng)達(dá)1000多個(gè)，不卡才怪呢，我們?cè)偌?xì)看一下，當(dāng)前擁有這個(gè)鎖的線程在做什么？

（2）?問題分析

很明顯，在記錄log上存在瓶頸，阻塞的時(shí)間太久。

1)?記錄的log4j不應(yīng)該加【%L】，它會(huì)創(chuàng)建Throwable對(duì)象，而這個(gè)在java里是一個(gè)重對(duì)象。

2)?日志記錄太頻繁，刷盤刷不動(dòng)。

3) log4j有全局鎖，會(huì)影響吞吐量。

（3）調(diào)整方案

1)?客戶的hadoop版本采用的是2.6.0版本，該版本的hadoop，在日志處理上存在諸多問題，故我們將官方明確表示存在問題的patch打了進(jìn)來

HDFS-8245??因日志原因?qū)е耼n慢

HDFS-7503? 將日志記錄到鎖外，避免卡鎖

HDFS-7213??processIncrementalBlockReport 導(dǎo)致的記錄日志問題，嚴(yán)重影響NN性能

2)?禁用namenode所有info級(jí)別的日志

觀察發(fā)現(xiàn)當(dāng)有大量日志輸出的時(shí)候，全局鎖會(huì)阻塞NN。

目前修改方式是屏蔽到log4j的日志輸出，禁用namenode所有info級(jí)別的日志。

3)?log4j 的日志輸出去掉【%L】參數(shù)

這個(gè)參數(shù)會(huì)為了得到行號(hào)而創(chuàng)建new Throwable對(duì)象，這個(gè)對(duì)象對(duì)性能影響很大，大量創(chuàng)建會(huì)影響吞吐量。

4)?啟用異步審計(jì)日志

dfs.namenode.audit.log.async 設(shè)置為true，將審計(jì)日志改為異步。

（4）優(yōu)化效果

優(yōu)化之后，確實(shí)因log4j導(dǎo)致的卡頓問題不存在了，但hadoop的吞吐量依然卡，仍舊卡在lock上。

3.Second Day：優(yōu)化du，排查解決所有卡頓

在現(xiàn)場(chǎng)的第二天，晴空依然萬里，心情不算美麗。

接著昨天的工作：

（1）在解決了log4j的問題后，繼續(xù)抓jstack發(fā)現(xiàn)了如下位置：

（2）通過代碼進(jìn)行分析，發(fā)現(xiàn)確實(shí)此處有鎖，證實(shí)此處會(huì)引起所有訪問阻塞：

（3）繼續(xù)深入研讀代碼，發(fā)現(xiàn)受如下參數(shù)控制：

（2.6.5版本這個(gè)默認(rèn)值是5000，已經(jīng)不存在這個(gè)問題了）

這個(gè)參數(shù)的核心邏輯是，如果配置上大于零的值，它會(huì)間隔一定文件數(shù)量，釋放鎖，讓別的程序得以繼續(xù)執(zhí)行，該問題只會(huì)在hadoop2.6.0的版本里存在，之后的版本里已經(jīng)對(duì)此做了修復(fù)。

（4）解決辦法

1)?打上官方patch：

HDFS-8046

2)?lsql內(nèi)部移除所有關(guān)于hadoop du的使用

（5）為什么要打patch

2.6.5版本中，可以自己定義休眠時(shí)間，默認(rèn)休眠時(shí)間為500ms，而2.6.0休眠時(shí)間為1ms,我擔(dān)心太短，會(huì)出現(xiàn)問題。

繼續(xù)按照原先思路，排查所有的jstack 。將所有涉及卡頓的地方都一一解決掉，至此hadoop通過jstack已經(jīng)抓不到任何的活動(dòng)線程，但是依然卡頓在讀寫鎖的切換上，這說明：

（1）namenode內(nèi)部的每個(gè)函數(shù)已經(jīng)最優(yōu)，jstack基本抓不到了；

（2）堆棧調(diào)用只能看到近1000個(gè)讀寫鎖在不斷切換，說明nn的請(qǐng)求并發(fā)非常高，多線程之間鎖的上下文切換已經(jīng)成為了主要瓶頸。

所以當(dāng)下主要思路應(yīng)該落在如何減少NN的調(diào)用頻率上面。

4.Third Day：盡可能減少NN請(qǐng)求頻率

在現(xiàn)場(chǎng)的第三天，突然下起了暴雨，“愛就像藍(lán)天白云，晴空萬里，突然暴風(fēng)雨”......一如我的心情。

為了減少NN的請(qǐng)求頻率，嘗試了多個(gè)方法：?

（1）啟用錄信數(shù)據(jù)庫lsql的不同表不同分片功能

考慮到現(xiàn)場(chǎng)有4000多張表，每張表有1000多個(gè)并發(fā)寫入分片，有可能是同時(shí)寫入的文件數(shù)太多，導(dǎo)致的nn請(qǐng)求頻率太高，故考慮將那些小表，進(jìn)行分片合并，寫入的文件數(shù)量少了，請(qǐng)求頻率自然而然就降低了。

（2）與現(xiàn)場(chǎng)人員配合，清理不必要的數(shù)據(jù)，減少hadoop集群的壓力。清理后hadoop集群的文件塊數(shù)由將近2億，降低到1.3億，清理力度足夠大。

（3）調(diào)整一系列與NN有關(guān)交互的心跳的頻率：如blockmanager等相關(guān)參數(shù)。

（4）調(diào)整NN內(nèi)部鎖的類型：由公平鎖調(diào)整為非公平鎖。

本次調(diào)整涉及的參數(shù)有：

dfs.blockreport.intervalMsec 由21600000L調(diào)整為259200000L (3天)，全量心跳

dfs.blockreport.incremental.intervalMsec 增量數(shù)據(jù)心跳由0改為300，盡量批量一次上報(bào) （老版本無該參數(shù)）

dfs.namenode.replication.interval 由3秒調(diào)整為60秒，減少心跳頻率

dfs.heartbeat.interval 心跳時(shí)間由默認(rèn)3秒調(diào)整為60秒，減少心跳頻率

dfs.namenode.invalidate.work.pct.per.iteration 由0.32調(diào)整為0.15 (15%個(gè)節(jié)點(diǎn))，減少掃描節(jié)點(diǎn)數(shù)量

本次調(diào)整涉及的堆棧：

最終結(jié)果卡頓問題依然存在。本人已經(jīng)黔驢技窮，人已經(jīng)懵了，不知道該如何處理。

5.Fourth Day：無計(jì)可施，考慮建立分流機(jī)制

在現(xiàn)場(chǎng)的第四天，黑云壓城，暴雨臨門，當(dāng)然這是當(dāng)時(shí)的心里環(huán)境，實(shí)話實(shí)說當(dāng)天天氣還是不錯(cuò)滴。

拖著已經(jīng)連續(xù)熬了三個(gè)晚上的疲憊身軀，第四天一早就跟公司和客戶匯報(bào)排查具體情況，也直接說了已經(jīng)沒有任何的思路。希望能啟用B方案：

（1）啟用hadoop聯(lián)邦方案，靠多個(gè)namenode解決當(dāng)下問題；

（2）立即修改錄信lsql數(shù)據(jù)庫，在一個(gè)lsql數(shù)據(jù)庫內(nèi)適配hadoop多集群方案，也就是搭建兩個(gè)完全一樣的集群，錄信數(shù)據(jù)庫啟動(dòng)600個(gè)進(jìn)程，300個(gè)進(jìn)程請(qǐng)求舊集群，300個(gè)進(jìn)程分流到新集群，以達(dá)到減輕壓力的目的。

家里（公司）的意見是先回去睡覺，頭腦清醒時(shí)再做決定。

客戶這邊建議繼續(xù)排查，因?yàn)橄到y(tǒng)已經(jīng)穩(wěn)定運(yùn)行一年多了，沒道理突然就不行了，還是希望深入研究一下。

就像是系統(tǒng)故障大部分一次重啟就能解決，我決定先睡會(huì)，期待醒了之后問題能夠迎刃而解。在我睡著的半夢(mèng)半醒之中，我仿佛看見阿拉斯加的鱈魚正躍出水面，梅里雪山的金絲猴剛好爬上樹尖......還有那個(gè)站在hadoop之巔的男人——高高！

隨著高高出現(xiàn)在我的夢(mèng)里（實(shí)際上并沒有...），我一個(gè)機(jī)靈趕緊起身，立馬給高高打了個(gè)電話，高高是我以前在騰訊時(shí)專門負(fù)責(zé)HDFS的大牛，他對(duì)hadoop的精通程度堪比我熟知各類防脫發(fā)竅門，而且上萬臺(tái)大集群的優(yōu)化經(jīng)驗(yàn)，可遇而不可求，我想如果他也不能點(diǎn)播一二，恐怕就沒人搞得定了，我也不必白費(fèi)力氣。

高高首先詢問了集群的基本情況，并給我多項(xiàng)有效建議。最讓我振奮的是根據(jù)高高的分析，我們的集群絕對(duì)沒有達(dá)到性能的上限。

6.The last day：對(duì)調(diào)用NN的鎖的每個(gè)函數(shù)進(jìn)行分析

在現(xiàn)場(chǎng)的最后一天，白光萬道，紅霞滿天，終于有了解決方案的我心里暗爽。

這次沒有直接看jmx信息，擔(dān)心結(jié)果不準(zhǔn)確。采用的是btrace這個(gè)工具，排查具體是哪個(gè)線程頻繁給NN加鎖，導(dǎo)致NN負(fù)載如此之高。

花費(fèi)了3個(gè)小時(shí)分析，最終令人驚喜的是發(fā)現(xiàn)processIncrementalBlockReport這個(gè)線程請(qǐng)求頻率非常高，遠(yuǎn)遠(yuǎn)高于其他線程。而這個(gè)線程不是datanode （dn）節(jié)點(diǎn)增量心跳的邏輯嗎？為什么頻率如此之高？心跳頻率我不是都改掉了嗎？難道都沒生效么？

仔細(xì)查看hadoop代碼，發(fā)現(xiàn)這個(gè)邏輯確實(shí)有問題，每次寫數(shù)據(jù)和刪數(shù)據(jù)都會(huì)立即調(diào)用，而我設(shè)置的那些心跳參數(shù)在客戶的這個(gè)版本的hadoop集群里并沒有這方面優(yōu)化，設(shè)置了也沒用，于是緊急在網(wǎng)上尋找patch的方法，最終找到了這個(gè)，它不僅僅解決了心跳頻率的問題，還解決了加鎖頻率問題，通過減少鎖的使用次數(shù)，從而減少上下文切換的次數(shù)，進(jìn)而提升nn的吞吐量。

迅速打上此patch, ?明顯發(fā)現(xiàn)NN吞吐量上來了，而且不僅僅是訪問NN不卡了，實(shí)時(shí)kafka的消費(fèi)速度也一下子由原先的每小時(shí)處理40億，上升至每小時(shí)處理100億，入庫性能也跟著翻倍。打上patch后，此問題得到了根本的解決。

究其根本原因在于HDFS NameNode內(nèi)部的單一鎖設(shè)計(jì)，使得這個(gè)鎖顯得極為的“重”。持有這個(gè)鎖需要付出的代價(jià)很高。每個(gè)請(qǐng)求需要拿到這個(gè)鎖，然后讓NN 去處理這個(gè)請(qǐng)求，這里面就包含了很激烈的鎖競(jìng)爭(zhēng)。因此一旦NN的這個(gè)鎖被一些大規(guī)模的導(dǎo)入/刪除操作,容易使NameNode一下子處理大量請(qǐng)求，其它用戶的任務(wù)會(huì)馬上受到影響。這次patch的主要作用就是增量匯報(bào)的鎖修改為異步的鎖——讓刪除、上報(bào)等操作不影響查詢。

三、總 結(jié)：

最后，針對(duì)于這次性能故障的排查，我從問題成因和解決建議兩個(gè)方面總結(jié)一下：

1.問題成因

系統(tǒng)之前一直運(yùn)行平穩(wěn)，突然出現(xiàn)的問題的原因主要是因?yàn)橐韵聨讉€(gè)：

（1）用戶刪除了大量文件，造成hadoop壓力增大

近期硬盤快要滿了，集中清理了一批數(shù)據(jù)

最近hadoop不穩(wěn)定，集中釋放了一大批文件

（2）近期明顯的日常數(shù)據(jù)量暴增對(duì)hadoop調(diào)優(yōu)后，重入數(shù)據(jù)，按日志進(jìn)行數(shù)據(jù)條數(shù)統(tǒng)計(jì)，最近的數(shù)據(jù)規(guī)模增加很多

（3）消費(fèi)數(shù)據(jù)積壓

本次調(diào)優(yōu)過程中，由于數(shù)據(jù)積壓了很多天，導(dǎo)致kafka一直在滿速消費(fèi)數(shù)據(jù)。而在滿速消費(fèi)的情況下，會(huì)對(duì)nn造成較大的沖擊。

（4）快照和mover對(duì)hadoop造成的沖擊

清理快照的時(shí)候，釋放了大量的數(shù)據(jù)塊，造成數(shù)據(jù)的刪除

mover新增了大量的數(shù)據(jù)塊，致使系統(tǒng)刪除了大量的ssd上的文件塊。且因節(jié)點(diǎn)數(shù)增多，心跳頻繁，瞬時(shí)都進(jìn)行processIncrementalBlockReport對(duì)nn造成較大的壓力

2.我的幾點(diǎn)建議

（1）Never give up easily！

在排查的第四天，在嘗試過多種解決方案之后，我也想過要放棄，并且認(rèn)為這次的性能故障是無解的。在這種時(shí)候我們不妨多與同事，哪怕是以前的同事領(lǐng)導(dǎo)討論討論，也許會(huì)帶來不一樣的思路和啟發(fā)，要相信群體的智慧！

（2）一定要了解的hadoop原理，這也是本次hadoop調(diào)優(yōu)的關(guān)鍵點(diǎn)

? ?1）?當(dāng)我們?cè)贖DFS中刪除文件時(shí)：namenode只是把目錄入口刪掉，然后把需要?jiǎng)h除的數(shù)據(jù)塊記錄到pending deletion blocks列表。當(dāng)下一次datanode向namenode發(fā)送心跳時(shí)，namenode再把刪除命令和這個(gè)列表發(fā)送到datanode端，所以這個(gè)pending deletion blocks列表很長(zhǎng)很長(zhǎng)，導(dǎo)致了timeout。

? ?2）當(dāng)我們導(dǎo)入數(shù)據(jù)時(shí)：客戶端會(huì)將數(shù)據(jù)寫入到datanode里，而datanode在接到數(shù)據(jù)塊后，會(huì)立即調(diào)processIncrementalBlockReport給NN匯報(bào)，寫入數(shù)據(jù)量越多，越頻繁，機(jī)器數(shù)量越多，進(jìn)程越多，調(diào)用NN就會(huì)越頻繁。所以本次的異步鎖patch，在這里才會(huì)有效果。

（3）最關(guān)鍵的一點(diǎn)：千萬不要使用hadoop2.6.0這個(gè)版本?。?！

用hadoop官方的話來講，別的版本都是存在a few of bug，而這個(gè)版本存在a lot of bug，所以回去后第一件事要督促客戶盡快升級(jí)換版本。

更多干貨內(nèi)容請(qǐng)關(guān)注微信公眾號(hào)“錄信數(shù)軟”~