[Fix] Replace cached time with system clock in MasterService debug logs #7902

sandeshkr419 · 2023-06-02T20:30:05Z

Description

Cached Time gives imprecise duration in computing multiple computation time since it caches every 200ms and multiple operation in MasterService regarding cluster state creation, update, publish require time frames less than 200ms during debugging. So changing the computation time to consume System.nanotime() to get clock time instead of cached time. This is essential when debug logs are enabled - else this is not logged by default.

Before:

[2023-05-31T11:38:34,142][DEBUG][o.o.c.s.MasterService    ] [master1] took [0s] to compute cluster state update for [index-aliases]
[2023-05-31T11:38:34,307][DEBUG][o.o.c.s.MasterService    ] [master1] took [0s] to notify listeners on successful publication of cluster state (version: 55109, uuid: Fc58ns6mRHCNuxcvADvfOg) for [index-aliases]
[2023-05-31T11:38:32,416][DEBUG][o.o.c.s.MasterService    ] [master1] took [0s] to compute cluster state update for [cluster_reroute(reroute after starting shards)]
[2023-05-31T11:38:32,416][DEBUG][o.o.c.s.MasterService    ] [master1] took [0s] to notify listeners on unchanged cluster state for [cluster_reroute(reroute after starting shards)]
[2023-05-31T11:38:34,307][DEBUG][o.o.c.s.MasterService    ] [master1] took [0s] to notify listeners on successful publication of cluster state (version: 55109, uuid: Fc58ns6mRHCNuxcvADvfOg) for [index-aliases]

After:

[2023-06-02T12:28:49,551][DEBUG][o.o.c.s.MasterService    ] [master1] took [2ms] to notify listeners on unchanged cluster state for [index-aliases]
[2023-06-02T13:10:17,855][DEBUG][o.o.c.s.MasterService    ] [master1] took [93ms] to compute cluster state update for [index-aliases]
[2023-06-02T13:10:47,875][DEBUG][o.o.c.s.MasterService    ] [master1] executing cluster state update for [index-aliases]
[2023-06-02T13:10:47,876][DEBUG][o.o.c.s.MasterService    ] [master1] took [0s] to compute cluster state update for [index-aliases]
[2023-06-02T13:10:47,877][DEBUG][o.o.c.s.MasterService    ] [master1] took [0s] to notify listeners on unchanged cluster state for [index-aliases]
[2023-06-02T13:34:24,247][DEBUG][o.o.c.s.MasterService    ] [master1] took [0s] to notify listeners on successful publication of cluster state (version: 60931, uuid: G8fs82mZROGv4C0ufnehKA) for [index-aliases]

Related Issues

Resolves #7849

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
Commit changes are listed out in CHANGELOG.md file (See: Changelog)

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 · 2023-06-02T20:58:56Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/16767/
CommitID: dd26f70
Please examine the workflow log, locate, and copy-paste the failure(s) below, then iterate to green.
Is the failure a flaky test unrelated to your change?

github-actions · 2023-06-02T21:02:57Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/16768/
CommitID: 80e6027
Please examine the workflow log, locate, and copy-paste the failure(s) below, then iterate to green.
Is the failure a flaky test unrelated to your change?

github-actions · 2023-06-02T21:46:16Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/16775/
CommitID: 80e6027
Please examine the workflow log, locate, and copy-paste the failure(s) below, then iterate to green.
Is the failure a flaky test unrelated to your change?

andrross · 2023-06-05T21:30:12Z

Looks like some tests are failing?

CHANGELOG.md

shwetathareja · 2023-06-06T06:46:50Z

We should change ClusterApplierService class as well.

OpenSearch/server/src/main/java/org/opensearch/cluster/service/ClusterApplierService.java

Line 715 in aa21585

return threadPool.relativeTimeInMillis();

Bukhtawar

I would want us to double click on this to see if we really need this accuracy. Based on my understanding we are simply using this for debugging. What are the actionable items if these numbers stack around few seconds lets say.

server/src/main/java/org/opensearch/cluster/service/MasterService.java

server/src/test/java/org/opensearch/cluster/service/MasterServiceTests.java

Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com>

github-actions · 2023-06-19T05:04:56Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/17869/
CommitID: 08d0289
Please examine the workflow log, locate, and copy-paste the failure(s) below, then iterate to green.
Is the failure a flaky test unrelated to your change?

github-actions · 2023-06-19T05:16:27Z

Gradle Check (Jenkins) Run Completed with:

RESULT: UNSTABLE ❕
TEST FAILURES:

      3 org.opensearch.remotestore.RemoteStoreRefreshListenerIT.testRemoteRefreshRetryOnFailure
      1 org.opensearch.search.backpressure.SearchBackpressureIT.testSearchShardTaskCancellationWithHighCpu

URL: https://build.ci.opensearch.org/job/gradle-check/17871/
CommitID: 38905fa
Please review all flaky tests that succeeded after retry and create an issue if one does not already exist to track the flaky failure.

server/src/main/java/org/opensearch/threadpool/ThreadPool.java

Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com>

github-actions · 2023-06-28T21:16:10Z

Gradle Check (Jenkins) Run Completed with:

RESULT: UNSTABLE ❕
TEST FAILURES:

      1 org.opensearch.remotestore.SegmentReplicationUsingRemoteStoreIT.testNodeDropWithOngoingReplication
      1 org.opensearch.indices.replication.SegmentReplicationRelocationIT.testPrimaryRelocationWithSegRepFailure

URL: https://build.ci.opensearch.org/job/gradle-check/18610/
CommitID: fe67c1c
Please review all flaky tests that succeeded after retry and create an issue if one does not already exist to track the flaky failure.

dblock · 2023-06-28T23:06:07Z

@andrross want to take a look at the updated version? much appreciated

Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com>

github-actions · 2023-06-29T00:30:42Z

Gradle Check (Jenkins) Run Completed with:

RESULT: UNSTABLE ❕
TEST FAILURES:

      1 org.opensearch.snapshots.RestoreSnapshotIT.testRestoreInSameRemoteStoreEnabledIndex
      1 org.opensearch.remotestore.SegmentReplicationUsingRemoteStoreIT.testNodeDropWithOngoingReplication
      1 org.opensearch.cluster.allocation.AwarenessAllocationIT.testThreeZoneOneReplicaWithForceZoneValueAndLoadAwareness

URL: https://build.ci.opensearch.org/job/gradle-check/18630/
CommitID: 837f130
Please review all flaky tests that succeeded after retry and create an issue if one does not already exist to track the flaky failure.

Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com>

github-actions · 2023-06-29T07:00:24Z

Gradle Check (Jenkins) Run Completed with:

RESULT: FAILURE ❌
URL: https://build.ci.opensearch.org/job/gradle-check/18662/
CommitID: c054d08
Please examine the workflow log, locate, and copy-paste the failure(s) below, then iterate to green.
Is the failure a flaky test unrelated to your change?

github-actions · 2023-06-29T08:04:33Z

Gradle Check (Jenkins) Run Completed with:

RESULT: UNSTABLE ❕
TEST FAILURES:

      2 org.opensearch.remotestore.SegmentReplicationUsingRemoteStoreIT.testNodeDropWithOngoingReplication
      2 org.opensearch.remotestore.SegmentReplicationRemoteStoreIT.classMethod
      1 org.opensearch.remotestore.SegmentReplicationUsingRemoteStoreIT.testDropPrimaryDuringReplication
      1 org.opensearch.remotestore.SegmentReplicationRemoteStoreIT.testIndexReopenClose

URL: https://build.ci.opensearch.org/job/gradle-check/18667/
CommitID: c054d08
Please review all flaky tests that succeeded after retry and create an issue if one does not already exist to track the flaky failure.

opensearch-trigger-bot · 2023-06-29T15:33:01Z

The backport to 2.x failed:

The process '/usr/bin/git' failed with exit code 128

To backport manually, run these commands in your terminal:

# Fetch latest updates from GitHub
git fetch
# Create a new working tree
git worktree add ../.worktrees/backport-2.x 2.x
# Navigate to the new working tree
pushd ../.worktrees/backport-2.x
# Create a new branch
git switch --create backport/backport-7902-to-2.x
# Cherry-pick the merged commit of this pull request and resolve the conflicts
git cherry-pick -x --mainline 1 73b7a85d0a41580870a392aac9d47192adefa37a
# Push it to GitHub
git push --set-upstream origin backport/backport-7902-to-2.x
# Go back to the original working tree
popd
# Delete the working tree
git worktree remove ../.worktrees/backport-2.x

Then, create a pull request where the base branch is 2.x and the compare/head branch is backport/backport-7902-to-2.x.

…gs (opensearch-project#7902) * Replace cached time with system clock in MasterService debug logs Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> * Supply System.nanaoTime via TimeSupplier Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> * Add absolute time fetch method in Threadpool Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> * Rename absoluteTimeInNanos to preciseRelativeTimeInNanos Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> --------- Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> (cherry picked from commit 73b7a85)

…gs (#7902) (#8355)

…gs (opensearch-project#7902) * Replace cached time with system clock in MasterService debug logs Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> * Supply System.nanaoTime via TimeSupplier Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> * Add absolute time fetch method in Threadpool Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> * Rename absoluteTimeInNanos to preciseRelativeTimeInNanos Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> --------- Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com>

…gs (opensearch-project#7902) * Replace cached time with system clock in MasterService debug logs Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> * Supply System.nanaoTime via TimeSupplier Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> * Add absolute time fetch method in Threadpool Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> * Rename absoluteTimeInNanos to preciseRelativeTimeInNanos Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> --------- Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com> Signed-off-by: Shivansh Arora <hishiv@amazon.com>

sandeshkr419 changed the title ~~Replace cached time with system clock in MasterService debug logs~~ [Draft] Replace cached time with system clock in MasterService debug logs Jun 2, 2023

sandeshkr419 marked this pull request as ready for review June 2, 2023 20:38

sandeshkr419 requested review from reta, anasalkouz, andrross, Bukhtawar, CEHENKLE, dblock, gbbafna, setiah, kartg, kotwanikunal, mch2, nknize, owaiskazi19, Rishikesh1159, ryanbogan, saratvemulapalli, shwetathareja, dreamer-89, tlfeng, VachaShah and dbwiddis as code owners June 2, 2023 20:38

andrross reviewed Jun 6, 2023

View reviewed changes

CHANGELOG.md Outdated Show resolved Hide resolved

Bukhtawar reviewed Jun 6, 2023

View reviewed changes

Bukhtawar reviewed Jun 10, 2023

View reviewed changes

server/src/main/java/org/opensearch/cluster/service/MasterService.java Outdated Show resolved Hide resolved

dbwiddis reviewed Jun 10, 2023

View reviewed changes

server/src/test/java/org/opensearch/cluster/service/MasterServiceTests.java Outdated Show resolved Hide resolved

Add absolute time fetch method in Threadpool

08d0289

Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com>

sandeshkr419 requested a review from sachinpkale as a code owner June 19, 2023 04:33

Merge branch 'main' into debugTime

38905fa

Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com>

sandeshkr419 changed the title ~~[Draft] Replace cached time with system clock in MasterService debug logs~~ [Fix] Replace cached time with system clock in MasterService debug logs Jun 19, 2023

Bukhtawar reviewed Jun 20, 2023

View reviewed changes

server/src/main/java/org/opensearch/threadpool/ThreadPool.java Outdated Show resolved Hide resolved

Merge branch 'main' into debugTime

fe67c1c

Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com>

Rename absoluteTimeInNanos to preciseRelativeTimeInNanos

837f130

Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com>

shwetathareja approved these changes Jun 29, 2023

View reviewed changes

Merge branch 'main' into debugTime

c054d08

Signed-off-by: Sandesh Kumar <sandeshkr419@gmail.com>

andrross approved these changes Jun 29, 2023

View reviewed changes

andrross added the backport 2.x Backport to 2.x branch label Jun 29, 2023

andrross merged commit 73b7a85 into opensearch-project:main Jun 29, 2023

andrross mentioned this pull request Jun 29, 2023

[Backport 2.x] Replace cached time with system clock in MasterService debug lo… #8355

Merged

sandeshkr419 deleted the debugTime branch June 30, 2023 02:36

kotwanikunal pushed a commit that referenced this pull request Jul 6, 2023

[Fix] Replace cached time with system clock in MasterService debug lo…

58f4ce6

…gs (#7902) (#8355)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[Fix] Replace cached time with system clock in MasterService debug logs #7902

[Fix] Replace cached time with system clock in MasterService debug logs #7902

sandeshkr419 commented Jun 2, 2023 •

edited

Loading

github-actions bot commented Jun 2, 2023

github-actions bot commented Jun 2, 2023

github-actions bot commented Jun 2, 2023

andrross commented Jun 5, 2023

shwetathareja commented Jun 6, 2023 •

edited

Loading

Bukhtawar left a comment

github-actions bot commented Jun 19, 2023

github-actions bot commented Jun 19, 2023

github-actions bot commented Jun 28, 2023

dblock commented Jun 28, 2023

github-actions bot commented Jun 29, 2023

github-actions bot commented Jun 29, 2023

github-actions bot commented Jun 29, 2023

opensearch-trigger-bot bot commented Jun 29, 2023

[Fix] Replace cached time with system clock in MasterService debug logs #7902

[Fix] Replace cached time with system clock in MasterService debug logs #7902

Conversation

sandeshkr419 commented Jun 2, 2023 • edited Loading

Description

Related Issues

Check List

github-actions bot commented Jun 2, 2023

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Jun 2, 2023

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Jun 2, 2023

Gradle Check (Jenkins) Run Completed with:

andrross commented Jun 5, 2023

shwetathareja commented Jun 6, 2023 • edited Loading

Bukhtawar left a comment

Choose a reason for hiding this comment

github-actions bot commented Jun 19, 2023

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Jun 19, 2023

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Jun 28, 2023

Gradle Check (Jenkins) Run Completed with:

dblock commented Jun 28, 2023

github-actions bot commented Jun 29, 2023

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Jun 29, 2023

Gradle Check (Jenkins) Run Completed with:

github-actions bot commented Jun 29, 2023

Gradle Check (Jenkins) Run Completed with:

opensearch-trigger-bot bot commented Jun 29, 2023

sandeshkr419 commented Jun 2, 2023 •

edited

Loading

shwetathareja commented Jun 6, 2023 •

edited

Loading