时间戳

首页 > 技术文章 > Namenode服务挂

Namenode服务挂

moonypog 2019-09-12 09:36 原文

 

BUG修复：HDFS-13112

这两天排查了小集群Crash的问题，这里先总结下这两天排查的结果

 

一、查看日志

首先查看了Namenode Crash的时候的日志

（一）以下是patch hdfs-11306输出的日志：可以看出还保存在bufCurrent中的op是CancelDelegationTokenOp

2019-09-10 03:50:16,403 WARN org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer: The edits buffer is 85 bytes long with 1 unflushed transactions. Below is the list of unflushed transactions:

2019-09-10 03:50:16,408 WARN org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer: Unflushed op [0]: CancelDelegationTokenOp [token=token for yarn: HDFS_DELEGATION_TOKEN owner=yarn/chdd520.bigdata.pab.com.cn@PASC.COM, renewer=yarn, realUser=, issueDate=1567970236988, maxDate=1568575036988, sequenceNumber=621170591, masterKeyId=108, opCode=OP_CANCEL_DELEGATION_TOKEN, txid=5061382841]

2019-09-10 03:50:16,409 FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log segment 5060982535, 5061382841 failed for required journal (JournalAndStream(mgr=QJM to [10.0.67.216:8485, 10.0.67.217:8485, 10.0.67.218:8485], stream=QuorumOutputStream starting at txid 5060982535))

java.io.IOException: FSEditStream has 85 bytes still to be flushed and cannot be closed.

（二）以下是patch hdfs-11292输出的日志：

2019-09-10 03:46:03,830 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: logSyncAll toSyncToTxId=5060853010 lastSyncedTxid=5060853007 mostRecentTxid=5060853010

2019-09-10 03:46:03,864 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Done logSyncAll lastWrittenTxId=5060853010 lastSyncedTxid=5060853010 mostRecentTxid=5060853010

2019-09-10 03:48:10,273 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: logSyncAll toSyncToTxId=5060982534 lastSyncedTxid=5060982511 mostRecentTxid=5060982534

2019-09-10 03:48:10,290 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Done logSyncAll lastWrittenTxId=5060982534 lastSyncedTxid=5060982534 mostRecentTxid=5060982534

2019-09-10 03:50:16,323 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: logSyncAll toSyncToTxId=5061382825 lastSyncedTxid=5061371306 mostRecentTxid=5061382825

2019-09-10 03:50:16,402 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Done logSyncAll lastWrittenTxId=5061382841 lastSyncedTxid=5061382840 mostRecentTxid=5061382841

以上每两行是一组操作，表示一次rolleditlog同步的日志，从日志中我们可以发现问题

正常情况下，第一行的toSyncToTxId（5060853010）是等于第二行的lastWrittenTxId（5060853010），toSyncToTxId（5060853010）表示OP_END_LOG_SEGMENT的txid，代表一个editlog文件最后一个操作

但是在出错的情况下，第一行的toSyncToTxId（5061382825）是不等于第二行的lastWrittenTxId（5061382841），表示在rolleditlog将OP_END_LOG_SEGMENT写入缓冲区后，还有其他线程在写，即rolleditlog和其他线程同时工作。这个现象从已有的认知是不可能发生，我们下面可以分析下。另外lastWrittenTxId（5061382841）与 lastSyncedTxid（5061382840）不等，也说明还有数据没持久化。

 

下面我们看下一般操作的流程：

可以看到处理setAcl 的Handler线程在logSync的flush阶段，处理setPermission的Handler线程是有机会把op写入缓冲区的

　

SetAcl Thread

SetPermission Thread

fslock.writerlock.lock

have not fslock.writerlock

SetAcl operation

FSEditlog.logEdit()

FSEditLog synchronized enter

txid++

editLogStream.write(op)

FSEditLog synchronized exit

　

fslock.writerlock.unlock

FSEditLog.logSync()

FSEditLog synchronized enter

fslock.writerlock.lock

while mytxid > synctxid && isSyncRunning -> wait
mytxid <= synctxid return
isSyncRunning=true

SetPermission operation

FSEditLog synchronized exit

　

editLogStream.flush()

FSEditLog synchronized enter

　

txid++

　

editLogStream.write(op)

　

FSEditLog synchronized exit

FSEditLog synchronized enter

fslock.writerlock.unlock

isSyncRunning=false

　

FSEditLog synchronized exit

　

　

SetAcl Finished

FSEditLog synchronized enter

while mytxid > synctxid && isSyncRunning -> wait
mytxid <= synctxid return
isSyncRunning=true

FSEditLog synchronized exit

editLogStream.flush()

FSEditLog synchronized enter

isSyncRunning=false

FSEditLog synchronized exit

然后看下当发生rolleditlog时的情况

由于rolleditlog整个操作都在fslock内，所以处理setPermission的Handler线程是没有任何机会进行任何操作的

　

rolleditlog Thread

SetPermission Thread

fslock.writerlock.lock

have not fslock.writerlock

FSEditLog synchronized enter

endCurrentLogSegment

logedit(OP_END_LOG_SEGMENT)

logsync()

finalizeLogSegment

startCurrentLogSegment

logedit(OP_START_LOG_SEGMENT)

logsync()

　

FSEditLog synchronized exit

fslock.writerlock.unlock

 

二-查看监控

查看ganglia监控，发现在发生crash的时候，journalnode的每秒txid的写入量都很大

chdd374在9月8日的06:48左右

 

chdd374在9月10日的03:50左右

 

然后发现其实每隔一小时，都有这个高峰

 

 

登录服务器验证editlog文件大小，可以看到15:53和16:52的文件大小确实比其他文件大很多

 

 

 

 

 

使用edilog工具查看，发现OP_CANCEL_DELEGATION_TOKEN的操作有55W

 

查看服务端日志，namenode Crash的时候，并没有cancleDelegationToken RPC请求处理的相关日志，说明记录cancleDelegationToken操作还有其他地方

 

继续查看源码，终于发现产生这么多cancleDelegationToken的原因：

Namenode里有个DelegationTokenSecretManager，会每隔一小时删除过期的token，而删除过期token的操作，而调用logEdit将日志记录到缓冲区，而这个操作只获取了FSEditlog锁对象，但是没有获取FSLock的写锁，而rolleditlog操作在logedit和logsync都有可能释放锁，这样DelegationTokenSecretManager就有机会将删除token的操作写入缓冲区，从而导致最开始的日志错误

 

明天会先看下高版本hadoop代码中，这个流程是否还是这样；然后看下为什么会有这么多过期的delegationToken，基本一台机器对应的delegationToken有900多次操作，我们有490台，差不多总计55W。然后考虑下怎么修复这个问题

推荐阅读