Check existence of start/stop parameters #4
Conversation
1 similar comment
|
It's just a safe check or did you run into it? I'm curious about how did it happened. Also wondering if it'd be better to set |
|
I run into this randomly when trying to profile waterline in a sailsjs app. I'll make a miniprofiler-waterline project maybe today to share what I'm doing. I originally ran into this when waterline would return a deferred query object, but I take deferreds into account and now I get I'd be good with setting stop equal to process.hrtime. I'd ultimately like to track down why it's undefined from the waterline profiler code, too |
|
It'd be better to understand why that's happening before merging something like this, even if it's 0 or hrtime. This is a good safe check, but it'd also hide the real problem. |
|
@goenning I open sourced the waterline provider - https://github.com/jgeurts/miniprofiler-waterline If you want to take a peek, I'm open to ideas for why |
|
That's awesome! 👍 The only thing that comes to mind right now is a fire and forget situation in which the HTTP response is being sent back to the browser without waiting for a pending async call. By doing that, MiniProfiler would request the server for the details about the previous HTTP response and the async call might not have finished yet or failed to call Does it make sense? Edit: This is not something specific to your waterline impl, could happen with any other provider. |
|
I would have thought the results would all be collected by the time the ajax request comes through to collect them. I did make a tweak in my provider to give |
That depends on how long the async call will take to finish. It would be helpful if you could create a sample app using By the way, you can try removing this line, still not sure if this is needed at all. |
|
fyi, I'm trying to reproduce the issue and am unsuccessful thus far. I'll let you know if I can get things to reproduce. |
|
I can repro reliably with It's a concurrency issue so to reliably repro you need to hammer a db-dependent express page quite heavily, e.g. with
Simply ignoring the null doesn't work either, it just leads to weirder errors, point being is that miniprofiler needs to wait for all events to fire, or promises to finish for its request before proceeding. |
When using `req.miniprofiler` to track the miniprofiler extension, two requests can dispute this resource where the reference will always point to the last request. So a scenario with async timings, the first request can endup using `req.miniprofiler` that points to the second request extension. (Check the tests to see a scenario simulation) Using NodeJS "async_hooks" we can track the reference to the correct extension for each request. Related to: MiniProfiler#4
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)
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)
This should handle the case where the
stopparameter is null/undefined