HBASE-27153 Improvements to read-path tracing

[ndimiduk]

Take another pass through tracing of the read path, make adjustments accordingly. One of the major concerns raised previously is that we create a span for every block access. Start by simplifying this to trace events and see what else comes up.

Block-level and stream-level interactions are represented as span events with attached attributes (that's otel terminology for "structured logs", attached to the spans). I made an effort to surface information that an operator might be interested in while diagnosing slow read performance, and details that the previous generation of dev had already seen fit to surface via trace-level logging. We no longer emit spans for HFileReaderImpl.readBlock. I hope this is a good compromise between visibility and performance.

Also added a span context for block-cache pre-fetching.

[ndimiduk]

These are some screenshots of traces emitted by a build of branch-2 plus this patch, running in pseudo-distributed mode, sent to a Jaeger backed. Notice that the span events are marked as lines on spans. See the attributes on those event.s

[apurtell]

I wish we didn't have to pass the scan attribute builder through as an extra parameter to methods that don't care about tracing per se, they simply exist on the traced path. Is it possible to use threadlocals or some otel notion of thread context for these? Or is that an anti-pattern?

[ndimiduk]

@apurtell

I wish we didn't have to pass the scan attribute builder through as an extra parameter to methods that don't care about tracing per se, they simply exist on the traced path.

The reason that I have to pass this attributes object around is that I'm providing context that is eventually annotated to a span "event" -- essentially a log line. Otel API lets me stuff arbitrary attributes into a thread local for span attributes, not for span event attributes.

Is it possible to use threadlocals or some otel notion of thread context for these? Or is that an anti-pattern?

I am also not a fan of the current approach. Introducing a ThreadLocal for this purpose that is inspected at arbitrary code points seems ham-handed to me. At the very least, it should somehow be limited in scope to the current request, not the current thread. Let me see if I can find a better solution.

[ndimiduk]

@apurtell I changed the implementation to use the otel Context for propagating the additional information I wanted, without changing the method signatures. I'm not sure if this is intended use of the otel api or not...

[apurtell]

Approved. I like the

 final AttributesBuilder attributesBuilder = builderFromContext(Context.current());
attributesBuilder...

style way of building attributes along a method call chain without adding the builder as a method parameter.

[Apache-HBase]

🎊 +1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	1m 32s	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 23s	Maven dependency ordering for branch
+1 💚	mvninstall	3m 32s	master passed
+1 💚	compile	4m 35s	master passed
+1 💚	checkstyle	1m 10s	master passed
+1 💚	spotless	0m 49s	branch has no errors when running spotless:check.
+1 💚	spotbugs	3m 5s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 12s	Maven dependency ordering for patch
+1 💚	mvninstall	2m 48s	the patch passed
+1 💚	compile	3m 56s	the patch passed
+1 💚	javac	3m 56s	the patch passed
+1 💚	checkstyle	1m 17s	the patch passed
+1 💚	whitespace	0m 0s	The patch has no whitespace issues.
+1 💚	hadoopcheck	17m 31s	Patch does not cause any errors with Hadoop 3.1.2 3.2.2 3.3.1.
+1 💚	spotless	1m 1s	patch has no errors when running spotless:check.
+1 💚	spotbugs	4m 23s	the patch passed
		_ Other Tests _
+1 💚	asflicense	0m 35s	The patch does not generate ASF License warnings.
		54m 45s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/4/artifact/yetus-general-check/output/Dockerfile
GITHUB PR	#4572
Optional Tests	dupname asflicense javac spotbugs hadoopcheck hbaseanti spotless checkstyle compile
uname	Linux dfb41767a851 5.4.0-1071-aws #76~18.04.1-Ubuntu SMP Mon Mar 28 17:49:57 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	dev-support/hbase-personality.sh
git revision	master / 6886d02
Default Java	AdoptOpenJDK-1.8.0_282-b08
Max. process+thread count	64 (vs. ulimit of 30000)
modules	C: hbase-common hbase-client hbase-server U: .
Console output	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/4/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.

[Apache-HBase]

💔 -1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	1m 6s	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 14s	Maven dependency ordering for branch
+1 💚	mvninstall	2m 52s	master passed
+1 💚	compile	1m 20s	master passed
+1 💚	shadedjars	4m 38s	branch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	1m 1s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 10s	Maven dependency ordering for patch
+1 💚	mvninstall	2m 40s	the patch passed
+1 💚	compile	1m 13s	the patch passed
+1 💚	javac	1m 13s	the patch passed
+1 💚	shadedjars	4m 19s	patch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	0m 56s	the patch passed
		_ Other Tests _
+1 💚	unit	1m 36s	hbase-common in the patch passed.
+1 💚	unit	1m 27s	hbase-client in the patch passed.
-1 ❌	unit	231m 56s	hbase-server in the patch failed.
		257m 52s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/4/artifact/yetus-jdk8-hadoop3-check/output/Dockerfile
GITHUB PR	#4572
Optional Tests	javac javadoc unit shadedjars compile
uname	Linux 3a2f1d160cdd 5.4.0-1071-aws #76~18.04.1-Ubuntu SMP Mon Mar 28 17:49:57 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	dev-support/hbase-personality.sh
git revision	master / 6886d02
Default Java	AdoptOpenJDK-1.8.0_282-b08
unit	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/4/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-4572/4/testReport/
Max. process+thread count	3026 (vs. ulimit of 30000)
modules	C: hbase-common hbase-client hbase-server U: .
Console output	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/4/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]

💔 -1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	1m 46s	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 6s	Maven dependency ordering for branch
+1 💚	mvninstall	4m 17s	master passed
+1 💚	compile	2m 9s	master passed
+1 💚	shadedjars	4m 55s	branch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	1m 31s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 15s	Maven dependency ordering for patch
+1 💚	mvninstall	4m 9s	the patch passed
+1 💚	compile	2m 10s	the patch passed
+1 💚	javac	2m 10s	the patch passed
+1 💚	shadedjars	5m 50s	patch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	1m 19s	the patch passed
		_ Other Tests _
+1 💚	unit	2m 51s	hbase-common in the patch passed.
+1 💚	unit	2m 4s	hbase-client in the patch passed.
-1 ❌	unit	272m 30s	hbase-server in the patch failed.
		308m 17s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/4/artifact/yetus-jdk11-hadoop3-check/output/Dockerfile
GITHUB PR	#4572
Optional Tests	javac javadoc unit shadedjars compile
uname	Linux b934934803c7 5.4.0-90-generic #101-Ubuntu SMP Fri Oct 15 20:00:55 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	dev-support/hbase-personality.sh
git revision	master / 6886d02
Default Java	AdoptOpenJDK-11.0.10+9
unit	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/4/artifact/yetus-jdk11-hadoop3-check/output/patch-unit-hbase-server.txt
Test Results	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/4/testReport/
Max. process+thread count	2567 (vs. ulimit of 30000)
modules	C: hbase-common hbase-client hbase-server U: .
Console output	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/4/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.

[apurtell]

TestAsyncTableScan.testReverseScanNoStopKey[1: scan=batch] failure seems relevant.

[ndimiduk]

TestAsyncTableScan.testReverseScanNoStopKey[1: scan=batch] failure seems relevant.

This failure is baffling to me. The assertion failed because a span with the name TracedScanResultConsumer#onComplete was not found in the collection. However, you can see that a span of that name is printed in the DEBUG logging!

[Apache-HBase]

🎊 +1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	3m 28s	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 51s	Maven dependency ordering for branch
+1 💚	mvninstall	2m 22s	master passed
+1 💚	compile	3m 24s	master passed
+1 💚	checkstyle	0m 51s	master passed
+1 💚	spotless	0m 42s	branch has no errors when running spotless:check.
+1 💚	spotbugs	2m 14s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 10s	Maven dependency ordering for patch
+1 💚	mvninstall	2m 29s	the patch passed
+1 💚	compile	4m 6s	the patch passed
+1 💚	javac	4m 6s	the patch passed
+1 💚	checkstyle	1m 4s	the patch passed
+1 💚	whitespace	0m 0s	The patch has no whitespace issues.
+1 💚	hadoopcheck	13m 38s	Patch does not cause any errors with Hadoop 3.1.2 3.2.2 3.3.1.
+1 💚	spotless	0m 54s	patch has no errors when running spotless:check.
+1 💚	spotbugs	4m 17s	the patch passed
		_ Other Tests _
+1 💚	asflicense	0m 39s	The patch does not generate ASF License warnings.
		48m 3s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/5/artifact/yetus-general-check/output/Dockerfile
GITHUB PR	#4572
Optional Tests	dupname asflicense javac spotbugs hadoopcheck hbaseanti spotless checkstyle compile
uname	Linux a9ae449a9f06 5.4.0-1071-aws #76~18.04.1-Ubuntu SMP Mon Mar 28 17:49:57 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	dev-support/hbase-personality.sh
git revision	master / e8c14ee
Default Java	AdoptOpenJDK-1.8.0_282-b08
Max. process+thread count	60 (vs. ulimit of 30000)
modules	C: hbase-common hbase-client hbase-server U: .
Console output	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/5/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.

[Apache-HBase]

💔 -1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	1m 4s	Docker mode activated.
-0 ⚠️	yetus	0m 3s	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 17s	Maven dependency ordering for branch
+1 💚	mvninstall	2m 42s	master passed
+1 💚	compile	1m 26s	master passed
+1 💚	shadedjars	3m 44s	branch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	0m 58s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 14s	Maven dependency ordering for patch
+1 💚	mvninstall	2m 41s	the patch passed
+1 💚	compile	1m 23s	the patch passed
+1 💚	javac	1m 23s	the patch passed
+1 💚	shadedjars	3m 44s	patch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	0m 59s	the patch passed
		_ Other Tests _
+1 💚	unit	1m 54s	hbase-common in the patch passed.
+1 💚	unit	1m 23s	hbase-client in the patch passed.
-1 ❌	unit	208m 39s	hbase-server in the patch failed.
		233m 22s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/5/artifact/yetus-jdk11-hadoop3-check/output/Dockerfile
GITHUB PR	#4572
Optional Tests	javac javadoc unit shadedjars compile
uname	Linux 868547b198ce 5.4.0-122-generic #138-Ubuntu SMP Wed Jun 22 15:00:31 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	dev-support/hbase-personality.sh
git revision	master / e8c14ee
Default Java	AdoptOpenJDK-11.0.10+9
unit	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/5/artifact/yetus-jdk11-hadoop3-check/output/patch-unit-hbase-server.txt
Test Results	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/5/testReport/
Max. process+thread count	2442 (vs. ulimit of 30000)
modules	C: hbase-common hbase-client hbase-server U: .
Console output	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/5/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]

💔 -1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	0m 35s	Docker mode activated.
-0 ⚠️	yetus	0m 3s	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 12s	Maven dependency ordering for branch
+1 💚	mvninstall	2m 30s	master passed
+1 💚	compile	1m 3s	master passed
+1 💚	shadedjars	4m 1s	branch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	0m 47s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 11s	Maven dependency ordering for patch
+1 💚	mvninstall	2m 12s	the patch passed
+1 💚	compile	1m 3s	the patch passed
+1 💚	javac	1m 3s	the patch passed
+1 💚	shadedjars	4m 0s	patch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	0m 46s	the patch passed
		_ Other Tests _
+1 💚	unit	1m 23s	hbase-common in the patch passed.
+1 💚	unit	1m 7s	hbase-client in the patch passed.
-1 ❌	unit	228m 2s	hbase-server in the patch failed.
		250m 4s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/5/artifact/yetus-jdk8-hadoop3-check/output/Dockerfile
GITHUB PR	#4572
Optional Tests	javac javadoc unit shadedjars compile
uname	Linux 24056846fce9 5.4.0-1081-aws #88~18.04.1-Ubuntu SMP Thu Jun 23 16:29:17 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
Build tool	maven
Personality	dev-support/hbase-personality.sh
git revision	master / e8c14ee
Default Java	AdoptOpenJDK-1.8.0_282-b08
unit	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/5/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-4572/5/testReport/
Max. process+thread count	2629 (vs. ulimit of 30000)
modules	C: hbase-common hbase-client hbase-server U: .
Console output	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4572/5/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.