Bad continuations in async method analysis

Hi

I am evaluating dottrace to be able to analyze async total calls time using the option Analyse Async Method

I have two async methods always called with an await.
CreateAndUpdateParentsAsync and  CreateAsync.
What is important is that method CreateAndUpdateParentsAsync always call once the method CreateAsync.

If i analyse the CreateAsync i got this


And all is good. I can see in the continuations the time of my async calls in the method.

Now if i analyse CreateAndUpdateParentsAsync i got this.


Orange line
First i do not understand the await line of 86.5 %. Why the analyze cannot analyze the continuation of 86.5% of the method ?

Red line
While the CreateAsync is not approx. 1505 ms (as it is above) and is analyzed without continuation ?

Do i miss something ?


Thanks

 

1
7 comments

Hi
Thanks for fast support first :)
Perhaps it may be good i explain what we want to achieve:

Imagine we have this:
async Task method1()
     await method2();
     await method3();

 async Task  method2()
     await method4();

When analysing the TOTAL time of method1
I would like to see something like that (i know the numbers of async cannot be exactly the sum)

method1 - 700 ms
      Continuations
             method2  500 ms
                  Continuations
                        method4 500 ms
             method3   200 ms


Thank

1

Hi, Eric.

First i do not understand the await line of 86.5 %. Why the analyze cannot analyze the continuation of 86.5% of the method ?

It means that CreateAndUpdateParentsAsync was awaiting other code for 3850ms, to find out which code was that - you need to look at the source code for `await` calls and analyze async methods that were called after await keyword. `continuations` is a special node, that showing what happened after the await returned. Please check documentation at https://www.jetbrains.com/help/profiler/Analyzing_Async_Calls.html

While the CreateAsync is not approx. 1505 ms (as it is above) and is analyzed without continuation ?

Yes, async methods are analyzed one level at a time, however you can expand the child async node in the tree and find continuations and await nodes there to estimate spent time.

0

Ok then i  understand.
The fact the analyzer stops on first level make the tools not usable for our objectives.

To iterate all async and analyze them one by one is just not possible. We will find another solution.

Thanks for uspport

 

0

You can add continuations and await time to the "root" node on exactly one level, but you can see these times in the tree on any level, just by expanding async methods and looking for await and continuation times. 

Are you looking for a way to see the async method time from the entrance until the exit of a function, including all awaits called from the child async functions as well?

0

I second this. If I see that my method takes 10s, and has 5 async calls I want to be able to easily drill down into the slowest ones. Without it the value of the "call tree" for an async method is next to 0. I don't get why is it a problem to include that timing by default, since "Total" value in "Hotspots" windows seem to already include the awaits. 

Oh, and same applies to flamegraph

0

Thank you for reaching out to us.

The reason we can't perform aggregation across multiple async methods is due to parallelism. If async method A waits on async method B and something else - we can't sum these waiting times, otherwise we will show incorrect wall time for the A method.
Consider the following example:

```
async Task A() {
    Foo(); //Works for 100 ms
    var bTask = B();
    await Task.Delay(1000);
    await bTask;    
}

async Task B() {
    Bar(); //Works for 300 ms
    await Task.Delay(1000);
}
```

If we assume that there is no overhead on method calls and async/await, the wall time of the `A` method is 1400ms.
However, if we were to build an 'honest' tree with everything summed up, we would see the following picture:

```
2400ms A
    100ms Foo
    1300ms continuations
        1300ms B
            300ms Bar
            1000ms await
    1000ms await
```

We added the same 1000ms delay twice and got wrong wall time for the `A` method. 

We are currently thinking about how to solve this problem but haven't come up with a good solution yet.

@Timur, regarding the await time in "Hotspots," we are not adding it to the parent method for the same reasons; we only aggregate continuation times there.

0

Thanks for elaboration! Based on your example, why can't we have something like this?

```
1400ms A
    100ms Foo
    1000ms await Task.Delay()
    300ms await B() (total time - 1300 ms) 
```

95-98% of my situations don't have parallelism (at least on my user-code level) anyway (the whole point of async/await is to make code look linear after all). 

0

Please sign in to leave a comment.