Uploaded image for project: 'Ratis'
  1. Ratis
  2. RATIS-1831

GrpcLogAppender spinning idle between heartbeats

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Critical
    • Resolution: Fixed
    • 3.0.0, 2.5.0
    • 3.0.0, 2.5.1
    • gRPC
    • None

    Description

      https://github.com/apache/ratis/blob/a9036487c5f09e8f1132be9655eb54a177573e7c/ratis-grpc/src/main/java/org/apache/ratis/grpc/server/GrpcLogAppender.java#L173-L183
        public long getWaitTimeMs() {
    if (haveTooManyPendingRequests()) {
      return getHeartbeatWaitTimeMs(); // Should wait for a short time
    } else if (shouldSendAppendEntries() && !isSlowFollower()) {
      // For normal nodes, new entries should be sent ASAP
      // however for slow followers (especially when the follower is down),
      // keep sending without any wait time only ends up in high CPU load
      return Math.max(getMinWaitTimeMs(), 0L);
    }
    return Math.min(getMinWaitTimeMs(), getHeartbeatWaitTimeMs());
  }

      GrpcLogAppender's main loop does not wait if there is nothing to be sent or follower is slow (last return in getWaitTimeMs):

      (GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(10, 72) -> 10
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 61) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 61) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 61) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 61) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 61) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 60) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 60) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 60) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 60) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 60) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 60) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 60) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 59) -> -2
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 59) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 59) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 59) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3
(GrpcLogAppender.java:getWaitTimeMs(187)) - s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-3, 58) -> -3

      Attachments

        Issue Links

          Discovered while testing

          Task - A task that needs to be done. HDDS-8382 Upgrade Ratis to 2.5.1

          • Critical - Crashes, loss of data, severe memory leak.
          • Resolved
          is caused by

          Improvement - An improvement or enhancement to an existing feature or task. RATIS-1793 Enforce raft.server.log.appender.wait-time.min

          • Major - Major loss of function.
          • Resolved
          links to

          Web Link GitHub Pull Request #872

          Activity

            People

              adoroszlai Attila Doroszlai
              adoroszlai Attila Doroszlai
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 50m
                  50m