[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17244908#comment-17244908
]
angerszhu commented on HDFS-14437:
--
Seems the Precondition is added later. I think we can ignore this since It has
no effect on the current problem
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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
> Attachments: HDFS-14437.reproduction.patch,
> HDFS-14437.reproductionwithlog.patch, screenshot-1.png
>
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17244711#comment-17244711
]
Ravuri Sushma sree commented on HDFS-14437:
---
[~angerszhuuu]
I'm using 3.1.1 Hadoop version
ERROR :
{code:java}
java.lang.IllegalArgumentException: LastWrittenTxId 891 is expected to be the
same as lastSyncedTxId 888
at
com.google.common.base.Preconditions.checkArgument(Preconditions.java:115)
at
org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1473)
at
org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1360)
at
org.apache.hadoop.hdfs.server.namenode.TestEditLog$TransactionRollEditLog.run(TestEditLog.java:270)
at java.lang.Thread.run(Thread.java:748)
{code}
I encountered this when dfs.namenode.edits.asynclogging is set as true
In the parameterized testcase, testMultiThreadedEditLog[1] , when we set
dfs.namenode.edits.asynclogging as true, endCurrentLogSegment calls
logSyncAll() in FSEditLogAsync which just ensures that the queues are drained .
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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
> Attachments: HDFS-14437.reproduction.patch,
> HDFS-14437.reproductionwithlog.patch, screenshot-1.png
>
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17244428#comment-17244428
]
angerszhu commented on HDFS-14437:
--
[~Sushma_28]
No, don't meet this problem, can you show the detail error message ? and which
hadoop version you are using?
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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
> Attachments: HDFS-14437.reproduction.patch,
> HDFS-14437.reproductionwithlog.patch, screenshot-1.png
>
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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 {
> //
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17244117#comment-17244117
]
Ravuri Sushma sree commented on HDFS-14437:
---
Thanks for the reply [~angerszhuuu].
Sounds great!
I just had a doubt regarding the UT provided.
Without the fix in PR , I encountered java.lang.IllegalArgumentException in
both testMultiThreadedEditLog[0] and testMultiThreadedEditLog[1] .
With the fix, this issue is resolved in testMultiThreadedEditLog[0] but in
testMultiThreadedEditLog[1] logs it is still reproducible. Can you please let
me know if you faced the same?
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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
> Attachments: HDFS-14437.reproduction.patch,
> HDFS-14437.reproductionwithlog.patch, screenshot-1.png
>
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "Could not sync enough journals to persistent storage " +
> "due
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17243767#comment-17243767
]
angerszhu commented on HDFS-14437:
--
[~Sushma_28]
I have updated this patch in our product env for 20 months, this problem never
happened again and no other impact.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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
> Attachments: HDFS-14437.reproduction.patch,
> HDFS-14437.reproductionwithlog.patch, screenshot-1.png
>
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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 {
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17243763#comment-17243763
]
Ravuri Sushma sree commented on HDFS-14437:
---
I used the HDFS-14437.reproduction.patch provided and it seems that the PR
resolved the "java.lang.IllegalArgumentException: LastWrittenTxId 558 is
expected to be the same as lastSyncedTxId 532" error . [~angerszhuuu]
[~hexiaoqiao] Do you think any impact .
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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
> Attachments: HDFS-14437.reproduction.patch,
> HDFS-14437.reproductionwithlog.patch, screenshot-1.png
>
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "Could not sync enough journals to persistent storage " +
> "due to " + e.getMessage() + ". " +
> "Unsynced transactions: " + (txid - synctxid);
> LOG.fatal(msg, new Exception());
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17240663#comment-17240663
]
Xiaoqiao He commented on HDFS-14437:
[~Sushma_28] Actually, I also meet the similar case (NameNode crash) long
before, it is solved after patch HDFS-13112.
For this issue, there is no strict proof and we have not reached the final
agreement. Welcome more discussion here. Thanks.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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
> Attachments: HDFS-14437.reproduction.patch,
> HDFS-14437.reproductionwithlog.patch, screenshot-1.png
>
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "Could not sync enough journals to persistent storage " +
> "due to " + e.getMessage() + ". " +
> "Unsynced transactions: " + (txid - synctxid);
> LOG.fatal(msg, new Exception());
> synchronized(journalSetLock) {
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17240493#comment-17240493
]
Ravuri Sushma sree commented on HDFS-14437:
---
Thank you everyone for the discussion here, I have tried applying the patch and
the solution on PR. [~hexiaoqiao] can you please let me know if anymore updates
are available on this JIRA.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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
> Attachments: HDFS-14437.reproduction.patch,
> HDFS-14437.reproductionwithlog.patch, screenshot-1.png
>
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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);
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16932246#comment-16932246
]
He Xiaoqiao commented on HDFS-14437:
[~daryn],[~jojochuang],[~linyiqun],[~xkrogen],[~elgoiri], are you interested in
this case and give some more suggestions and helps?
I would like to offer some more additional information.
1. For FSEditlog class, there are three interfaces (#logEdit, #rollEditLog,
#logSync) which are used high frequently.
2. Among them, #logEdit and #rollEditLog are exactly hold FSN lock to control
concurrent, however, #logSync is not hold FSN lock, so we have to rely on
FSEditlog `synchronize`.
3. Based on test case [^HDFS-14437.reproduction.patch] which can reproduce
stably this issue, wait-notifyAll could not be safety completely for this case
as [~angerszhuuu] detailed digs and analysis above.
Any discussions or corrections are very welcome. Thanks guys.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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
> Attachments: HDFS-14437.reproduction.patch,
> HDFS-14437.reproductionwithlog.patch, screenshot-1.png
>
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16928584#comment-16928584
]
feiwang commented on HDFS-14437:
[~linyiqun] Hi, yiqun, are you interested in this issue?
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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
> Attachments: HDFS-14437.reproduction.patch,
> HDFS-14437.reproductionwithlog.patch, screenshot-1.png
>
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16928556#comment-16928556
]
angerszhu commented on HDFS-14437:
--
Hi watchers, after dig deep FSEditLog logic and try to reproduce this case, we
believe it is BUG.
1. we (cooperate with [~angerszhuuu],[~hexiaoqiao]) try to reproduce the case
as reported above reference to [^HDFS-14437.reproduction.patch]. more log info
reference to [^^HDFS-14437.reproductionwithlog.patch], We build unit test based
on TestEditLog#testMultiThreadedEditLog with new thread for analoging edit log
rolling by SBN periodically, create more (default by 1000) threads and make
them run editlog transactions concurrently. Then it can reproduce stably, the
exception shows as below,
{code:java}
java.lang.IllegalArgumentException: LastWrittenTxId 319373 is expected to be
the same as lastSyncedTxId 319198
at com.google.common.base.Preconditions.checkArgument(Preconditions.java:370)
at
org.apache.hadoop.hdfs.server.namenode.FSEditLog.endCurrentLogSegment(FSEditLog.java:1431)
at
org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1319)
at
org.apache.hadoop.hdfs.server.namenode.TestEditLog$TransactionRollEditLog.run(TestEditLog.java:269)
at java.lang.Thread.run(Thread.java:748)
{code}
2. After adjust parameters for multiple tests, we think the trigger condition
include:
* run editlog transactions with high sync concurrently .
* roll editlog when run editlog logSync() at the same time and rollEditLog
wait for sync lock.
* when rollEditLog thread get sync lock, we go through two rounds flush
process.
3. More detailed information,
* The following code segment at `FSEditLog#logSync` could release lock when
`wait` and other thread could acquire FSEditLog#Lock
{code:java}
while (mytxid > synctxid && isSyncRunning) {
try {
wait(1000);
} catch (InterruptedException ie) {
}
}
{code}
* `logStream.flush` L719 at `FSEditLog#logSync` is out of lock, while other
logic of `FSEditLog#logSync` are under lock, so at this moment, other thread
also could acquire FSEditLog#Lock
At these time slot, if there rolleditlog thread is running and another thread
is logedit, double buffer will not empty and this issue appear.
h3. TEST CASE
There is another patch[^HDFS-14437.reproductionwithlog.patch] to print log to
show the case.
We will get log like below:
!screenshot-1.png|width=678,height=128!
we make some change to print log
{code:java}
When logSync (mytxid <- synctxid) ...etc
{code}
In code line L685
{code:java}
if (mytxid <= synctxid) {
if (txid > synctxid && isEndLog)
LOG.info("When logSync (mytxid <= synctxid) mytxid=" + mytxid
+
" lastSyncedTxid=" + synctxid
+" mostRecentTxid=" +
txid); return;
}
{code}
only when method logSync() is called under endCurrentLogSegment(), and when
logSync() get sync lock.
here will return from logSync() method. but you can see.
# mytxid=194098
# lastSyncTxid=194159 bigger then mytxid
# mostrecentTxid=194346 bigger then lastSyncTxid mean we still have some
editLog in currentBuffer.
In this case it will just return, and meet error. we show above, then Roll
EditLog failed and NameNode crash down.
||variable||thread1||thread2||thread3||thread4||thread5||...||
|txid=10, synctxid=6, isSyncRunning = true|logSync(),
mytxid=10,
and get lock |rollEditLog and miss wait for lock |editLog() and wait for
lock|editLog() and wait for lock|editLog() and wait for lock| |
|txid=11, synctxid=6, isSyncRunning = true|wait lock|rollEditLog get lock
current mytxid = 11| | | | |
|txid=11, synctxid=10, isSyncRunning = false|end logSync() and release
lock|thread wait() since isSyncingRunning == true|wait lock|wait lock|wait
lock| |
|txid=12, synctxid=10, isSyncRunning = false|thread end|wait lock|get lock and
write one log|wait lock|wait lock| |
|txid=13, synctxid=6, isSyncRunning = false| |wait lock|thread end|get lock and
write one log
trigger auto logSync
mytxid=13|wait lock| |
|txid=13, synctxid=6, isLogSyncRunning = true| |wait lock| |logSync()
mytxid=13|get lock and write one log | |
|txid=20, synctxid=6, isLogSyncRunning = true| |wait lock| |wait lock|thread
end |get lock and write one log
...
(for many times )|
|txid=20, synctxid=13, isLogSyncRunning = true| |wait lock| |logSync() end
Thread end| | |
| | |get lock, since mytxid < synctxid return, but currentBuffer still have
some EditLog. Error happened.| | | | |
| | | | | | | |
| | | | | | | |
> Exception happened when rollEditLog expects empty
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16928141#comment-16928141
]
angerszhu commented on HDFS-14437:
--
[~daryn]
In current hadoop truck branch, still have this bug.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
> //editLogStream may become null,
> //so store a local
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16832024#comment-16832024
]
Daryn Sharp commented on HDFS-14437:
Unless I'm overlooking new details, I explained on the cited HDFS-10943 that
this is not an edit log problem.
{quote}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. 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.
{quote}
QJM uses async streams. If a stream fails to flush it will buffer the data. If
those unflushed streams are closed, ex. during a log roll, they abort due to
the unflushed data. The edit log cannot fix this bug with the underlying
quorum streams.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16826612#comment-16826612
]
angerszhu commented on HDFS-14437:
--
[~starphin]
it seem work not well when high concurrency. LOCK in FSNameSystem level is
complex.
Hard to say what I think is totally right. But see our production env 's error.
It seem match my guess that rollEditLog trap in #wait in logSync.
The best way to confirm this is add some log in production env, to show the
sequence of _*txid, synctxid,myTransactionId*_ . But risk so high, add these
detail log will make more pressure. My boos won't let me to do like this.
Any way, what I change in pull request is to prevent this situation happen.
And I test that when low concurrency, it truly not happen, when high
concurrency, it happened..
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16826604#comment-16826604
]
star commented on HDFS-14437:
-
As [~kihwal] said in HDFS-10943 that '{{rollEditLog()}} does not and cannot
solely depend on {{FSEditLog}} synchronization', it's not enough to reproduce
such issue in FSEditLog level. We should reproduce it in the FSNamesystem level
or event RPC level. As far as I know, all method of FSEditLog are called in
FSNamesystem with either readlock or writelock.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "Could not sync enough journals to persistent storage " +
> "due to " + e.getMessage() + ". " +
> "Unsynced transactions: " + (txid - synctxid);
> LOG.fatal(msg, new Exception());
> synchronized(journalSetLock) {
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16824719#comment-16824719
]
angerszhu commented on HDFS-14437:
--
[~starphin]
Yesterday I omit a point that in the process table you show .
After *_logEdit_ , there should have another logSync process been called.*
*then myTxid can be less than synctxid.*
*Since during the duration of #wait, the sequence of all behavior is out of
control.*
*That is why this error will happen when cluster is in high Concurrent pressure
but work well in normal.*
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "Could not sync enough journals to persistent storage " +
> "due to " + e.getMessage() + ". " +
> "Unsynced transactions: " + (txid - synctxid);
> LOG.fatal(msg, new Exception());
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823779#comment-16823779
]
angerszhu commented on HDFS-14437:
--
[~hexiaoqiao]
[angers@gmail.com|mailto:angers@gmail.com] that is my google mail.
contact me and I give you my phone number or wechat.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823774#comment-16823774
]
He Xiaoqiao commented on HDFS-14437:
[~angerszhuuu] I would like to connect with you offline and let's recheck the
truth then back to discuss. Please attach any contacts if convenient. Thanks.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823769#comment-16823769
]
angerszhu commented on HDFS-14437:
--
[~hadoopqa]
Hi can you test my pull request.
Thanks
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
> //editLogStream may become null,
> //so store a local variable
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823750#comment-16823750
]
star commented on HDFS-14437:
-
ok, Later I will take a view.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
> //editLogStream may become null,
> //so store a local variable for flush.
> logStream =
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823746#comment-16823746
]
angerszhu commented on HDFS-14437:
--
[~starphin]
You can see my pull request, two way both can solve this problem , but I advise
the way in pull request.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823742#comment-16823742
]
star commented on HDFS-14437:
-
[~angerszhuuu] Right. lock state fixed.
{quote}But logAppend also need lock.
{quote}
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
> //editLogStream may become null,
> //so
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823732#comment-16823732
]
angerszhu commented on HDFS-14437:
--
[~starphin]
But logAppend also need lock.
What you show is just the situation I want to say.
lol
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
> //editLogStream may
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823726#comment-16823726
]
star commented on HDFS-14437:
-
locked is object lock of FSEditLog.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
> //editLogStream may become null,
> //so store a local variable for flush.
> logStream
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823717#comment-16823717
]
angerszhu commented on HDFS-14437:
--
[~starphin]
yeah , that is what i want to show .
you can see my pull request.
I think I should improve my skill of show technology logic
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823714#comment-16823714
]
star commented on HDFS-14437:
-
[~angerszhuuu], I think I've got that.
||Thread0||thread1||Thread2||locked||isSyncRunning||
| |flush| |false|true|
|endCurrentSegment#{color:#33}logSyncAll{color}| | |true|true|
|wait| | |false|true|
| |flush done| |false|false|
| | |*logAppend*|false|false|
|{color:#d04437}finalize error{color}| | |true|false|
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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);
> }
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823669#comment-16823669
]
angerszhu commented on HDFS-14437:
--
[~hexiaoqiao]
You can see that when other thread is also run logsync, isSyncRunning ==
true.Current thread call #endCurrentLogSegment will go into while loop:
{code:java}
while (mytxid > synctxid && isSyncRunning) {
try {
wait(1000);
} catch (InterruptedException ie) {
}
}
{code}
if other thread can't get lock, isSyncRunning won't be false, and synctxid
won't change.
the the current thread will always blocking in the while loop, this situation
is not correct.
My english is not very good . may have some mistake, if you need, send a mail
to me and explain to you in chinese.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "Could not sync enough journals to
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16823660#comment-16823660
]
He Xiaoqiao commented on HDFS-14437:
Thanks [~angerszhuuu] for your more information.
{quote}When #rollEditLog#endCurrentLogSegment call logSync, if there is some
other thread is calling logSync, it will #wait() in the while loop. then other
thread can get the lock.{quote}
Sorry, I still don't understand why other threads could acquire the FSEditLog
Lock and run #logSync or #LogEdit (these two method also need acquire FSEditLog
Lock) when execute endCurrentLogSegment#logSync which is synchronized.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "Could not sync enough journals to persistent storage " +
> "due to " + e.getMessage() + ". " +
> "Unsynced transactions: " + (txid -
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16822863#comment-16822863
]
angerszhu commented on HDFS-14437:
--
[~hexiaoqiao]
Look the table above your last comment. This situation can happen.
And in my test case, when the error happen , logSync return at condition [
myTrasactionId <= synctxid ].
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16822861#comment-16822861
]
angerszhu commented on HDFS-14437:
--
Hi [~hexiaoqiao]
you are right that seems some point is conflict of what I said.
Since in the beginning, some point is wrong and I find it by myself .
You can see my last serval comment.
When #rollEditLog#endCurrentLogSegment call logSync, if there is some other
thread is calling logSync, it will #wait() in the while loop. then other thread
can get the lock.
For this comment :
{code:java}
when #endCurrentLogSegment call #logSync() if #isSyncRunning == true and mytxid
> synctxid,Current thread will call #wait, other thread will run. if other
thread can't run, #isSyncRunning will always be true. current thread can't run
out of the while loop this will become a dead lock.
{code}
I just want to say that when thread call #wait, it will lose lock and other
thread can get the lock, and in my unit test, this situation actually happened.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16822856#comment-16822856
]
He Xiaoqiao commented on HDFS-14437:
[~angerszhuuu] sorry for my late response. I believe you try to do some more
experiment and get the expect result, And there are many comments about that,
But I found they are not keep the same conclusion, Could you like give unified
summary?
{quote}when #endCurrentLogSegment call #logSync() if #isSyncRunning == true and
mytxid > synctxid,Current thread will call #wait, other thread will run. if
other thread can't run, #isSyncRunning will always be true. current thread
can't run out of the while loop this will become a dead lock.{quote}
It is possible to meet this case I think, for instance, when there is
network/ioutil bottleneck from namenode to journalnode which for HA using QJM,
and util bottleneck recovery. But I do not think it could meet dead lock.
For the last execution sequence diagram you supply, I am confused that when run
endCurrentLogSegment#logSync which is synchronized, why other threads could
acquire the FSEditLog Lock and run #logSync or #LogEdit (these two method also
need acquire FSEditLog).
Another side, I suggest to test with trunk branch. FYI. Thanks again.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16822835#comment-16822835
]
angerszhu commented on HDFS-14437:
--
Auto Scheduler Sync 's step2(flush ) can process async
Call #logSync from #endCurrentLogSegment only can profess with #FSditLog's
Object lock
Since many thread may wait for the lock, we can't promise that Thread 1 will
get the lock first after thread 2's #logSync finish.
||Var||Thread 1||Thread 2||Thread 3||Thread 4||
|txid=10, synctxid=8, isSyncRunning=true|#rollEditLog [myTransactionId=6]| | | |
|txid=10, synctxid=8, isSyncRunning=true|#endCurrentLogSegment
[myTransactionId=6]| | | |
|txid=11, synctxid=8, isSyncRunning=true|#endCurrentLogSegment#logEdit()
[myTransactionId = 11]| | | |
|txid=11, synctxid=8, isSyncRunning=true|#endCurrentLogSegment#logSync()
[myTransactionId= 11]| | | |
|txid=11, synctxid=8,
isSyncRunning=true|#endCurrentLogSegment#logSync#wait|#logSync#flush| | |
|txid=11, synctxid=10, isSyncRunning=false| |#logSync#step3| | |
|txid=14, synctxid=10, isSyncRunning=false| | |#logEdit,
#logEdit
#logEdit| |
|txid=14, synctxid=10, isSyncRunning=true| | | |#logSync#step1|
|txid=16, synctxid=10, isSyncRunning=true| | |#logEdit
#logEdit|#logSync#step2|
|txid=16, synctxid=14, isSyncRunning=false| | | |#logSync#step3|
|txid=16, synctxid=14, isSyncRunning=false|whild myTrasactionId < synctxid ,
return
then call method close EditDoubleBuffer| | | |
|txid=16, synctxid=14, isSyncRunning=false|since bufCurrent.size > 0 , error
happen| | | |
| | | | | |
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16822096#comment-16822096
]
angerszhu commented on HDFS-14437:
--
[~hexiaoqiao]
add #waitForSyncToFinish before #endCurrentLogSegment in #rollEditLog will
have the same result as my pull request.
Both work in my test case with high QPS of rollEditLog request.
2000 thread randomly call logEdit and rollEditLog. work fine
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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);
> }
> }
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821898#comment-16821898
]
angerszhu commented on HDFS-14437:
--
[~starphin]
Just add some code in
#TestEditCode.Transactions.run()
Run test:
#testMultiThreadedEditLog
**Improtant**
add thread num and change bufferCapacity
{code:java}
@Override
public void run() {
PermissionStatus p = namesystem.createFsOwnerPermissions(
new FsPermission((short)0777));
FSEditLog editLog = namesystem.getEditLog();
for (int i = 0; i < numTransactions; i++) {
INodeFile inode = 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 ==0){
try {
editLog.rollEditLog();
} catch (IOException e) {
e.printStackTrace();
}
}
}
}
{code}
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821862#comment-16821862
]
star commented on HDFS-14437:
-
[~angerszhuuu], better upload your unit test code for others to reproduce the
issue.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
> //editLogStream may become null,
> //so
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821826#comment-16821826
]
angerszhu commented on HDFS-14437:
--
[~hexiaoqiao] [~daryn] [~starphin] [~kihwal] [~arpitagarwal]
when #endCurrentLogSegment call #logSync() if #isSyncRunning == true and
mytxid > synctxid,
Current thread will call #wait, other thread will run.
if other thread can't run , #isSyncRunning will always be true.
current thread can't run out of the while loop
this will become a dead lock.
If other thread get lock to run, They can do many things in 1000ms.
Then other thread call logSync will end the flush process.
synctxid may be bigger than mytxid.
Then error happen.
So , the lock control is not correct.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "Could not sync enough journals to persistent storage
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821808#comment-16821808
]
angerszhu commented on HDFS-14437:
--
In the code of #logSync() this #wait
{code:java}
while (mytxid > synctxid && isSyncRunning) {
try {
wait(1000);
} catch (InterruptedException ie) {
}
}
{code}
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821795#comment-16821795
]
angerszhu commented on HDFS-14437:
--
[~hexiaoqiao] [~daryn] [~starphin] [~kihwal] [~arpitagarwal]
When I do Unit test , I add some log in my code and print thread id in log4j.
In TestEditLog#Transactions's run method, I add a call for #rollEditLog to
simulate random multithreading call of logSync().
{code:java}
@Override
public void run() {
PermissionStatus p = namesystem.createFsOwnerPermissions(
new FsPermission((short)0777));
FSEditLog editLog = namesystem.getEditLog();
for (int i = 0; i < numTransactions; i++) {
INodeFile inode = 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 ==0){
try {
editLog.rollEditLog();
} catch (IOException e) {
e.printStackTrace();
}
}
}
}
{code}
and I add some Log of these there transaction id:
* txid : 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
{code:java}
TransactionThread-267{code}
{code:java}
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Rolling
edit logs
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Ending
log segment 829
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - When
endCurrentLogSegment was called : txid = 1286
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - When
endCurrentLogSegment was called : myTransationId = 830
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - When
endCurrentLogSegment was called : synctxid = 830
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - when
logEdit, OpCode OP_END_LOG_SEGMENT
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - when
logEdit, should not forceSync
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Start
LogSync
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - when
logSyncAll, myTransactionId 1287
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - When
logSync was called : txid = 1287
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - When
logSync was called : myTransationId = 1287
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - When
logSync was called : synctxid = 830
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - when
logSync, start flush
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - when
logSync, finish flush
2019-04-19 16:32:08,068 INFO namenode.FSEditLog TransactionThread-267 - Number
of transactions: 459 Total time for transactions(ms): 9 Number of transactions
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/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1/current/edits_inprogress_829
->
/Users/angerszhu/Documents/project/gdc/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1/current/edits_829-0001287
2019-04-19 16:32:08,069 INFO namenode.FileJournalManager TransactionThread-267
- Finalizing edits file
/Users/angerszhu/Documents/project/gdc/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name2/current/edits_inprogress_829
->
/Users/angerszhu/Documents/project/gdc/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name2/current/edits_829-0001287
2019-04-19 16:32:08,069 INFO namenode.FSEditLog TransactionThread-267 - Finish
Ending log segment
20
{code}
we can see that the sequence of this three Id is Ok .
The Error #rollEditLog Case: see
{code:java}
TransactionThread-226 {code}
{code:java}
2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - When
logSync was called : txid = 760
2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - When
logSync was called : myTransationId = 19
2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - When
logSync was called : synctxid = 23
2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - Rolling
edit logs
2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - Ending
log segment 3
2019-04-19 16:32:07,978 INFO namenode.FSEditLog TransactionThread-226 - When
endCurrentLogSegment
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821767#comment-16821767
]
He Xiaoqiao commented on HDFS-14437:
[~angerszhuuu], would you like to supply detailed about reproduce? Is there any
different with scenario I attached above?
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821756#comment-16821756
]
angerszhu commented on HDFS-14437:
--
[~hexiaoqiao]
I just run it. And reappear it
{code:java}
2019-04-19 15:37:07,955 INFO namenode.FSEditLog TransactionThread-151 - When
logSync was called : txid = 11369
2019-04-19 15:37:07,955 INFO namenode.FSEditLog TransactionThread-151 - When
logSync was called : myTransationId = 11337
2019-04-19 15:37:07,955 INFO namenode.FSEditLog TransactionThread-151 - When
logSync was called : synctxid = 11366
2019-04-19 15:37:07,955 INFO namenode.FSEditLog TransactionThread-151 - when
logEdit, OpCode OP_ADD
2019-04-19 15:37:07,955 INFO namenode.FSEditLog TransactionThread-151 - when
logEdit, should not forceSync
2019-04-19 15:37:07,955 INFO namenode.FSEditLog TransactionThread-151 - when
logEdit, OpCode OP_CLOSE
2019-04-19 15:37:07,955 INFO namenode.FSEditLog TransactionThread-151 - when
logEdit, should not forceSync
2019-04-19 15:37:07,955 INFO namenode.FSEditLog TransactionThread-163 - When
logSync was called : txid = 11371
2019-04-19 15:37:07,955 INFO namenode.FSEditLog TransactionThread-163 - When
logSync was called : myTransationId = 11338
2019-04-19 15:37:07,955 INFO namenode.FSEditLog TransactionThread-163 - When
logSync was called : synctxid = 11366
2019-04-19 15:37:07,955 INFO namenode.FSEditLog TransactionThread-163 - Number
of transactions: 10 Total time for transactions(ms): 1 Number of transactions
batched in Syncs: 2 Number of syncs: 5 SyncTimes(ms): 1 0
2019-04-19 15:37:07,955 WARN namenode.EditsDoubleBuffer TransactionThread-163 -
The edits buffer is 316 bytes long with 3 unflushed transactions. Below is the
list of unflushed transactions:
2019-04-19 15:37:07,955 WARN namenode.EditsDoubleBuffer TransactionThread-163 -
Unflushed op [0]: AddOp [length=0, inodeId=21471, path=/filename74492,
replication=3, mtime=0, atime=0, blockSize=64, blocks=[],
permissions=angerszhu:supergroup:rwxrwxrwx, aclEntries=null, clientName=,
clientMachine=, overwrite=false, RpcClientId=, RpcCallId=-2, storagePolicyId=0,
opCode=OP_ADD, txid=11369]
2019-04-19 15:37:07,955 WARN namenode.EditsDoubleBuffer TransactionThread-163 -
Unflushed op [1]: AddOp [length=0, inodeId=21482, path=/filename75922,
replication=3, mtime=0, atime=0, blockSize=64, blocks=[],
permissions=angerszhu:supergroup:rwxrwxrwx, aclEntries=null, clientName=,
clientMachine=, overwrite=false, RpcClientId=, RpcCallId=-2, storagePolicyId=0,
opCode=OP_ADD, txid=11370]
2019-04-19 15:37:07,955 WARN namenode.EditsDoubleBuffer TransactionThread-163 -
Unflushed op [2]: CloseOp [length=0, inodeId=0, path=/filename75922,
replication=3, mtime=0, atime=0, blockSize=64, blocks=[],
permissions=angerszhu:supergroup:rwxrwxrwx, aclEntries=null, clientName=,
clientMachine=, overwrite=false, storagePolicyId=0, opCode=OP_CLOSE, txid=11371]
2019-04-19 15:37:07,955 ERROR namenode.FSEditLog TransactionThread-163 - Error:
finalize log segment 11362, 11371 failed for (journal
JournalAndStream(mgr=FileJournalManager(root=/Users/angerszhu/Documents/project/gdc/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1),
stream=EditLogFileOutputStream(/Users/angerszhu/Documents/project/gdc/hadoop/hadoop-hdfs-project/hadoop-hdfs/target/test/data/dfs/name1/current/edits_inprogress_0011362)))
java.io.IOException: FSEditStream has 316 bytes still to be flushed and cannot
be closed.
at
org.apache.hadoop.hdfs.server.namenode.EditsDoubleBuffer.close(EditsDoubleBuffer.java:73)
at
org.apache.hadoop.hdfs.server.namenode.EditLogFileOutputStream.close(EditLogFileOutputStream.java:151)
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:1252)
at
org.apache.hadoop.hdfs.server.namenode.FSEditLog.rollEditLog(FSEditLog.java:1178)
at
org.apache.hadoop.hdfs.server.namenode.TestEditLog$Transactions.run(TestEditLog.java:223)
at java.lang.Thread.run(Thread.java:748)
{code}
look at Thread 163, when do logSync, the mtTransationId and syncTxId
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821755#comment-16821755
]
He Xiaoqiao commented on HDFS-14437:
[~angerszhuuu], I try to run unit test local and debug with breakpoint and
evaluate expression. It could be complex to reproduce using unit test directly
as mentioned above.:)
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821705#comment-16821705
]
angerszhu commented on HDFS-14437:
--
[~hexiaoqiao]
hi He Xiaoqiao, how do you run local test to reappear that problem。
just use Test in hadoop file.
Since IN test cluster, the pressure is not enough to trigger that problem.
But if I add log to show logEdit process, will influence product env 's
performance too much.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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,
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821095#comment-16821095
]
angerszhu commented on HDFS-14437:
--
[~starphin]
Since #endCurrentLogSegment() have gain the lock of FSEditLog Object, so when
logSync was called by #endCurrentLogSegment, it will not been interrupted.
when #logSync() was called by those #logEdit() method, it just lock process of
write op.
{code:java}
/**
* Write an operation to the edit log. Do not sync to persistent
* store yet.
*/
void logEdit(final FSEditLogOp op) {
synchronized (this) {
assert isOpenForWrite() :
"bad state: " + state;
// wait if an automatic sync is scheduled
waitIfAutoSyncScheduled();
long start = beginTransaction();
op.setTransactionId(txid);
try {
editLogStream.write(op);
} catch (IOException ex) {
// All journals failed, it is handled in logSync.
} finally {
op.reset();
}
endTransaction(start);
// check if it is time to schedule an automatic sync
if (!shouldForceSync()) {
return;
}
isAutoSyncScheduled = true;
}
// From here , the thread has release the lock
// sync buffered edit log entries to persistent store
logSync();
}
{code}
so when this situation, #logSync().step2 -> flush() will not have the lock.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821092#comment-16821092
]
star commented on HDFS-14437:
-
[~angerszhuuu]. If fsLock ignored, the senario He Xiaoqiao listed could occur
because flush doesn't need object lock of FSEditlog.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16821040#comment-16821040
]
He Xiaoqiao commented on HDFS-14437:
[~angerszhuuu],Thanks for your correction, I will check it later.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
> //editLogStream may become null,
> //so store a
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820974#comment-16820974
]
He Xiaoqiao commented on HDFS-14437:
Thanks [~starphin].
{quote}But the table you presented will hardly occurred, for rollEditLog and
FSEditLog#logEdit are almost called with FSNamesystem.fsLock holding such as
mkdir, setAcl. I'm still working on it to find that racing case.{quote}
It is complex to reproduce actually, especially in unit test. I think we could
construct the right way if we make sure it is truth. for instance multi-thread
to logSync, just my own opinion, maybe there is more graceful way.
I think it is not necessary to consider #fsLock as mentioned above, it is not
related with #fsLock, we should test FSEditLog independently.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "Could not sync
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820972#comment-16820972
]
angerszhu commented on HDFS-14437:
--
The scenario won't happen since the thread that call #rollEditLog will get the
lock of FSEditLog Object and #endCurrentLogSegment() will also hold this lcok
since they are the same thread called , when #endCurrentLogSegment call
#logSync, that thread will still get this FSEditLog Object's lock.
During this flush() process, the thread won't be interrupted.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "Could not sync enough journals to persistent storage " +
> "due to " + e.getMessage() + ". " +
> "Unsynced transactions: " + (txid - synctxid);
> LOG.fatal(msg, new Exception());
> synchronized(journalSetLock) {
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820969#comment-16820969
]
angerszhu commented on HDFS-14437:
--
[~hexiaoqiao]
In my first description, I make something mistake. Since I have double check
the {{synchronized}} logic, without #waitForSyncToFinish() is ok for the
logic. Since it't can't change the situation I said above. It can't guarantee
that when I call #endCurrentLogSegment myTransasionId will larger than
syncTxId.
In version > 2.8， call #logSyncAll() in #endCurrentLogSegment() will prevent
from happening myTransasionId <= syncTxId.
{code:java}
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));
}
//
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}
But I am not sure that just only the case I have said above. I will test in our
Cluster. And if Ok I will ping you.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820953#comment-16820953
]
He Xiaoqiao commented on HDFS-14437:
[~angerszhuuu],[~starphin] please help to double check.
[~angerszhuuu] would you like to submit patch to fix this issue, If need any
help, please send ping to me.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820950#comment-16820950
]
star commented on HDFS-14437:
-
[~hexiaoqiao], agreed.
{quote}In my opinion, The following code segment in FSEditLog#logSync which is
out of {{synchronized}} is core reason.
try {if (logStream != null) \{
logStream.flush();
}
}{quote}
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820942#comment-16820942
]
He Xiaoqiao commented on HDFS-14437:
Thanks [~angerszhuuu],[~starphin], It looks that root cause is clearer.
some minor comment:
[~starphin], IIUC, all FSEditLog#logSync is out of FsLock and only
FSEditLog#rollEditlog hold on FsLock, so {{FSEditLog}} is not related with
{{FsLock}} overall. Thus {{FSEditLog}} using {{synchronized}} to control
concurrency.
In my opinion, The following code segment in FSEditLog#logSync which is out of
{{synchronized}} is core reason.
{code:java}
try {
if (logStream != null) {
logStream.flush();
}
}
{code}
Consider scenario:
||Time||Thread1(rollEditlog)||Thread2(invoke logSync by somewhat NN write op)||
|t1| |*enter synchronized*|
|t2| |check Syncing|
|t3| |set #syncStart and #isSyncRunning|
|t4| |swap buffers|
|t5| |do auto sync scheduling|
|t6| |*exit synchronized*|
|t7|*enter synchronized*| |
|t8|endCurrentLogSegment#logEdit| |
|t9|endCurrentLogSegment#logSyncAll (then doble buffer will be empty)| |
|t10|checkArgument pass about txid| |
|t11| |logStream.flush() (then double buffer will fill will editlog record,
maybe many records here)|
|t12|journalSet.finalizeLogSegment| |
|t13|try to close JournalAndStream but fail since double buffer not | |
|t14|exception and terminate| |
I try to reproduce this issue with Unit test, first try to stop rollEditLog at
{{journalSet.finalizeLogSegment}} in #endCurrentLogSegment, then #logEdit
something and #logSync, after that, resume #rollEditLog, the expect exception
appears.
If this is truth, I am confused that:
1. Why only few report about this issue, IMO, the probability may be high.
2. How to fix that, only invoke #waitForSyncToFinish at the beginning of
#rollEditLog could not be resolved.
Please correct if something I missed, Thanks again.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = null;
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820903#comment-16820903
]
angerszhu commented on HDFS-14437:
--
[~hexiaoqiao] I have seen some version of code, you use 2.7.1, it don't fix
these problem also.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
> //editLogStream may
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820901#comment-16820901
]
angerszhu commented on HDFS-14437:
--
[~hexiaoqiao]
What I'm saying is not very clear, but I found what I have said above is not
all correct .
When I see the function of logSync() it will check myTranctionId with synctxId,
if it's lower to synctxId, it won't do swap and flush. then it will close the
OutputStream and DoubleBuffer. But these time , when the bufCurrent , it may
have edit log write in before last sync or duration flush(). these may happened
before rollEditLog. Just like the sequence:
||Action||Thread1||Thread2||Thread3||
|txnId=1| | |logEdit()|
| | | |logSync.step1|
|txnid=2| |logEdit()|logSync.step2|
|synctnId=1| | |logSync.step3|
| |rollEditlog()| | |
| |endCurrentLogSegment()| | |
| |logSync().step1 -> myTransationId <= synctnId return | | |
| |journalSet.finlizeLogSegment()| | |
| |stream.close() => trigger error| | |
| | | | |
Since autoScheduler Log sync process's step2 don't need lock, so other thread
will have chance to write log. the txid may bigger than synctnId.
When during autoScheduler process, it's sementic is write that it won't flush
the log that has been flushed.
But during #endCurrentLogSegment() process, it will close the DoubleBuffer
directly while logSync() just return .
But when these happends, since txid >= syncTnId, so there may have some
records in bufCurrent.
then cause the error.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820886#comment-16820886
]
star commented on HDFS-14437:
-
Thanks [~hexiaoqiao] . The table really make the issue clearer.
I've tracking FSNamesystem and FSEditLog, found that FSEditLog#rollEditlog
always being called holding fsLock, such as {color:#33}rollEditLog{color},
startRollingUpgrade, finalizeRollingUpgrade in FSNamesystem.
{quote}CheckpointSignature {color:#ffc66d}rollEditLog{color}()
{color:#cc7832}throws {color}IOException {{color:#cc7832}
{color} writeLock(){color:#cc7832};
{color}{color:#cc7832} try {color}{
result =
getFSImage().rollEditLog(getEffectiveLayoutVersion()){color:#cc7832};
{color} } {color:#cc7832}finally {color}{
writeUnlock(operationName){color:#cc7832};
{color} }{color:#cc7832}
{color}{color:#cc7832} return {color}result{color:#cc7832};
{color}}{quote}
FSEditLog#logSync is also called holding fsLock in most file/dir related
operations, such as mkdir, delete. But permission related operation is called
out of fsLock, such as setPermission, setOwner, setAcl.
{quote}{color:#cc7832}void {color}{color:#ffc66d}setPermission{color}(String
src{color:#cc7832}, {color}FsPermission permission) {color:#cc7832}throws
{color}IOException {{color:#cc7832}
{color} writeLock(){color:#cc7832};
{color}{color:#cc7832} try {color}{{color:#cc7832}
{color} auditStat =
FSDirAttrOp.setPermission({color:#9876aa}dir{color}{color:#cc7832},
{color}pc{color:#cc7832}, {color}src{color:#cc7832},
{color}permission){color:#cc7832};
{color} } {color:#cc7832}catch {color}(AccessControlException e)
{{color:#cc7832}
{color} } {color:#cc7832}finally {color}{
writeUnlock(operationName){color:#cc7832};
{color} }
getEditLog().logSync(){color:#cc7832};{color}{color:#cc7832}
{color}}{quote}
Theoretically it will be a race case to cause this issue. Following operations
as table below will reproduce the issue though it seems very difficult.
||Time||Thread1(rollEditlog)||Thread2(somewhat write)||
|t0| |writeUnlock|
|t1|logEdit|-|
|t2|logSyncAll|-|
|t3|-|logSync|
|t4|finalize|-|
|t5|exception and terminate| |
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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()
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820750#comment-16820750
]
He Xiaoqiao commented on HDFS-14437:
[~angerszhuuu], tracking code logic again, and do you mean the following
run-sequence cause this issue?
||Time||Thread1(rollEditlog)||Thread2(somewhat write)||
|t1|logEdit|-|
|t2|logSyncAll|-|
|t3|-|logSync|
|t4|finalize|-|
|t5|exception and terminate| |
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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);
> }
> }
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820742#comment-16820742
]
He Xiaoqiao commented on HDFS-14437:
[~angerszhuuu], Thanks for the ping. It is interesting dig. I think it is OK
here if attach somewhat documents.
I confused detailed explain about #endCurrentLogSegment:
When we invoke #endCurrentLogSegment, it will do all log sync firstly, then
finalize log segment, which are all in synchronized. IIUC, it should guarantee
that edit double-buffer are empty before finalize. Look forward the truth.
Thanks again.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent 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 https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "Could not sync enough journals to persistent storage " +
> "due to " + e.getMessage() + ". " +
> "Unsynced transactions: " + (txid - synctxid);
> LOG.fatal(msg, new Exception());
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820703#comment-16820703
]
angerszhu commented on HDFS-14437:
--
If some one can understand Chinese, can contact with me to chat about this,
since I write some document in Chinese to explain these.
[angers@gmail.com|mailto:angers@gmail.com]
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent but not
> -
>
> Key: HDFS-14437
> URL: https://issues.apache.org/jira/browse/HDFS-14437
> Project: Hadoop HDFS
> Issue Type: Improvement
>Reporter: angerszhu
>Priority: Major
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
>
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820687#comment-16820687
]
angerszhu commented on HDFS-14437:
--
[~yzhangal] [~hexiaoqiao]
hi I have meet this problem too, can you look at my explanation?
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent but not
> -
>
> Key: HDFS-14437
> URL: https://issues.apache.org/jira/browse/HDFS-14437
> Project: Hadoop HDFS
> Issue Type: Improvement
>Reporter: angerszhu
>Priority: Major
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
> //editLogStream may become null,
> //so store a local
[jira] [Commented] (HDFS-14437) Exception happened when rollEditLog expects empty EditsDoubleBuffer.bufCurrent but not
[
https://issues.apache.org/jira/browse/HDFS-14437?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=16820686#comment-16820686
]
angerszhu commented on HDFS-14437:
--
[~kihwal] [~daryn]
Hi both, can your look at my explanation about this issue, since in our
production env, we meet this problem too.
> Exception happened when rollEditLog expects empty
> EditsDoubleBuffer.bufCurrent but not
> -
>
> Key: HDFS-14437
> URL: https://issues.apache.org/jira/browse/HDFS-14437
> Project: Hadoop HDFS
> Issue Type: Improvement
>Reporter: angerszhu
>Priority: Major
>
> For the problem mentioned in https://issues.apache.org/jira/browse/HDFS-10943
> , I have sort the process of write and flush EditLog and some important
> function, I found the in the class FSEditLog class, the close() function
> will call such process like below:
>
> {code:java}
> waitForSyncToFinish();
> endCurrentLogSegment(true);{code}
> since we have gain the object lock in the function close(), so when
> waitForSyncToFish() method return, it mean all logSync job has done and all
> data in bufReady has been flushed out, and since current thread has the lock
> 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 :
>
> {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, logSync()
> * uses a ThreadLocal transaction ID to determine what edit number must
> * be synced to.
> * - The isSyncRunning volatile boolean tracks whether a sync is currently
> * under progress.
> *
> * 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.
> */
> public void logSync() {
> long syncStart = 0;
> // Fetch the transactionId of this thread.
> long mytxid = myTransactionId.get().txid;
>
> boolean sync = false;
> try {
> EditLogOutputStream logStream = 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 <= synctxid) {
> numTransactionsBatchedInSync++;
> if (metrics != null) {
> // Metrics is non-null only when used inside name node
> metrics.incrTransactionsBatchedInSync();
> }
> return;
> }
>
> // now, this thread will do the sync
> syncStart = txid;
> isSyncRunning = true;
> sync = true;
> // swap buffers
> try {
> if (journalSet.isEmpty()) {
> throw new IOException("No journals available to flush");
> }
> editLogStream.setReadyToFlush();
> } catch (IOException e) {
> final String msg =
> "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
> doneWithAutoSyncScheduling();
> }
> //editLogStream may
