Skip to content

HDFS-16143. Add Timer in EditLogTailer and de-flake TestEditLogTailer#testStandbyTriggersLogRollsWhenTailInProgressEdits #3235

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
liuml07 merged 5 commits into from
Aug 26, 2021
Merged

HDFS-16143. Add Timer in EditLogTailer and de-flake TestEditLogTailer#testStandbyTriggersLogRollsWhenTailInProgressEdits #3235

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
b5554b6
HDFS-16143. De-flake TestEditLogTailer#testStandbyTriggersLogRollsWhe…
virajjasani Jul 26, 2021
d5d2db7
addressing comments
virajjasani Aug 2, 2021
f21efea
addressing latest review comments
virajjasani Aug 21, 2021
3720dec
minor change
virajjasani Aug 22, 2021
c18b3d3
addressing review on renaming to insufficientTimeForLogRoll
virajjasani Aug 23, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
17 changes: 9 additions & 8 deletions ...ct/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/namenode/ha/EditLogTailer.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -179,7 +179,7 @@ public EditLogTailer(FSNamesystem namesystem, Configuration conf) {
this.editLog = namesystem.getEditLog();

lastLoadTimeMs = monotonicNow();
lastRollTimeMs = monotonicNow();
resetLastRollTimeMs();

logRollPeriodMs = conf.getTimeDuration(
DFSConfigKeys.DFS_HA_LOGROLL_PERIOD_KEY,
Expand Down Expand Up @@ -423,21 +423,22 @@ void triggerActiveLogRoll() {
try {
future = rollEditsRpcExecutor.submit(getNameNodeProxy());
future.get(rollEditsTimeoutMs, TimeUnit.MILLISECONDS);
lastRollTimeMs = monotonicNow();
resetLastRollTimeMs();
lastRollTriggerTxId = lastLoadedTxnId;
} catch (ExecutionException e) {
} catch (ExecutionException | InterruptedException e) {
LOG.warn("Unable to trigger a roll of the active NN", e);
} catch (TimeoutException e) {
if (future != null) {
future.cancel(true);
}
future.cancel(true);
Copy link
Contributor

@xkrogen xkrogen Jul 30, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why is the null-check removed here?

Copy link
Contributor Author

@virajjasani virajjasani Jul 31, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because future will never be null here. The only way we can reach here is by catching TimeoutException and TimeoutException can only occur here because of future.get(rollEditsTimeoutMs, TimeUnit.MILLISECONDS), hence we don't need null-check.

Copy link
Contributor

@xkrogen xkrogen Aug 2, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I see. Both ExecutionException and InterruptedException will also only be thrown by Future#get, so I think the try-catch should probably look like:

Future<Void> future = rollEditsRpcExecutor.submit(getNameNodeProxy());
try {
  future.get(....)
  ...
} catch (...) {
  ...
}

This will make it more clear why future will not be null when we get into the catch block.

Copy link
Contributor

@xkrogen xkrogen Aug 2, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But also this is unrelated to this JIRA, can you put up a separate JIRA/PR for it? Particular since this JIRA is just aimed at fixing test flakiness, it's better to minimize any production code changes.

LOG.warn(String.format(
"Unable to finish rolling edits in %d ms", rollEditsTimeoutMs));
} catch (InterruptedException e) {
LOG.warn("Unable to trigger a roll of the active NN", e);
}
}

@VisibleForTesting
public void resetLastRollTimeMs() {
Copy link
Contributor

@xkrogen xkrogen Jul 30, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

package-private instead of public?

this.lastRollTimeMs = monotonicNow();
}

@VisibleForTesting
void sleep(long sleepTimeMillis) throws InterruptedException {
Thread.sleep(sleepTimeMillis);
Expand Down
60 changes: 37 additions & 23 deletions ...adoop-hdfs/src/test/java/org/apache/hadoop/hdfs/server/namenode/ha/TestEditLogTailer.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -394,13 +394,20 @@ public void testStandbyTriggersLogRollsWhenTailInProgressEdits()
// Time in seconds to wait before checking if edit logs are rolled while
// expecting no edit log roll
final int noLogRollWaitTime = 2;

// Time in seconds to wait before checking if edit logs are rolled while
// expecting edit log roll
final int logRollWaitTime = 3;
// expecting edit log roll.
// Aggressive tests like this one are resource sensitive and bound to
// fail with slow system, hence waiting to confirm
// curSegmentTxId for 7 seconds makes it more reliable in case
// EditLogTailer#doWork() takes few more milliseconds to retrieve result
// from EditLogTailer#triggerActiveLogRoll() and lastRollTimeMs is not
// updated frequently.
final int logRollWaitTime = 7;

Configuration conf = getConf();
conf.setInt(DFSConfigKeys.DFS_HA_LOGROLL_PERIOD_KEY,
standbyCatchupWaitTime + noLogRollWaitTime + 1);
standbyCatchupWaitTime + noLogRollWaitTime + 2);
conf.setInt(DFSConfigKeys.DFS_HA_TAILEDITS_PERIOD_KEY, 1);
conf.setBoolean(DFSConfigKeys.DFS_HA_TAILEDITS_INPROGRESS_KEY, true);

Expand Down Expand Up @@ -433,15 +440,28 @@ public void testStandbyTriggersLogRollsWhenTailInProgressEdits()
NameNodeAdapter.mkdirs(active, getDirPath(i),
new PermissionStatus("test", "test",
new FsPermission((short)00755)), true);
// reset lastRollTimeMs in EditLogTailer.
active.getNamesystem().getEditLogTailer().resetLastRollTimeMs();
Copy link
Contributor

@jojochuang jojochuang Jul 30, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

mind to explain when this is needed?

Copy link
Contributor Author

@virajjasani virajjasani Jul 30, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for taking a look @jojochuang.
EditLogTailer has a thread that keeps running to identify when is the right time to trigger log rolling by calling Active Namenode's rollEditLog() API.

    private void doWork() {
      long currentSleepTimeMs = sleepTimeMs;
      while (shouldRun) {
        long editsTailed  = 0;
        try {
          // There's no point in triggering a log roll if the Standby hasn't
          // read any more transactions since the last time a roll was
          // triggered.
          boolean triggeredLogRoll = false;
          if (tooLongSinceLastLoad() &&
              lastRollTriggerTxId < lastLoadedTxnId) {
            triggerActiveLogRoll();
            triggeredLogRoll = true;
          }
...
...

What happens with this test is that by the time we create new dirs in this for loop, this active thread would keep checking and intermittently keep triggering log roll by making RPC calls to Active Namenode, and hence this test would become flaky because the test expects Standby Namenode's last applied txn id to be less than active Namenode's last written txn id within a specific time duration (this is the only reason behind it's flakiness). When it comes to how long EditLogTailer's thread keeps waiting to trigger log roll, it depends on lastRollTimeMs.

In the above code, tooLongSinceLastLoad() refers to:

  /**
   * @return true if the configured log roll period has elapsed.
   */
  private boolean tooLongSinceLastLoad() {
    return logRollPeriodMs >= 0 && 
      (monotonicNow() - lastRollTimeMs) > logRollPeriodMs;
  }

Hence, until lastRollTimeMs worth of time is elapsed, log roll would not be tailed, however, this always tends to be flaky because we have no control over how much time mkdir calls in this for loop is going to take and in that meantime, lastRollTimeMs worth of time can be elapsed easily, hence this test is flaky. When we expect Standby Namenode's txnId to be less than that of Active Namenode, it is not the case because log is rolled by above thread in EditLogTailer.

Hence, it is important for this test to keep resetting lastRollTimeMs while mkdir calls are getting executed so that we don't give chance for tooLongSinceLastLoad() to be successful until we want it to be successful.

Copy link
Contributor Author

@virajjasani virajjasani Jul 30, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FYI @xkrogen @ayushtkn if you have some bandwidth and would like to take a look.
Thanks

}

boolean exceptionThrown = false;
// We should explicitly update lastRollTimeMs in EditLogTailer
// so that our timeout test provided just below can take advantage
// of validation: (monotonicNow() - lastRollTimeMs) > logRollPeriodMs
// provided in EditLogTailer#tooLongSinceLastLoad().
active.getNamesystem().getEditLogTailer().resetLastRollTimeMs();
Copy link
Contributor

@xkrogen xkrogen Jul 30, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

if you just updated the last roll time on L444 above, why do we need to do it again?


try {
checkForLogRoll(active, origTxId, noLogRollWaitTime);
// Aggressive checks like this one are resource sensitive and bound to
// fail with slow system, hence waiting to confirm
// curSegmentTxId for (noLogRollWaitTime - 1) seconds
// makes it more reliable in case EditLogTailer#doWork() takes few
// more milliseconds to retrieve result from
// EditLogTailer#triggerActiveLogRoll().
checkForLogRoll(active, origTxId, noLogRollWaitTime - 1);
fail("Expected to timeout");
} catch (TimeoutException e) {
exceptionThrown = true;
// expected
}
assertTrue(exceptionThrown);

checkForLogRoll(active, origTxId, logRollWaitTime);
} finally {
Expand All @@ -452,26 +472,20 @@ public void testStandbyTriggersLogRollsWhenTailInProgressEdits()
private static void waitForStandbyToCatchUpWithInProgressEdits(
final NameNode standby, final long activeTxId,
int maxWaitSec) throws Exception {
GenericTestUtils.waitFor(new Supplier<Boolean>() {
@Override
public Boolean get() {
long standbyTxId = standby.getNamesystem().getFSImage()
.getLastAppliedTxId();
return (standbyTxId >= activeTxId);
}
}, 100, maxWaitSec * 1000);
GenericTestUtils.waitFor(() -> {
long standbyTxId = standby.getNamesystem().getFSImage()
.getLastAppliedTxId();
return (standbyTxId >= activeTxId);
}, 100, TimeUnit.SECONDS.toMillis(maxWaitSec));
}

private static void checkForLogRoll(final NameNode active,
final long origTxId, int maxWaitSec) throws Exception {
GenericTestUtils.waitFor(new Supplier<Boolean>() {
@Override
public Boolean get() {
long curSegmentTxId = active.getNamesystem().getFSImage().getEditLog()
.getCurSegmentTxId();
return (origTxId != curSegmentTxId);
}
}, 100, maxWaitSec * 1000);
GenericTestUtils.waitFor(() -> {
long curSegmentTxId = active.getNamesystem().getFSImage().getEditLog()
.getCurSegmentTxId();
return (origTxId != curSegmentTxId);
}, 500, TimeUnit.SECONDS.toMillis(maxWaitSec));
Copy link
Contributor

@xkrogen xkrogen Jul 30, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why is the check interval increased from 100ms to 500ms?

Copy link
Contributor Author

@virajjasani virajjasani Jul 31, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think checking above condition every 100ms is too aggressive, keeping it to 500ms is less aggressive and quite enough for both of our tests: a) timeout during verification b) successful verification of Standby NN's txnId.
However, now that we are going to add Timer implementation, it's better to keep it as is.

}

private static MiniDFSCluster createMiniDFSCluster(Configuration conf,
Expand Down