Jest: Reinstate timestamps for mock calls

[acostalima]

🚀 Feature Proposal

Record the timestamp of individual mock calls.

Motivation

I am well aware timestamps were removed in favor of invocationCallOrder(https://github.com/facebook/jest/pull/5867). However, to implement a new matcher proposed in https://github.com/jest-community/jest-extended/issues/112, timestamps are necessary. I am proposing to restore the implementation alongside invocationCallOrder and, at the same time, address the concerns raised previously regarding the precision issues (https://github.com/jest-community/jest-extended/issues/98#issuecomment-355440156, https://github.com/facebook/jest/issues/4402#issuecomment-375939427). @brigonzalez was already headed towards a possible solution for this resorting to process.hrtime() instead of Date.

Example

One potential scenario for this feature is, by making use of the aforementioned matcher, to ensure a function is called in compliance with a given exponential back-off strategy.

Pitch

I believe this feature supports a legitimate use case and other may follow.

[SimenB]

Not sure about this one. What if people want a timestamp for when it returned instead of invoked? Or if it's a promise, when it settled?

Checking the order of invocations makes sense to me (error handler invoked before logger, or whatever). Not sure about how close to mocks were called. We don't want a too big of an API surface. If you _really_ want that, you could in theory implement it as you mockImplementation, and just push into some array you have in your test or something.

[SimenB]

@thymikee @rickhanlonii thoughts? Also @UselessPickles since you've been working on the mocks lately 🙂

[UselessPickles]

It would be fairly simple to update the mock code to record 2 timestamps per call:

• Time of call/invokation
• Time of completion (return or throw)

There's already a convenient structure containing the "result" data where we could also store the time of completion. But the current structure of the rest of the "mock" object would require that we add yet another parallel array to contain invocation/call timestamps.

It would be nice to combine all of the parallel arrays into a single array of "mock call" objects some day, but that's a big breaking change.

So my thoughts are that it's simple and low risk to implement, so it might be a worthwhile inclusion if it helps others write custom matchers that analyze the relationships between different method calls.

[UselessPickles]

...but the real question is how we obtain the the "now" timestamp. I haven't fully researched this, but I'm vaguely aware of some options:

• Date.now() is reliably supported, but limited to no better than millisecond precision, and can be thrown off if the system time is manually or automatically adjusted during execution.
• performance.now() isn't thrown off by system clock changes during execution, and may return better than millisecond precision in some implementations, but can we assume it is supported in all environments where Jest is run?
• I believe there's also some NodeJS-specific process timestamp that can be obtained that is high precision.

Also note that performance.now() and the NodeJS process timestamp are NOT real date-time timestamps. They start at zero at the beginning of execution and count how long the process has been running. Is that a problem? Will anyone expect these timestamps to be absolute timestamps, or is it OK for them to be relative to the beginning of the process?

[SimenB]

I believe there's also some NodeJS-specific process timestamp that can be obtained that is high precision.

process.hrtime is that one :) we can use https://www.npmjs.com/package/browser-process-hrtime which should work in all envs we care about

[acostalima]

@UselessPickles @SimenB Yep, that's it. At least for the use case I presented, timestamps relative to the beginning of the process will do. The package convert-hrtime may prove itself useful for this.

[acostalima]

@UselessPickles @SimenB what's the way forward?

[acostalima]

Ping @UselessPickles @SimenB

[UselessPickles]

I think we need this PR merged first, because it includes changes to related code/structures: https://github.com/facebook/jest/pull/6381

Once that is merged, I could easily create a PR to store invocation and completion timestamps, but it might be time to seriously think about restructuring the parallel arrays of information about mock calls. Without any restructuring, it would require adding yet another parallel array to store the invocation timestamps (which may be "good enough" for now to avoid serious breaking changes). I would like feedback from the Jest team on this before I put any work into it.

No matter what approach we take, it will technically be a breaking change to the mock serializer.

The completion timestamp would simply be a new property on the MockFunctionResult structure that would be undefined while the type property is incomplete, then updated to a timestamp value when the function either returns or throws.

[UselessPickles]

@SimenB Now that #6381 is merged, what are your thoughts on this issue?
(see previous comment for some options to consider)

[SimenB]

I wonder if we should have jestMock.mockInvocations (or something) be an array of this shape:

type MockInvocation = {
  call: { args: Array<any> },
  result: { type: 'return' | 'throw', value: any },
  // Drop it, maybe? #7070
  instance: any
};

Then we could in theory add some more stuff

@thymikee @rickhanlonii thoughts?

[UselessPickles]

I don't see any reason to nest args in a call property.

Also, a slight correction on the type of result (can be undefined while the function is incomplete), adding timestamps for this issue, and some suggestions for #7070

type MockResult = { 
  type: 'return' | 'throw', 
  value: any,
  // timestamp of function completion
  timestamp: number,
  // #7070 - if we want to get fancy and correctly determine whether 
  // the function is called with `new` and created a new instance
  newInstance: any 
};

type MockInvocation = {
  args: Array<any>,
  result: MockResult | void,
  // #7070 - rename of `instance` to indicate what it really means.
  // This is simply the "this" context upon which the function was called.
  thisContext: any,
  // timestamp of function invocation
  timestamp: number
};

[SimenB]

I like it! Do we want a real timestamp, or just something relative to process startup? Depends on if we want higher precision than milliseconds

[rickhanlonii]

Looks like this is stalled (sorry, I've been afk)

Can we wrap it up for Jest 24? What do we need?

[UselessPickles]

@SimenB

Do we want a real timestamp, or just something relative to process startup?

You suggested using browser-process-hrtime previously: https://github.com/facebook/jest/issues/6672#issuecomment-404218660

And there seemed to be agreement previously that time relative to process startup is sufficient.

@rickhanlonii

Can we wrap it up for Jest 24? What do we need?

Updating the mock code itself to use the structures suggested in my previous comment would be easy. The harder parts are:

• Updating all existing matchers and unit tests to work with the new structure (time consuming).
• Updating documentation (time consuming).
• Adding unit tests for the new timestamps (tricky because it involves timestamps).
• Impact on #7070 needs to be decided. Easiest solution is replace the current instances with MockInvocation.thisContext (same behavior as current instances, but named/documented correctly), while implementing MockResult.newInstance correctly (to match what people expect from the current naming of instances) requires depending on an ES6 feature: https://github.com/facebook/jest/issues/7070#issuecomment-434882343

I could probably update the mock code and structures itself to help get it started, but I don't think I'll have time to deal with all the other "harder parts" I listed. My free time this winter is consumed by a project car.

[SimenB]

there seemed to be agreement previously that time relative to process startup is sufficient.

SGTM.

Adding unit tests for the new timestamps (tricky because it involves timestamps).

Can mock whatever module we use for timing and increment with 1 or something for each invocation