Add ENVOY_LOG_PERIODIC by oschaaf · Pull Request #12961 · envoyproxy/envoy

oschaaf · 2020-09-02T22:40:14Z

Follow up to #12830 with another sparse log variant.
The periodic version relies on a real world time source, which can
be discussed separately here.

Signed-off-by: Otto van der Schaaf oschaaf@we-amp.com

Risk Level: Low
Testing: Unit tests

Follow up to envoyproxy#12830 with another sparse log variant. The periodic version relies on a real world time source, which can be discussed separately here. Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

oschaaf · 2020-09-02T22:40:25Z

/assign htuch
/cc @ggreenway

source/common/common/logger.h

test/common/common/log_macros_test.cc

htuch

LGTM, but quick check with @jmarantz on whether it would make sense to have a time singleton here for testing.

jmarantz · 2020-09-03T20:42:55Z

IMO I'd rather test with real-time here and not introduce singletons.

htuch

Thanks!

source/common/common/logger.h

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

source/common/common/logger.h

glodomorski · 2020-09-04T13:10:34Z

source/common/common/logger.h

-      ENVOY_LOG(LEVEL, ##__VA_ARGS__);                                                             \
+    if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) {                                             \
+      static auto* countdown = new std::atomic<uint64_t>();                                        \
+      if (countdown->fetch_add(1) < N) {                                                           \


The counter may eventually overflow. ;)

source/common/common/logger.h

glodomorski · 2020-09-04T13:41:01Z

source/common/common/logger.h

-      ENVOY_LOG(LEVEL, ##__VA_ARGS__);                                                             \
+    if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) {                                             \
+      static auto* count = new std::atomic<uint64_t>();                                            \
+      if (std::bitset<64>(1 + count->fetch_add(1)).count() == 1) {                                 \


How about this kind of thing:

auto bits = count->fetch_add(1); if ( bits && !(bits & (bits-1)) )

The unsigned type here is fine.
Any bitwise && of any power of 2 with a number less by 1 will give 0. No need to involve std::bitset and we get rid of that magic number too.

I went with std::bitset because I think I remember it being compiled to something fast under the hood (__builtin_popcount?); but also - and this is probably subjective - I find it easier to grok. The +1 deserves a comment, e.g. // +1 because the first hit needs to be logged, but this imho this also wouldn't hurt with the -1 (or maybe the whole expression) in the variant you propose, depending on who the audience is?

Ok. Let's leave it be for now, no problemo. bitset.count() is readable, true.
Yes, __builtin_popcount for GCC and for LLVM it's a similar thing; which translates, depending on the platform, into about 2-3 cpu intructions, or into Kernighan’s algorithm (latter is slower than this little trick).

But you're right. To follow readibility guidelines i should've suggested a lambda at least here, sth like auto is_exactly_one_bit_set = [](const uint64_t bits) { return bits && !(bits & (bits-1)); };.

glodomorski · 2020-09-04T14:05:45Z

I'm still trying to figure out how relaxed these atomic ops we could make. We probably can be fine with memory_order_consume in some cases, and, depending on the platform, go with a logic based on compare_exchange_weak (like, do we even care for spurious failures in sparse logging?). With atomics running on default full sequential consistency (the default is memory_order_seq_cst everywhere iirc) we may be introducing unnecessary sync points.
I'll bite deeper into it next week and hopefully be able to give some design ideas there. (Logging is always very interesting and complex topic.)

oschaaf · 2020-09-04T14:24:26Z

re: I'm still trying to figure out how relaxed these atomic ops we could make.

Yeah, I had some similar thoughts there: #12830 (comment)
But I wanted to propose the "straight forward" version first. But I was thinking that this could potentially go from being precise to tracking local to the thread and accepting the log line duplication. Or maybe approximate what was configured by relaxing barriers a lot, trading precision for speed.
Also, in a thread local variant, maybe working with an assumption that log lines will be hit evenly distributed across workers allows a different type of opportunity. For example guaranteeing caps by dividing the periodic log frequency by the number of workers.

glodomorski · 2020-09-04T14:33:45Z

Rgr. Pretty much exactly my thoughts. I won't be blocking you on this PR anymore, apologies. Let's get it going. I will read up on this and hopefully be able to contribute with more insight later on.

oschaaf · 2020-09-04T14:42:24Z

Rgr. Pretty much exactly my thoughts. I won't be blocking you on this PR anymore, apologies. Let's get it going. I will read up on this and hopefully be able to contribute with more insight later on.

Sure; super appreciate the feedback. If you want, we can discuss more on Slack too if you like, my handle is oschaaf.

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

glodomorski

approved, but keeping my eye on it ;)

htuch · 2020-09-08T14:40:21Z

source/common/common/logger.h

-    if ((count->fetch_add(1) % N) == 0) {                                                          \
-      ENVOY_LOG(LEVEL, ##__VA_ARGS__);                                                             \
+    if (ENVOY_LOG_COMP_LEVEL(ENVOY_LOGGER(), LEVEL)) {                                             \
+      static auto* count = new std::atomic<int64_t>();                                             \


Please switch these back to uint64_t. There is no possibility of overflow in 500+ years if we're bumping once a nanosecond..

Done in 15819e6, except in the case where it's implied via the chrono count() call.

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

htuch

LGTM, thanks!

htuch · 2020-09-09T15:47:35Z

@oschaaf this looks like a legitimate build failure on Windows.

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

oschaaf · 2020-09-09T16:46:10Z

@oschaaf this looks like a legitimate build failure on Windows.

Pushed efbabc5 to resolve a platform issue. Let's hope that resolves the CI error.

Add ENVOY_LOG_PERIODIC

42a4eba

Follow up to envoyproxy#12830 with another sparse log variant. The periodic version relies on a real world time source, which can be discussed separately here. Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

repokitteh-read-only bot assigned htuch Sep 2, 2020

glodomorski suggested changes Sep 3, 2020

View reviewed changes

source/common/common/logger.h Outdated Show resolved Hide resolved

test/common/common/log_macros_test.cc Outdated Show resolved Hide resolved

htuch reviewed Sep 3, 2020

View reviewed changes

htuch previously approved these changes Sep 3, 2020

View reviewed changes

glodomorski suggested changes Sep 4, 2020

View reviewed changes

source/common/common/logger.h Outdated Show resolved Hide resolved

Review feedback

85003d4

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

oschaaf dismissed htuch’s stale review via 85003d4 September 4, 2020 12:13

Amend comment

aca8716

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

glodomorski reviewed Sep 4, 2020

View reviewed changes

Review feedback II

541e555

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

glodomorski previously approved these changes Sep 4, 2020

View reviewed changes

htuch reviewed Sep 8, 2020

View reviewed changes

review feedback: uint64 where it's not implied

15819e6

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

oschaaf dismissed glodomorski’s stale review via 15819e6 September 8, 2020 20:26

htuch previously approved these changes Sep 9, 2020

View reviewed changes

oschaaf added 2 commits September 9, 2020 18:22

Merge remote-tracking branch 'upstream/master' into envoy-log-periodic

cc387f0

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

Fix platform issue, eliminate sleep() call.

efbabc5

Signed-off-by: Otto van der Schaaf <oschaaf@we-amp.com>

oschaaf dismissed htuch’s stale review via efbabc5 September 9, 2020 16:44

htuch approved these changes Sep 9, 2020

View reviewed changes

htuch merged commit 5187c34 into envoyproxy:master Sep 9, 2020

Conversation

oschaaf commented Sep 2, 2020

Uh oh!

oschaaf commented Sep 2, 2020

Uh oh!

Uh oh!

Uh oh!

htuch left a comment

Choose a reason for hiding this comment

Uh oh!

jmarantz commented Sep 3, 2020

Uh oh!

htuch left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

glodomorski Sep 4, 2020

Choose a reason for hiding this comment

Uh oh!

Uh oh!

glodomorski Sep 4, 2020

Choose a reason for hiding this comment

Uh oh!

oschaaf Sep 4, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

glodomorski Sep 4, 2020

Choose a reason for hiding this comment

Uh oh!

glodomorski commented Sep 4, 2020

Uh oh!

oschaaf commented Sep 4, 2020

Uh oh!

glodomorski commented Sep 4, 2020

Uh oh!

oschaaf commented Sep 4, 2020

Uh oh!

glodomorski left a comment

Choose a reason for hiding this comment

Uh oh!

htuch Sep 8, 2020

Choose a reason for hiding this comment

Uh oh!

oschaaf Sep 8, 2020

Choose a reason for hiding this comment

Uh oh!

htuch left a comment

Choose a reason for hiding this comment

Uh oh!

htuch commented Sep 9, 2020

Uh oh!

oschaaf commented Sep 9, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

oschaaf Sep 4, 2020 •

edited

Loading