Waiting in parallel

[gabrielf]

It seems that parallel external requests are stacked in the graphs in New relic's GUI. This makes two parallel requests that takes 500ms look like they take 1000ms in the graphs even though they happen at the same time. The numeric total request time is still displayed correctly though.

Is parallel external requests something that you will be able to deal with in a better way in the future? I'm just curious, if it isn't possible that is not a deal breaker for me.

[othiym23]

If you could attach a screenshot with an example of what you mean, that would help us a lot. We're in the process of refining how we display transaction traces for Node data in New Relic. It's the first platform we support that's always asynchronous, and we've had to make a lot of tweaks and adjustments to get things looking mostly correct.

[gabrielf]

Sure. I have a express application with the route below. It uses the async library to perform two requests in parallel. Both are done to a dummy service that simply waits a provided number of milliseconds before returning, in this case 500ms. A complete request to the parallel-wait route takes 500ms + a few milliseconds overhead:

app.get('/parallel-wait', function(req, res, next) {
    var tasks = [
        function (callback) {
            request.get({url: 'http://app1.example.com/wait?t=500ms'}, function (err, response, data) {
                callback(err);
            });
        },
        function (callback) {
            request.get({url: 'http://app2.example.com/wait?t=500ms'}, function (err, response, data) {
                callback(err);
            });
        }
    ];
    async.parallel(tasks, function (err) {
        if (err) {
            next(err);
            return;
        }
        res.send('done');
    });
});

This is what it looks in the new relic console:

The reason why the image is confusing is that it looks like the request to parallel-wait takes 1000ms when looking at the graph. It is also not obvious from the graph that the requests are happening at the same time. In the real application that I'm working on we use async in several places to make parallel requests and it is very hard to pinpoint which request is slowing the down a certain request.

I realize this is not a simple problem to solve but it is probably a pretty interesting problem to work with :)

[othiym23]

Thanks for the fantastic comment! It's great to get such detailed feedback.

Before New Relic can fix this, we have to reach a consensus on how the problem should be handled: ideally the breakdown graph would show time exclusive to each instrumented call, and the breakdown would sum up to the total of all of those exclusive times (which would, of course, match the duration of the request as a whole). However, New Relic hasn't really had to deal with concurrent external requests before. In the example scenario you describe, both requests are collectively / simultaneously causing your route to run slowly. It doesn't really fit into the current breakdown visualization because the graph presumes that each piece of the transaction is running in series. Do you have any preferences as to how that would be presented?

The best solution for now is probably to combine child requests in the transaction breakdown and then highlight the critical path in the transaction trace detail view (in practice, it's unlikely that both external requests will have exactly the same duration – one of the requests will be the blocker on the critical path). There are changes coming to the transaction breakdown and trace detail pages to deal with some of this, and there will be further iterations after the 1.0 release of the agent; I don't think this problem can be solved all at once.

[gabrielf]

No problem :)

Highlighting the critical path would be awesome if at all possible. But for it to be useful it would need to be handle quite complex scenarios such as series of bursts of parallel requests.

I'm not sure how to deal with the particular view in the screenshot. I think a info message stating that parallel requests are not shown as such would be enough.

I found another view, that I can not find anymore, that did a much better job at showing that the requests were being done at the same time. It might have been the view shown for very slow requests.

[txase]

Hi @gabrielf,

We have recorded your issue as a feature request for better async support. This is a top priority for us, as much of the power of Node.js is its support for asynchronous work. However, we are also cleaning up our GitHub issues, and there is no further action we can do with this ticket at this time. As such, I am closing it out.

Thank you for your understanding as we tidy our issue tracker!

[gabrielf]

👍