Mitigate controller leadership switch latency - improve leader -> standby

[i3wangyi]

Issues

• My PR addresses the following Helix issues and references them in the PR description:

#661

Description

• Here are some details about my PR, including screenshots of any UI changes:

• The code change will skip the getChildren() request on listener's removal, and the zkClient's unsubscribeAll will be used instead of unsubscribing a single path;

• It also includes some log optimization works.

Tests

• The following tests are written for this issue:

(List the names of added unit/integration tests)
testControllerConnectThenSessionExpire in TestControllerLeaderhshipChange

• The following is the result of the "mvn test" command on the appropriate module:

(Copy & paste the result of "mvn test")
[ERROR] Tests run: 890, Failures: 3, Errors: 0, Skipped: 0, Time elapsed: 3,909.929 s <<< FAILURE! - in TestSuite
[ERROR] testDeleteStoppingStuckWorkflowForcefully(org.apache.helix.integration.task.TestForceDeleteWorkflow) Time elapsed: 60.645 s <<< FAILURE!
java.lang.AssertionError: expected: but was:
at org.apache.helix.integration.task.TestForceDeleteWorkflow.testDeleteStoppingStuckWorkflowForcefully(TestForceDeleteWorkflow.java:279)

[ERROR] testForceDeleteJobFromJobQueue(org.apache.helix.integration.task.TestDeleteJobFromJobQueue) Time elapsed: 0.498 s <<< FAILURE!
org.apache.helix.HelixException: Failed to delete job: testForceDeleteJobFromJobQueue_job2 from queue: testForceDeleteJobFromJobQueue
at org.apache.helix.integration.task.TestDeleteJobFromJobQueue.testForceDeleteJobFromJobQueue(TestDeleteJobFromJobQueue.java:75)

[ERROR] testStateTransitionTimeoutByClusterLevel(org.apache.helix.integration.paticipant.TestStateTransitionTimeoutWithResource) Time elapsed: 38.119 s <<< FAILURE!
java.lang.AssertionError: expected: but was:
at org.apache.helix.integration.paticipant.TestStateTransitionTimeoutWithResource.testStateTransitionTimeoutByClusterLevel(TestStateTransitionTimeoutWithResource.java:196)

[INFO]
[INFO] Results:
[INFO]
[ERROR] Failures:
[ERROR] TestStateTransitionTimeoutWithResource.testStateTransitionTimeoutByClusterLevel:196 expected: but was:
[ERROR] TestDeleteJobFromJobQueue.testForceDeleteJobFromJobQueue:75 » Helix Failed to ...
[ERROR] TestForceDeleteWorkflow.testDeleteStoppingStuckWorkflowForcefully:279 expected: but was:
[INFO]
[ERROR] Tests run: 890, Failures: 3, Errors: 0, Skipped: 0

Failed tests get passed running individually in IDE

Commits

• My commits all reference appropriate Apache Helix GitHub issues in their subject lines, and I have squashed multiple commits if they address the same issue. In addition, my commits follow the guidelines from "How to write a good git commit message":
  1. Subject is separated from body by a blank line
  2. Subject is limited to 50 characters (not including Jira issue reference)
  3. Subject does not end with a period
  4. Subject uses the imperative mood ("add", not "adding")
  5. Body wraps at 72 characters
  6. Body explains "what" and "why", not "how"

Documentation

• In case of new functionality, my PR adds documentation in the following wiki page:

(Link the GitHub wiki you added)

Code Quality

• My diff has been formatted using helix-style.xml

[i3wangyi]

Current Leader -> Standby diagram:

[i3wangyi]

After applying the changes

[junkaixue]

Logically, it sounds good to me. But I think this is not the majority contribution in LeaderSwitch when controller is trying acquiring leadership, right?

How much it reduces the overhead?

[i3wangyi]

Logically, it sounds good to me. But I think this is not the majority contribution in LeaderSwitch when controller is trying acquiring leadership, right?

How much it reduces the overhead?

No, the optimization is only for leader -> standby, one data point shows a 10X latency improvement (from 1700ms -> 170ms); For optimizing the other part of the story: standby -> leader, there're different options, I will explore them later in different PRs.

[junkaixue]

Please add a test for it. I saw you link to #681. Have you tested your change with it?

[jiajunwang]

Why removing these logs? While debugging, how do we know if this listener is configured with what kind of _eventTypes list? Since there are still some concerns or bug reports regarding callbacks, we'd better keep the detail logs.

[i3wangyi]

These logs are actually redundant. The private subscribeForChanges() will eventually call other private methods

  private void subscribeChildChange(String path, NotificationContext.Type callbackType) {
    if (callbackType == NotificationContext.Type.INIT
        || callbackType == NotificationContext.Type.CALLBACK) {
      if (logger.isDebugEnabled()) {
        logger.debug(_manager.getInstanceName() + " subscribes child-change. path: " + path
            + ", listener: " + _listener);
      }
      _zkClient.subscribeChildChanges(path, this);
    } else if (callbackType == NotificationContext.Type.FINALIZE) {
      logger.info(_manager.getInstanceName() + " unsubscribe child-change. path: " + path
          + ", listener: " + _listener);

      _zkClient.unsubscribeChildChanges(path, this);
    }
  }

  private void subscribeDataChange(String path, NotificationContext.Type callbackType) {
    if (callbackType == NotificationContext.Type.INIT
        || callbackType == NotificationContext.Type.CALLBACK) {
      if (logger.isDebugEnabled()) {
        logger.debug(_manager.getInstanceName() + " subscribe data-change. path: " + path
            + ", listener: " + _listener);
      }
      _zkClient.subscribeDataChanges(path, this);
    } else if (callbackType == NotificationContext.Type.FINALIZE) {
      logger.info(_manager.getInstanceName() + " unsubscribe data-change. path: " + path
          + ", listener: " + _listener);

      _zkClient.unsubscribeDataChanges(path, this);
    }
  }

To perform the actual listener subscription. I think keeping the verbose log in the last step is sufficient enough and you know helix.log is flooded with all listeners logs

[jiajunwang]

So we are not sending FINALIZE events on the reset anymore? I think this is problematic.

[i3wangyi]

Yeah. That's the design of using unsubscribeAll. Because the current callback handler's FINALIZE method is pretty expensive (involving read all children node under currentstates then remove them one by one).
I could perform tests that prove without the FINALIZE event, HelixManager could clean up all information when disconnect(). And the single callback handler could still use the FINALIZE event to un-register itself.

[jiajunwang]

The thing is that our customers also depend on the FINALIZE event to do the cleanup. I believe with this change disconnect will clean up all the listeners. But you break the agreement.

[i3wangyi]

@jiajunwang I understand your concern. With the current helix structure & library dependency, many times there's really no easy way to satisfy everything while still keeping the code clean & short IMO, even we overall agree with the overall design here. Let's take it offline.

I will try to resolve rest concerns as much as I could and propose a new draft code structure

[jiajunwang]

Sure, feel free to call for a short meeting with more people. My point is that we shall never trade-off correctness or functionality for performance.

[jiajunwang]

START:INVOKE/END:INVOKE are for the callbacks. Please don't use it here. It will be confusing to whoever debug later.

[jiajunwang]

Besides my concern of not sending FINALIZE, this method is a subset of void reset(boolean isShutdown); I think you can avoid duplicate code.

Of course, please address my concern about not having the FINALIZE first. Then we can revisit this one.