Get Timestamp with process.hrtime and Date.now by mayurkale22 · Pull Request #261 · census-instrumentation/opencensus-node

mayurkale22 · 2019-01-03T19:53:49Z

Although process.hrtime() provides a high-resolution timer, it is from an unknown relative time, not epoch i.e. The time is relative to an arbitrary time in the past (not related to the time of day) and therefore not subject to clock drifts. The whole purpose of hrtime is to gather information on intervals or durations. That's why it doesn't really matter what the point in time was. Also, it is impossible to construct the ISO timestamp from hrtime, which is required when we export metrics data using stackdriver monitoring exporter.

I raised this concern in #196, but I failed to justify reasoning that time. While converting OC metrics data to stackdriver exporter I faced the issue with converting process.hrtime() to a timestamp in RFC3339 UTC "Zulu" format something like this https://github.com/census-instrumentation/opencensus-node/blob/master/packages/opencensus-exporter-stackdriver/src/stackdriver-monitoring.ts#L183.

I am proposing to use Date.now function, as it returns the number of milliseconds elapsed since 1 January 1970 00:00:00 UTC. I have written timestampFromMillis function to construct Timestamp object from the given milliseconds. Although this is not accurate to nanoseconds, But I think this is the best we can get in nodejs. Correct me if I am wrong and let me know your views.

codecov-io · 2019-01-03T20:13:49Z

Codecov Report

Merging #261 into master will decrease coverage by <.01%.
The diff coverage is n/a.

@@            Coverage Diff            @@
##           master    #261      +/-   ##
=========================================
- Coverage    94.6%   94.6%   -0.01%     
=========================================
  Files         105     103       -2     
  Lines        7397    7391       -6     
  Branches      691     691              
=========================================
- Hits         6998    6992       -6     
  Misses        399     399

Impacted Files	Coverage Δ
src/stats/view.ts	`97.67% <0%> (-0.03%)`	⬇️
test/test-view.ts	`99.14% <0%> (-0.03%)`	⬇️
src/metrics/gauges/gauge.ts	`100% <0%> (ø)`	⬆️
test/test-derived-gauge.ts	`100% <0%> (ø)`	⬆️
test/test-metric-producer.ts	`100% <0%> (ø)`	⬆️
test/test-gauge.ts	`100% <0%> (ø)`	⬆️
src/stats/stats.ts	`97.91% <0%> (ø)`	⬆️
test/test-metric-registry.ts	`100% <0%> (ø)`	⬆️
src/metrics/metric-component.ts
test/test-metric-producer-manager.ts
... and 7 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 3e1a9a0...4e58473. Read the comment docs.

draffensperger · 2019-01-04T21:26:17Z

I think it would be nice to preserve high-resolution timestamps if we can.

What if we measured Date.now immediately followed by process.hrtime when the library is initializing in order to calculate the epoch timestamp origin that process.hrtime is using? Then we could use that offset to convert hrtime calculations into epoch timestamps going forward using a consistent basis. That would preserve allowing nanosecond measurements of span times, just the time origin would be accurate to milliseconds, which I think is OK.

justindsmith

Just adding a review to agree with @draffensperger's comment above. Preserving high res timestamps would definitely be ideal and his approach should work.

Update: Also, this functionality seems very similar to the logic done inside the src/internal/clock.ts class, which also utilizes the Date for starting times and process.hrtime() for high resolution duration. We should probably move the time logic in this PR to be colocated for simplicity.

mayurkale22 · 2019-01-06T21:17:36Z

@draffensperger and @justindsmith Thanks for the great suggestion. I managed to write function getNowWithProcessHRTime to calculate [seconds, nanoseconds] using now and hrtime. Let me know your views on same.

const MILLIS_PER_SECOND = 1e3;
const NANOS_PER_MILLI = 1e3 * 1e3;
const NANOS_PER_SECOND = 1e3 * 1e3 * 1e3;

const refTime = Date.now();
const startSecs = Math.floor(refTime / MILLIS_PER_SECOND);
const startNanos = (refTime % MILLIS_PER_SECOND) * NANOS_PER_MILLI;

const hrtime = process.hrtime;
const origin = hrtime();

function getNowWithProcessHRTime() {
  const [offsetSecs, offsetNanos] = hrtime(origin); // [seconds, nanoseconds]

  // determine drfit in seconds and nanoseconds
  const seconds = startSecs + offsetSecs;
  const nanoseconds = startNanos + offsetNanos;

  // if nanos excess NANOS_PER_SECOND value.
  if (nanoseconds >= NANOS_PER_SECOND) {
    return [seconds + 1, nanoseconds % NANOS_PER_SECOND];
  }
  return [seconds, nanoseconds];
}

justindsmith · 2019-01-07T16:35:23Z

@mayurkale22 LGTM!

draffensperger

The function looks good. One minor suggestion would be to move the const hrtime = process.hrtime; const origin = hrtime(); code block right above const refTime = Date.now(). That way there are no statements between when you measure hrtime and when you measure now so the accuracy could be very slightly better.

draffensperger · 2019-01-07T16:33:06Z

packages/opencensus-core/src/common/time-util.ts

+const nanos = (epochMilli: number): number => {
+  const mos = epochMilli - seconds(epochMilli) * MILLIS_PER_SECOND;
+  return Number(BigInt(mos).times(NANOS_PER_MILLI).toString());
+};


Optional nit: would it be cleaner to make these regular function declarations rather than const function expressions?

mayurkale22 · 2019-01-08T01:17:08Z

I have modified the code to use above mentioned logic, PTAL @draffensperger @justindsmith

draffensperger · 2019-01-08T01:19:41Z

packages/opencensus-core/src/common/time-util.ts

+export function getTimestampWithProcessHRTime(): Timestamp {
+  const [offsetSecs, offsetNanos] = hrtime(origin);  // [seconds, nanoseconds]
+
+  // determine drfit in seconds and nanoseconds


Nit: "drift" spelling

draffensperger · 2019-01-08T01:20:39Z

packages/opencensus-core/src/common/time-util.ts

+  const seconds = startSecs + offsetSecs;
+  const nanos = startNanos + offsetNanos;
+
+  // if nanos excess NANOS_PER_SECOND value.


Is this comment needed, it seems to express pretty closely what the if statement says?

Make sense, removed.

draffensperger · 2019-01-08T01:22:55Z

packages/opencensus-core/test/test-derived-gauge.ts

+      const [points] = timeseries.points;
+      assert.deepStrictEqual(timeseries.labelValues, LABEL_VALUES_200);
+      assert.equal(points.value, 2);
+      assert.equal(Math.floor(now / 1e3), points.timestamp.seconds);


What would you think about mocking Date.now and process.hrtime for the test (setting them and unsetting them before/after)? That way if someone sets a breakpoint in the test and some time elapses it will still pass and you can also assert exact values for nanoseconds.

Initially I was thinking about it, but then realized Date.now and process.hrtime are initialized once in common/time-util.ts. I think it is hard to mock them in before/after tests. I tried exporting const TEST_ONLY_ORIGIN_HRTIME = origin; and const TEST_ONLY_REF_TIME = refTime; but, couldn't manage to assert exact values for nanoseconds. Let me know if you have a better approach to mock these.

What if you had something like this:

let hrtime = process.hrtime; let hrtimeOrigin: [number, number] = [0, 0]; let hrtimeRefSeconds = 0; let hrtimeRefNanos = 0; /** This is used to enable tests to mock process.hrtime while still allow us to cache it. */ function resetHrtimeFunctionCache() { hrtime = process.hrtime; } function setHrtimeReference() { resetHrtimeFunctionCache(); hrtimeOrigin = hrtime(); const refTime = Date.now(); hrtimeRefSeconds = ... hrtimeRefNanos = ... } setHrtimeReference(); export TEST_ONLY = {setHrtimeReference}; ..... // In the test import {TEST_ONLY, ...} from '../common/time-utils.ts'; ... let realHrtimeFn = process.hrtime; let realNowFn = Date.now; beforeEach(() => { process.hrtime = () => [55, 22]; Date.now = () => 14500000; // Force the clock to recalibrate the time offset with the mocked time TEST_ONLY.setHrtimeReference(); // Simulate that now some time passed ... process.hrtime = () => [66, 33]; TEST_ONLY.resetHrtimeFunctionCache(); }); afterEach(() => { process.hrtime = realHrtimeFn; Date.now = realDateNow; // Reset the hrtime reference so that it uses a real clock again. TEST_ONLY.setHrtimeReference(); });

If this feels too involved, I'm OK with skipping it but wanted to put it there as an option. If you go this route, it could be helpful to export these as some kind of time testing helpers to easily set/unset the mocked time.

@draffensperger Awesome, thanks for the help. I have modified the tests, PTAL.

draffensperger · 2019-01-08T01:25:17Z

packages/opencensus-core/test/test-metric-registry.ts

    const pointEntry = int64Gauge.getOrCreateTimeSeries(LABEL_VALUES_200);
    pointEntry.add(100);

+    now = Date.now();


Similar comment here about mocking out the time vs. measuring it in the test

draffensperger · 2019-01-08T01:25:51Z

packages/opencensus-core/test/test-metric-registry.ts

    derivedInt64Gauge.createTimeSeries(LABEL_VALUES_200, map);
    map.set('key1', 'value1');

+    now = Date.now();


For these tests and others below too

draffensperger · 2019-01-08T01:33:27Z

packages/opencensus-core/test/test-time-util.ts

+import {getTimestampWithProcessHRTime} from '../src/common/time-util';
+
+describe('getTimestampWithProcessHRTime()', () => {
+  it('compare now with getTimestampWithProcessHRTime', () => {


What would you think about using time mocking here and adding tests that cover the cases where the nanoseconds both do and don't overflow?

What you could do is move the initialization logic in common/time-util.ts above into a function say setupHrtimeDrift or similar, then you would add a new exported variable export TEST_ONLY = {setupHrtimeDrift} with a comment that is exported to enable testing the drift configuration (and of course you call the setupHrtimeDrift in the time-util.ts file).

Then you import the TEST_ONLY symbol here in the test and call setupHrtimeDrift after you have mocked process.hrtime and Date.now. Then you redefine them again before calling getTimestampWithProcessHRTime for the two cases to test.

If this seems too involved, I'm open to leaving this as-is though.

Although process.hrtime() provides a high-resolution timer, it is from an unknown relative time, not epoch i.e. The time is relative to an arbitrary time in the past (not related to the time of day) and therefore not subject to clock drifts. The whole purpose of hrtime is to gather information on intervals or durations. That's why it doesn't really matter what the point in time was. Also, it is impossible to construct the ISO timestamp from hrtime, which is required when we export metrics data using stackdriver exporter. I am proposing to use Date.now function, as it returns the number of milliseconds elapsed since 1 January 1970 00:00:00 UTC. I have written timestampFromMillis function to construct Timestamp object from the given milliseconds.

draffensperger

LGTM, thanks for changing this code to be testable with mocked time.

mayurkale22 · 2019-01-08T21:58:56Z

@justindsmith please take another look. Thanks.

justindsmith

LGTM!

googlebot added the cla: yes label Jan 3, 2019

mayurkale22 requested review from OsvaldoRosado, bogdandrutu and justindsmith January 3, 2019 19:53

justindsmith suggested changes Jan 5, 2019

View reviewed changes

draffensperger reviewed Jan 7, 2019

View reviewed changes

mayurkale22 force-pushed the timestamp branch 2 times, most recently from d5da3d6 to 4e58473 Compare January 7, 2019 23:57

mayurkale22 changed the title ~~Replace process.hrtime with Date.now~~ Get Timestamp with process.hrtime and Date.now Jan 8, 2019

draffensperger reviewed Jan 8, 2019

View reviewed changes

mayurkale22 added 3 commits January 7, 2019 17:47

Construct Timestamp from Date.now and Process.hrtime

9a2fc3b

mock time for tests

da80ba9

mayurkale22 force-pushed the timestamp branch from 4e58473 to da80ba9 Compare January 8, 2019 20:31

draffensperger approved these changes Jan 8, 2019

View reviewed changes

justindsmith approved these changes Jan 10, 2019

View reviewed changes

mayurkale22 merged commit 47a672e into census-instrumentation:master Jan 10, 2019

mayurkale22 deleted the timestamp branch January 10, 2019 06:28

mayurkale22 mentioned this pull request Feb 12, 2019

chore(multiple): 0.0.9 release proposal #341

Merged

Conversation

mayurkale22 commented Jan 3, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

codecov-io commented Jan 3, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

draffensperger commented Jan 4, 2019

Uh oh!

justindsmith left a comment • 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!

mayurkale22 commented Jan 6, 2019

Uh oh!

justindsmith commented Jan 7, 2019

Uh oh!

draffensperger left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

mayurkale22 commented Jan 8, 2019

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!

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!

draffensperger left a comment

Choose a reason for hiding this comment

Uh oh!

mayurkale22 commented Jan 8, 2019

Uh oh!

justindsmith left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

5 participants

mayurkale22 commented Jan 3, 2019 •

edited

Loading

codecov-io commented Jan 3, 2019 •

edited

Loading

justindsmith left a comment •

edited

Loading