From hdfs-issues-return-260831-archive-asf-public=cust-asf.ponee.io@hadoop.apache.org Fri Apr 19 09:17:06 2019 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [207.244.88.153]) by mx-eu-01.ponee.io (Postfix) with SMTP id 788A7180627 for ; Fri, 19 Apr 2019 11:17:05 +0200 (CEST) Received: (qmail 13639 invoked by uid 500); 19 Apr 2019 09:17:01 -0000 Mailing-List: contact hdfs-issues-help@hadoop.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Delivered-To: mailing list hdfs-issues@hadoop.apache.org Received: (qmail 13627 invoked by uid 99); 19 Apr 2019 09:17:01 -0000 Received: from mailrelay1-us-west.apache.org (HELO mailrelay1-us-west.apache.org) (209.188.14.139) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 19 Apr 2019 09:17:01 +0000 Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 90BCBE008D for ; Fri, 19 Apr 2019 09:17:00 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 3170F256EB for ; Fri, 19 Apr 2019 09:17:00 +0000 (UTC) Date: Fri, 19 Apr 2019 09:17:00 +0000 (UTC) From: "angerszhu (JIRA)" To: hdfs-issues@hadoop.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/HDFS-14437?page=3Dcom.atlassian= .jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=3D1682= 1795#comment-16821795 ]=20 angerszhu commented on HDFS-14437: ---------------------------------- [~hexiaoqiao] [~daryn] [~starphin] [~kihwal] [~arpitagarwal] =C2=A0 When I do Unit test , I add some log in my code and print thread id in log4= j. In TestEditLog#Transactions's run method, I add a call for #rollEditLog to = simulate random multithreading call of logSync(). =C2=A0 {code:java} @Override public void run() { PermissionStatus p =3D namesystem.createFsOwnerPermissions( new FsPermission((short)0777)); FSEditLog editLog =3D namesystem.getEditLog(); for (int i =3D 0; i < numTransactions; i++) { INodeFile inode =3D new INodeFile(namesystem.allocateNewInodeId(), null, p, 0L, 0L, BlockInfo.EMPTY_ARRAY, replication, blockSize, (byte)0); inode.toUnderConstruction("", ""); editLog.logOpenFile("/filename" + (startIndex + i), inode, false, false); editLog.logCloseFile("/filename" + (startIndex + i), inode); editLog.logSync(); if(i % 100 =3D=3D0){ try { editLog.rollEditLog(); } catch (IOException e) { e.printStackTrace(); } } } } {code} =C2=A0 and I add some Log of these there transaction id:=C2=A0 * txid=C2=A0 : Current max transaction id of all thread * myTransactionId : max transaction id of current thread * syncTxId : current transaction if of EditLog that has been synced to QJM The Right #rollEditLog Event: see thread=C2=A0 {code:java} TransactionThread-267{code} =C2=A0 {code:java} 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Rol= ling edit logs 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - End= ing log segment 829 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Whe= n endCurrentLogSegment was called : txid =3D 1286 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Whe= n endCurrentLogSegment was called : myTransationId =3D 830 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Whe= n endCurrentLogSegment was called : synctxid =3D 830 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - whe= n logEdit, OpCode OP_END_LOG_SEGMENT 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - whe= n logEdit, should not forceSync 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Sta= rt LogSync 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - whe= n logSyncAll, myTransactionId 1287 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Whe= n logSync was called : txid =3D 1287 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Whe= n logSync was called : myTransationId =3D 1287 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Whe= n logSync was called : synctxid =3D 830 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - whe= n logSync, start flush 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - whe= n logSync, finish flush 2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Num= ber of transactions: 459 Total time for transactions(ms): 9 Number of trans= actions batched in Syncs: 280 Number of syncs: 4 SyncTimes(ms): 0 3 2019-04-19 16:32:08,068 INFO namenode.FileJournalManager TransactionThread-= 267 - Finalizing edits file /Users/angerszhu/Documents/project/gdc/hadoop/h= adoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1/current/edits_inp= rogress_0000000000000000829 -> /Users/angerszhu/Documents/project/gdc/hadoo= p/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1/current/edits_= 0000000000000000829-0000000000000001287 2019-04-19 16:32:08,069 INFO namenode.FileJournalManager TransactionThread-= 267 - Finalizing edits file /Users/angerszhu/Documents/project/gdc/hadoop/h= adoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name2/current/edits_inp= rogress_0000000000000000829 -> /Users/angerszhu/Documents/project/gdc/hadoo= p/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name2/current/edits_= 0000000000000000829-0000000000000001287 2019-04-19 16:32:08,069 INFO namenode.FSEditLog TransactionThread-267 - Fin= ish Ending log segment 20 {code} we can see that the sequence of this three Id is Ok .=C2=A0 =C2=A0 =C2=A0 The Error #rollEditLog Case: see=C2=A0 {code:java} TransactionThread-226 {code} =C2=A0 {code:java} 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - Whe= n logSync was called : txid =3D 760 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - Whe= n logSync was called : myTransationId =3D 19 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - Whe= n logSync was called : synctxid =3D 23 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - Rol= ling edit logs 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - End= ing log segment 3 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - Whe= n endCurrentLogSegment was called : txid =3D 760 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - Whe= n endCurrentLogSegment was called : myTransationId =3D 19 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - Whe= n endCurrentLogSegment was called : synctxid =3D 23 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - whe= n logEdit, OpCode OP_END_LOG_SEGMENT 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - Sta= rt LogSync 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - whe= n logSyncAll, myTransactionId 761 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-265 - whe= n logEdit, OpCode OP_ADD 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-265 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-264 - whe= n logEdit, OpCode OP_ADD 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-264 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-227 - whe= n logEdit, OpCode OP_CLOSE 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-227 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-263 - whe= n logEdit, OpCode OP_ADD 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-263 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-228 - whe= n logEdit, OpCode OP_CLOSE 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-228 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-262 - whe= n logEdit, OpCode OP_ADD 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-262 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-261 - whe= n logEdit, OpCode OP_ADD 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-261 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-261 - whe= n logEdit, OpCode OP_CLOSE 2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-261 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,979 INFO namenode.FSEditLog TransactionThread-229 - whe= n logEdit, OpCode OP_CLOSE 2019-04-19 16:32:07,979 INFO namenode.FSEditLog TransactionThread-229 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,979 INFO namenode.FSEditLog TransactionThread-260 - whe= n logEdit, OpCode OP_ADD 2019-04-19 16:32:07,979 INFO namenode.FSEditLog TransactionThread-260 - whe= n logEdit, should not forceSync ................ .................. 2019-04-19 16:32:07,982 INFO namenode.FSEditLog TransactionThread-260 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,982 INFO namenode.FSEditLog TransactionThread-262 - whe= n logEdit, OpCode OP_CLOSE 2019-04-19 16:32:07,982 INFO namenode.FSEditLog TransactionThread-262 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,982 INFO namenode.FSEditLog TransactionThread-263 - whe= n logEdit, OpCode OP_CLOSE 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-263 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-264 - whe= n logEdit, OpCode OP_CLOSE 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-264 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-265 - whe= n logEdit, OpCode OP_CLOSE 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-265 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-266 - whe= n logEdit, OpCode OP_CLOSE 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-266 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - Rol= ling edit logs 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - End= ing log segment 3 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - Whe= n endCurrentLogSegment was called : txid =3D 827 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - Whe= n endCurrentLogSegment was called : myTransationId =3D 758 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - Whe= n endCurrentLogSegment was called : synctxid =3D 758 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - whe= n logEdit, OpCode OP_END_LOG_SEGMENT 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - Sta= rt LogSync 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - whe= n logSyncAll, myTransactionId 828 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - Whe= n logSync was called : txid =3D 828 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - Whe= n logSync was called : myTransationId =3D 828 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - Whe= n logSync was called : synctxid =3D 758 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - whe= n logSync, start flush 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - whe= n logSync, finish flush 2019-04-19 16:32:07,983 INFO namenode.FSEditLog TransactionThread-225 - Num= ber of transactions: 826 Total time for transactions(ms): 55 Number of tran= sactions batched in Syncs: 1 Number of syncs: 5 SyncTimes(ms): 1 2 2019-04-19 16:32:07,984 INFO namenode.FileJournalManager TransactionThread-= 225 - Finalizing edits file /Users/angerszhu/Documents/project/gdc/hadoop/h= adoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1/current/edits_inp= rogress_0000000000000000003 -> /Users/angerszhu/Documents/project/gdc/hadoo= p/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1/current/edits_= 0000000000000000003-0000000000000000828 2019-04-19 16:32:07,984 INFO namenode.FileJournalManager TransactionThread-= 225 - Finalizing edits file /Users/angerszhu/Documents/project/gdc/hadoop/h= adoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name2/current/edits_inp= rogress_0000000000000000003 -> /Users/angerszhu/Documents/project/gdc/hadoo= p/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name2/current/edits_= 0000000000000000003-0000000000000000828 2019-04-19 16:32:07,984 INFO namenode.FSEditLog TransactionThread-225 - Fin= ish Ending log segment 2019-04-19 16:32:07,984 INFO namenode.FSEditLog TransactionThread-225 - Sta= rting log segment at 829 2019-04-19 16:32:07,985 INFO namenode.FSEditLog TransactionThread-225 - whe= n logEdit, OpCode OP_START_LOG_SEGMENT 2019-04-19 16:32:07,985 INFO namenode.FSEditLog TransactionThread-225 - whe= n logEdit, should not forceSync 2019-04-19 16:32:07,985 INFO namenode.FSEditLog TransactionThread-225 - Whe= n logSync was called : txid =3D 829 2019-04-19 16:32:07,985 INFO namenode.FSEditLog TransactionThread-225 - Whe= n logSync was called : myTransationId =3D 829 2019-04-19 16:32:07,986 INFO namenode.FSEditLog TransactionThread-225 - Whe= n logSync was called : synctxid =3D 828 2019-04-19 16:32:07,986 INFO namenode.FSEditLog TransactionThread-225 - whe= n logSync, start flush 2019-04-19 16:32:07,986 INFO namenode.FSEditLog TransactionThread-225 - whe= n logSync, finish flush 2019-04-19 16:32:07,986 INFO namenode.FSEditLog TransactionThread-225 - Fin= ish Rolling edit logs 2019-04-19 16:32:07,986 INFO namenode.FSEditLog TransactionThread-267 - whe= n logEdit, OpCode OP_CLOSE 2019-04- ................. ................ 2019-04-19 16:32:08,080 INFO namenode.FSEditLog TransactionThread-227 - Whe= n endCurrentLogSegment was called : txid =3D 1328 2019-04-19 16:32:08,081 INFO namenode.FSEditLog TransactionThread-227 - Whe= n endCurrentLogSegment was called : myTransationId =3D 764 2019-04-19 16:32:08,081 INFO namenode.FSEditLog TransactionThread-227 - Whe= n endCurrentLogSegment was called : synctxid =3D 1288 2019-04-19 16:32:08,081 INFO namenode.FSEditLog TransactionThread-227 - whe= n logEdit, OpCode OP_END_LOG_SEGMENT 2019-04-19 16:32:08,081 INFO namenode.FSEditLog TransactionThread-227 - whe= n logEdit, should not forceSync 2019-04-19 16:32:08,081 INFO namenode.FSEditLog TransactionThread-227 - Sta= rt LogSync 2019-04-19 16:32:08,081 INFO namenode.FSEditLog TransactionThread-227 - whe= n logSyncAll, myTransactionId 1329 2019-04-19 16:32:08,081 INFO namenode.FSEditLog TransactionThread-226 - Whe= n logSync was called : txid =3D 1329 2019-04-19 16:32:08,081 INFO namenode.FSEditLog TransactionThread-226 - Whe= n logSync was called : myTransationId =3D 761 2019-04-19 16:32:08,081 INFO namenode.FSEditLog TransactionThread-226 - Whe= n logSync was called : synctxid =3D 1288 2019-04-19 16:32:08,081 INFO namenode.FSEditLog TransactionThread-226 - Num= ber of transactions: 42 Total time for transactions(ms): 2 Number of transa= ctions batched in Syncs: 41 Number of syncs: 3 SyncTimes(ms): 1 1 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - The edits buffer is 663 bytes long with 39 unflushed transactions. Bel= ow is the list of unflushed transactions: 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [0]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D12= 91] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [1]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D12= 92] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [2]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D12= 93] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [3]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D12= 94] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [4]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D12= 95] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [5]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D12= 96] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [6]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D12= 97] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [7]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D12= 98] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [8]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D12= 99] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [9]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D13= 00] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [10]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 301] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [11]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 302] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [12]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 303] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [13]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 304] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [14]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 305] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [15]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 306] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [16]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 307] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [17]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 308] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [18]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 309] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [19]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 310] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [20]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 311] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [21]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 312] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [22]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 313] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [23]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 314] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [24]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 315] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [25]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 316] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [26]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 317] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [27]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 318] 2019-04-19 16:32:08,084 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [28]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 319] 2019-04-19 16:32:08,085 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [29]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 320] 2019-04-19 16:32:08,085 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [30]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 321] 2019-04-19 16:32:08,085 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [31]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 322] 2019-04-19 16:32:08,085 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [32]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 323] 2019-04-19 16:32:08,085 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [33]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 324] 2019-04-19 16:32:08,085 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [34]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 325] 2019-04-19 16:32:08,085 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [35]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 326] 2019-04-19 16:32:08,085 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [36]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 327] 2019-04-19 16:32:08,085 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [37]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 328] 2019-04-19 16:32:08,085 WARN namenode.EditsDoubleBuffer TransactionThread-2= 26 - Unflushed op [38]: LogSegmentOp [opCode=3DOP_END_LOG_SEGMENT, txid=3D1= 329] 2019-04-19 16:32:08,085 ERROR namenode.FSEditLog TransactionThread-226 - Er= ror: finalize log segment 1288, 1329 failed for (journal JournalAndStream(m= gr=3DFileJournalManager(root=3D/Users/angerszhu/Documents/project/gdc/hadoo= p/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1), stream=3DEdi= tLogFileOutputStream(/Users/angerszhu/Documents/project/gdc/hadoop/hadoop-h= dfs-project/hadoop-hdfs/target/test/data/dfs/name1/current/edits_inprogress= _0000000000000001288))) java.io.IOException: FSEditStream has 663 bytes still to be flushed and can= not be closed. at org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoub= leBuffer.java:73) at org.apache.hadoop.hdfs.server.namenode.EditLogFileOutputStream.close(Edi= tLogFileOutputStream.java:151) at org.apache.hadoop.hdfs.server.namenode.JournalSet$JournalAndStream.close= Stream(JournalSet.java:115) at org.apache.hadoop.hdfs.server.namenode.JournalSet$4.apply(JournalSet.jav= a:235) at org.apache.hadoop.hdfs.server.namenode.JournalSet.mapJournalsAndReportEr= rors(JournalSet.java:393) at org.apache.hadoop.hdfs.server.namenode.JournalSet.finalizeLogSegment(Jou= rnalSet.java:231) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FS= EditLog.java:1259) at org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.j= ava:1182) at org.apache.hadoop.hdfs.server.namenode.TestEditLog$Transactions.run(Test= EditLog.java:223) at java.lang.Thread.run(Thread.java:748) {code} For the TransactionThread-226=EF=BC=8C we can see that it's interrupted,=C2= =A0 During the whole cycle of=C2=A0 #rollEditLog, it was been interrupted by ot= her thread's evnent. And this make the #syncTxId will be larger then the old thread that call #r= ollEditLog and been interrupted. Finally because: myTxid <=3D synctxid, it just returned here. =C2=A0 {code:java} if (mytxid <=3D synctxid) { numTransactionsBatchedInSync++; if (metrics !=3D null) { // Metrics is non-null only when used inside name node metrics.incrTransactionsBatchedInSync(); } return; } {code} But when this time. bufCurrent will still have data not been flushed. Then cause that error. =C2=A0 =C2=A0 But I can't say why it's interrupted since there are many way's will call l= ogSync and I don't know more detail of the whole HA and QJM.=C2=A0 =C2=A0 =C2=A0 > Exception happened when rollEditLog expects empty EditsDoubleBuffer.buf= Current but not > -------------------------------------------------------------------------= ---------------- > > Key: HDFS-14437 > URL: https://issues.apache.org/jira/browse/HDFS-14437 > Project: Hadoop HDFS > Issue Type: Bug > Components: ha, namenode, qjm > Reporter: angerszhu > Priority: Major > > For the problem mentioned in=C2=A0https://issues.apache.org/jira/browse/H= DFS-10943=C2=A0, I have sort the process of write and flush EditLog and som= e important function, I found the in the class=C2=A0 FSEditLog class, the c= lose() function will call such process like below: > =C2=A0 > {code:java} > waitForSyncToFinish(); > endCurrentLogSegment(true);{code} > since we have gain the object lock in the function close(), so when=C2=A0= waitForSyncToFish() method return, it mean all logSync job has done and al= l data in bufReady has been flushed out, and since current thread has the l= ock of this object, when call endCurrentLogSegment(), no other thread will = gain the lock so they can't write new editlog into currentBuf. > But when we don't call waitForSyncToFish() before endCurrentLogSegment(),= there may be some autoScheduled logSync()'s flush process is doing, since = this process don't need > synchronization since it has mention in the comment of logSync() method : > =C2=A0 > {code:java} > /** > * Sync all modifications done by this thread. > * > * The internal concurrency design of this class is as follows: > * - Log items are written synchronized into an in-memory buffer, > * and each assigned a transaction ID. > * - When a thread (client) would like to sync all of its edits, logSyn= c() > * uses a ThreadLocal transaction ID to determine what edit number mu= st > * be synced to. > * - The isSyncRunning volatile boolean tracks whether a sync is curren= tly > * under progress. > * > * The data is double-buffered within each edit log implementation so tha= t > * 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 isSyncRunni= ng > * flag. > * 2. unsynchronized, it flushes the data to storage > * 3. synchronized, it resets the flag and notifies anyone waiting on t= he > * 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. > */ > public void logSync() { > long syncStart =3D 0; > // Fetch the transactionId of this thread.=20 > long mytxid =3D myTransactionId.get().txid; > =20 > boolean sync =3D false; > try { > EditLogOutputStream logStream =3D null; > synchronized (this) { > try { > printStatistics(false); > // if somebody is already syncing, then wait > while (mytxid > synctxid && isSyncRunning) { > try { > wait(1000); > } catch (InterruptedException ie) { > } > } > // > // If this transaction was already flushed, then nothing to do > // > if (mytxid <=3D synctxid) { > numTransactionsBatchedInSync++; > if (metrics !=3D null) { > // Metrics is non-null only when used inside name node > metrics.incrTransactionsBatchedInSync(); > } > return; > } > =20 > // now, this thread will do the sync > syncStart =3D txid; > isSyncRunning =3D true; > sync =3D true; > // swap buffers > try { > if (journalSet.isEmpty()) { > throw new IOException("No journals available to flush"); > } > editLogStream.setReadyToFlush(); > } catch (IOException e) { > final String msg =3D > "Could not sync enough journals to persistent storage " + > "due to " + e.getMessage() + ". " + > "Unsynced transactions: " + (txid - synctxid); > LOG.fatal(msg, new Exception()); > synchronized(journalSetLock) { > IOUtils.cleanup(LOG, journalSet); > } > terminate(1, msg); > } > } finally { > // Prevent RuntimeException from blocking other log edit write=20 > doneWithAutoSyncScheduling(); > } > //editLogStream may become null, > //so store a local variable for flush. > logStream =3D editLogStream; > } > =20 > // do the sync > long start =3D now(); > try { > if (logStream !=3D null) { > logStream.flush(); > } > } catch (IOException ex) { > synchronized (this) { > final String msg =3D > "Could not sync enough journals to persistent storage. " > + "Unsynced transactions: " + (txid - synctxid); > LOG.fatal(msg, new Exception()); > synchronized(journalSetLock) { > IOUtils.cleanup(LOG, journalSet); > } > terminate(1, msg); > } > } > long elapsed =3D now() - start; > if (metrics !=3D null) { // Metrics non-null only when used inside na= me node > metrics.addSync(elapsed); > } > =20 > } finally { > // Prevent RuntimeException from blocking other log edit sync=20 > synchronized (this) { > if (sync) { > synctxid =3D syncStart; > for (JournalManager jm : journalSet.getJournalManagers()) { > /** > * {@link FileJournalManager#lastReadableTxId} is only meaningf= ul > * for file-based journals. Therefore the interface is not adde= d to > * other types of {@link JournalManager}. > */ > if (jm instanceof FileJournalManager) { > ((FileJournalManager)jm).setLastReadableTxId(syncStart); > } > } > isSyncRunning =3D false; > } > this.notifyAll(); > } > } > } > {code} > So=C2=A0 when not call waitForSyncFinish() before endCurrentLogSegment() = will came to a situation that when it can't guarantee that when call endCur= rentLogSegment() method, there is no flush job was doing. Then in the=C2=A0= endCurrentLogSegment() method process , bufReady may haven't been flushed o= ut totally, then it swap with the bufCurrent, finally when call EditLogOutp= utStream's close() function, there is still un-flushed bytes in bufCurrent = then cause the error in=C2=A0 > https://issues.apache.org/jira/browse/HDFS-10943 > =C2=A0 > so maybe we should add=C2=A0waitForSyncFinish() before endCurrentLogSegme= nt() method in rollEditLog() method in FSEditLog class ? > {code:java} > synchronized long rollEditLog() throws IOException { > LOG.info("Rolling edit logs"); > waitForSyncToFinish(); > endCurrentLogSegment(true); > =20 > long nextTxId =3D getLastWrittenTxId() + 1; > startLogSegment(nextTxId, true); > =20 > assert curSegmentTxId =3D=3D nextTxId; > return nextTxId; > }{code} > =C2=A0 > =C2=A0 -- This message was sent by Atlassian JIRA (v7.6.3#76005) --------------------------------------------------------------------- To unsubscribe, e-mail: hdfs-issues-unsubscribe@hadoop.apache.org For additional commands, e-mail: hdfs-issues-help@hadoop.apache.org