Confusing `await` time for async function calls in Timeline view
Hello,
While profiling the app which is using async/await functionality with dotTrace I noticed that there is some inconsistency in `await` time for parent and children methods. Let's consider this example:
static async Task Main()
{
await ChildMethod();
}
static async Task ChildMethod()
{
await SomeOperationAsync();
}
The interesting thing is that await time of Main method might be (or even will be) less than the await time of the ChildMethod which looks strange to me, because intuitively await time of parent should be at least as await time of child.
For real numbers let's go back to the previous example and assume that SomeOperationAsync is Task.Delay(n). So the await time of the parent will be x (x is ~n for the app targeting .NET 6.0 and < n for the app targeting .NET Core 3.1) and the await time of child will be ~2*x.
This is the screenshot from dotTrace to get an idea how it looks (for the app targeting .NET Core 3.1 and for Task.Delay(800)):
1. This is await time of the method Main. 567ms for await ChildMethod(), I expect this to be ~800, because ChildMethod awaits Task.Delay(800)
2. This is await time of the method ChildMethod. 1140ms for await Task.Delay(800). I also expect this to be ~800.
Probably I misunderstand what await time in dotTrace is, so please correct me if so. I understand it as the time needed to schedule a task + real task execution.
Would be great if someone knew if this behavior is expected and could explain how to analyze it.
I'm using Timeline Viewer in dotTrace 2021.3.3.
Probably this is related somehow https://youtrack.jetbrains.com/issue/DTRC-25385
Please sign in to leave a comment.
I think I understand why await time is less than time passed to Task.Delay in the Main method. This is probably because the timer of the task started earlier than continuation attached (internal call to AwaitUnsafeOnCompleted), , therefore it awaits only for the remaining time. In my case this call takes about 300ms so that await time becomes time passed to Task.Delay - time spent on attaching continuation.
Hello,
Thank you for your report.
We are investigating this issue and will provide details soon.
Valentina Serbakova
Hello, thank you for the reply. Please feel free to reach me for any details needed.
Hello Eugene,
Thank you a lot for your report!
That was a bug with calculating await time. The time appeared twice larger than expected. We’ve fixed that issue and fix will be available in 2022.1 EAP4
Hello Valentina,
Thank you very much for letting me know and taking care of this!