HBASE-26545 Implement tracing of scan #4106

ndimiduk · 2022-02-10T15:15:13Z

on AsyncTable, both scan and scanAll methods should result in SCAN table operations.
the span of the SCAN table operation should have children representing all the RPC calls
involved in servicing the scan.
when a user provides custom implementation of AdvancedScanResultConsumer, any spans emitted
from the callback methods should also be tied to the span that represents the SCAN table
operation. This is easily done because these callbacks are executed on the RPC thread.
when a user provides a custom implementation of ScanResultConsumer, any spans emitted from the
callback methods are tied to the context of user application code. We could link them to the
SCAN table operation, except that we have no means of passing that span along.

hbase-server/src/test/java/org/apache/hadoop/hbase/trace/OpenTelemetryTestRule.java

Apache9 · 2022-02-12T01:46:34Z

So for async table, we will create a span when starting the scanner, and once we actually execute a piece of code, we will restore that span? So when will we end the span?

ndimiduk · 2022-02-14T13:52:13Z

So for async table, we will create a span when starting the scanner, and once we actually execute a piece of code, we will restore that span? So when will we end the span?

For async table, we create the span in AsyncClientScanner#start. That span wraps the runnable that starts the async callback chain that handles populating scanner results behind the scenes for the client application. Each callback handles making sure that span is restored to its current context. In the test, there are asserts that confirm this span has ended and with StatusCode.OK. Perhaps you are correct that this implementation does not handle error cases. I don't see test code that covers an error while scanning. While the test code asserts the parent-child relationships of spans, it does not cover explicitly the start/end times of those children as relates to their parent. I will look closer here.

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncClientScanner.java

ndimiduk · 2022-02-17T14:28:22Z

I've pushed an update. Rebased onto master. Reworked how the span is threaded through AsyncClientScanner based on @Apache9 's comments. Likewise, thread the span through the AsyncTableResultScanner for the same purpose. I also enabled span lifetime auditing for unit tests.

Marked the PR as a draft because I think there's more work to do -- at the very least, I plan to introduce test coverage via new, dedicated test class(es) instead of piggy-backing on the existing scan tests.

Duo -- I look forward to your further thoughts/observations.

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncClientScanner.java

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncConnectionImpl.java

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncTableImpl.java

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncTableResultScanner.java

hbase-client/src/main/java/org/apache/hadoop/hbase/client/RawAsyncTableImpl.java

hbase-client/src/test/java/org/apache/hadoop/hbase/client/TestAsyncTableTracing.java

hbase-client/src/test/java/org/apache/hadoop/hbase/client/trace/StringTraceRenderer.java

ndimiduk · 2022-02-17T14:54:09Z

pom.xml

@@ -1884,12 +1884,13 @@
      -Djava.security.egd=file:/dev/./urandom -Djava.net.preferIPv4Stack=true
      -Djava.awt.headless=true -Djdk.net.URLClassPath.disableClassPathURLCheck=true
      -Dorg.apache.hbase.thirdparty.io.netty.leakDetection.level=advanced
-      -Dio.netty.eventLoopThreads=3
+      -Dio.netty.eventLoopThreads=3 -Dio.opentelemetry.context.enableStrictContext=true


This is supposed to enable strict checking that scopes are closed properly. I'm not convinced it works in practice.

https://github.com/open-telemetry/opentelemetry-java/blob/77f0b0adc4ab9748cb7acf72952ecea2b4fda5f6/context/src/main/java/io/opentelemetry/context/StrictContextStorage.java#L147

ndimiduk · 2022-02-21T16:47:19Z

I broke off HBASE-26764 and HBASE-26765 as #4120 and #4121 respectively.

ndimiduk · 2022-03-10T20:10:30Z

Ping @joshelser @taklwu @Apache9

apurtell

Test changes that assert continuity are fairly extensive. I started skimming there after realizing the pattern of the refactor.

apurtell · 2022-03-11T20:02:35Z

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncClientScanner.java

-      .operationTimeout(scanTimeoutNs, TimeUnit.NANOSECONDS).pause(pauseNs, TimeUnit.NANOSECONDS)
-      .pauseForCQTBE(pauseForCQTBENs, TimeUnit.NANOSECONDS).maxAttempts(maxAttempts)
-      .startLogErrorsCnt(startLogErrorsCnt).action(this::callOpenScanner).call();
+    try (Scope ignored = span.makeCurrent()) {


Do you want to also maintain your volatile usage discipline here and copy 'span' to a 'localSpan' first, as you have done at other call sites?

I didn't do so here because the member field is accessed only once in the method lifetime, while the other call sites made multiple references to the field. I can use the same pattern here, sure, it won't hurt anything.

apurtell · 2022-03-11T20:04:49Z

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncTableImpl.java

-          break;
+    Span span = null;
+    try (AsyncTableResultScanner scanner = rawTable.getScanner(scan)) {
+      span = scanner.getSpan();


Can this be null? I guess not as long as someone is aware of getter/setter for span in AsyncTableResultScanner and the expected convention. I suppose the resulting NPE would clear enough if not.
And ditto other call sites. I might have thrown something with an explicit message about failure to maintain the code discipline but it seems fine.

In an earlier version of this patch, I hade null-protection sprinkled throughout this method. IntelliJ static analysis annotated it all as unnecessary. If you're also wondering... I'll trust two devs over the tool. Let me bring it back.

I don't want to throw because a disruption in tracing should not hinder application execution.

Okay, I'm simplifying this according to the hints provided by the IDE. I cannot make the field final because the compiler errors in the catch block that the field hasn't been initialized, but static analysis agrees with @Apache9 that the field can never be null.

apurtell · 2022-03-11T20:08:16Z

hbase-client/src/test/java/org/apache/hadoop/hbase/client/TestAsyncTableTracing.java

@@ -452,6 +456,53 @@ public void testScanAll() {
    assertTrace("SCAN");
  }

+  @Test
+  public void testScan() throws Throwable {


Name: testScanTracing?

The class has "Tracing" in the name, so I didn't think it necessary.

apurtell · 2022-03-11T20:08:29Z

hbase-client/src/test/java/org/apache/hadoop/hbase/client/TestAsyncTableTracing.java

+  }
+
+  @Test
+  public void testGetScanner() {


Name: testGetScannerTracing?

hbase-client/src/test/java/org/apache/hadoop/hbase/client/trace/StringTraceRenderer.java

apurtell · 2022-03-11T20:10:09Z

hbase-server/src/test/java/org/apache/hadoop/hbase/client/AbstractTestAsyncTableScan.java

+  protected static final ConnectionRule connectionRule =
+    new ConnectionRule(miniClusterRule::createConnection);
+
+  private static final class Setup extends ExternalResource {


Initially I was wondering about this but I see it is just a junit convention refactor

It's not just convention. JUnit makes no promises re: execution order of @Before and @Rule, of @BeforeClass and @ClassRule. I want to use fields that are initialized by the @ClassRule annotation, so I need to participate in that annotation. The ChainRule allows me to explicitly order the execution, so that otel is initialize first, then the miniCluster, then the connection to the miniCluster, and finally my code that makes use of the previous.

I much much much prefer the Rules over test class inheritance because mixing in functionality is so much easier to reason about.

Can upgrading to junit5 solve this problem?

I don't see the RuleChain stuff as a "problem", it's just the way this API works. I believe that JUnit 5 is a complete overhaul of the testing harness, I haven't looked into what all is involved, but I think it is involved.

Apache9 · 2022-03-14T10:05:08Z

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncClientScanner.java

      });
  }

  public void start() {
-    openScanner();
+    final Span localSpan = new TableOperationSpanBuilder(conn)


The only place where we create this scanner and call start on it is in RawAsyncTableImpl.scan method, where both these two operations are in the same thread, so I think here we could make the Span field final and create it in the constructor, so we do not need to care about concurrency access any more.

Hmm yes, I suppose so.

Apache9 · 2022-03-14T10:34:44Z

...ent/src/main/java/org/apache/hadoop/hbase/client/AsyncScanSingleRegionRpcRetryingCaller.java

@@ -573,7 +574,8 @@ private void call() {
    resetController(controller, callTimeoutNs, priority);
    ScanRequest req = RequestConverter.buildScanRequest(scannerId, scan.getCaching(), false,
      nextCallSeq, scan.isScanMetricsEnabled(), false, scan.getLimit());
-    stub.scan(controller, req, resp -> onComplete(controller, resp));
+    Context context = Context.current();


What is the purpose here? Wrap the callback in the span in the current context?

Yes, it's to wrap the onComplete callback invocation. The line following would be less awkward if Context offered a method <T> Consumer<T> wrap(Consumer<T> consumer).

In fact, this API has been added upstream, open-telemetry/opentelemetry-java@cffbd32

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncTableImpl.java

Apache9 · 2022-03-14T10:44:39Z

Haven't finished the review yet. Will take a look on the second half tonight.

Apache9

No big concerns on the second half, most changes are tests, which I think is good.

Apache9 · 2022-03-15T14:42:34Z

hbase-server/src/test/java/org/apache/hadoop/hbase/client/AbstractTestAsyncTableScan.java

+  protected static final ConnectionRule connectionRule =
+    new ConnectionRule(miniClusterRule::createConnection);
+
+  private static final class Setup extends ExternalResource {


Can upgrading to junit5 solve this problem?

ndimiduk · 2022-03-21T16:10:48Z

Rebased onto master and I believe I've addressed all outstanding reviewer feedback.

ndimiduk · 2022-03-22T13:45:42Z

Awkwardly, the tests of interest have the xml read error. They pass locally. Kicking the PR build again.

@Apache9 @apurtell do you have any further comments?

Apache9

Overall LGTM. The only thing is still about when to end the span. I think since we have a ScanResultConsumer, we could just follow the old logic, to add span.end at the place where we call consumer.onComplate and consumer.onError.

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncClientScanner.java

Apache9 · 2022-03-28T08:39:23Z

Approved.

I think this is last piece of tracing? Thanks @ndimiduk for the hard!

Apache-HBase · 2022-03-28T09:13:15Z

🎊 +1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	1m 11s	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 21s	Maven dependency ordering for branch
+1 💚	mvninstall	2m 18s	master passed
+1 💚	compile	6m 14s	master passed
+1 💚	checkstyle	1m 9s	master passed
+1 💚	spotbugs	9m 10s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 15s	Maven dependency ordering for patch
+1 💚	mvninstall	2m 15s	the patch passed
+1 💚	compile	6m 12s	the patch passed
+1 💚	javac	6m 12s	the patch passed
-0 ⚠️	checkstyle	1m 9s	root: The patch generated 1 new + 9 unchanged - 2 fixed = 10 total (was 11)
+1 💚	whitespace	0m 0s	The patch has no whitespace issues.
+1 💚	xml	0m 1s	The patch has no ill-formed XML file.
+1 💚	hadoopcheck	11m 46s	Patch does not cause any errors with Hadoop 3.1.2 3.2.2 3.3.1.
+1 💚	spotbugs	9m 38s	the patch passed
		_ Other Tests _
+1 💚	asflicense	0m 29s	The patch does not generate ASF License warnings.
		57m 34s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4106/11/artifact/yetus-general-check/output/Dockerfile
GITHUB PR	#4106
Optional Tests	dupname asflicense javac spotbugs hadoopcheck hbaseanti checkstyle compile xml
uname	Linux ae3354419463 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 / `4f491fd`
Default Java	AdoptOpenJDK-1.8.0_282-b08
checkstyle	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4106/11/artifact/yetus-general-check/output/diff-checkstyle-root.txt
Max. process+thread count	138 (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-4106/11/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.

* on `AsyncTable`, both `scan` and `scanAll` methods should result in `SCAN` table operations. * the span of the `SCAN` table operation should have children representing all the RPC calls involved in servicing the scan. * when a user provides custom implementation of `AdvancedScanResultConsumer`, any spans emitted from the callback methods should also be tied to the span that represents the `SCAN` table operation. This is easily done because these callbacks are executed on the RPC thread. * when a user provides a custom implementation of `ScanResultConsumer`, any spans emitted from the callback methods should be also be tied to the span that represents the `SCAN` table operation. This accomplished by carefully passing the span instance around after it is created. Signed-off-by: Andrew Purtell <[email protected]> Signed-off-by: Duo Zhang <[email protected]>

Apache-HBase · 2022-03-28T12:40:58Z

🎊 +1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	0m 43s	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 43s	Maven dependency ordering for branch
+1 💚	mvninstall	2m 56s	master passed
+1 💚	compile	1m 47s	master passed
+1 💚	shadedjars	4m 4s	branch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	2m 29s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 13s	Maven dependency ordering for patch
+1 💚	mvninstall	2m 39s	the patch passed
+1 💚	compile	1m 51s	the patch passed
+1 💚	javac	1m 51s	the patch passed
+1 💚	shadedjars	4m 2s	patch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	2m 28s	the patch passed
		_ Other Tests _
+1 💚	unit	237m 26s	root in the patch passed.
		265m 20s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4106/11/artifact/yetus-jdk11-hadoop3-check/output/Dockerfile
GITHUB PR	#4106
Optional Tests	javac javadoc unit shadedjars compile
uname	Linux e1c57335233d 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 / `4f491fd`
Default Java	AdoptOpenJDK-11.0.10+9
Test Results	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4106/11/testReport/
Max. process+thread count	4684 (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-4106/11/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-28T14:38:31Z

💔 -1 overall

Vote	Subsystem	Runtime	Comment
+0 🆗	reexec	1m 13s	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 25s	Maven dependency ordering for branch
+1 💚	mvninstall	3m 54s	master passed
+1 💚	compile	1m 44s	master passed
+1 💚	shadedjars	4m 23s	branch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	2m 17s	master passed
		_ Patch Compile Tests _
+0 🆗	mvndep	0m 15s	Maven dependency ordering for patch
+1 💚	mvninstall	2m 24s	the patch passed
+1 💚	compile	1m 41s	the patch passed
+1 💚	javac	1m 41s	the patch passed
+1 💚	shadedjars	4m 19s	patch has no errors when building our shaded downstream artifacts.
+1 💚	javadoc	2m 18s	the patch passed
		_ Other Tests _
-1 ❌	unit	355m 59s	root in the patch failed.
		382m 50s

Subsystem	Report/Notes
Docker	ClientAPI=1.41 ServerAPI=1.41 base: https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4106/11/artifact/yetus-jdk8-hadoop3-check/output/Dockerfile
GITHUB PR	#4106
Optional Tests	javac javadoc unit shadedjars compile
uname	Linux e6b16a6a42e1 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 / `4f491fd`
Default Java	AdoptOpenJDK-1.8.0_282-b08
unit	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4106/11/artifact/yetus-jdk8-hadoop3-check/output/patch-unit-root.txt
Test Results	https://ci-hbase.apache.org/job/HBase-PreCommit-GitHub-PR/job/PR-4106/11/testReport/
Max. process+thread count	2394 (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-4106/11/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 joshelser, taklwu and Apache9 February 10, 2022 15:15

This comment was marked as outdated.

Sign in to view

ndimiduk commented Feb 11, 2022

View reviewed changes

hbase-server/src/test/java/org/apache/hadoop/hbase/trace/OpenTelemetryTestRule.java Outdated Show resolved Hide resolved

Apache9 reviewed Feb 15, 2022

View reviewed changes

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncClientScanner.java Outdated Show resolved Hide resolved

ndimiduk force-pushed the 26545-trace-scans branch from ad27bcb to 12a5621 Compare February 17, 2022 14:24

ndimiduk marked this pull request as draft February 17, 2022 14:24

ndimiduk commented Feb 17, 2022

View reviewed changes

This comment was marked as outdated.

Sign in to view

ndimiduk force-pushed the 26545-trace-scans branch 3 times, most recently from 3b4b77f to 46d0c9d Compare February 21, 2022 16:28

This comment was marked as outdated.

Sign in to view

ndimiduk force-pushed the 26545-trace-scans branch from 46d0c9d to 4cc2aa4 Compare February 28, 2022 14:37

This comment was marked as outdated.

Sign in to view

ndimiduk force-pushed the 26545-trace-scans branch from 4cc2aa4 to 667c6d3 Compare March 7, 2022 13:51

This comment was marked as outdated.

Sign in to view

ndimiduk requested review from apurtell and busbey March 11, 2022 14:11

apurtell approved these changes Mar 11, 2022

View reviewed changes

ndimiduk force-pushed the 26545-trace-scans branch from e00d40c to 46d6e8f Compare March 14, 2022 10:01

Apache9 reviewed Mar 14, 2022

View reviewed changes

This comment was marked as outdated.

Sign in to view

Apache9 reviewed Mar 15, 2022

View reviewed changes

ndimiduk force-pushed the 26545-trace-scans branch from 46d6e8f to 2b7bc6d Compare March 21, 2022 16:09

This comment was marked as outdated.

Sign in to view

Apache9 reviewed Mar 26, 2022

View reviewed changes

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncClientScanner.java Show resolved Hide resolved

hbase-client/src/main/java/org/apache/hadoop/hbase/client/AsyncClientScanner.java Outdated Show resolved Hide resolved

ndimiduk force-pushed the 26545-trace-scans branch from 2b7bc6d to 92fbdc0 Compare March 28, 2022 08:01

Apache9 approved these changes Mar 28, 2022

View reviewed changes

ndimiduk force-pushed the 26545-trace-scans branch from 92fbdc0 to 2c439d2 Compare March 28, 2022 10:46

ndimiduk merged commit 620e5c6 into apache:master Mar 28, 2022

ndimiduk deleted the 26545-trace-scans branch March 28, 2022 10:47

HBASE-26545 Implement tracing of scan #4106

HBASE-26545 Implement tracing of scan #4106

Conversation

ndimiduk commented Feb 10, 2022

This comment was marked as outdated.

This comment was marked as outdated.

This comment was marked as outdated.

This comment was marked as outdated.

This comment was marked as outdated.

This comment was marked as outdated.

Apache9 commented Feb 12, 2022

ndimiduk commented Feb 14, 2022

ndimiduk commented Feb 17, 2022

Choose a reason for hiding this comment

This comment was marked as outdated.

This comment was marked as outdated.

This comment was marked as outdated.

ndimiduk commented Feb 21, 2022

This comment was marked as outdated.

This comment was marked as outdated.

This comment was marked as outdated.

This comment was marked as outdated.

This comment was marked as outdated.

ndimiduk commented Mar 10, 2022

apurtell left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

apurtell Mar 11, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ndimiduk Mar 14, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Apache9 commented Mar 14, 2022

This comment was marked as outdated.

This comment was marked as outdated.

This comment was marked as outdated.

Apache9 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ndimiduk commented Mar 21, 2022

This comment was marked as outdated.

This comment was marked as outdated.

This comment was marked as outdated.

ndimiduk commented Mar 22, 2022

This comment was marked as outdated.

Apache9 left a comment

Choose a reason for hiding this comment

Apache9 commented Mar 28, 2022

Apache-HBase commented Mar 28, 2022

Apache-HBase commented Mar 28, 2022

Apache-HBase commented Mar 28, 2022

apurtell Mar 11, 2022 •

edited

Loading

ndimiduk Mar 14, 2022 •

edited

Loading