解Bug之路-應(yīng)用999線升高
解Bug之路-應(yīng)用999線升高
前言
監(jiān)控指標(biāo)誠(chéng)然是發(fā)現(xiàn)問(wèn)題于微末之時(shí)的極佳手段，但指標(biāo)往往有其表達(dá)的極限。在很多情況下，單獨(dú)看一個(gè)黃金指標(biāo)并不能表征系統(tǒng)的健康程度，反而有可能被其迷惑，進(jìn)而忽略相關(guān)問(wèn)題。(本文所提及的Linux Kernel源碼版本為4.18.10)
Bug現(xiàn)場(chǎng)
某天中午，某應(yīng)用的999線突然升高。由于是個(gè)QPS高達(dá)幾十萬(wàn)的查詢服務(wù)，1分鐘的升高就會(huì)影響數(shù)千個(gè)請(qǐng)求。初步判斷應(yīng)用容量不夠，直接進(jìn)行相關(guān)擴(kuò)容，擴(kuò)容后反而加劇了問(wèn)題!不得已又做了一次緊急擴(kuò)容，999線才恢復(fù)。這兩波操作過(guò)去，20多分鐘已經(jīng)過(guò)去了。
為了防止問(wèn)題再次發(fā)生，我們必須要徹查相關(guān)原因。于是筆者也就參與了調(diào)查。
Young GC升高
首先是去看常用的指標(biāo)，例如CPU idle, GC Time。發(fā)現(xiàn)有一些機(jī)器的CPU達(dá)到了60%，而在這些機(jī)器中，young gc有一個(gè)大幅度的增長(zhǎng)。
為什么Young GC升高
看上去GC問(wèn)題。那么，筆者就開(kāi)始思考為什么young gc升高。翻看gc日志。看到故障期間，不停的young gc。但這些young gc的表現(xiàn)很詭異。有時(shí)候young gc很快，只有數(shù)十毫秒，有時(shí)確達(dá)到了數(shù)百毫秒。而且這個(gè)耗時(shí)的跳躍沒(méi)什么規(guī)律，不是從某個(gè)時(shí)間點(diǎn)之后就一直是數(shù)百毫秒，而是數(shù)十和數(shù)百一直參雜著。
觀察young GC的詳細(xì)輸出，在數(shù)百毫秒的young GC時(shí)間里，大部分時(shí)間都在[Object Copy]上。令人奇怪的是。其Copy的Object大小確實(shí)差不多的。而這是個(gè)非常單純的查詢服務(wù)，故障期間，它的流量分布以及對(duì)應(yīng)的Object分布不應(yīng)該有非常大的變化。那么究竟是什么原因讓同樣大小以及數(shù)量的Object Copy會(huì)有十倍的差距呢？
再仔細(xì)觀察，不僅僅是Object Copy，在其它的GC階段也會(huì)出現(xiàn)時(shí)間暴漲的情況，只不過(guò)大部分集中在Object Copy而已。僅僅靠這些信息是無(wú)法看出來(lái)相關(guān)問(wèn)題的。
為什么只有部分機(jī)器Young GC升高
繼續(xù)觀察監(jiān)控，發(fā)現(xiàn)問(wèn)題出現(xiàn)在一部分機(jī)器上。而這部分機(jī)器都在一個(gè)機(jī)房(B機(jī)房)里面。另一個(gè)機(jī)房(A機(jī)房)的機(jī)器沒(méi)有受任何影響。當(dāng)然，出問(wèn)題的機(jī)器都出現(xiàn)了Young GC飆高的現(xiàn)象。難道兩個(gè)機(jī)房的流量分布不一樣？經(jīng)過(guò)一番統(tǒng)計(jì)，發(fā)現(xiàn)接口的調(diào)用分布只是略微有些不同。但細(xì)細(xì)思考一下，如果是機(jī)房流量分布不一樣，由于同機(jī)房是負(fù)載均衡的。要出問(wèn)題，也是同機(jī)房都出問(wèn)題。但問(wèn)題只集中B機(jī)房的一部分機(jī)器中。
尋找這些機(jī)器的共同特征
young gc都大幅升高
那么既然只有一部分機(jī)器出問(wèn)題。那么筆者開(kāi)始搜索起這些機(jī)器的共同特征。young gc在這部分機(jī)器耗時(shí)都大幅增長(zhǎng)。但由于筆者尚不能通過(guò)gc日志找出原因。那么就尋找了其它特征。
CPU.Busy
首先，是CPU.busy指標(biāo)。筆者發(fā)現(xiàn)，出問(wèn)題的機(jī)器CPU都在60%左右。但是，正常的節(jié)點(diǎn)CPU也有60%的，也有50%的，特征不是很明顯。
delta_nr_throttled和delta_throttled_time
在筆者觀察某臺(tái)故障機(jī)器監(jiān)控指標(biāo)的時(shí)候發(fā)現(xiàn)，發(fā)現(xiàn)delta_nr_throttled和delta_throttled_time這個(gè)指標(biāo)大幅度升高。
我們看下這兩個(gè)指標(biāo)的含義
nr_throttled:
Linux Doc: Number of times the group has been throttled/limited.
中文解釋: CGROUP被限制的數(shù)量
delta_nr_throttled: 是通過(guò)取間隔1分鐘的兩個(gè)點(diǎn)，計(jì)算出每分鐘CGROUP被限制的數(shù)量
throttled_time:
linux Doc: The total time duration (in nanoseconds) for which entities of the group have been throttled.
中文解釋: 某個(gè)CGroup被限制的時(shí)間
delta_throttled_time: 通過(guò)取間隔1分鐘的兩個(gè)點(diǎn)，計(jì)算出每分鐘CGROUP被限制的總時(shí)間
由于線上應(yīng)用這邊采用的是docker容器，所以會(huì)有這兩個(gè)指標(biāo)。而這兩個(gè)指標(biāo)表明了，這個(gè)CGroup由于CPU消耗太高而被宿主機(jī)的Kernel限制運(yùn)行。而令人奇怪的是，這些機(jī)器的CPU最多只有60%左右，按理來(lái)說(shuō)只有達(dá)到100%才能被限制(throttled/limit)。
宿主機(jī)CPU飆升
既然是宿主機(jī)限制了相關(guān)docker容器，那么很自然的聯(lián)想到宿主機(jī)出了問(wèn)題。統(tǒng)計(jì)了一下出故障容器在宿主機(jī)上的分布。發(fā)現(xiàn)出問(wèn)題的所有容器都是集中出現(xiàn)在兩臺(tái)宿主機(jī)上！
查看了下這兩臺(tái)宿主機(jī)的CPU Busy，發(fā)現(xiàn)平均已經(jīng)90%多了。
宿主機(jī)超賣
詳細(xì)觀察了下這兩個(gè)宿主機(jī)，發(fā)現(xiàn)它們超賣非常嚴(yán)重。而且當(dāng)前這個(gè)出問(wèn)題的應(yīng)用非常集中的部署在這兩個(gè)宿主機(jī)上。一臺(tái)48核的宿主機(jī)，僅僅出問(wèn)題的這個(gè)應(yīng)用就分配了10個(gè)，而且分配的資源是每個(gè)容器8核(實(shí)際上是時(shí)間片)。那么按照，每個(gè)容器使用了60%計(jì)算，正好用滿了這個(gè)宿主機(jī)的核
60% * 10 * 8 = 48 正好和宿主機(jī)的48核相對(duì)應(yīng)。
為什么第一次擴(kuò)容后加劇了問(wèn)題
因?yàn)檫@次是通過(guò)API自動(dòng)擴(kuò)容，而由于打散度計(jì)算的原因，還是擴(kuò)容到了這兩臺(tái)已經(jīng)不堪重負(fù)的CPU上。同時(shí)應(yīng)用啟動(dòng)加載時(shí)候的CPU消耗也加劇了宿主機(jī)CPU的消耗。
為什么第二次擴(kuò)容之后999線恢復(fù)正常
因?yàn)榈诙沃苯油ㄟ^(guò)API手動(dòng)擴(kuò)容，一次性在10多臺(tái)宿主機(jī)上機(jī)器上擴(kuò)了一倍的機(jī)器。這樣分配在這兩臺(tái)不堪重負(fù)的宿主機(jī)上的應(yīng)用流量降低到一半左右。進(jìn)而使得999線恢復(fù)正常。
為什么容器相關(guān)的CPU busy在宿主機(jī)已經(jīng)接近100%的情況下，依舊只展示60%的
很明顯的，容器的CPU Busy在很大程度上誤導(dǎo)了我們的決策。在之前的容量壓測(cè)中，壓到期望的TPS時(shí)候CPU Busy只有50%多，而且基本是按照TPS線性增長(zhǎng)的，就使得我們覺(jué)得這個(gè)應(yīng)用在當(dāng)前的資源下容量是綽綽有余。畢竟CPU Busy顯示的還是非常健康的。
但沒(méi)想到，在壓測(cè)CPU 50%多的時(shí)候，其實(shí)已經(jīng)到了整個(gè)應(yīng)用容量的極限。線上的流量和壓測(cè)流量的構(gòu)造有稍微一點(diǎn)的區(qū)別，讓CPU漲了個(gè)5%左右,過(guò)了那個(gè)宿主機(jī)CPU的臨界點(diǎn)，進(jìn)而就導(dǎo)致了應(yīng)用出現(xiàn)了非常高的999線。
容器CPU busy和idle的計(jì)算
為了探究這個(gè)問(wèn)題，筆者就不得不看下容器的CPU busy是如何計(jì)算出來(lái)的。畢竟Linux的CGroup并沒(méi)有提供CPU Busy這個(gè)指標(biāo)。翻閱了一下監(jiān)控的計(jì)算公式。
每隔5秒取一下cpuacct.usage的數(shù)據(jù)
cat /sys/fs/cgroup/cpu/cpuacct.usage
CPU.busy = (cpuacct.usage(T秒) - cpuacct.usage(T-5秒))/((5秒)*CPU核數(shù))
CPU.idle = 1- CPU.busy
那么我們可以看一下cpuacct.usage是如何計(jì)算的。Kernel的代碼實(shí)現(xiàn)為:
cpuusage_read
|->__cpuusage_read
|->cpuacct_cpuusage_read
static u64 __cpuusage_read(struct cgroup_subsys_state *css,
enum cpuacct_stat_index index)
{
/* 獲取當(dāng)前對(duì)應(yīng)cgroup中的cpuacct結(jié)構(gòu)體*/
struct cpuacct *ca = css_ca(css);
......
/* 遍歷所有可能的CPU */
for_each_possible_cpu(i)
totalcpuusage += cpuacct_cpuusage_read(ca, i, index);
return totalcpuusage;
}
static u64 cpuacct_cpuusage_read(struct cpuacct *ca, int cpu,
enum cpuacct_stat_index index)
{
// 從當(dāng)前cgroup中獲取對(duì)應(yīng)相應(yīng)的cpuusage結(jié)構(gòu)體
struct cpuacct_usage *cpuusage = per_cpu_ptr(ca->cpuusage, cpu);
......
/* i=0計(jì)算的是user space的usage，i=1計(jì)算的是kernel space的usage */
for (i = 0; i < CPUACCT_STAT_NSTATS; i++)
data += cpuusage->usages[i];
}
由代碼可見(jiàn)，其計(jì)算是將所有CPU中的關(guān)于當(dāng)前CGroup的cpuusage->usages中的user和system time相加，進(jìn)而獲取到最終此。那么我們可以進(jìn)一步看下CGroup中的cpuusage是如何計(jì)算的。這邊筆者以我們常用的CFS(完全公平調(diào)度的代碼實(shí)現(xiàn)為例):
/* 相關(guān)的一條cpuusage代碼路徑如下 *.
pick_next_task_fair
|->put_prev_entity
|->update_curr
|->cgroup_account_cputime /* 其中還包含對(duì)當(dāng)前cgroup的parentGroup的修正*/
|->cpuacct_charge
void cpuacct_charge(struct task_struct *tsk, u64 cputime)
{
struct cpuacct *ca;
int index = CPUACCT_STAT_SYSTEM;
struct pt_regs *regs = task_pt_regs(tsk);
/* 判斷是system time還是user time */
if (regs && user_mode(regs))
index = CPUACCT_STAT_USER;
rcu_read_lock();
/* 將相關(guān)的CPU運(yùn)行時(shí)間入賬 */
for (ca = task_ca(tsk); ca; ca = parent_ca(ca))
this_cpu_ptr(ca->cpuusage)->usages[index] += cputime;
rcu_read_unlock();
}
由上面代碼可知，kernel會(huì)在進(jìn)程間切換的時(shí)候，將當(dāng)前進(jìn)程的運(yùn)行時(shí)間記入到相關(guān)。那么就是這個(gè)cputime的計(jì)算了。
/* 一個(gè)cfs_rq可以是一個(gè)task進(jìn)程，也可以是一個(gè)cgroup，代表的是完全公平調(diào)度runqueue中的一個(gè)元素 */
static void update_curr(struct cfs_rq *cfs_rq){
/* 這個(gè)now=rq->clock_task，clock_task返回的rq->clock減去處理IRQs竊取的時(shí)間，其計(jì)算不在本文描述范圍內(nèi) , 不考慮IRQ的話，可以認(rèn)為等于此rq的總運(yùn)行時(shí)間*/
u64 now = rq_clock_task(rq_of(cfs_rq));
/* 這個(gè)delta_exec表明了在這一次的運(yùn)行中，此cfs_rq(進(jìn)程orCgroup)實(shí)際運(yùn)行了多長(zhǎng)時(shí)間*/
delta_exec = now - curr->exec_start;
curr->exec_start = now;
......
/* 將這一次進(jìn)程在當(dāng)前CFS調(diào)度下運(yùn)行的時(shí)間更新如相關(guān)cgroup的usage */
cgroup_account_cputime(curtask, delta_exec);
.....
}
好了，翻了一大堆代碼，我們的cpuusage實(shí)際上就是這個(gè)cgroup在這一次CFS的kernel調(diào)度時(shí)間片中實(shí)際運(yùn)行的時(shí)間。而我們的應(yīng)用主要是一個(gè)Java進(jìn)程，那么其基本就是這個(gè)Java進(jìn)程運(yùn)行了多長(zhǎng)時(shí)間。值得注意的是，每個(gè)CPU的調(diào)度都會(huì)進(jìn)行這樣的計(jì)算。如下圖所示:
那么我們來(lái)看一下在超賣情況下的表現(xiàn)。如下圖所示:
(圖中1.25s只是為了繪圖方便，實(shí)際調(diào)度時(shí)間切片非常小)
如果超賣了，而且進(jìn)程都比較繁忙，那么每個(gè)CGroup肯定不能完全的占用宿主機(jī)的CPU。指定到某個(gè)CPU上就勢(shì)必會(huì)有多個(gè)CGroup交替進(jìn)行。而之前的容器CPU.Busy計(jì)算公式
CPU.busy = (cpuacct.usage(T秒) - cpuacct.usage(T-5秒))/((5秒)*CPU核數(shù))
反應(yīng)的實(shí)際上是這個(gè)容器在這個(gè)CPU(核)上運(yùn)行了多長(zhǎng)時(shí)間。而完全不能反應(yīng)CPU的繁忙程度。
如果不超賣，每個(gè)CGroup被均勻的分到各自的CPU上互不影響(當(dāng)然如果cgroup綁核了那隔離性更好)，那么這個(gè)計(jì)算公式才能夠比較準(zhǔn)確的反映CPU的情況。
nr_throttled和throttled_time
在Kernel中這兩個(gè)參數(shù)表示由于分配給Cgroup的cfs_quota_us時(shí)間片額度用完。進(jìn)而導(dǎo)致被內(nèi)核限制,限制的次數(shù)為nr_throttled，限制的總時(shí)間為throttled_time。
cat /sys/fs/cgroup/cpuacct/cpu.cfs_period_us 100000(100ms)
cat /sys/fs/cgroup/cpuacct/cpu.cpu.cfs_quota_us 800000(800ms) 因?yàn)橛?個(gè)核，所以分配了800ms
cat /sys/fs/cgroup/cpuset/cpuset.cpus 基本打散到所有的CPU上
但這邊和上面的推論有一個(gè)矛盾的點(diǎn),如果由于CPU超賣而引起的問(wèn)題的話。那么每個(gè)CGroup并不能分到800ms這樣總的時(shí)間片。因?yàn)榘凑丈厦娴耐扑?，每個(gè)CGroup最多分到60% * 800=480ms的時(shí)間片。而這個(gè)時(shí)間片是不應(yīng)該觸發(fā)nr_throttled和throttled_time的！
就在筆者對(duì)著Kernel源碼百思不得其解之際，筆者發(fā)現(xiàn)Linux Kernel在5.4版本有個(gè)優(yōu)化
https://lwn.net/Articles/792268/
sched/fair: Fix low cpu usage with high throttling by removing expiration of cpu-local slices
也就是說(shuō)在5.4版本之前，在一些場(chǎng)景下low cpu usage依舊能導(dǎo)致cgroup被throttled。而這個(gè)場(chǎng)景即是:
that highly-threaded, non-cpu-bound applications
running under cpu.cfs_quota_us constraints can hit a high percentage of
periods throttled
高度線程化，非CPU密集的應(yīng)用程序在CPU.cfs_quota_us約束下運(yùn)行時(shí)，可能會(huì)有很高的周期被限制，同時(shí)不會(huì)消耗分配的配額。
出故障的應(yīng)用使用了大量的線程去處理請(qǐng)求，同時(shí)也有大量的IO操作(操作分布式緩存)，符合此Bug的描述。
# 那么到底是內(nèi)核Bug還是超賣是主因呢？
這個(gè)疑問(wèn)當(dāng)然靠對(duì)比來(lái)解決，我們?cè)诠收现?，做了一次壓測(cè)(CPU.Busy > 60%)，這次應(yīng)用是不超賣的。這次delta_nr_throttled和delta_throttled_time依舊存在，不過(guò)比故障時(shí)的數(shù)量少了一個(gè)數(shù)量級(jí)。
同時(shí)999線從故障時(shí)候的暴漲6倍變成了只增長(zhǎng)1倍。
很明顯的，宿主機(jī)超賣是主因！而且宿主機(jī)超賣后的宿主機(jī)CPU負(fù)載過(guò)高還加重了這個(gè)Bug的觸發(fā)。
關(guān)于Cgroup的核數(shù)分配
線上的Cgroup(容器)的核數(shù)分配實(shí)際上是按照(核數(shù)=cfs_quota_us/cfs_period_us)這個(gè)模型去分配的，同時(shí)并不會(huì)在cpuset進(jìn)行綁核。也就是說(shuō)一個(gè)48核的容器，應(yīng)用的各個(gè)線程可以跑在任何一個(gè)核上，只不過(guò)只分配了8核的時(shí)間片額度。這就利用了Cgroup的帶寬控制機(jī)制CFS_BANDWITH。
改進(jìn)措施
很明顯的改進(jìn)措施可以是下面幾種:
針對(duì)超賣:
1) 宿主機(jī)不超賣，但不是一個(gè)好的選擇，因?yàn)橘Y源利用率上不去，存在大量CPU利用率很低的應(yīng)用
2) 根據(jù)應(yīng)用的CPU利用率情況進(jìn)行高低錯(cuò)配放到宿主機(jī)上，在利用資源利用率的同時(shí)又不至于互相影響
針對(duì)內(nèi)核的Bug
1) 可以打Patch或者升級(jí)到5.4
為什么Young GC會(huì)變慢
回過(guò)頭來(lái)看看young gc為什么會(huì)慢就很明顯了。因?yàn)樵趛oung gc時(shí)候，被shedule出去了，而且沒(méi)有其它的空閑CPU讓jvm可以schedule回來(lái)，白白浪費(fèi)了很長(zhǎng)時(shí)間。
因?yàn)閛bject copy在這個(gè)應(yīng)用的young gc中是最耗費(fèi)CPU以及時(shí)間的操作，所以自然在object copy階段出現(xiàn)變慢的現(xiàn)象。
當(dāng)然，進(jìn)程schedule可以處在各種時(shí)間點(diǎn)，所以并不僅僅是Young GC變慢了，在請(qǐng)求處理階段也可能變慢。
總結(jié)
指標(biāo)雖然能夠比較準(zhǔn)確且客觀的反映兩個(gè)時(shí)間點(diǎn)的變化。但指標(biāo)的定義和對(duì)指標(biāo)的解讀確實(shí)比較主觀的，沒(méi)有理解清楚指標(biāo)所能表達(dá)的極限以及使用場(chǎng)景。往往會(huì)讓我們排查問(wèn)題進(jìn)入誤區(qū)！