[
https://issues.apache.org/jira/browse/RATIS-534?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16839560#comment-16839560
]
Hadoop QA commented on RATIS-534:
---------------------------------
| (x) *{color:red}-1 overall{color}* |
\\
\\
|| Vote || Subsystem || Runtime || Comment ||
| {color:blue}0{color} | {color:blue} reexec {color} | {color:blue} 0m
9s{color} | {color:blue} Docker mode activated. {color} |
|| || || || {color:brown} Prechecks {color} ||
| {color:blue}0{color} | {color:blue} findbugs {color} | {color:blue} 0m
0s{color} | {color:blue} Findbugs executables are not available. {color} |
| {color:green}+1{color} | {color:green} @author {color} | {color:green} 0m
0s{color} | {color:green} The patch does not contain any @author tags. {color} |
| {color:red}-1{color} | {color:red} test4tests {color} | {color:red} 0m
0s{color} | {color:red} The patch doesn't appear to include any new or modified
tests. Please justify why no new tests are needed for this patch. Also please
list what manual steps were performed to verify this patch. {color} |
|| || || || {color:brown} master Compile Tests {color} ||
| {color:green}+1{color} | {color:green} mvninstall {color} | {color:green} 3m
8s{color} | {color:green} master passed {color} |
| {color:green}+1{color} | {color:green} compile {color} | {color:green} 1m
0s{color} | {color:green} master passed {color} |
| {color:green}+1{color} | {color:green} checkstyle {color} | {color:green} 0m
20s{color} | {color:green} master passed {color} |
| {color:green}+1{color} | {color:green} javadoc {color} | {color:green} 0m
49s{color} | {color:green} master passed {color} |
|| || || || {color:brown} Patch Compile Tests {color} ||
| {color:green}+1{color} | {color:green} mvninstall {color} | {color:green} 1m
7s{color} | {color:green} the patch passed {color} |
| {color:green}+1{color} | {color:green} compile {color} | {color:green} 1m
4s{color} | {color:green} the patch passed {color} |
| {color:green}+1{color} | {color:green} javac {color} | {color:green} 1m
4s{color} | {color:green} the patch passed {color} |
| {color:green}+1{color} | {color:green} checkstyle {color} | {color:green} 0m
13s{color} | {color:green} the patch passed {color} |
| {color:green}+1{color} | {color:green} whitespace {color} | {color:green} 0m
0s{color} | {color:green} The patch has no whitespace issues. {color} |
| {color:green}+1{color} | {color:green} javadoc {color} | {color:green} 0m
41s{color} | {color:green} the patch passed {color} |
|| || || || {color:brown} Other Tests {color} ||
| {color:red}-1{color} | {color:red} unit {color} | {color:red} 14m 35s{color}
| {color:red} root in the patch failed. {color} |
| {color:green}+1{color} | {color:green} asflicense {color} | {color:green} 0m
18s{color} | {color:green} The patch does not generate ASF License warnings.
{color} |
| {color:black}{color} | {color:black} {color} | {color:black} 23m 36s{color} |
{color:black} {color} |
\\
\\
|| Reason || Tests ||
| Failed junit tests | ratis.server.simulation.TestGroupInfoWithSimulatedRpc |
\\
\\
|| Subsystem || Report/Notes ||
| Docker | Client=17.05.0-ce Server=17.05.0-ce Image:yetus/ratis:date2019-05-14
|
| JIRA Issue | RATIS-534 |
| JIRA Patch URL |
https://issues.apache.org/jira/secure/attachment/12968683/RATIS-534.003.patch |
| Optional Tests | dupname asflicense javac javadoc unit findbugs
checkstyle compile |
| uname | Linux 69d247c8a533 4.4.0-139-generic #165~14.04.1-Ubuntu SMP Wed Oct
31 10:55:11 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux |
| Build tool | maven |
| Personality |
/home/jenkins/jenkins-slave/workspace/PreCommit-RATIS-Build/yetus-personality.sh
|
| git revision | master / 21d7526 |
| maven | version: Apache Maven 3.6.0
(97c98ec64a1fdfee7767ce5ffb20918da4f719f3; 2018-10-24T18:41:47Z) |
| Default Java | 1.8.0_191 |
| unit |
https://builds.apache.org/job/PreCommit-RATIS-Build/766/artifact/out/patch-unit-root.txt
|
| Test Results |
https://builds.apache.org/job/PreCommit-RATIS-Build/766/testReport/ |
| Max. process+thread count | 2467 (vs. ulimit of 5000) |
| modules | C: ratis-grpc U: ratis-grpc |
| Console output |
https://builds.apache.org/job/PreCommit-RATIS-Build/766/console |
| Powered by | Apache Yetus 0.8.0 http://yetus.apache.org |
This message was automatically generated.
> Leader reelection due to JVM GC pauses
> --------------------------------------
>
> Key: RATIS-534
> URL: https://issues.apache.org/jira/browse/RATIS-534
> Project: Ratis
> Issue Type: Bug
> Reporter: Lokesh Jain
> Assignee: Lokesh Jain
> Priority: Major
> Attachments: RATIS-534.001.patch, RATIS-534.002.patch,
> RATIS-534.003.patch
>
>
> Due to JVM GC pauses a follower is not able to process the append entries and
> as a result turns into a candidate. This leads to leader reelection. Below
> are the logs illustrating the scenario.
> Below are the leader ratis logs. The leader sends heartbeat to follower after
> every 500ms.
> {code:java}
> 2019-04-23 18:34:46,360 INFO org.apache.ratis.grpc.server.GrpcLogAppender:
> 5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:group-80F1E6232C38 APPENDER
> GrpcLogAppender(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16 ->
> eaa2a877-0e7f-44f3-a514-12243ce2b925) appendRequest=leaderTerm=2,
> previousLog=term: 2
> index: 211601
> , leaderCommit=211601, commits:
> [5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:c211601,
> 187c2006-dc9e-40c7-b3e7-ca32b0c3ef45:c211601,
> eaa2a877-0e7f-44f3-a514-12243ce2b925:c211601], entries: []
> 2019-04-23 18:34:46,360 INFO org.apache.ratis.grpc.server.GrpcLogAppender:
> 5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:group-80F1E6232C38 APPENDER
> GrpcLogAppender(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16 ->
> eaa2a877-0e7f-44f3-a514-12243ce2b925) wait 500ms
> 2019-04-23 18:34:46,862 INFO org.apache.ratis.grpc.server.GrpcLogAppender:
> 5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:group-80F1E6232C38 APPENDER
> GrpcLogAppender(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16 ->
> eaa2a877-0e7f-44f3-a514-12243ce2b925) appendRequest=leaderTerm=2,
> previousLog=term: 2
> index: 211601
> , leaderCommit=211601, commits:
> [5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:c211601,
> 187c2006-dc9e-40c7-b3e7-ca32b0c3ef45:c211601,
> eaa2a877-0e7f-44f3-a514-12243ce2b925:c211601], entries: []
> 2019-04-23 18:34:46,862 INFO org.apache.ratis.grpc.server.GrpcLogAppender:
> 5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:group-80F1E6232C38 APPENDER
> GrpcLogAppender(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16 ->
> eaa2a877-0e7f-44f3-a514-12243ce2b925) wait 500ms
> 2019-04-23 18:34:47,362 INFO org.apache.ratis.grpc.server.GrpcLogAppender:
> 5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:group-80F1E6232C38 APPENDER
> GrpcLogAppender(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16 ->
> eaa2a877-0e7f-44f3-a514-12243ce2b925) appendRequest=leaderTerm=2,
> previousLog=term: 2
> index: 211601
> , leaderCommit=211601, commits:
> [5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:c211601,
> 187c2006-dc9e-40c7-b3e7-ca32b0c3ef45:c211601,
> eaa2a877-0e7f-44f3-a514-12243ce2b925:c211601], entries: []
> 2019-04-23 18:34:47,362 INFO org.apache.ratis.grpc.server.GrpcLogAppender:
> 5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:group-80F1E6232C38 APPENDER
> GrpcLogAppender(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16 ->
> eaa2a877-0e7f-44f3-a514-12243ce2b925) wait 500ms
> 2019-04-23 18:34:47,862 INFO org.apache.ratis.grpc.server.GrpcLogAppender:
> 5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:group-80F1E6232C38 APPENDER
> GrpcLogAppender(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16 ->
> eaa2a877-0e7f-44f3-a514-12243ce2b925) appendRequest=leaderTerm=2,
> previousLog=term: 2
> index: 211601
> , leaderCommit=211601, commits:
> [5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:c211601,
> 187c2006-dc9e-40c7-b3e7-ca32b0c3ef45:c211601,
> eaa2a877-0e7f-44f3-a514-12243ce2b925:c211601], entries: []
> 2019-04-23 18:34:47,863 INFO org.apache.ratis.grpc.server.GrpcLogAppender:
> 5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:group-80F1E6232C38 APPENDER
> GrpcLogAppender(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16 ->
> eaa2a877-0e7f-44f3-a514-12243ce2b925) wait 500ms
> 2019-04-23 18:34:48,363 INFO org.apache.ratis.grpc.server.GrpcLogAppender:
> 5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:group-80F1E6232C38 APPENDER
> GrpcLogAppender(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16 ->
> eaa2a877-0e7f-44f3-a514-12243ce2b925) appendRequest=leaderTerm=2,
> previousLog=term: 2
> index: 211601
> , leaderCommit=211601, commits:
> [5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:c211601,
> 187c2006-dc9e-40c7-b3e7-ca32b0c3ef45:c211601,
> eaa2a877-0e7f-44f3-a514-12243ce2b925:c211601], entries: []
> 2019-04-23 18:34:48,363 INFO org.apache.ratis.grpc.server.GrpcLogAppender:
> 5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:group-80F1E6232C38 APPENDER
> GrpcLogAppender(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16 ->
> eaa2a877-0e7f-44f3-a514-12243ce2b925) wait 500ms
> {code}
> Below are the follower logs showing a GC pause.
> {code:java}
> 2019-04-23 18:34:46,361 INFO org.apache.ratis.server.impl.RaftServerImpl:
> eaa2a877-0e7f-44f3-a514-12243ce2b925:group-80F1E6232C38 HEARTBEAT:
> eaa2a877-0e7f-44f3-a514-12243ce2b925: receive
> appendEntries(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16, 2, (t:2, i:211601),
> 211601, false, commits[5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:c211601,
> 187c2006-dc9e-40c7-b3e7-ca32b0c3ef45:c211601,
> eaa2a877-0e7f-44f3-a514-12243ce2b925:c211601], entries: []
> 2019-04-23 18:34:46,362 INFO org.apache.ratis.server.impl.RaftServerImpl:
> eaa2a877-0e7f-44f3-a514-12243ce2b925:group-80F1E6232C38 HEARTBEAT:
> eaa2a877-0e7f-44f3-a514-12243ce2b925: succeeded to handle AppendEntries.
> Reply:
> 5c400f35-d7ba-4911-8cd3-7ceb48e2ef16->eaa2a877-0e7f-44f3-a514-12243ce2b925,true,SUCCESS,nextIndex:211602,term:2,followerCommit:211601
> 2019-04-23 18:34:48,583 INFO org.apache.ratis.server.impl.FollowerState:
> eaa2a877-0e7f-44f3-a514-12243ce2b925:group-80F1E6232C38 changes to CANDIDATE,
> lastRpcTime:2221, electionTimeout:1124ms
> 2019-04-23 18:34:48,583 INFO org.apache.ratis.server.impl.RoleInfo:
> eaa2a877-0e7f-44f3-a514-12243ce2b925: shutdown FollowerState
> 2019-04-23 18:34:48,583 INFO org.apache.ratis.server.impl.RaftServerImpl:
> eaa2a877-0e7f-44f3-a514-12243ce2b925:group-80F1E6232C38 changes role from
> FOLLOWER to CANDIDATE at term 2 for changeToCandidate
> 2019-04-23 18:34:48,583 INFO org.apache.ratis.server.impl.RaftServerImpl:
> eaa2a877-0e7f-44f3-a514-12243ce2b925:group-80F1E6232C38 HEARTBEAT:
> eaa2a877-0e7f-44f3-a514-12243ce2b925: receive
> appendEntries(5c400f35-d7ba-4911-8cd3-7ceb48e2ef16, 2, (t:2, i:211601),
> 211601, false, commits[5c400f35-d7ba-4911-8cd3-7ceb48e2ef16:c211601,
> 187c2006-dc9e-40c7-b3e7-ca32b0c3ef45:c211601,
> eaa2a877-0e7f-44f3-a514-12243ce2b925:c211601], entries: []
> 2019-04-23 18:34:48,583 INFO org.apache.hadoop.util.JvmPauseMonitor: Detected
> pause in JVM or host machine (eg GC): pause of approximately 1774ms
> GC pool 'PS MarkSweep' had collection(s): count=1 time=1359ms
> GC pool 'PS Scavenge' had collection(s): count=1 time=532ms
> 2019-04-23 18:34:48,583 INFO org.apache.ratis.server.impl.RoleInfo:
> eaa2a877-0e7f-44f3-a514-12243ce2b925: start LeaderElection
> 2019-04-23 18:34:48,598 INFO org.apache.ratis.server.impl.RaftServerImpl:
> eaa2a877-0e7f-44f3-a514-12243ce2b925:group-80F1E6232C38 changes role from
> CANDIDATE to FOLLOWER at term 2 for appendEntries
> 2019-04-23 18:34:48,598 INFO org.apache.ratis.server.impl.RoleInfo:
> eaa2a877-0e7f-44f3-a514-12243ce2b925: shutdown LeaderElection
> {code}
> There is a GC pause of approx. 2 seconds which causes the leader election to
> start in the follower.
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
