[
https://issues.apache.org/jira/browse/RATIS-1831?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Attila Doroszlai updated RATIS-1831:
------------------------------------
Priority: Critical (was: Major)
> GrpcLogAppender spinning idle between heartbeats
> ------------------------------------------------
>
> Key: RATIS-1831
> URL: https://issues.apache.org/jira/browse/RATIS-1831
> Project: Ratis
> Issue Type: Bug
> Components: gRPC
> Affects Versions: 3.0.0, 2.5.0
> Reporter: Attila Doroszlai
> Assignee: Attila Doroszlai
> Priority: Critical
>
> {code:title=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());
> }
> {code}
> {{GrpcLogAppender}}'s main loop does not wait if there is nothing to be sent
> (last {{return}} in {{getWaitTimeMs}}):
> {code}
> 2023-04-13 10:30:47,058
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(10, 72) -> 10
> 2023-04-13 10:30:47,068
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,068
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,068
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,068
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,068
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(0, 61) -> 0
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 61) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 61) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 61) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 61) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 61) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,069
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-1, 60) -> -1
> 2023-04-13 10:30:47,070
> [s2@group-6BFAB8E011F7->s0-GrpcLogAppender-LogAppenderDaemon] TRACE
> server.GrpcLogAppender (GrpcLogAppender.java:getWaitTimeMs(187)) -
> s2@group-6BFAB8E011F7->s0-GrpcLogAppender: wait min(-2, 60) -> -2
> {code}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
