Added timing data and more granular stages to SegmentReplicationState #4222

kartg · 2022-08-16T02:23:03Z

Description

This change introduces instrumentation logging that measures the latency of the various stages of segment replication as seen by each replica. Logs have also been added to the source node for checkpoint publishing and checkpoint metadata responses. All logging is currently at the TRACE level.

Signed-off-by: Kartik Ganesh [email protected]

Issues Resolved

Part of #2583

Check List

New functionality includes testing.
- All tests pass
New functionality has been documented.
- New functionality has javadoc added
Commits are signed per the DCO using --signoff

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.
For more information on following Developer Certificate of Origin and signing off your commits, please check here.

github-actions · 2022-08-16T02:48:44Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/1752/
CommitID: 928d9a59d3e86f144c79f61dc36b718b0cff26d0

dreamer-89 · 2022-08-16T02:51:31Z

Looks unrelated, refiring.

 REPRODUCE WITH: ./gradlew ':server:test' --tests "org.opensearch.index.fielddata.SortedSetDVStringFieldDataTests.testSortMissingFirstReverse" -Dtests.seed=9E522164F9706EE1 -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=sv -Dtests.timezone=Pacific/Kwajalein -Druntime.java=17
  2> java.lang.AssertionError: expected:<1201> but was:<1198>

github-actions · 2022-08-16T03:13:55Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/1753/
CommitID: 928d9a59d3e86f144c79f61dc36b718b0cff26d0

dreamer-89 · 2022-08-16T03:18:32Z

Looks like a legit failure. @kartg you may want to look

REPRODUCE WITH: ./gradlew ':server:test' --tests "org.opensearch.indices.replication.SegmentReplicationTargetTests.testFailureResponse_getSegmentFiles" -Dtests.seed=C313BB5FDBB52A99 -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=ms-MY -Dtests.timezone=Asia/Bangkok -Druntime.java=17

org.opensearch.indices.replication.SegmentReplicationTargetTests > testFailureResponse_getSegmentFiles FAILED
    java.lang.AssertionError: can't move replication to stage [DONE]. current stage: [GET_FILES] (expected [FINALIZE_REPLICATION])
        at __randomizedtesting.SeedInfo.seed([C313BB5FDBB52A99:7591A80679BD22D6]:0)
        at org.opensearch.indices.replication.SegmentReplicationState.validateAndSetStage(SegmentReplicationState.java:113)
        at org.opensearch.indices.replication.SegmentReplicationState.setStage(SegmentReplicationState.java:150)
        at org.opensearch.indices.replication.SegmentReplicationTarget.onDone(SegmentReplicationTarget.java:88)
        at org.opensearch.indices.replication.common.ReplicationTarget.markAsDone(ReplicationTarget.java:141)
        at org.opensearch.indices.replication.SegmentReplicationTargetTests.tearDown(SegmentReplicationTargetTests.java:501)

server/src/main/java/org/opensearch/indices/replication/SegmentReplicationState.java

github-actions · 2022-08-16T19:24:32Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/1782/
CommitID: 8dbb9144e4398813213e1a0fe403326e6fab1ffa

server/src/main/java/org/opensearch/indices/replication/SegmentReplicationTarget.java

kartg · 2022-08-16T19:40:29Z

Looks like two flaky test failures:

REPRODUCE WITH: ./gradlew ':server:test' --tests "org.opensearch.action.admin.cluster.node.tasks.ResourceAwareTasksTests.testTaskIdPersistsInThreadContext" -Dtests.seed=EFD06E521F630F36 -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=de-DE -Dtests.timezone=America/Santarem -Druntime.java=17

org.opensearch.action.admin.cluster.node.tasks.ResourceAwareTasksTests > testTaskIdPersistsInThreadContext FAILED
    java.lang.AssertionError: 
    Expected: iterable with items [<1L>] in any order
         but: no match for: <2L>
        at __randomizedtesting.SeedInfo.seed([EFD06E521F630F36:9F72BFDDEAB30CF]:0)
        at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:18)
        at org.junit.Assert.assertThat(Assert.java:964)
        at org.junit.Assert.assertThat(Assert.java:930)
        at org.opensearch.action.admin.cluster.node.tasks.ResourceAwareTasksTests.testTaskIdPersistsInThreadContext(ResourceAwareTasksTests.java:620)

REPRODUCE WITH: ./gradlew ':server:test' --tests "org.opensearch.index.fielddata.SortedSetDVStringFieldDataTests.testSortMissingLast" -Dtests.seed=EFD06E521F630F36 -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=ar-AE -Dtests.timezone=Asia/Muscat -Druntime.java=17

org.opensearch.index.fielddata.SortedSetDVStringFieldDataTests > testSortMissingLast FAILED
    java.lang.AssertionError: expected:<1105> but was:<1085>
        at __randomizedtesting.SeedInfo.seed([EFD06E521F630F36:7AFE1DBA9C25A37]:0)
        at org.junit.Assert.fail(Assert.java:89)
        at org.junit.Assert.failNotEquals(Assert.java:835)

and one legitimate test failure related to segment replication -

REPRODUCE WITH: ./gradlew ':server:test' --tests "org.opensearch.indices.replication.SegmentReplicationTargetServiceTests.testNewCheckpointBehindCurrentCheckpoint" -Dtests.seed=EFD06E521F630F36 -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=sv -Dtests.timezone=Africa/Maputo -Druntime.java=17

org.opensearch.indices.replication.SegmentReplicationTargetServiceTests > testNewCheckpointBehindCurrentCheckpoint FAILED
    com.carrotsearch.randomizedtesting.UncaughtExceptionError: Captured an uncaught exception in thread: Thread[id=135, name=opensearch[org.opensearch.indices.replication.SegmentReplicationTargetServiceTests][generic][T#3], state=RUNNABLE, group=TGRP-SegmentReplicationTargetServiceTests]
        at __randomizedtesting.SeedInfo.seed([EFD06E521F630F36:7513D7183489253A]:0)

        Caused by:
        java.lang.AssertionError: can't move replication to stage [DONE]. current stage: [REPLICATING] (expected [FINALIZE_REPLICATION])
            at __randomizedtesting.SeedInfo.seed([EFD06E521F630F36]:0)
            at org.opensearch.indices.replication.SegmentReplicationState.validateAndSetStage(SegmentReplicationState.java:113)
            at org.opensearch.indices.replication.SegmentReplicationState.setStage(SegmentReplicationState.java:150)
            at org.opensearch.indices.replication.SegmentReplicationTarget.onDone(SegmentReplicationTarget.java:88)
            at org.opensearch.indices.replication.common.ReplicationTarget.markAsDone(ReplicationTarget.java:141)
            at org.opensearch.indices.replication.common.ReplicationCollection.markAsDone(ReplicationCollection.java:202)
            at org.opensearch.indices.replication.SegmentReplicationTargetService$3.onResponse(SegmentReplicationTargetService.java:246)
            at org.opensearch.indices.replication.SegmentReplicationTargetService$3.onResponse(SegmentReplicationTargetService.java:243)
            at org.opensearch.indices.replication.SegmentReplicationTargetServiceTests.lambda$testTargetReturnsSuccess_listenerCompletes$0(SegmentReplicationTargetServiceTests.java:106)

github-actions · 2022-08-16T23:11:43Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/1796/
CommitID: 9b6cbff8f1bfff5745bc0ee6b6137ec0c7dea6d3

kartg · 2022-08-16T23:22:17Z

One failing test, unrelated to segment replication, but i can consistently repro the failure locally with the given seed

REPRODUCE WITH: ./gradlew ':server:test' --tests "org.opensearch.index.fielddata.SortedSetDVStringFieldDataTests.testSortMissingLast" -Dtests.seed=BC7C1431A4F70C5D -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=ga-IE -Dtests.timezone=Europe/Belgrade -Druntime.java=17

org.opensearch.index.fielddata.SortedSetDVStringFieldDataTests > testSortMissingLast FAILED
    java.lang.AssertionError: expected:<1105> but was:<1023>

reta · 2022-08-16T23:35:45Z

One failing test, unrelated to segment replication, but i can consistently repro the failure locally with the given seed

REPRODUCE WITH: ./gradlew ':server:test' --tests "org.opensearch.index.fielddata.SortedSetDVStringFieldDataTests.testSortMissingLast" -Dtests.seed=BC7C1431A4F70C5D -Dtests.security.manager=true -Dtests.jvm.argline="-XX:TieredStopAtLevel=1 -XX:ReservedCodeCacheSize=64m" -Dtests.locale=ga-IE -Dtests.timezone=Europe/Belgrade -Druntime.java=17

org.opensearch.index.fielddata.SortedSetDVStringFieldDataTests > testSortMissingLast FAILED
    java.lang.AssertionError: expected:<1105> but was:<1023>

@kartg could you please create an issue for this flaky test, I suspect it has been introduced in [1], first time spotted there [2]

[1] #4183
[2] #4183 (comment)

github-actions · 2022-08-16T23:43:41Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/1800/
CommitID: 9b6cbff8f1bfff5745bc0ee6b6137ec0c7dea6d3

github-actions · 2022-08-17T00:13:30Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/1802/
CommitID: 9b6cbff8f1bfff5745bc0ee6b6137ec0c7dea6d3

github-actions · 2022-08-17T00:43:25Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/1804/
CommitID: 9b6cbff8f1bfff5745bc0ee6b6137ec0c7dea6d3

github-actions · 2022-08-17T02:47:32Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/1810/
CommitID: 9b6cbff8f1bfff5745bc0ee6b6137ec0c7dea6d3

This change introduces instrumentation logging that measures the latency of the various stages of segment replication as seen by each replica. Logs have also been added to the source node for checkpoint publishing and checkpoint metadata responses. All logging is currently at the TRACE level. Signed-off-by: Kartik Ganesh <[email protected]>

Signed-off-by: Kartik Ganesh <[email protected]>

github-actions · 2022-08-17T03:34:33Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/1814/
CommitID: 9b6cbff8f1bfff5745bc0ee6b6137ec0c7dea6d3

github-actions · 2022-08-17T04:03:45Z

Gradle Check (Jenkins) Run Completed with:

RESULT: UNSTABLE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/1815/
CommitID: c395ac1

github-actions · 2022-08-17T17:15:43Z

Gradle Check (Jenkins) Run Completed with:

RESULT: SUCCESS ✅
URL: https://build.ci.opensearch.org/job/gradle-check/1834/
CommitID: c395ac1

kartg · 2022-08-17T17:20:45Z

@reta @dreamer-89 @mch2 test issues resolved, ready for your 👀

reta · 2022-08-17T18:01:12Z

server/src/main/java/org/opensearch/indices/replication/SegmentReplicationTarget.java

+         * Segments are immutable. So if the replica has any segments with the same name that differ from the one in the incoming
+         * snapshot from source that means the local copy of the segment has been corrupted/changed in some way and we throw an
+         * IllegalStateException to fail the shard
+         */
        if (diff.different.isEmpty() == false) {
            getFilesListener.onFailure(


Certainly an existing code, but it seems like there is a bug here: we don't thrown an exception but call the listener direclty and move on ... @kartg wdyt?

@reta Good catch! We shouldn't be proceeding if the failure listener is invoked. Would you mind if i incorporated the fix for this as a follow-up PR? I'd like to keep the scope of this PR focused on the seg-rep stages and timing data.

reta · 2022-08-17T18:04:07Z

server/src/main/java/org/opensearch/indices/replication/SegmentReplicationTarget.java

        // Get list of files to copy from this checkpoint.
+        state.setStage(SegmentReplicationState.Stage.GET_CHECKPOINT_INFO);
        source.getCheckpointMetadata(getId(), checkpoint, checkpointInfoListener);

        checkpointInfoListener.whenComplete(checkpointInfo -> getFiles(checkpointInfo, getFilesListener), listener::onFailure);


I think there is an issue between stage demarcation and handlng the unhappy path. @kartg please correct me if I am wrong but in case of failure checkpointInfoListener (and others) would delegate to listener::onFailure without marking the current stage as "finished", correct?

Yes, that's a conscious choice. We're treating the DONE stage as a successful replication run. I opted to avoid an explicit FAILED stage since the target and state objects are local to each replication, and the replication stages are currently only relevant when tracking timing data

That's fine (I think), the dangling stage is what concerns me: since we publish timing on success only, we do nothing on failure (we don't even know if stage was run, which could be even more important than success for troubleshooting). In any case, leaving the decision up to you.

mch2

LGTM

…#4222) * Added timing data and more granular stages to SegmentReplicationState This change introduces instrumentation logging that measures the latency of the various stages of segment replication as seen by each replica. Logs have also been added to the source node for checkpoint publishing and checkpoint metadata responses. All logging is currently at the TRACE level. Signed-off-by: Kartik Ganesh <[email protected]> * Fixing SegmentReplicationTarget tests Signed-off-by: Kartik Ganesh <[email protected]> * Incorporated PR feedback Signed-off-by: Kartik Ganesh <[email protected]> * Fixing SegmentReplicationTargetService tests Signed-off-by: Kartik Ganesh <[email protected]> Signed-off-by: Kartik Ganesh <[email protected]> (cherry picked from commit a2ba3a8)

…eplicationState (#4367) * Added timing data and more granular stages to SegmentReplicationState (#4222) * Added timing data and more granular stages to SegmentReplicationState This change introduces instrumentation logging that measures the latency of the various stages of segment replication as seen by each replica. Logs have also been added to the source node for checkpoint publishing and checkpoint metadata responses. All logging is currently at the TRACE level. Signed-off-by: Kartik Ganesh <[email protected]> * Fixing SegmentReplicationTarget tests Signed-off-by: Kartik Ganesh <[email protected]> * Incorporated PR feedback Signed-off-by: Kartik Ganesh <[email protected]> * Fixing SegmentReplicationTargetService tests Signed-off-by: Kartik Ganesh <[email protected]> Signed-off-by: Kartik Ganesh <[email protected]> (cherry picked from commit a2ba3a8) * Update changelog for backport pr. Signed-off-by: Marc Handalian <[email protected]> Signed-off-by: Marc Handalian <[email protected]> Co-authored-by: Kartik Ganesh <[email protected]> Co-authored-by: Marc Handalian <[email protected]>

kartg requested review from a team and reta as code owners August 16, 2022 02:23

dreamer-89 mentioned this pull request Aug 16, 2022

[Segment Replication] Refactor Store.recoveryDiff method #4221

Closed

reta reviewed Aug 16, 2022

View reviewed changes

server/src/main/java/org/opensearch/indices/replication/SegmentReplicationState.java Outdated Show resolved Hide resolved

reta reviewed Aug 16, 2022

View reviewed changes

server/src/main/java/org/opensearch/indices/replication/SegmentReplicationState.java Outdated Show resolved Hide resolved

reta reviewed Aug 16, 2022

View reviewed changes

server/src/main/java/org/opensearch/indices/replication/SegmentReplicationTarget.java Show resolved Hide resolved

reta reviewed Aug 16, 2022

View reviewed changes

server/src/main/java/org/opensearch/indices/replication/SegmentReplicationTarget.java Show resolved Hide resolved

kartg mentioned this pull request Aug 16, 2022

[BUG] Flakey test failure in SortedSetDVStringFieldDataTests testSortMissingLast #4238

Closed

kartg added 4 commits August 16, 2022 20:33

Fixing SegmentReplicationTarget tests

2e3e16c

Signed-off-by: Kartik Ganesh <[email protected]>

Incorporated PR feedback

15da49f

Signed-off-by: Kartik Ganesh <[email protected]>

Fixing SegmentReplicationTargetService tests

c395ac1

Signed-off-by: Kartik Ganesh <[email protected]>

kartg force-pushed the segRepBenchmarking branch from 9b6cbff to c395ac1 Compare August 17, 2022 03:33

kartg requested a review from mch2 August 17, 2022 17:19

reta reviewed Aug 17, 2022

View reviewed changes

mch2 approved these changes Aug 17, 2022

View reviewed changes

reta approved these changes Aug 17, 2022

View reviewed changes

kartg merged commit a2ba3a8 into opensearch-project:main Aug 17, 2022

kartg deleted the segRepBenchmarking branch August 17, 2022 22:28

mch2 added pending backport Identifies an issue or PR that still needs to be backported backport 2.x Backport to 2.x branch labels Sep 1, 2022

opensearch-trigger-bot bot mentioned this pull request Sep 1, 2022

[Backport 2.x] Added timing data and more granular stages to SegmentReplicationState #4367

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Added timing data and more granular stages to SegmentReplicationState #4222

Added timing data and more granular stages to SegmentReplicationState #4222

kartg commented Aug 16, 2022

github-actions bot commented Aug 16, 2022

dreamer-89 commented Aug 16, 2022

github-actions bot commented Aug 16, 2022

dreamer-89 commented Aug 16, 2022

github-actions bot commented Aug 16, 2022

kartg commented Aug 16, 2022

github-actions bot commented Aug 16, 2022

kartg commented Aug 16, 2022

reta commented Aug 16, 2022 •

edited

Loading

github-actions bot commented Aug 16, 2022

github-actions bot commented Aug 17, 2022

github-actions bot commented Aug 17, 2022

github-actions bot commented Aug 17, 2022

github-actions bot commented Aug 17, 2022

github-actions bot commented Aug 17, 2022

github-actions bot commented Aug 17, 2022

kartg commented Aug 17, 2022

reta Aug 17, 2022

kartg Aug 17, 2022

reta Aug 17, 2022

kartg Aug 17, 2022

reta Aug 17, 2022 •

edited

Loading

mch2 left a comment

Added timing data and more granular stages to SegmentReplicationState #4222

Added timing data and more granular stages to SegmentReplicationState #4222

Conversation

kartg commented Aug 16, 2022

Description

Issues Resolved

Check List

github-actions bot commented Aug 16, 2022

Gradle Check (Jenkins) Run Completed with:

dreamer-89 commented Aug 16, 2022

github-actions bot commented Aug 16, 2022

Gradle Check (Jenkins) Run Completed with:

dreamer-89 commented Aug 16, 2022

github-actions bot commented Aug 16, 2022

Gradle Check (Jenkins) Run Completed with:

kartg commented Aug 16, 2022

github-actions bot commented Aug 16, 2022

Gradle Check (Jenkins) Run Completed with:

kartg commented Aug 16, 2022

reta commented Aug 16, 2022 • edited Loading

github-actions bot commented Aug 16, 2022

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Aug 17, 2022

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Aug 17, 2022

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Aug 17, 2022

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Aug 17, 2022

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Aug 17, 2022

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Aug 17, 2022

Gradle Check (Jenkins) Run Completed with:

kartg commented Aug 17, 2022

reta Aug 17, 2022

Choose a reason for hiding this comment

kartg Aug 17, 2022

Choose a reason for hiding this comment

reta Aug 17, 2022

Choose a reason for hiding this comment

kartg Aug 17, 2022

Choose a reason for hiding this comment

reta Aug 17, 2022 • edited Loading

Choose a reason for hiding this comment

mch2 left a comment

Choose a reason for hiding this comment

reta commented Aug 16, 2022 •

edited

Loading

reta Aug 17, 2022 •

edited

Loading