問題描述
近日，在生產(chǎn)環(huán)境上，一個使用了Jedis 操作Redis數(shù)據(jù)庫的客戶端應(yīng)用，出現(xiàn)了如下異常：
15:43:55.102 ERROR [RpcWorkThread_7] cache.MstpMysqlCacheClient getInstance 168 - Cache 異常
redis.clients.jedis.exceptions.JedisConnectionException: All sentinels down, cannot determine where is X.X.X.X-6379 master is running...
at redis.clients.jedis.JedisSentinelPool.initSentinels(JedisSentinelPool.java:153) ~[jedis-2.6.2.jar:na]
at redis.clients.jedis.JedisSentinelPool.<init>(JedisSentinelPool.java:69) ~[jedis-2.6.2.jar:na]
at redis.clients.jedis.JedisSentinelPool.<init>(JedisSentinelPool.java:52) ~[jedis-2.6.2.jar:na]
省略
從異常可以明確，這是一個Jedis連接異常。All sentinels down? 馬上去檢查了所有Sentinel服務(wù)器，發(fā)現(xiàn)所有的Sentinel服務(wù)進(jìn)程都在運(yùn)行，沒有Down掉。但是卻出現(xiàn)了下面的問題：
可以發(fā)現(xiàn)每臺Sentinel的Cpu占有率一直都是接近于100%（注意是接近，經(jīng)常在99%上下），然后使用Redis-cli連接到Sentinel上進(jìn)行狀態(tài)查看，但是輸入任何命令都會超時：
現(xiàn)象就這么簡單，敘述完了，問題很詭異，現(xiàn)在開始進(jìn)行問題的追蹤和分析。
問題追蹤
生產(chǎn)環(huán)境Redis使用的版本是2.8.21，Jedis是2.6.2。為了方便定位，我們需要瀏覽他們的源碼。
尋找問題發(fā)生所在地
首先我們要了解目前生產(chǎn)環(huán)境的Jedis連接Redis集群的機(jī)制。目前的集群架構(gòu)設(shè)計為：
如上圖所示，客戶端使用JedisClient（即JedisSentinelPool）連接到各個Sentinel，通過Sentinel操作相應(yīng)的Redis主服務(wù)器。
首先，我們定位到異常所在函數(shù)：initSentinels。這段函數(shù)比較長，但很關(guān)鍵，能讓我們清楚問題到底出現(xiàn)在Jedis和服務(wù)器的哪一端。
private HostAndPort initSentinels(Set<String> sentinels, final String masterName) {
HostAndPort master = null;
boolean sentinelAvailable = false;
log.info("Trying to find master from available Sentinels...");
for (String sentinel : sentinels) {
final HostAndPort hap = toHostAndPort(Arrays.asList(sentinel.split(":")));
log.fine("Connecting to Sentinel " + hap);
Jedis jedis = null;
try {
jedis = new Jedis(hap.getHost(), hap.getPort());
List<String> masterAddr = jedis.sentinelGetMasterAddrByName(masterName);
// connected to sentinel...
sentinelAvailable = true;
if (masterAddr == null || masterAddr.size() != 2) {
log.warning("Can not get master addr, master name: " + masterName + ". Sentinel: " + hap
+ ".");
continue;
}
master = toHostAndPort(masterAddr);
log.fine("Found Redis master at " + master);
break;
} catch (JedisException e) {
// resolves #1036, it should handle JedisException there's another chance
// of raising JedisDataException
log.warning("Cannot get master address from sentinel running @ " + hap + ". Reason: " + e
+ ". Trying next one.");
} finally {
if (jedis != null) {
jedis.close();
}
}
}
if (master == null) {
if (sentinelAvailable) {
// can connect to sentinel, but master name seems to not
// monitored
throw new JedisException("Can connect to sentinel, but " + masterName
+ " seems to be not monitored...");
} else {
throw new JedisConnectionException("All sentinels down, cannot determine where is "
+ masterName + " master is running...");
}
}
log.info("Redis master running at " + master + ", starting Sentinel listeners...");
for (String sentinel : sentinels) {
final HostAndPort hap = toHostAndPort(Arrays.asList(sentinel.split(":")));
MasterListener masterListener = new MasterListener(masterName, hap.getHost(), hap.getPort());
// whether MasterListener threads are alive or not, process can be stopped
masterListener.setDaemon(true);
masterListeners.add(masterListener);
masterListener.start();
}
我們先了解initSentinels的作用：
- 首先，根據(jù)客戶端提供的Sentinel集合（存儲了所有Sentinel服務(wù)器的地址）進(jìn)行遍歷，每次遍歷中：
- 構(gòu)造一個Jedis實(shí)例與當(dāng)前Sentinel建立連接。
- 通過調(diào)用sentinelGetMasterAddrByName向Sentinel取得Master的地址和端口。
- 以上遍歷結(jié)束后，如果成功的獲取所有Master的地址和端口話，則繼續(xù)啟動多個（與Sentinel服務(wù)器個數(shù)對應(yīng)）MasterListener線程。
這些線程的作用是為了不斷的訂閱Sentinel的消息， 以監(jiān)聽Master的主從切換。
為什么要監(jiān)聽主從切換呢，這涉及到了另一個函數(shù)initPool，篇幅限制，我們只要了解它的作用：
如果發(fā)生了主從切換，則重新初始化連接池，以改變連接池里的Jedis的句柄關(guān)聯(lián)對象，以始終關(guān)聯(lián)Master而不是Slave。所以，監(jiān)聽主從切換的目的是確保連接池給用戶的Jedis連接句柄絕對指向Master，因?yàn)槲覀兊募褐挥蠱aster接受讀寫。
現(xiàn)在 ，我們開始追蹤問題。可以清楚的看到，問題出現(xiàn)在第50行“All sentinels down...”。程序運(yùn)行到這里，說明前面的sentinel集合遍歷結(jié)束了。并且，此時“master == null、sentinelAvailable==false”。而“sentinelAvailable==false”說明了程序還未執(zhí)行到“sentinelAvailable = true;”就發(fā)生了異常，繼而說明問題出現(xiàn)在了前面：
jedis = new Jedis(hap.getHost(), hap.getPort());
List<String> masterAddr = jedis.sentinelGetMasterAddrByName(masterName);
結(jié)合之前連接Sentinel出現(xiàn)的超時現(xiàn)象，猜測或許是因?yàn)闊o法與Sentinel建立正常的連接導(dǎo)致這里拋出異常。至此，可以明確這個問題與本地客戶端沒有多大關(guān)系，所以我們可以大膽的將注意力投入到Sentinel服服務(wù)器之上。
尋找問題函數(shù)
通過第一步，我們確定了問題出現(xiàn)在Sentinel服務(wù)器之上，繼續(xù)追蹤和分析。
根據(jù)我的經(jīng)驗(yàn)，一個進(jìn)程的CPU占有率一直接近或達(dá)到100%，大部分情況下都可以說明該處于一個無限或類無限循環(huán)中，并且循環(huán)間隔沒有進(jìn)行Sleep的調(diào)用，使得進(jìn)程持續(xù)占有CPU時間片。這個猜測對嗎？我也不確定。
對于主服務(wù)是單進(jìn)程的Sentinel服務(wù)，如果出現(xiàn)死循環(huán)，對于外界的響應(yīng)必定是超時的。所以，我們目前首先要定位這個假設(shè)的循環(huán)到底在哪里。
此時，需要祭出兩個大殺器：GDB以及Strace，這兩個工具我就不做過多介紹了。
首先，在使用GDB前，我們需要得到Sentinel進(jìn)程ID，運(yùn)行top：
然后，根據(jù)其進(jìn)程ID得到其下所有線程的運(yùn)行狀況，運(yùn)行top -H -p 5515：
可以發(fā)現(xiàn)，Sentinel總共有三個線程，5515線程CPU占用率異常，我們記住這個線程ID：5515。然后，使用GDB調(diào)試正在運(yùn)行的Sentinel進(jìn)程，執(zhí)行 gdb icdn 5515：
然后，我們輸入info thread以列出當(dāng)前進(jìn)程的所有線程信息：
上面，LWP即表示線程ID，所以，我們定位到了1號，繼續(xù)執(zhí)行thread 1表示切換到該進(jìn)程：
接著輸入bt，查看當(dāng)前的函數(shù)棧幀信息：
觀察棧幀信息，這一行很引人注目：
#1 0x00000000004194d1 in anetGenericAccept (err=0x6f9438 "accept: Too many open files", s=5, sa=0x7fff4851ab00, len=0x7fff4851ab8c) at anet.c:487
也就是說anetGenericAccept函數(shù)的一個err參數(shù)的值為“accept:Too many open files”。
另外，如果你多次運(yùn)行g(shù)db icdn 5515，有時候也會得到不同與上面的如下信息（每次attach不一樣說明程序調(diào)用的不是同一個函數(shù)棧）：
可以看到，redisLograw的參數(shù)也包括了“Too many open files”這個錯誤。
綜上，可以發(fā)現(xiàn)兩類棧幀都出現(xiàn)了“Too many open files”錯誤，難道這些都是因?yàn)榇蜷_的文件數(shù)太多造成的？不急，我們先記住這個錯誤。
由前面可知，當(dāng)前Sentinel進(jìn)程的函數(shù)調(diào)用鏈?zhǔn)恰癿ain->aeMain->aeProcessEvents->acceptTcpHandler->anetTcpAccept->anetGenericAcept->accept”。馬上打開Redis的源碼，最終定位到這里：
static int anetGenericAccept(char *err, int s, struct sockaddr *sa, socklen_t *len) {
int fd;
while(1) {
fd = accept(s,sa,len);
if (fd == -1) {
if (errno == EINTR)
continue;
else {
anetSetError(err, "accept: %s", strerror(errno));
return ANET_ERR;
}
}
break;
}
return fd;
}
看到一個代碼里的while(1)讓我很是激動，所以我猜測是不是這里出現(xiàn)了問題，但只是猜測。此時，還需要使用另外一個殺器——strace，我們利用它對Sentinel使用的系統(tǒng)調(diào)用進(jìn)行跟蹤。執(zhí)行strace -T -r -c -p 5515（需要等待一定時間后手動結(jié)束strace）：
由上圖可以清楚的看到，在跟蹤的這段時間內(nèi)，accept、epoll_wait、open三個系統(tǒng)調(diào)用就占用了總計98%的時間，這當(dāng)然是不正常的。另外，accetp函數(shù)在短短的時間內(nèi)調(diào)用了2434680次，失敗調(diào)用占據(jù)了100%，這說明了之前anetGenericAccept中，accept 返回值每次都是-1。
最開始猜測的是Sentinel在anetGenericAccept中陷入while(1)不能自拔，但發(fā)現(xiàn)我想錯了，因?yàn)榇藭rerrno != EINTR，而應(yīng)該是“Too many open files”（錯誤號我沒查），整個函數(shù)返回的是ANET_ERR（-1）。
為了再次證實(shí)這個結(jié)論，決定使用strace打印當(dāng)前Sentinel正在執(zhí)行的函數(shù)，運(yùn)行strace -t -p 5515：
果然，可以看到基本上都是這三個函數(shù)的執(zhí)行，說明Sentinel正在被這三個函數(shù)所糾纏。但是這個如何與之前GDB調(diào)試的結(jié)果對應(yīng)呢？很清楚，這里accept即為之前anetGenericAccept的accept調(diào)用。
而open函數(shù)，是否對應(yīng)了redisLograw函數(shù)？查看了redisLograw的源碼：
void redisLogRaw(int level, const char *msg) {
const int syslogLevelMap[] = { LOG_DEBUG, LOG_INFO, LOG_NOTICE, LOG_WARNING };
const char *c = ".-*#";
FILE *fp;
char buf[64];
int rawmode = (level & REDIS_LOG_RAW);
int log_to_stdout = server.logfile[0] == '\0';
level &= 0xff; /* clear flags */
if (level < server.verbosity) return;
fp = log_to_stdout ? stdout : fopen(server.logfile,"a");
if (!fp) return;
if (rawmode) {
fprintf(fp,"%s",msg);
} else {
int off;
struct timeval tv;
gettimeofday(&tv,NULL);
off = strftime(buf,sizeof(buf),"%d %b %H:%M:%S.",localtime(&tv.tv_sec));
snprintf(buf+off,sizeof(buf)-off,"%03d",(int)tv.tv_usec/1000);
fprintf(fp,"[%d] %s %c %s\n",(int)getpid(),buf,c[level],msg);
}
fflush(fp);
if (!log_to_stdout) fclose(fp);
if (server.syslog_enabled) syslog(syslogLevelMap[level], "%s", msg);
}
原來，關(guān)鍵就在于fp = log_to_stdout ? stdout : fopen(server.logfile,”a”);這一句,下面請聽解釋：
- fopen底層實(shí)際調(diào)用的是open系統(tǒng)調(diào)用：
int open(const char *pathname, int flags, mode_t mode);。 - 通過查看fopen源碼，模式a表示的即為O_WRONLY|O_CREAT|O_APPEND，默認(rèn)權(quán)限為0666。
- 所以，最終體現(xiàn)為：
open(“/usr/local/SINO/redis/log/sentinel.log”,O_WRONLY|O_CREAT|O_APPEND, 0666)
這樣，我們可以得出這個結(jié)論：accept和fopen的所在函數(shù)anetGenericAccept與redisLogRaw的調(diào)用，導(dǎo)致CPU居高不下。
繼續(xù)往下定位
前面GDB的調(diào)試的兩類函數(shù)棧幀結(jié)果，發(fā)現(xiàn)調(diào)用棧中都存在acceptTcpHandler這個函數(shù)：
acceptTcpHandler的源碼非常關(guān)鍵：
void acceptTcpHandler(aeEventLoop *el, int fd, void *privdata, int mask) {
int cport, cfd, max = MAX_ACCEPTS_PER_CALL;
char cip[REDIS_IP_STR_LEN];
REDIS_NOTUSED(el);
REDIS_NOTUSED(mask);
REDIS_NOTUSED(privdata);
while(max--) {
// accept 客戶端連接
cfd = anetTcpAccept(server.neterr, fd, cip, sizeof(cip), &cport);
if (cfd == ANET_ERR) {
if (errno != EWOULDBLOCK)
redisLog(REDIS_WARNING,
"Accepting client connection: %s", server.neterr);
return;
}
redisLog(REDIS_VERBOSE,"Accepted %s:%d", cip, cport);
// 為客戶端創(chuàng)建客戶端狀態(tài)（redisClient）
acceptCommonHandler(cfd,0);
根據(jù)redislogRaw記錄的錯誤“Accepting client connection…”，可以發(fā)現(xiàn)， 問題出現(xiàn)在這句：redisLog(REDIS_WARNING,”Accepting client connection: %s”, server.neterr);
原來，anetTcpAccept中的accept調(diào)用返回了ANET_ERR，并且errno 對應(yīng)錯誤內(nèi)容為“Too many open files”，所以acceptTcpHandler會馬上返回?；旧峡梢源_定，CPU占用率居高不下的原因是對acceptTcpHandler不停的進(jìn)行調(diào)用，并且調(diào)用時間很短。
看到acceptTcpHandler這個函數(shù)，如果了解Redis事件處理機(jī)制的人應(yīng)該會比較熟悉。對滴!這就是Redis事件處理機(jī)制中文件事件的處理函數(shù)之一，大概提一下：
Redis的事件包括時間和文件兩種事件，其中文件事件使用IO多路復(fù)用監(jiān)聽多個套接字。
- 當(dāng)套接字變得可讀時，如客戶端執(zhí)行write、close或connect操作時，套接字產(chǎn)生AS_READBALE事件
- 當(dāng)套接字變得可寫時，如客戶端執(zhí)行read操作時，套接字產(chǎn)生AE_WRITABLE事件。
而這里的acceptTcpHandler，是專門針對connect操作的，是Redis的連接應(yīng)答處理函數(shù)，用來對連接服務(wù)器監(jiān)聽套接字的客戶端進(jìn)行應(yīng)答。
在initServer函數(shù)中可以看到，專門為連接事件注冊了acceptTcpHandler事件處理函數(shù)(傳入函數(shù)指針)。
void initServer() {
省略
/* Create an event handler for accepting new connections in TCP and Unix
* domain sockets. */
for (j = 0; j < server.ipfd_count; j++) {
if (aeCreateFileEvent(server.el, server.ipfd[j], AE_READABLE,
acceptTcpHandler,NULL) == AE_ERR)
{
redisPanic(
"Unrecoverable error creating server.ipfd file event.");
}
}
省略
}
誰在不停的調(diào)用acceptTcpHandler
現(xiàn)在，我們定位到了CPU占有率持續(xù)增長的原因，是由于“Too many open files”導(dǎo)致acceptTcpHandler持續(xù)調(diào)用而產(chǎn)生的。歸納為兩個問題：
- 為什么會產(chǎn)生too many open files
- acceptTcpHandler為什么會持續(xù)調(diào)用
對于第一個問題，我們最后再做解釋，我們首先分析第二個。
在前面的GDB調(diào)試的結(jié)果的圖中，我們都發(fā)現(xiàn)了main->aeMain->aeProcessEvents這樣一個調(diào)用鏈，查看源碼，發(fā)現(xiàn)在aeMain中，這樣調(diào)用aeProcessEvents：
void aeMain(aeEventLoop *eventLoop) {
eventLoop->stop = 0;
while (!eventLoop->stop) {
if (eventLoop->beforesleep != NULL)
eventLoop->beforesleep(eventLoop);
aeProcessEvents(eventLoop, AE_ALL_EVENTS);
}
}
aeMain是Redis事件處理的主循環(huán)，這里有個while()循環(huán)，我覺得似乎發(fā)現(xiàn)了什么。原來，這一句表示，只要eventLoop->stop == 0，循環(huán)會一直繼續(xù)，aeProcessEvents會一直被調(diào)用。其中，eventLoop你可以理解為保存了所有事件的一個結(jié)構(gòu)體，里面的每個事件都會綁定一個相應(yīng)的事件處理函數(shù)，如對連接事件，會綁定acceptTcpHandler這個事件，具體可以查看源碼。
進(jìn)入aeProcessEvents中，我們可以發(fā)現(xiàn)其首先調(diào)用了aeApiPoll得到就緒事件的個數(shù)numevents，然后使用一個for循環(huán)去循環(huán)處理事件，直到numevents個數(shù)為0。
aeProcessEvents中主要通過fe->rfileProc(eventLoop,fd,fe->clientData,mask);來調(diào)用acceptTcpHandler以處理事件。為什么是rfileProc，回顧之前的Redis事件定義，因?yàn)檫B接事件是讀事件。
aeProcessEvents源碼如下：
int aeProcessEvents(aeEventLoop *eventLoop, int flags)
{
省略
numevents = aeApiPoll(eventLoop, tvp);
for (j = 0; j < numevents; j++) {
aeFileEvent *fe = &eventLoop->events[eventLoop->fired[j].fd];
int mask = eventLoop->fired[j].mask;
int fd = eventLoop->fired[j].fd;
int rfired = 0;
/* note the fe->mask & mask & ... code: maybe an already processed
* event removed an element that fired and we still didn't
* processed, so we check if the event is still valid. */
if (fe->mask & mask & AE_READABLE) {
// rfired
rfired = 1;
fe->rfileProc(eventLoop,fd,fe->clientData,mask);
}
if (fe->mask & mask & AE_WRITABLE) {
if (!rfired || fe->wfileProc != fe->rfileProc)
fe->wfileProc(eventLoop,fd,fe->clientData,mask);
}
processed++;
}
省略
}
所以，結(jié)合以上代碼，我們終于可以得出結(jié)論：
- 由于aeMain中的while循環(huán)一直進(jìn)行，導(dǎo)致aeProcessEvents會不斷執(zhí)行。
- aeProcessEvents先調(diào)用aeApiPoll，aeApiPoll會返回就緒事件的個數(shù)numevents 。
- aeProcessEvents在有限循環(huán)（numevents ）中調(diào)用
fe->rfileProc(eventLoop,fd,fe->clientData,mask);，也就是調(diào)用了acceptTcpHandler去處理事件。 - 而acceptTcpHandler又因?yàn)槌霈F(xiàn)了“Too many open files”問題快速返回，導(dǎo)致整個aeProcessEvents快速返回。
- 如此周而復(fù)始。
當(dāng)然，有人會問，為什么CPU占有率不一直是100%，上面這個調(diào)用鏈即給出了答案，因?yàn)檫€有一丁點(diǎn)的時間片分給了這個調(diào)用鏈里的其他調(diào)用，而不只是accept、epoll_wait、open這三個系統(tǒng)調(diào)用。
至此，我們只剩下一個問題，為什么會出現(xiàn)“Too many open files”這個問題，造成前面acceptTcpHandler無法正確處理連接事件，這也是本次問題追蹤的最終目標(biāo)。下一篇文章將針對這個問題繼續(xù)進(jìn)行探討，敬請期待。
第一次寫真正意義上的技術(shù)博文，希望能得到大家的認(rèn)可，如有錯誤，請不吝指出，非常感謝。我會繼續(xù)努力，O(∩_∩)O哈哈~。
補(bǔ)充
aeApiPoll
aeApiPoll會調(diào)用epoll_wait，這也對應(yīng)了前面strace展示的三個函數(shù)之一，但epoll_wait調(diào)用正常，如圖：
aeApiPoll會獲取可執(zhí)行事件（其實(shí)是保存在了eventLoop->fired的fired數(shù)組中),最后返回就緒事件個數(shù)。源碼如下：
static int aeApiPoll(aeEventLoop *eventLoop, struct timeval *tvp) {
aeApiState *state = eventLoop->apidata;
int retval, numevents = 0;
retval = epoll_wait(state->epfd,state->events,eventLoop->setsize,
tvp ? (tvp->tv_sec*1000 + tvp->tv_usec/1000) : -1);
if (retval > 0) {
int j;
numevents = retval;
for (j = 0; j < numevents; j++) {
int mask = 0;
struct epoll_event *e = state->events+j;
if (e->events & EPOLLIN) mask |= AE_READABLE;
if (e->events & EPOLLOUT) mask |= AE_WRITABLE;
if (e->events & EPOLLERR) mask |= AE_WRITABLE;
if (e->events & EPOLLHUP) mask |= AE_WRITABLE;
eventLoop->fired[j].fd = e->data.fd;
eventLoop->fired[j].mask = mask;
}
}
return numevents;
}
aeEventLoop
可以保存所有的事件及其對應(yīng)的事件處理器，這是一個很重要的結(jié)構(gòu)體。
aeApiPoll將事件保存到aeEventLoop 里面，然后aeProcessEvents調(diào)用aeEventLoop 的事件處理函數(shù)去處理事件。當(dāng)然，事件處理函數(shù)一開始已經(jīng)注冊給aeEventLoop 了。
/* State of an event based program
*/
typedef struct aeEventLoop {
int maxfd; /* highest file descriptor currently registered */
int setsize; /* max number of file descriptors tracked */
long long timeEventNextId;
time_t lastTime; /* Used to detect system clock skew */
aeFileEvent *events; /* Registered events */
aeFiredEvent *fired; /* Fired events */
aeTimeEvent *timeEventHead;
int stop;
void *apidata; /* This is used for polling API specific data */
aeBeforeSleepProc *beforesleep;
} aeEventLoop;
aeFileEvent 即表示了一個事件，其包括事件數(shù)據(jù)clientData及對應(yīng)的處理函數(shù)rfileProc或wfileProc。
/* File event structure
*/
typedef struct aeFileEvent {
int mask; /* one of AE_(READABLE|WRITABLE) */
aeFileProc *rfileProc;
aeFileProc *wfileProc;
void *clientData;
} a
