trace: update tracing-subscriber to 0.2.0-alpha.5

[hawkw]

Version 0.0.7 of sharded-slab contains a bug where, when the remove
method is called with the index of a slot that is not being accessed
concurrently, the slot is emptied but not placed on the free list.
This issue meant that, under tracing-subscriber's usage pattern, where
slab entries are almost always uncontended when reused, allocated slab
pages are almost never reused, resulting in unbounded slab growth over
time (i.e. a memory leak).

This commit updates tracing-subscriber' to version 0.2.0-alpha.6,
which in turn bumps the sharded-slab dependency to v0.0.8, which
includes commit hawkw/sharded-slab@dfdd7ae. That commit fixes this bug.

I've empirically verified that, after running linkerd2-proxy under
load with a global trace filter that enables a lot of spans, heap
usage remains stable, and the characteristic stair-step heap growth
pattern of doubling slab allocations doesn't occur. This indicates that
freed slots are actually being reused, and (once fully warmed up), the
slab will only grow when the number of active spans in the system
increases.

Closes linkerd/linkerd2#3998

Signed-off-by: Eliza Weisman [email protected]

[olix0r]

Hmm... does this break log formatting? I see log lines like

[ 43809.10997271s] TRACE outbound:accept{{peer.addr}}:source{{target.addr}}:logical{{addr}}:making:profile:balance{{addr}}: linkerd2_app_core::trace::layer: poll ready

after enabling trace logging

need to check a few more things..

[olix0r]

Hmm, I'm also seeing some weird behavior with the log env...

      annotations:
        config.linkerd.io/proxy-log-level: linkerd2_http_metrics=info,linkerd2_metrics=info,linkerd=trace,warn

logs trace events for metrics modules

[hawkw]

@olix0r the trace events in linkerd2_metrics are enabled by the linkerd=trace directive. When specifying filters for different targets, if a more specific filter doesn't enable an event, it may still be enabled by a more general directive. tracing-subscriber has always had this behavior. This could definitely be changed (open an issue!) but it's always been there.

[hawkw]

Hmm... does this break log formatting? I see log lines like

[ 43809.10997271s] TRACE outbound:accept{{peer.addr}}:source{{target.addr}}:logical{{addr}}:making:profile:balance{{addr}}: linkerd2_app_core::trace::layer: poll ready

after enabling trace logging

hmm...that looks wrong to me — I didn't see this while testing, but I'll have to take another look?

Edit: hmm, everything looks fine for me:

[     0.269954304s] TRACE proxy{test=http1::outbound_asks_controller_api:proxy}:outbound{}:accept{peer.addr=127.0.0.1:51769}:source{target.addr=127.0.0.1:51764}:addr{addr=disco.test.svc.cluster.local:80}:logical{dst.logical=disco.test.svc.cluster.local:80}: linkerd2_app_core::profiles: response received

[olix0r]

Also... did the formatter change to no longer format levels as 4-char strings?

We now see DEBUG and TRACE -- this breaks vertical alignment in logs when mixed with INFO and WARN. I'm fine with using the longer strings but we should left-pad them with space so that they align?

[hawkw]

@olix0r whoops, I thought that our old custom formatter was identical to the default except for the (no longer used) custom logging contexts, but I had forgotten we formatted levels differently. FWIW, the default formatter should left-pad 4-character levels like INFO and WARN already. I can re-add a custom formatter to make it identical to the old formatting, though!

[hawkw]

FWIW, the default formatter should left-pad 4-character levels like INFO and WARN already.

ugh, apparently it only does that when ANSI colors are enabled? that looks like a bug upstream

[hawkw]

tokio-rs/tracing#560 should fix any wrong formatting with ansi colors turned off

[hawkw]

@olix0r I've published a new tracing-subscriber version with fixes for non-ANSI formatting and updated the proxy, should be all good now!

[olix0r]

I've tested this and don't see any of the issues I reported earlier

[kleimkuhler]

Looks good!