[
https://issues.apache.org/jira/browse/HDFS-13051?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
zhangwei updated HDFS-13051:
----------------------------
Comment: was deleted
(was: *Yes*
*when secondnode send a rollEditlog rpc call*
*In FSNamesystem below 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()*
*below is the code of* *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; }
*Remember!! This method will acquire FSEditlogAsync object lock.*
*In a case*
*At the same moment 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 also need acquire FSEditlogAsync lock*
*as we know rollEditlog method already acquire* *FSEditlogAsync* *lock.*
*Let's go back to*
*FSEditlog.rollEditlog method*
*within rollEditlog method it will call below method*
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; }
}
}
*we can see this method will not exit until variable 'done' is true, in other
hand, Rolleditlog will not release the FSEditlogAsync object lock until
variable 'done' is set to ture*
*where does variable done set to true, look back the FSEditlogAsync.run method
again*
*within* *FSEditlogAsync.run method we can see below code segment*
logSync(getLastWrittenTxId());
} catch (RuntimeException ex)
{ syncEx = ex; }
while ((edit = syncWaitQ.poll()) != null)
{ e*dit.logSyncNotify(syncEx);* }
}
}
@Override
public void logSyncNotify(RuntimeException ex) {
synchronized(lock)
{ done = true; syncEx = ex; lock.notifyAll(); }
}
*so only logSyncNotify method will set variable done to ture, but this method
is call at the end of run method. before this code segment is executed, we must
get the FSEditlogAsync object lock firstly to call the edit.logEdit method.*
private abstract static class Edit {
final FSEditLog log;
final FSEditLogOp op;
Edit(FSEditLog log, FSEditLogOp op)
{ this.log = log; this.op = op; }
// return whether edit log wants to sync.
*boolean logEdit() {*
return log.doEditTransaction(op);
}
*synchronized* boolean doEditTransaction(final FSEditLogOp op) {
long start = beginTransaction();
op.setTransactionId(txid);
try
{ editLogStream.write(op); }
catch (IOException ex)
{ // All journals failed, it is handled in logSync. }
finally
{ op.reset(); }
endTransaction(start);
return shouldForceSync();
}
*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 rolleditlog rpc call happen and editPendingQ is full
> --------------------------------------------------------------------------
>
> 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 doing rolleditlog it acquires fs write lock，then acquire FSEditLogAsync
> lock object，and write 3 EDIT(the second one override logEdit method and
> return true)
> in extremely case，when FSEditLogAsync's logSync is very
> slow，editPendingQ(default size 4096)is full，it case IPC thread can not offer
> edit object into editPendingQ when doing rolleditlog，it block on editPendingQ
> .put method，however it does't release FSEditLogAsync object lock, and
> edit.logEdit method in FSEditLogAsync.run thread can never acquire
> FSEditLogAsync object lock, it case dead lock
> stack trace like below
> "Thread[Thread-44528,5,main]" #130093 daemon prio=5 os_prio=0
> tid=0x0000000002377000 nid=0x13fda waiting on condition [0x00007fb3297de000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00007fbd3cb96f58> (a
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> at java.util.concurrent.ArrayBlockingQueue.put(ArrayBlockingQueue.java:353)
> at
> org.apache.hadoop.hdfs.server.namenode.FSEditLogAsync.enqueueEdit(FSEditLogAsync.java:156)
> at
> org.apache.hadoop.hdfs.server.namenode.FSEditLogAsync.logEdit(FSEditLogAsync.java:118)
> at
> org.apache.hadoop.hdfs.server.namenode.FSEditLog.logCancelDelegationToken(FSEditLog.java:1008)
> at
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.logExpireDelegationToken(FSNamesystem.java:7635)
> at
> org.apache.hadoop.hdfs.security.token.delegation.DelegationTokenSecretManager.logExpireToken(DelegationTokenSecretManager.java:395)
> - locked <0x00007fbd3cbae500> (a java.lang.Object)
> at
> org.apache.hadoop.hdfs.security.token.delegation.DelegationTokenSecretManager.logExpireToken(DelegationTokenSecretManager.java:62)
> at
> org.apache.hadoop.security.token.delegation.AbstractDelegationTokenSecretManager.removeExpiredToken(AbstractDelegationTokenSecretManager.java:604)
> at
> org.apache.hadoop.security.token.delegation.AbstractDelegationTokenSecretManager.access$400(AbstractDelegationTokenSecretManager.java:54)
> at
> org.apache.hadoop.security.token.delegation.AbstractDelegationTokenSecretManager$ExpiredTokenRemover.run(AbstractDelegationTokenSecretManager.java:656)
> at java.lang.Thread.run(Thread.java:745)
> "FSEditLogAsync" #130072 daemon prio=5 os_prio=0 tid=0x000000000715b800
> nid=0x13fbf waiting for monitor entry [0x00007fb32c51a000]
> java.lang.Thread.State: BLOCKED (on object monitor)
> at
> org.apache.hadoop.hdfs.server.namenode.FSEditLog.doEditTransaction(FSEditLog.java:443)
> - waiting to lock <*0x00007fbcbc131000*> (a
> org.apache.hadoop.hdfs.server.namenode.FSEditLogAsync)
> at
> org.apache.hadoop.hdfs.server.namenode.FSEditLogAsync$Edit.logEdit(FSEditLogAsync.java:233)
> at
> org.apache.hadoop.hdfs.server.namenode.FSEditLogAsync.run(FSEditLogAsync.java:177)
> at java.lang.Thread.run(Thread.java:745)
> "IPC Server handler 47 on 53310" #337 daemon prio=5 os_prio=0
> tid=0x00007fe659d46000 nid=0x4c62 waiting on condition [0x00007fb32fe52000]
> java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for <0x00007fbd3cb96f58> (a
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> at java.util.concurrent.ArrayBlockingQueue.put(ArrayBlockingQueue.java:353)
> at
> org.apache.hadoop.hdfs.server.namenode.FSEditLogAsync.enqueueEdit(FSEditLogAsync.java:156)
> at
> org.apache.hadoop.hdfs.server.namenode.FSEditLogAsync.logEdit(FSEditLogAsync.java:118)
> at
> org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1251)
> - locked <*0x00007fbcbc131000*> (a
> org.apache.hadoop.hdfs.server.namenode.FSEditLogAsync)
> at
> org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1190)
> - locked <0x00007fbcbc131000> (a
> org.apache.hadoop.hdfs.server.namenode.FSEditLogAsync)
> at
> org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1235)
> at
> org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6463)
> at
> org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1062)
> at
> org.apache.hadoop.hdfs.protocolPB.NamenodeProtocolServerSideTranslatorPB.rollEditLog(NamenodeProtocolServerSideTranslatorPB.java:142)
> at
> org.apache.hadoop.hdfs.protocol.proto.NamenodeProtocolProtos$NamenodeProtocolService$2.callBlockingMethod(NamenodeProtocolProtos.java:12025)
> at
> org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:617)
> at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:1073)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2141)
> at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2137)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:422)
> at
> org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1743)
> at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2135)
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
