fix time_since_epoch different in different os default return precision #4288

zyfjeff · 2018-08-29T05:40:20Z

Signed-off-by: tianqian.zyf [email protected]

Description: time_since_epoch different in different os default return precision, use abseil time library to use unified timestamp
Risk Level: low
Testing: N/A
Docs Changes:
Release Notes:
[Optional Fixes #Issue] #4278
[Optional Deprecated:]

zyfjeff · 2018-08-29T07:34:18Z

==21403==ERROR: AddressSanitizer: initialization-order-fiasco on address 0x00000b5e4e20 at pc 0x000003961e2a bp 0x7ffeb6aada40 sp 0x7ffeb6aada38
READ of size 4 at 0x00000b5e4e20 thread T0
    #0 0x3961e29 in std::__atomic_base<unsigned int>::load(std::memory_order) const /usr/bin/../lib/gcc/x86_64-linux-gnu/5.4.0/../../../../include/c++/5.4.0/bits/atomic_base.h:396:9
    #1 0x3961e29 in absl::base_internal::SpinLock::TryLockImpl() /proc/self/cwd/external/com_google_absl/absl/base/internal/spinlock.h:167
    #2 0x395ec13 in absl::base_internal::SpinLock::Lock() /proc/self/cwd/external/com_google_absl/absl/base/internal/spinlock.h:81:10
    #3 0x399291a in absl::GetCurrentTimeNanosSlowPath() /proc/self/cwd/external/com_google_absl/absl/time/clock.cc:393:8
    #4 0x39927cc in absl::GetCurrentTimeNanos() /proc/self/cwd/external/com_google_absl/absl/time/clock.cc:353:10
    #5 0x39911eb in absl::Now() /proc/self/cwd/external/com_google_absl/absl/time/clock.cc:39:15
    #6 0x588fcc in __cxx_global_var_init.49 /proc/self/cwd/external/envoy/test/test_common/utility.cc:37:47
    #7 0x5891c2 in _GLOBAL__sub_I_utility.cc /proc/self/cwd/external/envoy/test/test_common/utility.cc

Look abseil time library cause AddressSanitizer fail

dnoe · 2018-08-29T18:07:44Z

test/test_common/utility.cc

-static const int32_t SEED = std::chrono::duration_cast<std::chrono::nanoseconds>(
-                                std::chrono::system_clock::now().time_since_epoch())
-                                .count();
+static const int32_t SEED = absl::ToUnixNanos(absl::Now());


This looks like the spot where the static initialization fiasco is getting introduced. I'm actually surprised it wasn't an issue before - maybe it was, and the effect is benign if it just perturbs the random seed.

I would try the technique described in https://isocpp.org/wiki/faq/ctors#static-init-order-on-first-use to see if the ASAN error goes away.

Thanks, you are right

lizan

I think this direction (introducing absl::Time) is right. Though another thing to consideration is incorporate this better with Envoy::TimeSource, @jmarantz?

lizan · 2018-08-30T08:35:24Z

test/test_common/utility.cc

-                                std::chrono::system_clock::now().time_since_epoch())
-                                .count();
+int32_t getSeed() {
+  static int32_t seed = absl::ToUnixNanos(absl::Now());


Is it necessary to add a const to the return value that is a value type?

Is this what we want, to have the seed be static for the binary, as opposed to static for an individual test? Moreover, this may be related to the AddressSanitizer problem you have above.

More good reading about the static initialization "fiasco" referenced in the AddressSanitizer report is here:

https://isocpp.org/wiki/faq/ctors#static-init-order-on-first-use

My personal rule of thumb: avoid class statics and pre-main function-calls wherever possible and programs will be easier to reason about and more portable. Compile-time initialized scalars, arrays, and structs are fine.

Re the "const" question; that's covered in https://google.github.io/styleguide/cppguide.html#Use_of_const

jmarantz

Can you explain more about why you want to move from std::chrono to absl::time? From the description I don't fully understand what problem this solves.

If we do that I think it should be done pretty broadly over all of Envoy, and might be a bit easier in conjunction with follow-ups to #4257 , with check_format enhancements extending what's in #4248 to ensure we are working with a single coherent time system.

jmarantz · 2018-08-30T11:58:54Z

test/test_common/utility.cc

-                                std::chrono::system_clock::now().time_since_epoch())
-                                .count();
+int32_t getSeed() {
+  static int32_t seed = absl::ToUnixNanos(absl::Now());


Is this what we want, to have the seed be static for the binary, as opposed to static for an individual test? Moreover, this may be related to the AddressSanitizer problem you have above.

dnoe · 2018-08-30T13:00:43Z

@jmarantz Can you drive this PR to some conclusion that is compatible with your WIP? Thanks.

zyfjeff · 2018-08-30T14:19:14Z

@jmarantz
There are two main points:

std::chrono::system_clock::now().time_since_epoch() the duration unit returned by the default os is different, uniform use of absl::time can avoid this problem, Different unit of timestamp in metrics_service in linux and macos #4278 it is because of this problem that the timestamp units returned by metrics are different in different os.

  metric->set_timestamp_ms(std::chrono::system_clock::now().time_since_epoch().count());

Use absl::ToUnixMillis(absl::Now() to increase the readability of the code

-   const auto unix_timestamp = std::chrono::duration_cast<std::chrono::seconds>(
                                  std::chrono::system_clock::now().time_since_epoch())
                                  .count();
+   const auto unix_timestamp = absl::ToUnixSeconds(absl::Now());

jmarantz · 2018-08-30T15:07:18Z

Would it be possible to solve #4278 by using std::chrono differently, rather than switching to a different time library?

jmarantz · 2018-08-30T15:10:37Z

test/test_common/utility.cc

-                                std::chrono::system_clock::now().time_since_epoch())
-                                .count();
+int32_t getSeed() {
+  static const int32_t seed = absl::ToUnixNanos(absl::Now());


I see. The old code was probably only working because it got 'lucky', despite its static-init fiasco. With absl::time you are getting less lucky.

Can you try just removing the 'static' keyword here? It will only get called once (per test) when TestRandomGenerator is constructed, and that should be fine.

@jmarantz I'm reviewing #4314 atm and I tend to think it would be better to make this static. TestRandomGenerator can be constructed more than once per test; it's just a stack or member variable, it seems safer to ensure that it has a consistent seed each time.

Actually I followed up in #4314 as that's where the code change is being proposed; hopefully there's enough context there now.

zyfjeff · 2018-08-30T15:51:49Z

@jmarantz of course, but I still think that replacing std::chrono with absl::time is the right choice.

jmarantz

I agree absl::time is the right way to go, but not at just one point in the code. I think you should just fix the bug without introducing an alternate mechanism to measure time. Once there is a strong abstraction in place a global pivot to absl::time should be straightforward and safe.

In particular I would worry about subtle issues of skew.

Of course for a random seed it's probably ok, but seems unrelated to the bug fix and maybe should be split out?

zyfjeff · 2018-08-30T16:40:19Z

@jmarantz Agree, I am re-editing the code, about the static initialization "fiasco" question, do I need to create an issue and pr?

jmarantz · 2018-08-30T16:44:51Z

RE 'fiasco' -- I think just putting that getSeed() change into a separate PR would be fine; I'm not sure it needs to fix an issue, since the old code worked (even if just by luck).

jmarantz · 2018-08-31T01:29:58Z

source/extensions/stat_sinks/metrics_service/grpc_metrics_service_impl.cc

-  metric->set_timestamp_ms(std::chrono::system_clock::now().time_since_epoch().count());
+  metric->set_timestamp_ms(std::chrono::duration_cast<std::chrono::milliseconds>(
+                               std::chrono::system_clock::now().time_since_epoch())
+                               .count());


Looks great; can you factor out this verbose function call -- repeated 3x, into a helper function.

Ok, I can put the helper function on the anonymous namespace in the current file?Or in the common/common/utility?

easiest to put it in local anon namespace, I will be moving it into TimeSource anyway.

There's a bit of debt here -- we should be using TimeSource::systemTime() rather than directly reading the system-clock, so that this code can have time-injection, but I'll fix that after you merge.

And actually, can you add (near your helper method):
// TODO(#4160): use TimeSource::systemTime() rather than directly reading the system-clock

jmarantz

Thanks; looks great.

zyfjeff · 2018-09-03T16:07:36Z

@dnoe You need to continue to review?

dnoe · 2018-09-04T15:16:01Z

@lizan Is this ready to go from your perspective?

dnoe · 2018-09-04T17:01:33Z

I didn't actually intend to approve, just to remove the "changes requested" in UI. Defer to @lizan for initial maintainer review.

fix static initialization fiasco problem in #4288 Risk Level: low Signed-off-by: tianqian.zyf <[email protected]>

htuch · 2018-09-04T22:23:51Z

source/extensions/stat_sinks/metrics_service/grpc_metrics_service_impl.cc

@@ -16,6 +16,15 @@ namespace Extensions {
 namespace StatSinks {
 namespace MetricsService {

+namespace {
+// TODO(#4160): use TimeSource::systemTime() rather than directly reading the system-clock.
+int64_t getUnixMicrosForNow() {


The function name suggests that it returns microseconds, but the body is dealing with milliseconds, seems like one of these should change.

htuch · 2018-09-05T02:01:17Z

source/extensions/stat_sinks/metrics_service/grpc_metrics_service_impl.cc

@@ -16,6 +16,15 @@ namespace Extensions {
 namespace StatSinks {
 namespace MetricsService {

+namespace {
+// TODO(#4160): use TimeSource::systemTime() rather than directly reading the system-clock.


@jmarantz what's stopping us switching to this right away? Seems best to avoid exception cases like this if we can given how regular time is now treated in Envoy.

nothing, now that you merged the TimeSystem PR; this TODO is addressable.

@zyfjeff post #4257 merge, do you think we can now use this time source?

FYI the path to doing this is to plumb Event::TimeSystem& into constructors as needed, up to MainCommon. Note that both ServerImpl and Dispatcher support timeSystem() or timeSource() APIs, so once you go up the constructor stack till you have one of those, you can stop. #4341 is an example of this refactor.

Once we have all the std::chrono removed from everywhere in Envoy we could decide to switch to absl::Time, though I'd want to socialize the benefits of that to envoy-dev on slack first.

@htuch Yes i do, I am going to modify it.

@jmarantz I can try to replace all std::chrono with TimeSystem

…ecision Signed-off-by: tianqian.zyf <[email protected]>

Signed-off-by: tianqian.zyf <[email protected]>

htuch

Looks great, thanks for iterating on this. I've kicked the failing CI jobs, will merge when they pass.

Signed-off-by: Joshua Marantz <[email protected]>

zyfjeff requested a review from lizan as a code owner August 29, 2018 05:40

zyfjeff force-pushed the time_precision branch 2 times, most recently from 5577bbb to 33c7e57 Compare August 29, 2018 05:55

dnoe suggested changes Aug 29, 2018

View reviewed changes

lizan reviewed Aug 30, 2018

View reviewed changes

lizan requested a review from jmarantz August 30, 2018 08:39

jmarantz reviewed Aug 30, 2018

View reviewed changes

dnoe assigned jmarantz Aug 30, 2018

zyfjeff force-pushed the time_precision branch from a721b2e to e248078 Compare August 30, 2018 14:32

jmarantz reviewed Aug 30, 2018

View reviewed changes

zyfjeff force-pushed the time_precision branch 2 times, most recently from c6fad8e to 44b68e9 Compare August 30, 2018 16:00

jmarantz reviewed Aug 30, 2018

View reviewed changes

jmarantz mentioned this pull request Aug 30, 2018

Different unit of timestamp in metrics_service in linux and macos #4278

Closed

jmarantz reviewed Aug 31, 2018

View reviewed changes

zyfjeff mentioned this pull request Aug 31, 2018

fix static initialization fiasco problem #4314

Merged

jmarantz previously approved these changes Aug 31, 2018

View reviewed changes

dnoe assigned lizan Sep 4, 2018

dnoe previously approved these changes Sep 4, 2018

View reviewed changes

htuch pushed a commit that referenced this pull request Sep 4, 2018

fix static initialization fiasco problem (#4314)

07efc6d

fix static initialization fiasco problem in #4288 Risk Level: low Signed-off-by: tianqian.zyf <[email protected]>

htuch reviewed Sep 4, 2018

View reviewed changes

zyfjeff dismissed stale reviews from dnoe and jmarantz via 82d1695 September 5, 2018 00:54

htuch reviewed Sep 5, 2018

View reviewed changes

zyfjeff added 8 commits September 5, 2018 11:06

fix time_since_epoch on different OS returns the time of different pr…

9eaec74

…ecision Signed-off-by: tianqian.zyf <[email protected]>

fix static initialization fiasco

75696ba

Signed-off-by: tianqian.zyf <[email protected]>

Add const for return value

3bc8634

Signed-off-by: tianqian.zyf <[email protected]>

Revert all modtify

99d7473

Signed-off-by: tianqian.zyf <[email protected]>

Fix different unit in time_since_epoch return value

8d16553

Signed-off-by: tianqian.zyf <[email protected]>

Remove redundant code

8646d64

Signed-off-by: tianqian.zyf <[email protected]>

Fix incorrect named

51f3cb4

Signed-off-by: tianqian.zyf <[email protected]>

Use TimeSource replace std::chrono

a4e61f9

Signed-off-by: tianqian.zyf <[email protected]>

zyfjeff force-pushed the time_precision branch from 82d1695 to a4e61f9 Compare September 5, 2018 14:19

zyfjeff added 4 commits September 5, 2018 22:21

Revert unrelated modtify

43a1002

Signed-off-by: tianqian.zyf <[email protected]>

Fix build errors

95708c8

Signed-off-by: tianqian.zyf <[email protected]>

Fix test build errors

8fd5e4d

Signed-off-by: tianqian.zyf <[email protected]>

Kick CI

2f79ad1

Signed-off-by: tianqian.zyf <[email protected]>

htuch approved these changes Sep 5, 2018

View reviewed changes

htuch merged commit 7707c3b into envoyproxy:master Sep 6, 2018

zyfjeff deleted the time_precision branch September 6, 2018 09:09

jmarantz added a commit to jmarantz/envoy that referenced this pull request Sep 6, 2018

Apply changes intended for this PR to newly merged envoyproxy#4288

144864e

Signed-off-by: Joshua Marantz <[email protected]>

fix time_since_epoch different in different os default return precision #4288

fix time_since_epoch different in different os default return precision #4288

Conversation

zyfjeff commented Aug 29, 2018

zyfjeff commented Aug 29, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lizan left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zyfjeff Aug 30, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jmarantz left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dnoe commented Aug 30, 2018

zyfjeff commented Aug 30, 2018

jmarantz commented Aug 30, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

zyfjeff commented Aug 30, 2018

jmarantz left a comment • edited Loading

Choose a reason for hiding this comment

zyfjeff commented Aug 30, 2018

jmarantz commented Aug 30, 2018

Choose a reason for hiding this comment

zyfjeff Aug 31, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jmarantz left a comment

Choose a reason for hiding this comment

zyfjeff commented Sep 3, 2018

dnoe commented Sep 4, 2018

dnoe commented Sep 4, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jmarantz Sep 5, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

htuch left a comment

Choose a reason for hiding this comment

zyfjeff Aug 30, 2018 •

edited

Loading

jmarantz left a comment •

edited

Loading

zyfjeff Aug 31, 2018 •

edited

Loading

jmarantz Sep 5, 2018 •

edited

Loading