HBASE-26759 Fix trace continuity through CallRunner by ndimiduk · Pull Request #4126 · apache/hbase

ndimiduk · 2022-02-23T14:02:28Z

We appear to be generating spans with without a parent context with the name
RegionScanner.close.

Apache9 · 2022-02-23T15:04:15Z

I think the problem here is that we forget to end the span created in ServerRpcConnection? Anyway, I think we should have a big span to trace the whole rpc processing...

ndimiduk · 2022-02-23T15:20:40Z

I did not attempt to perform an audit of the span lifecycle, only reconnected the orphaned span to what appears to be its proper parent. If you think there are bugs in properly closing spans, I hope that we can find them by way of the pom change i have over on https://github.com/apache/hbase/pull/4106/files#diff-9c5fb3d1b7e3b0f54bc5c4182965c4fe1f9023d449017cece3005d3f90e8e4d8

ndimiduk · 2022-02-23T15:22:43Z

I believe this patch fixes the issue because I no longer see a litany of these spans attached to a test-root span, and instead see spans of this name attached to a region scanner lifecycle,

2022-02-23T15:00:48,627 DEBUG [Time-limited test] trace.StringTraceRenderer(98): ├─ [spanId=b0b3842300fa4bee,name=hbase.pb.ClientService/Scan,hasEnded=true]
2022-02-23T15:00:48,627 DEBUG [Time-limited test] trace.StringTraceRenderer(98): └─ [spanId=408de8bffa73710d,name=RpcServer.process,hasEnded=true]
2022-02-23T15:00:48,627 DEBUG [Time-limited test] trace.StringTraceRenderer(98): └─ [spanId=4a5742873c238ba9,name=hbase.pb.ClientService/Scan,hasEnded=true]
2022-02-23T15:00:48,627 DEBUG [Time-limited test] trace.StringTraceRenderer(98): └─ [spanId=55fe2264c8a3039d,name=Region.getScanner,hasEnded=true]
2022-02-23T15:00:48,627 DEBUG [Time-limited test] trace.StringTraceRenderer(98): ├─ [spanId=e2274d44a068b9b3,name=RegionScanner.close,hasEnded=true]

ndimiduk · 2022-02-23T15:24:15Z

I do find it strange that we have a span explicitly for a close method, but not other lifecycle methods on the same object (such as open, for example).

Apache9 · 2022-02-25T14:20:45Z

I mean we have a span here

hbase/hbase-server/src/main/java/org/apache/hadoop/hbase/ipc/ServerRpcConnection.java

Line 634 in 5dc663e

try (Scopescope = span.makeCurrent()) {

I think it will be the parent span for the spans at server side, and seems it has not been ended properly?

ndimiduk · 2022-02-28T15:19:00Z

@Apache9

I think the problem here is that we forget to end the span created in ServerRpcConnection?

I see that the trace scope is closed properly, but I think you're correct that the trace is not ended, neither with success nor failure.

Anyway, I think we should have a big span to trace the whole rpc processing...

My impression was that this span in processRequest is the big span to trace the whole rpc processing. Is there additional scope you would see included?

We appear to be generating spans with without a parent context with the name `RegionScanner.close`. This was a symptom of span scope disconnect through the `CallRunner` execution path.

ndimiduk · 2022-03-04T09:11:37Z

@Apache9 please take another look.

Apache-HBase · 2022-03-04T09:54:30Z

🎊 +1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	3m 38s	Docker mode activated.
		_ Prechecks _
+1 💚	dupname	0m 0s	No case conflicting files found.
+1 💚	hbaseanti	0m 0s	Patch does not have any anti-patterns.
+1 💚	@author	0m 0s	The patch does not contain any @author tags.
		_ master Compile Tests _
+0 🆗	mvndep	0m 48s	Maven dependency ordering for branch
+1 💚	mvninstall	3m 35s	master passed
+1 💚	compile	2m 52s	master passed
+1 💚	checkstyle	0m 48s	master passed
+1 💚	spotbugs	1m 50s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 10s	Maven dependency ordering for patch
+1 💚	mvninstall	2m 23s	the patch passed
+1 💚	compile	2m 47s	the patch passed
+1 💚	javac	2m 47s	the patch passed
+1 💚	checkstyle	0m 13s	The patch passed checkstyle in hbase-client
+1 💚	checkstyle	0m 33s	hbase-server: The patch generated 0 new + 20 unchanged - 2 fixed = 20 total (was 22)
+1 💚	whitespace	0m 0s	The patch has no whitespace issues.
+1 💚	hadoopcheck	11m 50s	Patch does not cause any errors with Hadoop 3.1.2 3.2.2 3.3.1.
+1 💚	spotbugs	2m 1s	the patch passed
		_ Other Tests _
+1 💚	asflicense	0m 16s	The patch does not generate ASF License warnings.
		39m 6s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4126/2/artifact/yetus-general-check/output/Dockerfile
GITHUB PR	#4126
Optional Tests	dupname asflicense javac spotbugs hadoopcheck hbaseanti checkstyle compile
uname	Linux 9b8727bc845d 5.4.0-1043-aws #45~18.04.1-Ubuntu SMP Fri Apr 9 23:32:25 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	dev-support/hbase-personality.sh
git revision	master / `9c037b1`
Default Java	AdoptOpenJDK-1.8.0_282-b08
Max. process+thread count	60 (vs. ulimit of 30000)
modules	C: hbase-client hbase-server U: .
Console output	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4126/2/console
versions	git=2.17.1 maven=3.6.3 spotbugs=4.2.2
Powered by	Apache Yetus 0.12.0 https://yetus.apache.org

This message was automatically generated.

Apache9 · 2022-03-04T10:24:23Z

@Apache9
I think the problem here is that we forget to end the span created in ServerRpcConnection?
I see that the trace scope is closed properly, but I think you're correct that the trace is not ended, neither with success nor failure.
Anyway, I think we should have a big span to trace the whole rpc processing...
My impression was that this span in processRequest is the big span to trace the whole rpc processing. Is there additional scope you would see included?

Ah, sorry, forgot to reply here. No additional scope. Let me check the newest PR.

Apache9

+1

Apache9 · 2022-03-04T10:28:42Z

- if (!this.rpcServer.scheduler.dispatch(new CallRunner(this.rpcServer, call))) {
+ if (this.rpcServer.scheduler.dispatch(new CallRunner(this.rpcServer, call, span))) {
+ // unset span do that it's not closed in the finally block
+ span = null;


Yes, the code structure here is not friendly for tracing...
Thanks for the detailed comments!

Apache-HBase · 2022-03-04T19:29:12Z

🎊 +1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	0m 36s	Docker mode activated.
		_ Prechecks _
+1 💚	dupname	0m 0s	No case conflicting files found.
+1 💚	hbaseanti	0m 0s	Patch does not have any anti-patterns.
+1 💚	@author	0m 0s	The patch does not contain any @author tags.
		_ master Compile Tests _
+0 🆗	mvndep	0m 9s	Maven dependency ordering for branch
+1 💚	mvninstall	2m 21s	master passed
+1 💚	compile	2m 48s	master passed
+1 💚	checkstyle	0m 47s	master passed
+1 💚	spotbugs	1m 47s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 9s	Maven dependency ordering for patch
+1 💚	mvninstall	2m 19s	the patch passed
+1 💚	compile	2m 53s	the patch passed
+1 💚	javac	2m 53s	the patch passed
+1 💚	checkstyle	0m 14s	The patch passed checkstyle in hbase-client
+1 💚	checkstyle	0m 34s	hbase-server: The patch generated 0 new + 20 unchanged - 2 fixed = 20 total (was 22)
+1 💚	whitespace	0m 0s	The patch has no whitespace issues.
+1 💚	hadoopcheck	11m 29s	Patch does not cause any errors with Hadoop 3.1.2 3.2.2 3.3.1.
+1 💚	spotbugs	2m 2s	the patch passed
		_ Other Tests _
+1 💚	asflicense	0m 14s	The patch does not generate ASF License warnings.
		33m 42s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4126/3/artifact/yetus-general-check/output/Dockerfile
GITHUB PR	#4126
Optional Tests	dupname asflicense javac spotbugs hadoopcheck hbaseanti checkstyle compile
uname	Linux 708f764fbc78 5.4.0-1043-aws #45~18.04.1-Ubuntu SMP Fri Apr 9 23:32:25 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	dev-support/hbase-personality.sh
git revision	master / `f4b05a8`
Default Java	AdoptOpenJDK-1.8.0_282-b08
Max. process+thread count	60 (vs. ulimit of 30000)
modules	C: hbase-client hbase-server U: .
Console output	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4126/3/console
versions	git=2.17.1 maven=3.6.3 spotbugs=4.2.2
Powered by	Apache Yetus 0.12.0 https://yetus.apache.org

This message was automatically generated.

Signed-off-by: Andrew Purtell <apurtell@apache.org> Signed-off-by: Duo Zhang <zhangduo@apache.org>

Apache-HBase · 2022-03-05T00:40:04Z

💔 -1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	0m 41s	Docker mode activated.
-0 ⚠️	yetus	0m 2s	Unprocessed flag(s): --brief-report-file --spotbugs-strict-precheck --whitespace-eol-ignore-list --whitespace-tabs-ignore-list --quick-hadoopcheck
		_ Prechecks _
		_ master Compile Tests _
+0 🆗	mvndep	0m 13s	Maven dependency ordering for branch
+1 💚	mvninstall	2m 41s	master passed
+1 💚	compile	0m 49s	master passed
+1 💚	shadedjars	4m 0s	branch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	0m 35s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 11s	Maven dependency ordering for patch
+1 💚	mvninstall	2m 18s	the patch passed
+1 💚	compile	0m 50s	the patch passed
+1 💚	javac	0m 50s	the patch passed
+1 💚	shadedjars	4m 1s	patch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	0m 34s	the patch passed
		_ Other Tests _
+1 💚	unit	1m 36s	hbase-client in the patch passed.
-1 ❌	unit	324m 8s	hbase-server in the patch failed.
		344m 33s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4126/3/artifact/yetus-jdk8-hadoop3-check/output/Dockerfile
GITHUB PR	#4126
Optional Tests	javac javadoc unit shadedjars compile
uname	Linux e46f4ae75c60 5.4.0-1025-aws #25~18.04.1-Ubuntu SMP Fri Sep 11 12:03:04 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	dev-support/hbase-personality.sh
git revision	master / `f4b05a8`
Default Java	AdoptOpenJDK-1.8.0_282-b08
unit	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4126/3/artifact/yetus-jdk8-hadoop3-check/output/patch-unit-hbase-server.txt
Test Results	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4126/3/testReport/
Max. process+thread count	1796 (vs. ulimit of 30000)
modules	C: hbase-client hbase-server U: .
Console output	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4126/3/console
versions	git=2.17.1 maven=3.6.3
Powered by	Apache Yetus 0.12.0 https://yetus.apache.org

This message was automatically generated.

Apache-HBase · 2022-03-05T00:53:05Z

🎊 +1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	0m 38s	Docker mode activated.
-0 ⚠️	yetus	0m 2s	Unprocessed flag(s): --brief-report-file --spotbugs-strict-precheck --whitespace-eol-ignore-list --whitespace-tabs-ignore-list --quick-hadoopcheck
		_ Prechecks _
		_ master Compile Tests _
+0 🆗	mvndep	0m 36s	Maven dependency ordering for branch
+1 💚	mvninstall	3m 29s	master passed
+1 💚	compile	1m 3s	master passed
+1 💚	shadedjars	4m 17s	branch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	0m 41s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 11s	Maven dependency ordering for patch
+1 💚	mvninstall	3m 2s	the patch passed
+1 💚	compile	1m 4s	the patch passed
+1 💚	javac	1m 4s	the patch passed
+1 💚	shadedjars	4m 11s	patch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	0m 40s	the patch passed
		_ Other Tests _
+1 💚	unit	1m 52s	hbase-client in the patch passed.
+1 💚	unit	333m 19s	hbase-server in the patch passed.
		357m 37s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4126/3/artifact/yetus-jdk11-hadoop3-check/output/Dockerfile
GITHUB PR	#4126
Optional Tests	javac javadoc unit shadedjars compile
uname	Linux ba4d8893f58b 5.4.0-1025-aws #25~18.04.1-Ubuntu SMP Fri Sep 11 12:03:04 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	dev-support/hbase-personality.sh
git revision	master / `f4b05a8`
Default Java	AdoptOpenJDK-11.0.10+9
Test Results	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4126/3/testReport/
Max. process+thread count	1577 (vs. ulimit of 30000)
modules	C: hbase-client hbase-server U: .
Console output	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4126/3/console
versions	git=2.17.1 maven=3.6.3
Powered by	Apache Yetus 0.12.0 https://yetus.apache.org

This message was automatically generated.

ndimiduk requested review from Apache9, joshelser and taklwu February 23, 2022 14:02

This comment was marked as outdated.
Sign in to view

HBASE-26759 Fix trace continuity through CallRunner
01ab773
We appear to be generating spans with without a parent context with the name `RegionScanner.close`. This was a symptom of span scope disconnect through the `CallRunner` execution path.

ndimiduk force-pushed the 26759-orphaned-span-RegionScanner.close branch from 4780035 to 01ab773Compare March 4, 2022 09:10

ndimiduk changed the title ~~HBASE-26759 Fix orphaned RegionScanner.close spans~~HBASE-26759 Fix trace continuity through CallRunnerMar 4, 2022

Apache9 approved these changes Mar 4, 2022
View reviewed changes

fix broken test
f4ff6c6

apurtell merged commit 2b9ab90 into apache:masterMar 4, 2022

asfgit pushed a commit that referenced this pull request Mar 5, 2022
HBASE-26759Fix trace continuity through CallRunner (#4126)
01acd87
Signed-off-by: Andrew Purtell <apurtell@apache.org> Signed-off-by: Duo Zhang <zhangduo@apache.org>

asfgit pushed a commit that referenced this pull request Mar 5, 2022
HBASE-26759Fix trace continuity through CallRunner (#4126)
09bd726
Signed-off-by: Andrew Purtell <apurtell@apache.org> Signed-off-by: Duo Zhang <zhangduo@apache.org>

ndimiduk deleted the 26759-orphaned-span-RegionScanner.close branch March 7, 2022 12:26

Uh oh!

Conversation

ndimiduk commented Feb 23, 2022

Uh oh!

This comment was marked as outdated.

This comment was marked as outdated.

Apache9 commented Feb 23, 2022

Uh oh!

ndimiduk commented Feb 23, 2022

Uh oh!

ndimiduk commented Feb 23, 2022

Uh oh!

ndimiduk commented Feb 23, 2022

Uh oh!

This comment was marked as outdated.

Apache9 commented Feb 25, 2022

Uh oh!

ndimiduk commented Feb 28, 2022

Uh oh!

ndimiduk commented Mar 4, 2022

Uh oh!

Apache-HBase commented Mar 4, 2022

Uh oh!

Apache9 commented Mar 4, 2022

Uh oh!

Apache9 left a comment

Choose a reason for hiding this comment

Uh oh!

Apache9Mar 4, 2022

Choose a reason for hiding this comment

Uh oh!

Apache-HBase commented Mar 4, 2022

Uh oh!

Apache-HBase commented Mar 5, 2022

Uh oh!

Apache-HBase commented Mar 5, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants