412 - Make timestamp generator monotonic #335

mpenick · 2017-01-23T21:55:18Z

Timestamps now use microsecond precision instead of millisecond.

* Timestamps now use microsecond precision instead of millisecond.

mpenick · 2017-01-23T22:00:22Z

It looks like I need to fix the format specifiers in that clock skew warning log message. I'll do that tomorrow.

stamhankar999

Generally looks very good; please address the typos, comment refinements, and mull over the warning reporting logic that I commented on.

stamhankar999 · 2017-01-24T17:36:11Z

include/cassandra.h

 *
+ * This timestamp generator will generate warnings if greater than 1 second of
+ * clock skew is detected. I will print an error every second until the clock skew
+ * is resolved. These setting can be changed by using


These setting => These settings

stamhankar999 · 2017-01-24T17:54:31Z

src/timestamp_generator.cpp

+  int64_t current = get_time_since_epoch_us();
+
+  if (last >= current) { // There's clock skew
+    // If we execeed our warning threshhold then warn periodically that clock


execeed => exceed

stamhankar999 · 2017-01-24T18:02:32Z

include/cassandra.h

 * microsecond timestamps with the sub-millisecond part generated using a counter.
 * The implementation guarantees that no more than 1000 timestamps will be generated
 * for a given clock tick even if shared by multiple session objects. If that rate is
 * exceeded then a warning is logged and timestamps stop incrementing until the next


The above comment-block probably needs to be updated -- the new code has proper microsecond precision and bumps the timestamp by 1 when there is clock skew, rather than using the lowest 3 digits as a counter?

Good catch. Fixing.

stamhankar999 · 2017-01-24T18:05:07Z

include/cassandra.h

+ * warnings about clock skew.
+ *
+ * @param warning_threshold_us The amount of clock skew, in microseconds, that
+ *                             must be detected before a warning is triggered.


You should mention that setting this < 0 will disable warnings generation.

stamhankar999 · 2017-01-24T18:14:17Z

src/timestamp_generator.cpp

+    if (warning_threshold_us_ >= 0 && last > current + warning_threshold_us_) {
+      int64_t now = get_time_since_epoch_ms();
+      int64_t last_warning = last_warning_.load();
+      if (now > last_warning + warning_interval_ms_ &&


With the default settings, will this trigger a warning after the first? If your clock is skewed by 1 sec (as determined in line 72), your now will be 1 sec less than real current time. If your last warning was emitted a second ago, then now won't be greater than last_warning + warning_interval_ms_. OTOH, last_warning was recorded with a skewed time, so maybe it balances out.

Maybe there isn't an issue here, but worth mulling over some more to be sure.

Good catch. This is interesting. I guess this could happen if your clock skews by another second consecutively several times in a row.

We just ran into this decision too. We decided that either behavior is reasonable, so we chose not to account for the 1-second offset to match the Java driver's behavior, as we understand it:

apache/cassandra-python-driver#681 (comment)

Open to hearing other opinions if people have strong ones, but I don't see a strong reason to diverge from the Java driver.

A real fix is to use a monotonic system clock to manage the warning interval. The problem is getting that to work properly on all supported platforms (esp. in Java and Python). It might be overkill for handling the warnings, but I'm going at least investigate how hard it would be to implement a millisecond precision monotonic clock for the C++ driver's major platforms (BSD, Linux, Windows).

stamhankar999 · 2017-01-24T18:17:58Z

src/timestamp_generator.hpp

+  Atomic<int64_t> last_warning_;
+
+  const int64_t warning_threshold_us_;
+  const int64_t warning_interval_ms_;


I understand that warning_threshold_us_ is signed so that a user can set it negative to indicate "don't emit warnings"; why is warning_interval_ms_ a signed 64-bit int?

If either of them being negative indicates disabling skew warnings, that's cool, but it should be documented as such and line 72 should check that warning_threshold_ms_ is non-negative.

I changed this to make warning_interval_ms_ zero if it's a negative number. I also added documentation. What do you think?

You mean warning_interval_ms_. But why not making it a uint64_t then? A user who supplies a negative value will get a compiler warning, wouldn't he?

It doesn't work like that. Try compiling this: https://gist.github.com/mpenick/7878d5d328bbb9aa74a1f7dd125ebe15

$ clang++ -Wall -Wextra -pedantic unsigned.cpp unsigned.cpp:5:30: warning: 'long long' is an extension when C99 mode is not enabled [-pedantic,-Wlong-long] printf("%llu\n", (unsigned long long)value); ^ 1 warning generated.

$ g++ -Wall -Wextra -pedantic unsigned.cpp unsigned.cpp: In function ‘void print(uint64_t)’: unsigned.cpp:5:21: warning: ISO C++ 1998 does not support ‘long long’ [-Wlong-long] unsigned.cpp:5:45: warning: ISO C++ does not support the ‘ll’ gnu_printf length modifier [-Wformat]

A warning is not generated for the negative values.

Yes, I meant warning_interval_ms.

I think it was a mistake to have unsigned values exposed in the API. I've been attempting to move away from it.

Interesting that the compiler doesn't warn when it knows you're trying to put a negative value into an unsigned type.

Also, why do you think it was a mistake to expose unsigned values? It shows an intent for valid argument values (even if the compiler doesn't enforce it).

It shows an intent for valid argument values.

I use to think this too, but for the pitfall shown in the above example it's not worth it. If a user passes a negative number the value turns into a really large number and it's not possible to detect an error. It's better to use signed values and return an explicit error (or at least document and correct it).

Good point. Signed it is! :)

stamhankar999 · 2017-01-24T18:27:46Z

test/unit_tests/src/test_timestamp_gen.cpp

+  // limit and the clock skew threshold then a log should have been printed.
+  double timestamp_rate = static_cast<double>(NUM_TIMESTAMPS) / elapsed;
+  if (timestamp_rate > 1000000.0 && elapsed > 1.0) {
+    BOOST_CHECK(counter > 0);


In practice, does the test get here? Does it take at least 1.0 seconds to get 5,000,000 timestamps?

Yes. I don't expect the warning to trigger if with the default settings unless we sustain a timestamp generation rate greater than one per millisecond for at least one second. Maybe this is incorrect?

Hmmm. I think a better test might use time instead of an arbitrary number of timestamps...I'm fixing this.

stamhankar999 · 2017-01-24T18:32:24Z

test/unit_tests/src/test_timestamp_gen.cpp

+
+  // The 100ms timestamp generator should have logged more times because
+  // it had a shorter iterval.
+  BOOST_CHECK(counter_100ms > counter_default);


I was confused at first that you're not doing any magic to fake out the clock (to make actual clock skew) but you get a good approximation by getting the current-time multiple times per microsecond and making sure the timestamp is still monotonically increasing. Good stuff.

* Fixed typos. * Set `warning_interval_ms` to 0 if it's passed as a negative value.

* Added monotonic clock support via `get_time_monotonic_ns()`. * Leveraging the monotonic clock to properly handle timestamp generation clock skew warnings.

* Monotonic timestamp tests now use a duration instead of an arbitrary number of generated timestamps. * Fix compiler errors for the 64-bit format specifiers.

Fixed unit test.

stamhankar999

Fix the remaining typos and consider making the interval attribute uint64_t. Looks good and merge at will.

stamhankar999 · 2017-01-25T21:14:37Z

include/cassandra.h

+ * is corrected.
+ *
+ * By default, this timestamp generator will generate warnings if more than
+ * 1 second of clock skew is detected. I will print an error every second until


stamhankar999 · 2017-01-25T21:16:01Z

include/cassandra.h

+ * be used to disable warnings.
+ * @param warning_interval_ms The amount of time, in milliseonds, to wait before
+ * warning again about clock skew. An interval value less than or equal to 0 allows
+ * the warning to be trigger every millisecond.


trigger => triggered

stamhankar999 · 2017-01-25T21:58:12Z

src/get_time.cpp

 #elif defined(__APPLE__) && defined(__MACH__)

-uint64_t get_time_since_epoch_ms() {
+// Information on converting the absolute time to nanaoseconds can be found


nanaoseconds => nanoseconds

stamhankar999 · 2017-01-25T23:22:33Z

src/get_time.cpp

+           static_cast<uint64_t>(tp.tv_nsec);
+  } else {
+    return get_time_since_epoch_us() * NANOSECONDS_PER_MICROSECOND;
+  }


I'm torn on one point here -- this whole file is platform-specific, so I feel like it would be better to split it into three files (say get_time-win.cpp, get_time-mac.cpp, get_time-unix.cpp) to make it easier for a developer to look at in the future. On the other hand, it's 150+ lines of code, which isn't that big.

Consider splitting, but I'm fine either way.

Good call. I didn't realized this file was getting big.

stamhankar999 · 2017-01-25T23:29:09Z

src/timestamp_generator.hpp

+  Atomic<int64_t> last_warning_;
+
+  const int64_t warning_threshold_us_;
+  const int64_t warning_interval_ms_;


You mean warning_interval_ms_. But why not making it a uint64_t then? A user who supplies a negative value will get a compiler warning, wouldn't he?

Fixed typos.

Split platform specific get time implementations into platform specific files.

Adjusted the timestamp generation unit test parameters so that they're less fragile (esp. in the CI environment).

Fix test build issue on Windows.

mpenick · 2017-01-26T21:32:24Z

Squashed and merged at 16577c5

412 - Make timestamp generator monotonic

dc556ab

* Timestamps now use microsecond precision instead of millisecond.

stamhankar999 suggested changes Jan 24, 2017

View reviewed changes

Michael Penick added 4 commits January 24, 2017 16:34

412 - Make timestamp generator monotonic

950f0a2

* Fixed typos. * Set `warning_interval_ms` to 0 if it's passed as a negative value.

412 - Make timestamp generator monotonic

b195e93

* Added monotonic clock support via `get_time_monotonic_ns()`. * Leveraging the monotonic clock to properly handle timestamp generation clock skew warnings.

412 - Make timestamp generator monotonic

2403850

* Monotonic timestamp tests now use a duration instead of an arbitrary number of generated timestamps. * Fix compiler errors for the 64-bit format specifiers.

412 - Make timestamp generator monotonic

4210ed7

Fixed unit test.

stamhankar999 reviewed Jan 25, 2017

View reviewed changes

Michael Penick added 4 commits January 26, 2017 08:08

412 - Make timestamp generator monotonic

acfee83

Fixed typos.

412 - Make timestamp generator monotonic

6594d30

Split platform specific get time implementations into platform specific files.

412 - Make timestamp generator monotonic

761bdd1

Adjusted the timestamp generation unit test parameters so that they're less fragile (esp. in the CI environment).

412 - Make timestamp generator monotonic

60edcee

Fix test build issue on Windows.

mpenick force-pushed the 412 branch from 52cfb03 to 60edcee Compare January 26, 2017 15:14

mpenick closed this Jan 26, 2017

mikefero deleted the 412 branch February 3, 2017 21:24

mpenick pushed a commit that referenced this pull request Dec 10, 2019

CPP-860 - Remove driver_utils in favor of testing (#335)

a183009

412 - Make timestamp generator monotonic #335

412 - Make timestamp generator monotonic #335

Uh oh!

Conversation

mpenick commented Jan 23, 2017

Uh oh!

mpenick commented Jan 23, 2017

Uh oh!

stamhankar999 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mpenick Jan 24, 2017 • 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!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mpenick Jan 25, 2017 • 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!

Choose a reason for hiding this comment

Uh oh!

mpenick Jan 26, 2017 • 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!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mpenick Jan 26, 2017 • 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!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

stamhankar999 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mpenick commented Jan 26, 2017

Uh oh!

mpenick Jan 24, 2017 •

edited

Loading

mpenick Jan 25, 2017 •

edited

Loading

mpenick Jan 26, 2017 •

edited

Loading

mpenick Jan 26, 2017 •

edited

Loading