[
https://issues.apache.org/jira/browse/HDFS-13051?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16336048#comment-16336048
]
zhangwei edited comment on HDFS-13051 at 1/23/18 5:04 PM:
----------------------------------------------------------
Yes
when secondnode send a rollEditlog rpc,
in FSNamespace this method will be call and acquire writelock
CheckpointSignature rollEditLog() throws IOException {
checkSuperuserPrivilege();
checkOperation(OperationCategory.JOURNAL);
writeLock();
try {
checkOperation(OperationCategory.JOURNAL);
checkNameNodeSafeMode("Log not rolled");
if (Server.isRpcInvocation())
{ LOG.info("Roll Edit Log from " + Server.getRemoteAddress()); }
return getFSImage().rollEditLog();
} finally
{ writeUnlock(); }
}
finally it calls getFSImage().rollEditLog() -> FSEditlog.rollEditlog()
synchronized long rollEditLog() throws IOException {
LOG.info("Rolling edit logs");
endCurrentLogSegment(true);
long nextTxId = getLastWrittenTxId() + 1;
startLogSegment(nextTxId, true);
assert curSegmentTxId == nextTxId;
return nextTxId;
}
this method is synchornized method it will acquire the FSEditlogAsync lock.
but in one case,
another thread concurrently take a RPCEdit log from queue like below
FSEditlogAsync run method
@Override
public void run() {
try {
while (true) {
boolean doSync;
Edit edit = dequeueEdit();
if (edit != null) {
// sync if requested by edit log.
doSync = edit.logEdit();
syncWaitQ.add(edit);
} else {
// sync when editq runs dry, but have edits pending a sync.
doSync = !syncWaitQ.isEmpty();
}
edit.logEdit method acquire FSEditlogAsync lock**
as we know rollEditlog already acquire lock as I mention before.
Let's go back to
FSEditlog.rollEditlog method
you can see it call
endCurrentLogSegment(true)**
public synchronized void endCurrentLogSegment(boolean writeEndTxn) {
LOG.info("Ending log segment " + curSegmentTxId);
Preconditions.checkState(isSegmentOpen(),
"Bad state: %s", state);
if (writeEndTxn)
{ logEdit(LogSegmentOp.getInstance(cache.get(),
FSEditLogOpCodes.OP_END_LOG_SEGMENT)); }
// always sync to ensure all edits are flushed.
logSyncAll();
printStatistics(true)
the key point is logSyncAll method
@Override
public void logSyncAll() {
// doesn't actually log anything, just ensures that the queues are
// drained when it returns.
Edit edit = new SyncEdit(this, null){
@Override
public boolean logEdit() {
return true;
}
};
enqueueEdit(edit);
edit.logSyncWait();
}
it will finally call edit.logSyncWait
@Override
public void logSyncWait() {
synchronized(lock) {
while (!done) {
try {
lock.wait(10);
} catch (InterruptedException e) {}
}
// only needed by tests that rely on ExitUtil.terminate() since
// normally exceptions terminate the NN.
if (syncEx != null) {
syncEx.fillInStackTrace();
throw syncEx;
}
}
}
this method will not exit until variable done is true
where does variable done set to true, look back the FSEditlogAsync.run
we found code in run method
logSync(getLastWrittenTxId());
} catch (RuntimeException ex) {
syncEx = ex;
}
while ((edit = syncWaitQ.poll()) != null) {
edit.logSyncNotify(syncEx);
}
}
}
@Override
public void logSyncNotify(RuntimeException ex) {
synchronized(lock) {
done = true;
syncEx = ex;
lock.notifyAll();
}
}
So the RollEditlog will not release the lock until run method set the variable
done to true.
but run method block on the lock which RollediltLog method hold to handle the
edit take from queue.
that's the dead lock, it will case namenode crash in any time.
**
was (Author: photogamrun):
Yes
when secondnode send a rollEditlog rpc,
in FSNamespace this method will be call and acquire writelock
CheckpointSignature rollEditLog() throws IOException {
checkSuperuserPrivilege();
checkOperation(OperationCategory.JOURNAL);
writeLock();
try {
checkOperation(OperationCategory.JOURNAL);
checkNameNodeSafeMode("Log not rolled");
if (Server.isRpcInvocation()) {
LOG.info("Roll Edit Log from " + Server.getRemoteAddress());
}
return getFSImage().rollEditLog();
} finally {
writeUnlock();
}
}
finally it calls *getFSImage().rollEditLog() -> FSEditlog.rollEditlog()*
*synchronized long rollEditLog() throws IOException {*
*LOG.info("Rolling edit logs");*
*endCurrentLogSegment(true);*
*long nextTxId = getLastWrittenTxId() + 1;*
*startLogSegment(nextTxId, true);*
*assert curSegmentTxId == nextTxId;*
*return nextTxId;*
*}*
*this method is synchornized method it will acquire the FSEditlogAsync lock.*
*but in one case,*
*another thread concurrently take a RPCEdit log from queue like below*
*FSEditlogAsync run method*
*@Override*
*public void run() {*
*try {*
*while (true) {*
*boolean doSync;*
*Edit edit = dequeueEdit();*
*if (edit != null) {*
*// sync if requested by edit log.*
*doSync = edit.logEdit();*
*syncWaitQ.add(edit);*
*} else {*
*// sync when editq runs dry, but have edits pending a sync.*
*doSync = !syncWaitQ.isEmpty();*
*}*
*edit.logEdit method acquire* *FSEditlogAsync lock***
*as we know rollEditlog already acquire lock as I mention before.*
*Let's go back to*
*FSEditlog.rollEditlog method*
*you can see it call*
*endCurrentLogSegment(true)***
public synchronized void endCurrentLogSegment(boolean writeEndTxn) {
LOG.info("Ending log segment " + curSegmentTxId);
Preconditions.checkState(isSegmentOpen(),
"Bad state: %s", state);
if (writeEndTxn) {
logEdit(LogSegmentOp.getInstance(cache.get(),
FSEditLogOpCodes.OP_END_LOG_SEGMENT));
}
// always sync to ensure all edits are flushed.
logSyncAll();
printStatistics(true)
the key point is logSyncAll method
*@Override*
*public void logSyncAll() {*
*// doesn't actually log anything, just ensures that the queues are*
*// drained when it returns.*
*Edit edit = new SyncEdit(this, null){*
*@Override*
*public boolean logEdit() {*
*return true;*
*}*
*};*
*enqueueEdit(edit);*
*edit.logSyncWait();*
*}*
*it will finally call edit.logSyncWait*
*@Override*
*public void logSyncWait() {*
*synchronized(lock) {*
*while (!done) {*
*try {*
*lock.wait(10);*
*} catch (InterruptedException e) {}*
*}*
*// only needed by tests that rely on ExitUtil.terminate() since*
*// normally exceptions terminate the NN.*
*if (syncEx != null) {*
*syncEx.fillInStackTrace();*
*throw syncEx;*
*}*
*}*
*}*
*this method will not exit until variable done is true*
*where does variable done set to true, look back the FSEditlogAsync.run*
*we found code in run method*
*logSync(getLastWrittenTxId());*
*} catch (RuntimeException ex) {*
*syncEx = ex;*
*}*
*while ((edit = syncWaitQ.poll()) != null) {*
*edit.logSyncNotify(syncEx);*
*}*
*}*
*}*
*So the RollEditlog will not release the lock until run method set the variable
done to true.*
*but run method block on the lock which RollediltLog method hold to handle the
edit take from queue.*
*that's the dead lock, it will case namenode crash in any time.*
> dead lock occurs when using async editlog while rolleditlog rpc call happen
> ---------------------------------------------------------------------------
>
> Key: HDFS-13051
> URL: https://issues.apache.org/jira/browse/HDFS-13051
> Project: Hadoop HDFS
> Issue Type: Bug
> Components: namenode
> Affects Versions: 2.7.5
> Reporter: zhangwei
> Priority: Major
>
> When we apply AsyncEditlog in our prod env, in extremely case, deadlock will
> occur and crash the namenode. in the case, rollEditlog rpc call happen while
> AsyncEditlog asynchronized takes edit object from queue and is going to
> acquire AsyncEditlog object lock to executed it's logEdit method.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
