Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix context between two async requests #7

Merged
merged 4 commits into from
Nov 29, 2018

Conversation

daniloisr
Copy link
Contributor

This commit fixes a bug where a request can end without finishing its timings. See: #4

Bug cause: The structure that is used to register Miniprofiler providers, like (Postgres, HTTP, Redis, ...), because it overrides the original method (globally) and uses the request object to access the
Miniprofiler extensions to build the timings, and this doesn't work in a scenario with simultaneous requests using an async provider.

Here is an example using pg to try illustrating the failing scenario (check tests/concurrent-async-test.js test to see it running).

request A start (it's expected to run two DB queries)

  • pg.Client.prototype.query holds a req object of requestA.
  • It calls .query in a pg instance
    • A miniprofiler timing starts with the call to req.miniprofiler.timeQuery(...) (let's call this timing A-1)
    • The original method is called (async).

request B start (it's expected to run a single DB query)

  • pg.Client.prototype.query holds a req object of request B.
  • It calls .query in a pg instance
    • Start timing with req.miniprofiler.timeQuery(...) (timing B-1)
    • The original method is called (async).

request A resume

  • The result of .query is returned (timing A-1 is stoped)
  • A new call to .query is made
    • This time the req points to request B, this means that req.miniprofiler.timeQuery(...) starts a timing on request B. (timing B-2)
    • The original method is called (async)

request B resume

  • The result of .query is returned (timing B-1 is stoped)
  • All data was fetched, the request is ready to finish, so internally Miniprofile calls stopProfilling.
    • This fails because the timing (B-2) is started (by request A) but not finished, so calculating the diffs will fails because stop is undefined.

Solution

Using NodeJS "async_hooks" we can track the reference to the correct extension for each request, so calls to req.miniprofiler.timeQuery() will point to the correct miniprofiler extension.

To check some performance analysis see:
nodejs/node#14794 (comment)

The goal of the current commit isn't introduce breaking changes, so the miniprofiler reference is injected into the request using JS getters.

Another solution is changing the API for providers, where instead of receiving a req reference, they would receive a function to get the reference to the correct miniprofiler instance. But this will break API with all existing providers.

References

@coveralls
Copy link

coveralls commented Oct 22, 2018

Coverage Status

Coverage increased (+0.01%) to 99.746% when pulling 7f9fa5e on daniloisr:handle-async-context into 426fb18 on MiniProfiler:master.

Danilo Resende added 3 commits November 20, 2018 16:17
This commit fixes a bug where a request can end without finishing its
timings. See: MiniProfiler#4

Bug cause: The structure that is used to register Miniprofiler timing
providers, like (Postgres, HTTP, Redis), because it overrides the
original method (globally) and uses the `request` object to access the
Miniprofiler extensions to build the timings, and this doesn't work in a
scenario with simultaneous requests using an async provider.

Here is an example using
[`pg`](https://github.com/goenning/miniprofiler-pg/blob/master/index.js)
to try illustrating the failing scenario (check out the
`tests/concurrent-async-test.js` test to see it running).

request A start:
* `pg.Client.prototype.query` holds a `req` object of requestA.
* It calls `.query` in a pg instance
  * A miniprofiler timing starts with the call to
    `req.miniprofiler.timeQuery(...)`
  * The original method is called (async).

request B start:
* `pg.Client.prototype.query` holds a `req` object of request B.
* It calls `.query` in a pg instance
  * Start timing with `req.miniprofiler.timeQuery(...)`
  * The original method is called (async).

request A resume:
* The result of `.query` is returned
* A new call to  `.query` is made
  * This time the `req` points to request B, this means that
    `req.miniprofiler.timeQuery(...)` will start a timing on request B.
  * The original method is called (async)

request B resume:
* The result of `.query` is returned.
* All data was fetched, the request is ready to finish, so internally
  Miniprofile calls
  [`stopProfilling`](https://github.com/MiniProfiler/node/blob/1a98e40698b1126ac8de728a33406656361f8870/lib/miniprofiler.js#L80).
  * This fails because there is a timing started (by request A) but not
    finished, so calculating the
    [diffs](https://github.com/MiniProfiler/node/blob/1a98e40698b1126ac8de728a33406656361f8870/lib/miniprofiler.js#L409)
    will fails because `stop` is undefined.

Solution
--------

Using NodeJS "async_hooks" we can track the reference to the correct
extension for each request, so calls to `req.miniprofiler.timeQuery()`
will point to the correct miniprofiler extension.

To check some performance analisys see:
nodejs/node#14794 (comment)

The goal of the current commit isn't introduce breaking changes, so the
miniprofiler reference is injected into the request using JS getters.

Another solution is changing the API for providers, where instead of
receiving a `req` reference, they can receive a function that gets the
reference to the correct miniprofiler instance. But this will break API
with all existing providers.

References
----------

- https://medium.com/the-node-js-collection/async-hooks-in-node-js-illustrated-b7ce1344111f
- https://medium.com/@guysegev/async-hooks-a-whole-new-world-of-opportunities-a1a6daf1990a
- nodejs/node#14794 (comment)
Koa adds dependency to `"debug": "*"` which fetch a version non
compatible with Node v4. Locking it on our package.json fix this issue.
After more testing the 'async-hooks' polyfill shown to not work properly
for Node version prior to 8.
daniloisr pushed a commit to goenning/miniprofiler-redis that referenced this pull request Nov 27, 2018
With the addition of `async_hooks` [0] the `req.miniprofiler` is now a
getter, and some Redis methods don't plays nice with it.

[0]: MiniProfiler/node#7
@NickCraver NickCraver merged commit fa9c21b into MiniProfiler:master Nov 29, 2018
@daniloisr
Copy link
Contributor Author

@NickCraver thank you very much for merging this one 🙇‍♂️
One more question, do you know who can publish this update on NPM registry (https://www.npmjs.com/package/miniprofiler)?

@daniloisr daniloisr deleted the handle-async-context branch November 29, 2018 16:03
@NickCraver
Copy link
Member

@goenning @mjibson Can either of you please chime in here on what the build and deploy process to npm was and if you'd like to maintain it going forward?

@goenning
Copy link
Contributor

@daniloisr sorry for the delay, I've add as you maintainer of miniprofiler package. AFAIK, the deploy process is manual

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

4 participants