admin: add an endpoint to dump spawned Tokio tasks #595

hawkw · 2020-07-15T21:33:36Z

Motivation

When debugging proxy issues, it can be useful to inspect the list of
currently spawned Tokio tasks and their states. This can be used
similarly to the thread or coroutine dumps provided by other languages'
runtimes.

Solution

This branch adds a new endpoint to the proxy's admin server, /tasks,
that returns a dump of all tasks currently spawned on the Tokio runtime,
using the new Tracing instrumentation added in tokio-rs/tokio#2655, and
a work-in-progress tokio-trace crate that provides Tokio-specific
Tracing layers.

Currently, the /tasks admin endpoint records the following information
about each task:

Whether it is a normal, local, or blocking task (not relevant to us
currently, since Linkerd does not use local or blocking tasks...but
we might eventually!)
Whether the task is active (currently being polled) or idle (waiting
to be polled)
The type of the future that was spawned
The Tracing span context from which the task was spawned
The total number of times the task has been polled
Timing statistics about the task, including:
- The time in nanoseconds between when the task was spawned and when
  it was first polled (essentially, measuring the Tokio scheduler's
  latency)
- The total time in nanoseconds the task has existed
- The task's busy time in nanoseconds (time it was actively being
  polled)
- The tasks idle time in nanoseconds (time it was not being
  polled)

In the future, Tokio will likely expose additional Tracing information,
which we'll be able to collect as well.

The task dump can be accessed either as an HTML table or as JSON. JSON
is returned if the request has an Accept: application/json header, or
whenever the path /tasks.json is requested; otherwise, the data is
rendered as an HTML table. Like the /proxy-log-level endpoint, access
is denied to requests coming from sources other than localhost, to help
restrict access to authorized users (since a high volume of requests for
task dumps could be used to starve the proxy).

Example JSON output (in Firefox Dev Edition's extremely nice GUI
JSON viewer):

Zoomed in on the timing data for a single task:

And HTML:

Because the task data is generated from Tracing spans emitted by Tokio,
the task spans must be enabled for it to be used. This can be done by
setting a trace filter that enables the trace level for the target
tokio::task, e.g.:

tokio::task=trace

or

tokio=trace

Notes

This branch depends on unreleased code from upstream, including a
Tokio change that has merged to master but not been published, and my
unreleased work-in-progress tokio-trace crate. Therefore, I've
pinned these upstreams to fixed Git SHAs, to guard against
dependencies changing under us unexpectedly.
I considered requiring a build-time feature flag to enable this
feature, the way we do for the mock SO_ORIG_DST implementation for
testing. However, this would make it harder to use task tracking to
debug issues in proxies not built with the flag. I'm happy to change
this code to be feature flagged if we think that's the right approach.

Closes linkerd/linkerd2#3803

Signed-off-by: Eliza Weisman eliza@buoyant.io

olix0r · 2020-07-15T21:36:21Z

@hawkw re: feature-flagging: What's the "cost" of this? Is there any discernible different in benchmarks, for instance?

hawkw · 2020-07-15T21:37:50Z

@hawkw re: feature-flagging: What's the "cost" of this? Is there any discernible different in benchmarks, for instance?

It should be pretty minimal when disabled at runtime, but I'll do a benchmark run to make sure, good call.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

davidbarsky · 2020-07-23T19:13:30Z

linkerd/app/core/src/admin/tasks.rs

+};
+use tokio_trace::tasks::TaskList;
+#[derive(Clone)]
+pub struct Tasks {


Not a blocker (obviously) but do you think this can live in hawkw/tokio-trace behind a feature flag?

kleimkuhler

This works well for me!

I installed linkerd with this change as the proxy version and set up a port-forward for 4191 from the controller pod.

I can go to localhost:4191/tasks or localhost:4191/tasks.json and see all the tasks for the controller's proxy.

kleimkuhler · 2020-07-24T00:25:07Z

Dockerfile

@@ -36,21 +36,21 @@ ARG PROXY_UNOPTIMIZED
 ARG PROXY_FEATURES

 RUN --mount=type=cache,target=/var/lib/apt/lists \
-    --mount=type=cache,target=/var/tmp \
-    apt update && apt install -y time cmake
+  --mount=type=cache,target=/var/tmp \


Auto formatting here? Not a blocker but just wondering if this was intentional.

yup, i think this change can be removed entirely — this was left over from an attempt at feature-flagging.

Yeah, would prefer to revert this as it removes some indentation below

olix0r · 2020-07-24T16:04:57Z

@hawkw re: feature-flagging: What's the "cost" of this? Is there any discernible different in benchmarks, for instance?

@hawkw Have you run benchmarks since your updates?

hawkw · 2020-07-24T20:52:12Z

@hawkw re: feature-flagging: What's the "cost" of this? Is there any discernible different in benchmarks, for instance?

@hawkw Have you run benchmarks since your updates?

@olix0r here are benchmark results with the most recent commit to this branch. Looks like a little bit of overhead:

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

hawkw · 2020-07-24T22:30:18Z

@ver my latest commit 3f404bb should decrease the overhead a little bit more:

(except for in the x100 case, weirdly? maybe that was bench env noise?)

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

olix0r · 2020-07-28T00:16:42Z

linkerd/app/core/src/trace.rs

-            Self::Json(level) => level.reload(filter)?,
-            Self::Plain(level) => level.reload(filter)?,
+            LevelHandle::Json(level) => level.reload(filter)?,
+            LevelHandle::Plain(level) => level.reload(filter)?,


Why change this from Self?

I think these methods briefly moved to a different type and then came back. Will back that out.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

olix0r · 2020-07-30T17:07:49Z

@hawkw looks like this merge wasn't clean

hawkw · 2020-07-30T18:10:52Z

@hawkw looks like this merge wasn't clean

yeah, I'm fixing that up right now!

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

This release enables a multi-threaded runtime. Previously, the proxy would only ever use a single thread for data plane processing; now, when the proxy is allocated more than 1 CPU share, the proxy allocates a thread per available CPU. This has shown substantial latency improvements in benchmarks, especially when the proxy is serving requests for many concurrent connections. --- * Add a `multicore` feature flag (linkerd/linkerd2-proxy#611) * Add `multicore` to default features (linkerd/linkerd2-proxy#612) * admin: add an endpoint to dump spawned Tokio tasks (linkerd/linkerd2-proxy#595) * trace: roll `tracing` and `tracing-subscriber` dependencies (linkerd/linkerd2-proxy#615) * stack: Add NewService::into_make_service (linkerd/linkerd2-proxy#618) * trace: tweak tracing & test support for the multithreaded runtime (linkerd/linkerd2-proxy#616) * Make FailFast cloneable (linkerd/linkerd2-proxy#617) * Move HTTP detection & server into linkerd2_proxy_http (linkerd/linkerd2-proxy#619) * Mark tap integration tests as flakey (linkerd/linkerd2-proxy#621) * Introduce a SkipDetect layer to preempt detection (linkerd/linkerd2-proxy#620)

hawkw requested review from olix0r and a team July 15, 2020 21:33

hawkw self-assigned this Jul 15, 2020

hawkw force-pushed the eliza/tokio-trace branch from cb0aa92 to 03e8cb2 Compare July 23, 2020 18:11

hawkw added 24 commits July 23, 2020 11:43

whoa it actually works now

363a2fe

make it look slightly less awful

94e91a5

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

timings/fancy table

b2db8c6

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

lol im good at html

6577aa5

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

lol im super good at html

1dd5599

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

whoopsie

4ae2063

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

blaaahhhh

f6bcab7

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

i'm *really* good at html

e590656

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

track total polls

d060941

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

json for @olix0r <3

3773642

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

use pretty ctor

ab9f68d

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

fixup serde stuff

57f9f0b

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

fixup

9607c6e

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

fixup tests

4557bdf

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

include tasks layer in json mode too

6eea722

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

require loopback to dump tasks

f4f3b1b

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

fixup

1aeb47b

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

fix panic in time-to-first-poll

e6e077b

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

pin unreleased crate to SHA

5addbd4

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

disembreak test

92750ed

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

upstream perf fixes

b42615c

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

use release version of Tokio!

519ce8c

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

rm patch

0ebff79

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

manual lockfile surgery

86db3c4

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

whoopsy

32051a4

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

hawkw force-pushed the eliza/tokio-trace branch from d2adde4 to 32051a4 Compare July 23, 2020 18:49

davidbarsky reviewed Jul 23, 2020

View reviewed changes

kleimkuhler approved these changes Jul 24, 2020

View reviewed changes

hawkw added 2 commits July 24, 2020 14:22

maybe hit filters less for task tracking

3f404bb

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

also handle disabling ansi correctly

84296a4

apparently i managed to screw up toml syntax somehow

d02213b

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

olix0r reviewed Jul 28, 2020

View reviewed changes

hawkw added 2 commits July 28, 2020 16:47

put back selfs

e3a3fc0

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Merge branch 'main' into eliza/tokio-trace

f2be0b0

hawkw added 2 commits July 30, 2020 11:41

fixup

bd0bbe7

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Merge branch 'main' into eliza/tokio-trace

7dad10d

hawkw mentioned this pull request Jul 31, 2020

[WIP] use tracing-flame to generate flamegraphs of tracing spans #614

Closed

olix0r approved these changes Jul 31, 2020

View reviewed changes

hawkw merged commit d5fe0e6 into main Jul 31, 2020

hawkw deleted the eliza/tokio-trace branch July 31, 2020 23:54

olix0r mentioned this pull request Aug 6, 2020

proxy: v2.106.0 linkerd/linkerd2#4842

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

admin: add an endpoint to dump spawned Tokio tasks #595

admin: add an endpoint to dump spawned Tokio tasks #595

hawkw commented Jul 15, 2020

olix0r commented Jul 15, 2020

hawkw commented Jul 15, 2020

davidbarsky Jul 23, 2020

hawkw Jul 23, 2020

kleimkuhler left a comment

kleimkuhler Jul 24, 2020

hawkw Jul 24, 2020

olix0r Jul 28, 2020

olix0r commented Jul 24, 2020

hawkw commented Jul 24, 2020

hawkw commented Jul 24, 2020

olix0r Jul 28, 2020

hawkw Jul 28, 2020

olix0r commented Jul 30, 2020

hawkw commented Jul 30, 2020

admin: add an endpoint to dump spawned Tokio tasks #595

admin: add an endpoint to dump spawned Tokio tasks #595

Conversation

hawkw commented Jul 15, 2020

Motivation

Solution

Notes

olix0r commented Jul 15, 2020

hawkw commented Jul 15, 2020

davidbarsky Jul 23, 2020

Choose a reason for hiding this comment

hawkw Jul 23, 2020

Choose a reason for hiding this comment

kleimkuhler left a comment

Choose a reason for hiding this comment

kleimkuhler Jul 24, 2020

Choose a reason for hiding this comment

hawkw Jul 24, 2020

Choose a reason for hiding this comment

olix0r Jul 28, 2020

Choose a reason for hiding this comment

olix0r commented Jul 24, 2020

hawkw commented Jul 24, 2020

hawkw commented Jul 24, 2020

olix0r Jul 28, 2020

Choose a reason for hiding this comment

hawkw Jul 28, 2020

Choose a reason for hiding this comment

olix0r commented Jul 30, 2020

hawkw commented Jul 30, 2020