[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16928352#comment-16928352 ] wangcong commented on HDFS-10943: - we found the patch related to our problem:HDFS-13112 The root cause which result in bufcurrent is not empty , is that there is two way to log CancelDelegationTokenOp:one is by FsnameSystem 's cancelDelegationToken() method, another is by DelegationTokenSecretManager 's logExpireToken method . logExpireToken accquire FSEditLog Lock only to write buffer , but not accquire FSNameSystme Lock,this cause when roll edit realease FSEditLog Lock,logExpireToken has chance to write log to buffer. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16927184#comment-16927184 ] angerszhu commented on HDFS-10943: -- [~swingcong] See my explain, https://issues.apache.org/jira/browse/HDFS-14437 [~hexiaoqiao] Seem the same reason. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on step 2 allows other threads to continue >* to write into the memory buffer while the sync is in progress. >* Because this step is unsynchronized, actions that need to avoid >* concurrency with sync() should be synchronized and also call >* waitForSyncToFinish() before assuming they are running alone. >*/ > {code} > We can see that step 2 is
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16927181#comment-16927181 ] wangcong commented on HDFS-10943: - Sorry,[~hexiaoqiao],the version we use is 2.6.0-cdh5.10.0. Through looking log of HDFS-11292,we found the problem as follow: If roll edit run normally, the log shows : 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,273 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Done logSyncAll lastWrittenTxId=5060982534 lastSyncedTxid=5060982534 mostRecentTxid=5060982534 toSyncToTxId in the firstline is the txId of EndLogSegmentOp,which is the last log of editlog,is equal to lastWrittenTxId in the secondline. This shows after EndLogSegmentOp,there is nothing to write to double buffer. but if roll edit run abnormally,the log shows : 2019-09-10 03:48:10,273 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: logSyncAll toSyncToTxId=5061382825 lastSyncedTxid=5061371306 mostRecentTxid=5061382825 2019-09-10 03:48:10,273 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Done logSyncAll lastWrittenTxId=5061382841 lastSyncedTxid=5061382840 mostRecentTxid=5061382841 toSyncToTxId in the firstline is not equal to lastWrittenTxId in the secondline,this shows after EndLogSegmentOp,another handler writer log to double buffer. In the secondline,lastWrittenTxId is not equal to lastSyncedTxid, which shows current buf is not empty in double buffer. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16926629#comment-16926629 ] He Xiaoqiao commented on HDFS-10943: Thanks [~swingcong] for your pings, It is important observation. Would you like to offer which version do you setup? > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on step 2 allows other threads to continue >* to write into the memory buffer while the sync is in progress. >* Because this step is unsynchronized, actions that need to avoid >* concurrency with sync() should be synchronized and also call >* waitForSyncToFinish() before assuming they are running alone. >*/ > {code} > We can see that step 2 is on-purposely
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16926355#comment-16926355 ] wangcong commented on HDFS-10943: - [~daryn],[~kihwal],[~zhz],[~hexiaoqiao],[~yzhangal] Our log cluster occurs this problem several times. We use individual cluster to write to yarn logs. But this log cluster crash serveral times.In the process of viewing logs,We found the same error as this issue. To diagnosis this problem ,we deploy HDFS-11306 and HDFS-11292. When log cluster crash again , diagnostic log as follows: 2019-09-10 03:50:16,403 ERROR org.apache.hadoop.hdfs.server.namenode.FSEditLog: LastWrittenTxId 5061382841 is expected to be the same as LastSyncedTxId 5061382840 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/datanod...@domain.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.0.1:8001,10.0.0.2:8001,10.0.0.3:8001],stream=QuorumOutputStream starting at txid 5060982535)) java.io.IOException: FSEditsStream has 85 bytes still to be flushed and cannot be closed After deploying patch,namenode crash occurs twice. The op which cause this problem all is CancelDelegationTokenOp. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16691701#comment-16691701 ] He Xiaoqiao commented on HDFS-10943: [~daryn],[~kihwal],[~zhz],[~yzhangal] Unfortunately, I meet this issue again recently. another interesting note was that ioutil of NN keeps on 100 for 2~5min before NN crash (the same observation when I first meet this issue), I am not sure it is related with this issue. After digging, I do not find that {{FileJournalManager}} will block {{JournalSetOutputStream}} or lead to NN crash, and FileJournal is not required by default if HA using QJM, in other word, even filejournal do not write/sync successfully, NN process will not terminate. This is just additional information for reference and DO NOT resolve it util now. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >*
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16446446#comment-16446446 ] Daryn Sharp commented on HDFS-10943: The quorum output stream will +always+ crash the NN if edits are rolled while a node is down. The edit roll will sync, flush, close. As we can see, closing a logger will fail if there are unflushed bytes. The issue is {{QuorumOutputStream#flush}} succeeds with only a simple majority of loggers. The those that failed cause close to fail due to unflushed bytes. Someone familiar with QJM (we don't use it) will need to decide if it's safe for the quorum's flush to clear the buffers of failed loggers. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16446329#comment-16446329 ] Daryn Sharp commented on HDFS-10943: This error should not be possible. The entire roll holds the FSN lock so nothing else can generate edits to avoid lingering bytes in the buffer. {{endCurrentLogSegment}} does a logSync which loops calling setReadyToFlush (which flips the buffer) & flush until the last written txid is synced. If the stream reports the last txid synced, there cannot/must-not be bytes lingering in the buffer or the stream lied. I'll take a quick look at the code. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on step 2 allows other threads to continue
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16445837#comment-16445837 ] He Xiaoqiao commented on HDFS-10943: hi [~daryn], I wonder is there any condition to make sure that {{EditsDoubleBuffer.bufReady}} is empty when swap buffer if disable assertions. Thanks for your help. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on step 2 allows other threads to continue >* to write into the memory buffer while the sync is in progress. >* Because this step is unsynchronized, actions that need to avoid >* concurrency with sync() should be synchronized and also call >* waitForSyncToFinish() before assuming they are running alone. >*/ >
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16445377#comment-16445377 ] He Xiaoqiao commented on HDFS-10943: Correct: {quote}1. only 2/3 JournalNodes active at that time since logs show SyncTimes(ms): 42337 29016{quote} this conclusion is not correct, and please ignore. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on step 2 allows other threads to continue >* to write into the memory buffer while the sync is in progress. >* Because this step is unsynchronized, actions that need to avoid >* concurrency with sync() should be synchronized and also call >* waitForSyncToFinish() before assuming they are running alone. >*/ >
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16445363#comment-16445363 ] He Xiaoqiao commented on HDFS-10943: I would like to provide more detail information: A. NameNode logs before fatal which is same as [~yzhangal] mentioned above: {code:java} 2018-04-19 13:10:24,222 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Rolling edit logs 2018-04-19 13:10:24,222 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Ending log segment 15221708217 2018-04-19 13:10:24,595 INFO org.apache.hadoop.hdfs.server.namenode.FSEditLog: Number of transactions: 206713 Total time for transactions(ms): 2575 Number of transactions batched in Syncs: 8218 Number of syncs: 138767 SyncTimes(ms): 42337 29016 2018-04-19 13:10:25,264 FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log segment 15221708217, 15221914929 failed for required journal (JournalAndStream(mgr=QJM to [0.0.0.0:8485, 0.0.0.0:8485, 0.0.0.0:8485], stream=QuorumOutputStream starting at txid 15221708217)) java.io.IOException: FSEditStream has 160370 bytes still to be flushed and cannot be closed. at org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) at org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) at org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) at org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) at org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) at org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1274) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1203) at org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1293) at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6084) at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1295) 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:616) at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:969) at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2049) at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2045) at java.security.AccessController.doPrivileged(Native Method) at javax.security.auth.Subject.doAs(Subject.java:415) at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1690) at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2043) 2018-04-19 13:10:25,390 WARN org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting QuorumOutputStream starting at txid 15221708217 {code} B. JournalNode logs when Standby NameNode transition To Active and recovery EditLog: {code:java} 2018-04-19 13:10:47,137 INFO org.apache.hadoop.hdfs.qjournal.server.Journal: Accepted recovery for segment 15221708217: segmentState { startTxId: 15221708217 endTxId: 15221913880 isInProgress: true } acceptedInEpoch: 24 {code} C. CallQueue of NameNode is full and lasted no more than three seconds. {code:java} Date Time RpcProcessingTimeAvgTime CallQueueLength RpcQueueTimeAvgTime 04-19 13:10:22 0.12 0 0.031 04-19 13:10:240.505 320010.619 04-19 13:10:25 1038.286 3200 265.548 {code} Based on logs, we can come to conclusions: 1. only two JournalNodes active at that time since logs show {{SyncTimes(ms): 42337 29016}} 2. 1049 {{FSEditLogOp}} transations (finalize TxId of NameNode before fatal: 15221914929 - endTxId of JournalNode after recovery: 15221913880) are still in {{bufCurrent}} of EditsDoubleBuffer and do not flushed out. 3. All write of NameNode from DFSClient request still not return at that time, and FsEditLogOps of DFSClient's write op. still continue to put into {{bufCurrent}}. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 >
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16444051#comment-16444051 ] He Xiaoqiao commented on HDFS-10943: Plz ignore my latest comments. HDFS-11292 is related for this issue and I am sorry that I don't read HDFS-11292 carefully. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on step 2 allows other threads to continue >* to write into the memory buffer while the sync is in progress. >* Because this step is unsynchronized, actions that need to avoid >* concurrency with sync() should be synchronized and also call >* waitForSyncToFinish() before assuming they are running alone. >*/ > {code} > We can see that step 2 is
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16443671#comment-16443671 ] He Xiaoqiao commented on HDFS-10943: hi [~zhz],[~daryn],[~yzhangal],[~kihwal] is this issue still going on? I meet the same problem in my production cluster, and my hadoop version is apache hadoop-2.7.1. I agree that some editlog in doublebuffer is not flush. maybe it is not related to {{logSyncAll}} since compare {{logSyncAll}} to {{logSync}}, it is only different about set {{txid}} but not different for doublebuffer. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang >Priority: Major > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on step 2 allows other threads to continue >* to write into the memory buffer while the sync is in
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15826910#comment-15826910 ] Yongjun Zhang commented on HDFS-10943: -- Hi [~zhz], I originally saw it with CDH 5.5.x. Then after digging, I think it's likely all upstream branches also have the issue. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on step 2 allows other threads to continue >* to write into the memory buffer while the sync is in progress. >* Because this step is unsynchronized, actions that need to avoid >* concurrency with sync() should be synchronized and also call >* waitForSyncToFinish() before assuming they are running alone. >*/ > {code} > We can see that step 2 is on-purposely not
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15826898#comment-15826898 ] Zhe Zhang commented on HDFS-10943: -- [~yzhangal] Thanks for reporting the issue. Which version did you use when observing the issue? > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on step 2 allows other threads to continue >* to write into the memory buffer while the sync is in progress. >* Because this step is unsynchronized, actions that need to avoid >* concurrency with sync() should be synchronized and also call >* waitForSyncToFinish() before assuming they are running alone. >*/ > {code} > We can see that step 2 is on-purposely not synchronized to let other threads > to write into
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15799075#comment-15799075 ] Yongjun Zhang commented on HDFS-10943: -- The issue remains even after HDFS-7964 is included. HDFS-7964 added the call {{logSyncAll{}}} before the edit log rolling. So either this method did not finish its job correctly, or some new edits gets in after the flush and before the edit log rolling. Created HDFS-11292 to help the diagnosis. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on step 2 allows other threads to continue >* to write into the memory buffer while the sync is in progress. >* Because this step is unsynchronized, actions that need to avoid >* concurrency with sync() should
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15721391#comment-15721391 ] wayhomeke commented on HDFS-10943: -- We got the same problem this week. 2016-12-04 03:05:46,591 FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log segment 37851383341, 37853543366 failed for required journal (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485], stream=QuorumOutputStream starting at txid 37851383341)) java.io.IOException: FSEditStream has 113664 bytes still to be flushed and cannot be closed. at org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) at org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) at org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) at org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) at org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) at org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) at org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15590210#comment-15590210 ] Yongjun Zhang commented on HDFS-10943: -- Thanks a lot [~daryn]! Sorry a follow-up question at the end with this comment: About Essentially the roll needs to be an atomic: # log segment end, # close segment, # open new segment, # log segment start. Step #1 and #2 above should have flushed all edits in the buffer before closing the segment, but seems we were not doing that in {{FSEditLog#endCurrentSegment}} before HDFS-7964 added the following call: {code} // always sync to ensure all edits are flushed. logSyncAll(); < {code} My problem is that some edits are not flushed to JN when the editlog is being rolled, and the release that has this problem doesn't have the fix of HDFS-7964. Though HDFS-7964 is reported as an enhancement to support async edit logging, as a side product, it also likely fixes my problem. {quote} The answer is track down why the fsn lock is not being held. {quote} Are you saying that if we were not to use HDFS-7964 fix, then the fsn lock should have been held, so we don't need to call {{logSyncAll()}} in {{FSEditLog#endCurrentSegment}}. That is, you suspect there is some place that the fsn lock was not held (as it's supposed to) rather than the missing {{logSyncAll()}} call? Thanks. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null,
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15590079#comment-15590079 ] Daryn Sharp commented on HDFS-10943: Unless something has changed semi-recently, you definitely cannot roll the edits w/o fsn synchronization. Kihwal was right, he's heard me grumble many times about the edit logs not really being thread-safe. I think I filed a jira about it many years ago... The main problem is the complex wait/notify behavior for interleaving edits and syncs. Essentially the roll needs to be an atomic: log segment end, close segment, open new segment, log segment start. Relinquishing the edit log mutex anywhere during that transaction due to wait() may cause "very bad things" to happen. Best case is an NPE when another thread tries to log between segments. The sync won't matter if another spurious edit slips in after the end segment edit or before the start segment edit. Must... bury... memories of scrambling to save the namespace of a few clusters after the standby crashed from corrupted edits. The answer is track down why the fsn lock is not being held. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15569447#comment-15569447 ] Yongjun Zhang commented on HDFS-10943: -- Hi [~daryn], About my last comment, do you think it's a bug for {{endCurrentLogSegment}} not to call {{logSyncAll()}}, which is fixed by HDFS-7964? Thanks a lot. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it swaps the double buffer and sets the isSyncRunning >* flag. >* 2. unsynchronized, it flushes the data to storage >* 3. synchronized, it resets the flag and notifies anyone waiting on the >* sync. >* >* The lack of synchronization on step 2 allows other threads to continue >* to write into the memory buffer while the sync is in progress. >* Because this step is unsynchronized, actions that need to avoid >* concurrency with sync() should be synchronized and also call >* waitForSyncToFinish() before assuming they are running alone. >*/ > {code} > We can see that
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15543293#comment-15543293 ] Yongjun Zhang commented on HDFS-10943: -- Thanks a lot [~kihwal]! About {quote} That's why it acquires the FSN write lock. This blocks everyone from edit logging. While still in the write lock, the edits are synced. {quote} I examined and found a diff between the branch I'm using and trunk, I saw trunk has {{logSyncAll()}} in the following code: {code} FSEditLog.java /** * Finalize the current log segment. * Transitions from IN_SEGMENT state to BETWEEN_LOG_SEGMENTS state. */ 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); final long lastTxId = getLastWrittenTxId(); try { journalSet.finalizeLogSegment(curSegmentTxId, lastTxId); editLogStream = null; } catch (IOException e) { //All journals have failed, it will be handled in logSync. } state = State.BETWEEN_LOG_SEGMENTS; } {code} The {{logSyncAll()}} call is introduced by HDFS-7964 (Add support for async edit logging), which seems to be the behavior I'm asking for in HDFS-10943 : we should flush edits before closing the stream. So likely HDFS-7964 is is not just as described "Add support for async edit logging", but likely also fixing the bug I reported here, that is, prior to HDFS-7964, we don't flush the edits before closing the stream. What do yout think? Hi [~daryn], welcome to comment if my above statement is correct since you worked out HDFS-7964? Many thanks. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618
[jira] [Commented] (HDFS-10943) rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed
[ https://issues.apache.org/jira/browse/HDFS-10943?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=15542701#comment-15542701 ] Kihwal Lee commented on HDFS-10943: --- Which version are you looking at? {{rollEditLog()}} does not and cannot solely depend on {{FSEditLog}} synchronization. That's why it acquires the FSN write lock. This blocks everyone from edit logging. While still in the write lock, the edits are synced. This is different from regular {{logSync()}}, which happens outside the write lock. If you are seeing such an exception, something is circumventing the FSN lock and edit logging. There are some places where locking is more complicated like use of {{noInterruptsLock}} in {{DelegationTokenSecretManager}}, but they are also not supposed to edit log while rolling edits. The exception clearly indicates a bug. If you can reproduce it, make it dump the buffer before terminating so that we can find out who did edit logging. > rollEditLog expects empty EditsDoubleBuffer.bufCurrent which is not guaranteed > -- > > Key: HDFS-10943 > URL: https://issues.apache.org/jira/browse/HDFS-10943 > Project: Hadoop HDFS > Issue Type: Bug >Reporter: Yongjun Zhang > > Per the following trace stack: > {code} > FATAL org.apache.hadoop.hdfs.server.namenode.FSEditLog: Error: finalize log > segment 10562075963, 10562174157 failed for required journal > (JournalAndStream(mgr=QJM to [0.0.0.1:8485, 0.0.0.2:8485, 0.0.0.3:8485, > 0.0.0.4:8485, 0.0.0.5:8485], stream=QuorumOutputStream starting at txid > 10562075963)) > java.io.IOException: FSEditStream has 49708 bytes still to be flushed and > cannot be closed. > at > org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:66) > at > org.apache.hadoop.hdfs.qjournal.client.QuorumOutputStream.close(QuorumOutputStream.java:65) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.closeStream(JournalSet.java:115) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.java:235) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportErrors(JournalSet.java:393) > at > org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(JournalSet.java:231) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1172) > at > org.apache.hadoop.hdfs.server.namenode.FSImage.rollEditLog(FSImage.java:1243) > at > org.apache.hadoop.hdfs.server.namenode.FSNamesystem.rollEditLog(FSNamesystem.java:6437) > at > org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.rollEditLog(NameNodeRpcServer.java:1002) > 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:1060) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2086) > at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2082) > 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:1671) > at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2080) > 2016-09-23 21:40:59,618 WARN > org.apache.hadoop.hdfs.qjournal.client.QuorumJournalManager: Aborting > QuorumOutputStream starting at txid 10562075963 > {code} > The exception is from EditsDoubleBuffer > {code} > public void close() throws IOException { > Preconditions.checkNotNull(bufCurrent); > Preconditions.checkNotNull(bufReady); > int bufSize = bufCurrent.size(); > if (bufSize != 0) { > throw new IOException("FSEditStream has " + bufSize > + " bytes still to be flushed and cannot be closed."); > } > IOUtils.cleanup(null, bufCurrent, bufReady); > bufCurrent = bufReady = null; > } > {code} > We can see that FSNamesystem.rollEditLog expects > EditsDoubleBuffer.bufCurrent to be empty. > Edits are recorded via FSEditLog$logSync, which does: > {code} >* The data is double-buffered within each edit log implementation so that >* in-memory writing can occur in parallel with the on-disk writing. >* >* Each sync occurs in three steps: >* 1. synchronized, it