[FLINK-15966][runtime] Capture callstacks for RPC ask() calls to improve exceptions. #11048

StephanEwen · 2020-02-10T11:54:42Z

What is the purpose of the change

This change preserves the call stack from the invocation of RPC ask() calls. When the call fails, this allows us to add a meaningful exception pointing to the original call site, rather than having just some weird stack trace from akka.

Note: While it is possible to do this for all types of ask() failures, this PR uses this approach for now only for timeouts.

Former exception message and stack trace:

akka.pattern.AskTimeoutException: Ask timed out on [Actor[akka://flink/user/test_name#-585757974]] after [1 ms]. Message of type [org.apache.flink.runtime.rpc.messages.LocalRpcInvocation]. A typical reason for `AskTimeoutException` is that the recipient actor didn't send a reply.
	at akka.pattern.PromiseActorRef$$anonfun$2.apply(AskSupport.scala:635)
	at akka.pattern.PromiseActorRef$$anonfun$2.apply(AskSupport.scala:635)
	at akka.pattern.PromiseActorRef$$anonfun$1.apply$mcV$sp(AskSupport.scala:648)
	at akka.actor.Scheduler$$anon$4.run(Scheduler.scala:205)
	at scala.concurrent.Future$InternalCallbackExecutor$.unbatchedExecute(Future.scala:601)
	at scala.concurrent.BatchingExecutor$class.execute(BatchingExecutor.scala:109)
	at scala.concurrent.Future$InternalCallbackExecutor$.execute(Future.scala:599)
	at akka.actor.LightArrayRevolverScheduler$TaskHolder.executeTask(LightArrayRevolverScheduler.scala:328)
	at akka.actor.LightArrayRevolverScheduler$$anon$4.executeBucket$1(LightArrayRevolverScheduler.scala:279)
	at akka.actor.LightArrayRevolverScheduler$$anon$4.nextTick(LightArrayRevolverScheduler.scala:283)
	at akka.actor.LightArrayRevolverScheduler$$anon$4.run(LightArrayRevolverScheduler.scala:235)
	at java.base/java.lang.Thread.run(Thread.java:834)

New exceptions and stack trace:

java.util.concurrent.TimeoutException: Invocation of java.util.concurrent.CompletableFuture org.apache.flink.runtime.rpc.akka.TimeoutCallStackTest$TestingGateway.callThatTimesOut(org.apache.flink.api.common.time.Time) timed out.
	at org.apache.flink.runtime.rpc.akka.TimeoutCallStackTest.testTimeoutException(TimeoutCallStackTest.java:87)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
	...

Brief change log

Add a new config option akka.ask.callstack (default: true)
Capture call stack at call site
Replace exception on timeout

Verifying this change

You can verify this with any Flink deployment where something times out, for example deploy/cancel calls when a TaskManager is killed

Does this pull request potentially affect one of the following parts:

Dependencies (does it add or upgrade a dependency): no
The public API, i.e., is any changed class annotated with @Public(Evolving): no
The serializers: no
The runtime per-record code paths (performance sensitive): no
Anything that affects deployment or recovery: JobManager (and its components), Checkpointing, Yarn/Mesos, ZooKeeper: no
The S3 file system connector: no

Documentation

Does this pull request introduce a new feature? yes
If yes, how is the feature documented? config docs

flinkbot · 2020-02-10T11:57:01Z

Thanks a lot for your contribution to the Apache Flink project. I'm the @flinkbot. I help the community
to review your pull request. We will use this comment to track the progress of the review.

Automated Checks

Last check on commit 04fe5b7 (Mon Feb 10 11:57:00 UTC 2020)

Warnings:

No documentation files were touched! Remember to keep the Flink docs up to date!

_{Mention the bot in a comment to re-run the automated checks.}

Review Progress

❓ 1. The [description] looks good.
❓ 2. There is [consensus] that the contribution should go into to Flink.
❓ 3. Needs [attention] from.
❓ 4. The change fits into the overall [architecture].
❓ 5. Overall code [quality] is good.

Please see the Pull Request Review Guide for a full explanation of the review process.

The Bot is tracking the review progress through labels. Labels are applied according to the order of the review items. For consensus, approval by a Flink committer of PMC member is required

Bot commands

The @flinkbot bot supports the following commands:

@flinkbot approve description to approve one or more aspects (aspects: description, consensus, architecture and quality)
@flinkbot approve all to approve all aspects
@flinkbot approve-until architecture to approve everything until architecture
@flinkbot attention @username1 [@username2 ..] to require somebody's attention
@flinkbot disapprove architecture to remove an approval you gave earlier

flinkbot · 2020-02-10T12:23:35Z

CI report:

04fe5b7 Travis: FAILURE Azure: FAILURE
7102a13 Travis: FAILURE Travis: SUCCESS Azure: SUCCESS Azure: PENDING

Bot commands

The @flinkbot bot supports the following commands:

@flinkbot run travis re-run the last Travis build
@flinkbot run azure re-run the last Azure build

…ove exceptions.

Jiayi-Liao · 2020-02-15T05:21:01Z

flink-core/src/main/java/org/apache/flink/configuration/AkkaOptions.java

 public class AkkaOptions {

+	/**
+	 * Timeout for akka ask calls.


forget to modify this :) ?

Jiayi-Liao · 2020-02-15T05:31:39Z

flink-runtime/src/main/java/org/apache/flink/runtime/rpc/akka/AkkaInvocationHandler.java

+
+		// remove the stack frames coming from the proxy interface invocation
+		final StackTraceElement[] stackTrace = callStackCapture.getStackTrace();
+		newException.setStackTrace(Arrays.copyOfRange(stackTrace, 3, stackTrace.length));


Can we filter the stack trace containing o.a.f.runtime.rpc.akka instead of using 3? Because others may change call stack of this function unintentionally in the future.

I would like to initially keep it like that. There is a test that guards this, so we should see it if someone breaks this by accident.

The check is slightly trickier than it looks, because the package name of the proxy class depends on visibility keyword of the interface, etc.

I would suggest to keep it simple for now and fix it when the test tells us that this simple solution is not enough. Then we should also know which cases cause it to break, what the involved classnames and package names are, etc.

zentol · 2020-02-15T08:27:44Z

flink-runtime/src/main/java/org/apache/flink/runtime/rpc/akka/AkkaInvocationHandler.java

+
+	static Throwable resolveTimeoutException(Throwable exception, @Nullable Throwable callStackCapture, Method method) {
+		if (callStackCapture == null || (!(exception instanceof akka.pattern.AskTimeoutException))) {
+			return exception;


The null branch implies that the exception type is dependent on the configuration option, which sounds like an accident waiting to happen if someone wants to handle timeouts explicitly as they would have to know what there are 2 types of timeouts that can occur.

How problematic would it be to always create a TimeoutException, and only have different behaviors for how the stacktrace is set?

I think that would be fine.
The main reason that I wanted this configurable is to have a way to turn call stack capture off, because during large RPC storms, this might add significantly to the memory consumption.
But always using a TimeoutException and referring to the RPC method name should be uncritical.

StephanEwen · 2020-02-18T16:34:06Z

Merged in 2746e6a

tillrohrmann

I'm a bit late to the party but the changes look really nice. This will help big time when debugging RPC timeout exceptions :-)

tisonkun · 2020-02-21T03:52:45Z

This is a really nice feature for debugging, indeed!

StephanEwen · 2020-02-21T12:40:21Z

Should we backport this to 1.10, switched off by default?
The one caveat is that it changes the resulting exception type, from akka.AskTimeoutException to java.util.concurrent.TimeoutException.

tillrohrmann · 2020-02-27T15:09:14Z

I couldn't find any direct usages of akka.AskTimeoutException in the production code. There is only usage in ResourceManagerTaskExecutorTest which might be affected by this change.

Apart from that the danger might be that users rely on AskTimeoutException for some exception matching. My gut feeling would be that this is more of a theoretical problem since the AskTimeoutException does not really add a lot of context and I would be surprised if people would really rely on it.

Hence, we could backport it but if we want to be on the safe side, then we only introduce it with Flink 1.11.

tisonkun · 2020-02-27T16:01:26Z

@tillrohrmann actually when I internally implement a job client depend on RPC, to support properly retry it depends on AskTimeoutException. However, it should be more elegant to wrap it into TimeoutException which is a Java standard Exception without pollute outside world with a Scala thirdparty library Exception.

tillrohrmann · 2020-03-04T09:55:09Z

Happy to do it, but not in a bug fix release.

[hotfix][runtime] Small docs/comments cleanups in RPC code.

1ab59d7

StephanEwen changed the title ~~Ask timeouts~~ [FLINK-15966][runtime] Capture callstacks for RPC ask() calls to improve exceptions. Feb 10, 2020

rmetzger added review=description? component=Runtime/Coordination labels Feb 10, 2020

[FLINK-15966][runtime] Capture callstacks for RPC ask() calls to impr…

7102a13

…ove exceptions.

StephanEwen force-pushed the ask_timeouts branch from 04fe5b7 to 7102a13 Compare February 10, 2020 17:36

StephanEwen requested a review from tillrohrmann February 11, 2020 10:58

Jiayi-Liao reviewed Feb 15, 2020

View reviewed changes

zentol reviewed Feb 15, 2020

View reviewed changes

StephanEwen closed this Feb 18, 2020

StephanEwen deleted the ask_timeouts branch February 19, 2020 14:57

tillrohrmann reviewed Feb 19, 2020

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

[FLINK-15966][runtime] Capture callstacks for RPC ask() calls to improve exceptions. #11048

[FLINK-15966][runtime] Capture callstacks for RPC ask() calls to improve exceptions. #11048

Uh oh!

StephanEwen commented Feb 10, 2020 •

edited

Loading

Uh oh!

flinkbot commented Feb 10, 2020

Uh oh!

flinkbot commented Feb 10, 2020 •

edited

Loading

Uh oh!

Jiayi-Liao Feb 15, 2020

Uh oh!

Jiayi-Liao Feb 15, 2020

Uh oh!

StephanEwen Feb 17, 2020

Uh oh!

zentol Feb 15, 2020

Uh oh!

StephanEwen Feb 17, 2020

Uh oh!

StephanEwen commented Feb 18, 2020

Uh oh!

tillrohrmann left a comment

Uh oh!

tisonkun commented Feb 21, 2020

Uh oh!

StephanEwen commented Feb 21, 2020

Uh oh!

tillrohrmann commented Feb 27, 2020

Uh oh!

tisonkun commented Feb 27, 2020

Uh oh!

tillrohrmann commented Mar 4, 2020

Uh oh!

Uh oh!

[FLINK-15966][runtime] Capture callstacks for RPC ask() calls to improve exceptions. #11048

[FLINK-15966][runtime] Capture callstacks for RPC ask() calls to improve exceptions. #11048

Uh oh!

Conversation

StephanEwen commented Feb 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

What is the purpose of the change

Brief change log

Verifying this change

Does this pull request potentially affect one of the following parts:

Documentation

Uh oh!

flinkbot commented Feb 10, 2020

Automated Checks

Review Progress

Uh oh!

flinkbot commented Feb 10, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

CI report:

Uh oh!

Jiayi-Liao Feb 15, 2020

Choose a reason for hiding this comment

Uh oh!

Jiayi-Liao Feb 15, 2020

Choose a reason for hiding this comment

Uh oh!

StephanEwen Feb 17, 2020

Choose a reason for hiding this comment

Uh oh!

zentol Feb 15, 2020

Choose a reason for hiding this comment

Uh oh!

StephanEwen Feb 17, 2020

Choose a reason for hiding this comment

Uh oh!

StephanEwen commented Feb 18, 2020

Uh oh!

tillrohrmann left a comment

Choose a reason for hiding this comment

Uh oh!

tisonkun commented Feb 21, 2020

Uh oh!

StephanEwen commented Feb 21, 2020

Uh oh!

tillrohrmann commented Feb 27, 2020

Uh oh!

tisonkun commented Feb 27, 2020

Uh oh!

tillrohrmann commented Mar 4, 2020

Uh oh!

Uh oh!

StephanEwen commented Feb 10, 2020 •

edited

Loading

flinkbot commented Feb 10, 2020 •

edited

Loading