Skip to content

common: add support for thread local sink overrides#18785

Merged
jmarantz merged 8 commits intomainfrom
tls-logging-context
Nov 1, 2021
Merged

common: add support for thread local sink overrides#18785
jmarantz merged 8 commits intomainfrom
tls-logging-context

Conversation

@snowp
Copy link
Copy Markdown
Contributor

@snowp snowp commented Oct 26, 2021

Commit Message:
This adds support for specifying a SinkDelegate that should be active
only on the current thread. This allows for per thread overrides of the
logging context, which opens up for overriding the logger for the
duration of a dispatcher event as well as overriding the logger for
specific function calls.
Additional Description: n/a
Risk Level: Low
Testing: New UTs, benchmarks
Docs Changes: n/a
Release Notes: n/a
Platform Specific Features: n/a

Snow Pettersen added 3 commits October 26, 2021 19:35
This adds support for specifying a SinkDelegate that should be active
only on the current thread. This allows for per thread overrides of the
logging context, which opens up for overriding the logger for the
duration of a dispatcher event as well as overriding the logger for
specific function calls.

Signed-off-by: Snow Pettersen <snowp@lyft.com>
Signed-off-by: Snow Pettersen <snowp@lyft.com>
Signed-off-by: Snow Pettersen <snowp@lyft.com>
@repokitteh-read-only
Copy link
Copy Markdown

As a reminder, PRs marked as draft will not be automatically assigned reviewers,
or be handled by maintainer-oncall triage.

Please mark your PR as ready when you want it to be reviewed!

🐱

Caused by: #18785 was opened by snowp.

see: more, trace.

@snowp
Copy link
Copy Markdown
Contributor Author

snowp commented Oct 26, 2021

logger_benchmarks after this change:

----------------------------------------------------------------------------------------
Benchmark                                              Time             CPU   Iterations
----------------------------------------------------------------------------------------
fancySlowPath/1024                                 55798 ns        55799 ns        12502
fancySlowPath/1024/process_time/threads:20        239374 ns      1124911 ns          620
fancySlowPath/1024/process_time/threads:200       186730 ns       775332 ns         1000
fancyMediumPath/1/iterations:1                     94097 ns        93742 ns            1
fancyFastPath/1024/0                                 572 ns          572 ns      1215734
fancyFastPath/1024/1                              863527 ns       863532 ns          810
fancyFastPath/1024/0/process_time/threads:20        52.7 ns          939 ns      1091080
fancyFastPath/1024/1/process_time/threads:20     1196688 ns      3203692 ns          200
fancyFastPath/1024/0/process_time/threads:200       11.6 ns          515 ns      2413000
fancyFastPath/1024/1/process_time/threads:200     924438 ns      2415483 ns          400
envoyNormal/1024/0                                  4775 ns         4775 ns       146659
envoyNormal/1024/1                                872084 ns       872083 ns          802
envoyNormal/1024/0/process_time/threads:20           363 ns         5688 ns       144020
envoyNormal/1024/1/process_time/threads:20       1263218 ns      3418039 ns          220
envoyNormal/1024/0/process_time/threads:200         93.9 ns         4143 ns       200000
envoyNormal/1024/1/process_time/threads:200       971759 ns      2514109 ns          200
fancyLevelSetting/1024                             45543 ns        45543 ns        15575
envoyLevelSetting/1024                              8282 ns         8282 ns        85165

Running on main:

fancySlowPath/1024                                 55781 ns        55781 ns        12380
fancySlowPath/1024/process_time/threads:20        243714 ns      1126557 ns          640
fancySlowPath/1024/process_time/threads:200       188794 ns       778096 ns         1000
fancyMediumPath/1/iterations:1                     98464 ns        98114 ns            1
fancyFastPath/1024/0                                 566 ns          566 ns      1223967
fancyFastPath/1024/1                              872297 ns       872302 ns          810
fancyFastPath/1024/0/process_time/threads:20        49.7 ns          840 ns      1085340
fancyFastPath/1024/1/process_time/threads:20     1251726 ns      3259741 ns          220
fancyFastPath/1024/0/process_time/threads:200       10.9 ns          471 ns      2000000
fancyFastPath/1024/1/process_time/threads:200    1027398 ns      2639843 ns          200
envoyNormal/1024/0                                  4767 ns         4767 ns       143457
envoyNormal/1024/1                                874195 ns       874199 ns          799
envoyNormal/1024/0/process_time/threads:20           399 ns         6699 ns       191080
envoyNormal/1024/1/process_time/threads:20       1289699 ns      3224021 ns          240
envoyNormal/1024/0/process_time/threads:200         94.2 ns         4205 ns       200000
envoyNormal/1024/1/process_time/threads:200       997137 ns      2567342 ns          200
fancyLevelSetting/1024                             45478 ns        45476 ns        15410
envoyLevelSetting/1024                              8222 ns         8222 ns        85135

Invoked via bazel run -c opt //test/common/common:logger_speed_test 2> /dev/null

@snowp
Copy link
Copy Markdown
Contributor Author

snowp commented Oct 26, 2021

@mattklein123 @ggreenway First stab at TLS logging override.

One thing to note is that using a thread_local within DelegatingLogSink means that two instances of DelegatingLogSink would end up consulting the same thread_local instance when looking for a TLS override. Since we have a use case of this internally I made this overridable via a base class, but lmk if anyone has a better idea. We could also change our internal usage to not rely on a second DelegatingLogSink, but figured I'd put this up

@mattklein123 mattklein123 self-assigned this Oct 26, 2021
@snowp snowp marked this pull request as ready for review October 26, 2021 21:48
Signed-off-by: Snow Pettersen <snowp@lyft.com>
@snowp
Copy link
Copy Markdown
Contributor Author

snowp commented Oct 27, 2021

/retest

@repokitteh-read-only
Copy link
Copy Markdown

Retrying Azure Pipelines:
Retried failed jobs in: envoy-presubmit

🐱

Caused by: a #18785 (comment) was created by @snowp.

see: more, trace.

Copy link
Copy Markdown
Member

@mattklein123 mattklein123 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks this makes sense to me. I have a couple of questions. From my read the perf delta is not very much if any so this is probably fine to add. cc @ggreenway

/wait


void SinkDelegate::setTlsDelegate() {
assert(previous_delegate_ == nullptr);
previous_delegate_ = log_sink_->tlsDelegate();
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Shouldn't this actually be a previous TLS delegate that is different from the global previous delegate?

Comment on lines +229 to +231
// This is virtual in order to allow for multiple DelegatingLogSinks to exist and use different
// thread local overrides. A base class defining a new thread_local would be necessary for each
// DelegatingLogSink that will coexist.
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry I'm a little lost on this. How would multiple overrides exist in practice? Don't we want there to be a single logger at a given time? If we don't have a use for this can we make this non-virtual for now?

Snow Pettersen added 2 commits October 28, 2021 01:30
Signed-off-by: Snow Pettersen <snowp@lyft.com>
Signed-off-by: Snow Pettersen <snowp@lyft.com>
Signed-off-by: Snow Pettersen <snowp@lyft.com>
mattklein123
mattklein123 previously approved these changes Oct 28, 2021
Copy link
Copy Markdown
Member

@mattklein123 mattklein123 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks!

@snowp
Copy link
Copy Markdown
Contributor Author

snowp commented Oct 28, 2021

@jmarantz @ggreenway either of you mind doing a non-Lyft review?

@jmarantz jmarantz self-assigned this Oct 28, 2021
@jmarantz
Copy link
Copy Markdown
Contributor

I'll take a look if you can wait a few hours.

Copy link
Copy Markdown
Contributor

@jmarantz jmarantz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

lgtm basically with small nit.


SinkDelegate** tlsSink() {
static thread_local SinkDelegate* tls_sink = nullptr;

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

minor nits: slightly prefer outlining some of these non-trivial impls into logger.cc. Any reason not to do it for these untemplated methods?

also do we need the blank line above here?

@jmarantz
Copy link
Copy Markdown
Contributor

Also, would you mind augmenting your microbenchmark numbers with the conclusions from that? I was trying to compare the two tables and couldn't figure out a tangible difference.

Signed-off-by: Snow Pettersen <snowp@lyft.com>
@snowp
Copy link
Copy Markdown
Contributor Author

snowp commented Oct 29, 2021

My takeaway was also that there was no significant difference. I ran it again and used the benchmark compare.py script to get a comparison:

➜  envoy git:(main) ✗ ../benchmark/tools/compare.py benchmarks old.json new.json
Comparing old.json to new.json
Benchmark                                                       Time             CPU      Time Old      Time New       CPU Old       CPU New
--------------------------------------------------------------------------------------------------------------------------------------------
fancySlowPath/1024                                           +0.0148         +0.0148         56388         57222         56388         57222
fancySlowPath/1024/process_time/threads:20                   -0.0828         -0.0284        250647        229905       1159673       1126693
fancySlowPath/1024/process_time/threads:200                  -0.0193         -0.0228        190559        186879        794117        775979
fancyMediumPath/1/iterations:1                               -0.0042         -0.0008         92588         92200         91877         91802
fancyFastPath/1024/0                                         +0.0326         +0.0326           565           584           565           584
fancyFastPath/1024/1                                         +0.7239         +0.0100     127697822     220135131       2902453       2931482
fancyFastPath/1024/0/process_time/threads:20                 +0.1556         +0.1310            38            44           632           715
fancyFastPath/1024/1/process_time/threads:20                 -0.1190         +0.0836      95193269      83869207       6705067       7265933
fancyFastPath/1024/0/process_time/threads:200                +0.0292         +0.0712            11            11           484           519
fancyFastPath/1024/1/process_time/threads:200                +1.5519         -0.0552      35492050      90571583       6796856       6421683
envoyNormal/1024/0                                           -0.0172         -0.0172          4757          4675          4757          4675
envoyNormal/1024/1                                           -0.8045         +0.0082     100137038      19575857       3010517       3035198
envoyNormal/1024/0/process_time/threads:20                   +0.0944         +0.0597           309           338          5082          5385
envoyNormal/1024/1/process_time/threads:20                   -0.7099         -0.0051      56534340      16401031       6942824       6907072
envoyNormal/1024/0/process_time/threads:200                  +0.0309         +0.0072            82            85          3717          3744
envoyNormal/1024/1/process_time/threads:200                  -0.3589         -0.0133      30771014      19727795       6363320       6278519
fancyLevelSetting/1024                                       -0.0129         -0.0129         46016         45424         46016         45424
envoyLevelSetting/1024                                       -0.0140         -0.0140          8241          8126          8241          8125

The differences seem to be inline with the differences we're seeing fancy log exhibit between the test runs, which wasn't touched at all by this PR. tl;dr not a big difference

return &tls_sink;
}

void DelegatingLogSink::setTlsDelegate(SinkDelegate* sink) { *tlsSink() = sink; }
Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FWIW I was OK with these 2 one-liners inlined, but this is fine too.

@jmarantz jmarantz merged commit fe2212c into main Nov 1, 2021
@mattklein123 mattklein123 deleted the tls-logging-context branch November 9, 2021 04:12
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants