|
| 1 | +--- |
| 2 | +title: Generate load and view Application Insights Profiler data |
| 3 | +description: Generate load to your Azure service to view the Profiler data |
| 4 | +ms.contributor: charles.weininger |
| 5 | +ms.topic: conceptual |
| 6 | +ms.date: 07/15/2022 |
| 7 | +ms.reviewer: jogrima |
| 8 | +--- |
| 9 | + |
| 10 | +# View Application Insights Profiler data |
| 11 | + |
| 12 | +Let's say you're running a web performance test. You'll need traces to understand how your web app is running under load. In this article, you'll: |
| 13 | + |
| 14 | +> [!div class="checklist"] |
| 15 | +> - Generate traffic to your web app by starting a web performance test or starting a Profiler on-demand session. |
| 16 | +> - View the Profiler traces after your load test or Profiler session. |
| 17 | +> - Learn how to read the Profiler performance data and call stack. |
| 18 | +
|
| 19 | +## Generate traffic to your Azure service |
| 20 | + |
| 21 | +For Profiler to upload traces, your service must be actively handling requests. |
| 22 | + |
| 23 | +If you've newly enabled Profiler, run a short [load test](/vsts/load-test/app-service-web-app-performance-test). |
| 24 | + |
| 25 | +If your Azure service already has incoming traffic or if you just want to manually generate traffic, skip the load test and start a **Profiler on-demand session**: |
| 26 | + |
| 27 | +1. From the Application Insights overview page for your Azure service, select **Performance** from the left menu. |
| 28 | +1. On the **Performance** pane, select **Profiler** from the top menu for Profiler settings. |
| 29 | + |
| 30 | + :::image type="content" source="./media/profiler-overview/profiler-button-inline.png" alt-text="Screenshot of the Profiler button from the Performance blade." lightbox="media/profiler-settings/profiler-button.png"::: |
| 31 | + |
| 32 | +1. Once the Profiler settings page loads, select **Profile Now**. |
| 33 | + |
| 34 | + :::image type="content" source="./media/profiler-settings/configure-blade-inline.png" alt-text="Screenshot of Profiler page features and settings." lightbox="media/profiler-settings/configure-blade.png"::: |
| 35 | + |
| 36 | +## View traces |
| 37 | + |
| 38 | +1. After the Profiler sessions finish running, return to the **Performance** pane. |
| 39 | +1. Under **Drill into...**, select **Profiler traces** to view the traces. |
| 40 | + |
| 41 | + :::image type="content" source="./media/profiler-overview/trace-explorer-inline.png" alt-text="Screenshot of trace explorer page." lightbox="media/profiler-overview/trace-explorer.png"::: |
| 42 | + |
| 43 | +The trace explorer displays the following information: |
| 44 | + |
| 45 | +| Filter | Description | |
| 46 | +| ------ | ----------- | |
| 47 | +| Profile tree v. Flame graph | View the traces as either a tree or in graph form. | |
| 48 | +| Hot path | Select to open the biggest leaf node. In most cases, this node is near a performance bottleneck. | |
| 49 | +| Framework dependencies | Select to view each of the traced framework dependencies associated with the traces. | |
| 50 | +| Hide events | Type in strings to hide from the trace view. Select *Suggested events* for suggestions. | |
| 51 | +| Event | Event or function name. The tree displays a mix of code and events that occurred, such as SQL and HTTP events. The top event represents the overall request duration. | |
| 52 | +| Module | The module where the traced event or function occurred. | |
| 53 | +| Thread time | The time interval between the start of the operation and the end of the operation. | |
| 54 | +| Timeline | The time when the function or event was running in relation to other functions. | |
| 55 | + |
| 56 | +## How to read performance data |
| 57 | + |
| 58 | +Profiler uses a combination of sampling methods and instrumentation to analyze your application's performance. While performing detailed collection, the Profiler: |
| 59 | + |
| 60 | +- Samples the instruction pointer of each machine CPU every millisecond. |
| 61 | + - Each sample captures the complete call stack of the thread, giving detailed information at both high and low levels of abstraction. |
| 62 | +- Collects events to track activity correlation and causality, including: |
| 63 | + - Context switching events |
| 64 | + - Task Parallel Library (TPL) events |
| 65 | + - Thread pool events |
| 66 | + |
| 67 | +The call stack displayed in the timeline view is the result of the sampling and instrumentation. Because each sample captures the complete call stack of the thread, it includes code from Microsoft .NET Framework, and any other frameworks that you reference. |
| 68 | + |
| 69 | +### Object allocation (clr!JIT\_New or clr!JIT\_Newarr1) |
| 70 | + |
| 71 | +**clr!JIT\_New** and **clr!JIT\_Newarr1** are helper functions in .NET Framework that allocate memory from a managed heap. |
| 72 | +- **clr!JIT\_New** is invoked when an object is allocated. |
| 73 | +- **clr!JIT\_Newarr1** is invoked when an object array is allocated. |
| 74 | + |
| 75 | +These two functions usually work quickly. If **clr!JIT\_New** or **clr!JIT\_Newarr1** take up time in your timeline, the code might be allocating many objects and consuming significant amounts of memory. |
| 76 | + |
| 77 | +### Loading code (clr!ThePreStub) |
| 78 | + |
| 79 | +**clr!ThePreStub** is a helper function in .NET Framework that prepares the code for initial execution, which usually includes just-in-time (JIT) compilation. For each C# method, **clr!ThePreStub** should be invoked, at most, once during a process. |
| 80 | + |
| 81 | +If **clr!ThePreStub** takes extra time for a request, it's the first request to execute that method. The .NET Framework runtime takes a significant amount of time to load the first method. Consider: |
| 82 | +- Using a warmup process that executes that portion of the code before your users access it. |
| 83 | +- Running Native Image Generator (ngen.exe) on your assemblies. |
| 84 | + |
| 85 | +### Lock contention (clr!JITutil\_MonContention or clr!JITutil\_MonEnterWorker) |
| 86 | + |
| 87 | +**clr!JITutil\_MonContention** or **clr!JITutil\_MonEnterWorker** indicate that the current thread is waiting for a lock to be released. This text is often displayed when you: |
| 88 | +- Execute a C# **LOCK** statement, |
| 89 | +- Invoke the **Monitor.Enter** method, or |
| 90 | +- Invoke a method with the **MethodImplOptions.Synchronized** attribute. |
| 91 | + |
| 92 | +Lock contention usually occurs when thread _A_ acquires a lock and thread _B_ tries to acquire the same lock before thread _A_ releases it. |
| 93 | + |
| 94 | +### Loading code ([COLD]) |
| 95 | + |
| 96 | +If the .NET Framework runtime is executing [unoptimized code](/cpp/build/profile-guided-optimizations) for the first time, the method name will contain **[COLD]**: |
| 97 | + |
| 98 | +`mscorlib.ni![COLD]System.Reflection.CustomAttribute.IsDefined` |
| 99 | + |
| 100 | +For each method, it should be displayed once during the process, at most. |
| 101 | + |
| 102 | +If loading code takes a substantial amount of time for a request, it's the request's initiate execute of the unoptimized portion of the method. Consider using a warmup process that executes that portion of the code before your users access it. |
| 103 | + |
| 104 | +### Send HTTP request |
| 105 | + |
| 106 | +Methods such as **HttpClient.Send** indicate that the code is waiting for an HTTP request to be completed. |
| 107 | + |
| 108 | +### Database operation |
| 109 | + |
| 110 | +Methods such as **SqlCommand.Execute** indicate that the code is waiting for a database operation to finish. |
| 111 | + |
| 112 | +### Waiting (AWAIT\_TIME) |
| 113 | + |
| 114 | +**AWAIT\_TIME** indicates that the code is waiting for another task to finish. This delay occurs with the C# **AWAIT** statement. When the code does a C# **AWAIT**: |
| 115 | +- The thread unwinds and returns control to the thread pool. |
| 116 | +- There's no blocked thread waiting for the **AWAIT** to finish. |
| 117 | + |
| 118 | +However, logically, the thread that did the **AWAIT** is "blocked", waiting for the operation to finish. The **AWAIT\_TIME** statement indicates the blocked time, waiting for the task to finish. |
| 119 | + |
| 120 | +### Blocked time |
| 121 | + |
| 122 | +**BLOCKED_TIME** indicates that the code is waiting for another resource to be available. For example, it might be waiting for: |
| 123 | +- A synchronization object |
| 124 | +- A thread to be available |
| 125 | +- A request to finish |
| 126 | + |
| 127 | +### Unmanaged Async |
| 128 | + |
| 129 | +In order for async calls to be tracked across threads, .NET Framework emits ETW events and passes activity IDs between threads. Since unmanaged (native) code and some older styles of asynchronous code lack these events and activity IDs, the Profiler can't track the thread and functions running on the thread. This item is labeled **Unmanaged Async** in the call stack. Download the ETW file to use [PerfView](https://github.com/Microsoft/perfview/blob/master/documentation/Downloading.md) for more insight. |
| 130 | + |
| 131 | +### CPU time |
| 132 | + |
| 133 | +The CPU is busy executing the instructions. |
| 134 | + |
| 135 | +### Disk time |
| 136 | + |
| 137 | +The application is performing disk operations. |
| 138 | + |
| 139 | +### Network time |
| 140 | + |
| 141 | +The application is performing network operations. |
| 142 | + |
| 143 | +### When column |
| 144 | + |
| 145 | +The **When** column is a visualization of the variety of _inclusive_ samples collected for a node over time. The total range of the request is divided into 32 time buckets, where the node's inclusive samples accumulate. Each bucket is represented as a bar. The height of the bar represents a scaled value. For the following nodes, the bar represents the consumption of one of the resources during the bucket: |
| 146 | +- Nodes marked **CPU_TIME** or **BLOCKED_TIME**. |
| 147 | +- Nodes with an obvious relationship to consuming a resource (for example, a CPU, disk, or thread). |
| 148 | + |
| 149 | +For these metrics, you can get a value of greater than 100% by consuming multiple resources. For example, if you use two CPUs during an interval on average, you get 200%. |
| 150 | + |
| 151 | +## Next steps |
| 152 | +Learn how to... |
| 153 | +> [!div class="nextstepaction"] |
| 154 | +> [Configure Profiler settings](./profiler-settings.md) |
| 155 | +
|
| 156 | + |
| 157 | +[performance-blade]: ./media/profiler-overview/performance-blade-v2-examples.png |
| 158 | +[trace-explorer]: ./media/profiler-overview/trace-explorer.png |
0 commit comments