Analyzing Async Calls
One of the downsides of asynchronous code is it's extremely difficult to profile it and analyze its performance. This is because, when an asynchronous method is executed, control is switched to a different thread and back, tangling the resulting call tree.
dotTrace dramatically simplifies the analysis of asynchronous code: It marks all
async call nodes in Call Tree and groups the corresponding
await time and continuation code under that node. This means that you can quickly find all "parts" of an asynchronous call in one place instead of searching for them in different call stacks.
To better understand how dotTrace treats asynchronous code, consider the following example (the code is shown on the left, the corresponding Call Tree on the right):
As you can see, all "parts" of the asynchronous call are shown inside the async RunAsyncOperation node:
The total time of
RunAsyncOperationis calculated as
119 ms =
Init()101 ms +
ReadAsync()13 ms +
clr.dll3.7 ms +
Initmethod (101 ms) is executed on the Main thread, therefore, its time is added to the total time of
ReadAsyncis started on the Main thread (13 ms) but the subsequent task is run on a thread pool. Thus, the time of the Task execution node (819 ms) is shown grey and is not added to the total time of
The await time in our case is equal to the Task execution time (819 ms) but in real life it can be higher as it also includes the time the task waits in schedule.
The continuations node is a continuation code which in our case consists of a single
ProcessFilemethod (301 ms). As this call is executed on the thread pool, its time is also shown gray and is not added to the total time of
Identifying the slowest async calls in Methods and Subsystems
As you can see, the total
async call time does not include the time of all its parts in Call Tree. But what if you want to quickly identify the 'hot spots' - the slowest methods in your app? For such kind of task it would be better if the
async method's total time included the continuation code. This is actually true for the Methods and Subsystems list, but only if you stand on the All Calls node in Call Tree.
Backtraces of the continuation code
Of course, Backtraces of the continuation code will lead you back not just to the callback function but to the original
async method. This could be very helpful, e.g., when the continuation code throws an exception and you need to identify its origin.
Filtering by async call's total time
To apply the filter by async call's total time, either double-click the call node in Call Tree or right-click the node (or its await or continuations node) and select Analyze Async Method from the context menu.
After you filter by an
async method's call time, dotTrace will leave only the time intervals where the method was executed. Note that you can include or exclude continuation code intervals (as well as the await time node) by selecting the corresponding check boxes that appear in Call Tree.
Note that if you apply filters so that the continuation code will be out of scope (e.g., a filter by Main thread), the Continuations check box will not be shown.
Tasks in Call Tree
The aforementioned functionality works not only with
async/await but with all tasks based on the
Task class. The
Run node contains the Task execution node with the task delegate:
Asynchronous calls and events
Last but not least worth to mention Call Tree works with calls time as well as with all other types of events supported in the Timeline profiling mode, e.g., memory allocation or exceptions. For example, you can view how much memory a particular async method allocates: