Sometimes you can see that AVIcode performance event’s function calls durations do not add up to the total time. Today we will discuss why does that happen and how to troubleshoot this kind of issues.

Hello and welcome back!

With this article we continue the series of posts concerning the AVIcode APM monitoring. The articles will deal with standalone AVIcode as well as with APM feature integrated into the SCOM 2012. We are going to cover functionality aspects, configuration, troubleshooting, workarounds for common issues etc. We hope you’ll find these series useful. Grab the ticket and join the ride!

AVIcode is great because it is very easy to install and to get started with. Just click through the setup wizard steps (or enable APM feature in SCOM 2012) and there it is deployed and ready to monitor your apps. Then you add some application to monitoring and shortly will get first events.

Sometimes AVIcode hits the nail on the head with diagnostics, but sometimes what you see is really confusing. For instance, you notice that the whole request was slow – entrypoint execution time is huge, but the individual functions’ execution times inside stack do not add up to the entrypoint duration. In fact it is much less than the request execution time. So where did the rest of the time go?

Suppose you have this:

130485 ms ASP page : /IncidentReporting/Default.aspx                                              

               108 ms SomeNamespace.Framework.PageBase.Render()
               103 ms SomeNamespace.Web.UI.RadAjaxControl.RenderPageInAjaxMode()
               96 ms SomeNamespace.Framework.PageBase.Render()
               90 ms SomeNamespace.UI.Modules.ModuleHost.RenderContents()
               88 ms SomeNamespace.Web.UI.RadMultiPage.Render()
               88 ms SomeNamespace.Web.UI.RadMultiPage.RenderContents()
               11 ms SomeNamespace.Web.UI.RadDatePicker.Render()
               11 ms SomeNamespace.Web.UI.RadWebControl.Render()
               10 ms SomeNamespace.Web.UI.PreControlToAjaxify.Render()
               10 ms SomeNamespace.Web.UI.ControlRenderer.Render()
               10 ms SomeNamespace.Web.UI.RadDatePicker.Render()
               10 ms SomeNamespace.Web.UI.RadWebControl.Render()

It says here “Default.aspx” took 130485 ms (more than 2 minutes!). This is the entrypoint duration. The stack, however, adds up to about 500 ms collected. What happened?

The short answer is you only collected a portion of stack.

In Premium Support Team we see people struggling with these sorts of questions. Below is the summary of the most common options you can use to make your events much more evident, detailed and easy to understand.

Here are the reasons why you might be missing portions of the stack:

  1. Your request has got huge number of quick calls which don’t break the sensitivity threshold. AVIcode just ignores them for good. This is rather typical in Object-Relational Mapping bugs, where loading a list of entities results in tens of thousands of millisecond-long second calls to the database that add up to minutes. 
  2. Some of namespaces are disabled in the current monitoring configuration. AVIcode does not even instrument the functions in these namespaces.
  3. Probably you should add some specific namespaces (for example, namespaces of your own application) to monitoring.
  4. Login calls will not be be collected, but might take a long time to complete.
  5. Page inline calls are not shown in default configuration.
    Using long duration inline method call, you may get event similar to one below:

    To collect an inline call you should enable “ASP” (or “ASP.default_aspx”) namespace.

How do you know what are you missing? Here are debug steps. These are not recommended in production. If you absolutely have to do these, take one of the nodes from the load balancer and work on it, as these settings will increase the monitoring overhead dramatically.

  1. Turn on “All Namespaces” and “ASP” monitoring for appropriate application in MMC.
  2. Decrease the sensitivity threshold for troubleshooting test.
  3. Generate new events for specific request.
  4. After the new stack is collected (you should see more functions inside event and some of these functions will be heavier than the others), pick the performance offenders and add them (or their namespaces) explicitly. 

If these steps still do not help, you are most likely either dealing with safety switches (or “Self Monitoring” features of AVIcode). We will discuss them in one of the following posts. Meanwhile check your event logs for AVIcode-specific warnings and contact support for clarifications.