WinDBG basic commands, part 2

How busy CPU is?

!theadpool command shows avg. CPU usage (during last second), number of active threads, and callbacks:

Threadpool

Use case: High CPU investigations, ensure snapshot was collected during maxed CPU. Shows pending callbacks (if any) as well as how many threads are there.

What threads are consuming CPU time?

!runaway shows aggregated CPU time taken by each alive thread:

Use case: A difference between a few sequential snapshots shows threads using CPU resource in between. Useful during high CPU investigations.

What does each thread do?

Each thread either performs some operation, or waits to do something.

!eestack -ee prints managed call stacks for all the threads:

Each thread call stack

Use case: Get an overview of ongoing activities, always useful:

  • Are threads waiting for exclusive access? F.e. lock (obj)
  • Are ASP.NET requests being processed? Trail – IIS7WorkerRequest class
  • What are the operations performed by most CPU consuming threads?
  • Similar/repeatable patterns?

What does each thread do (shorten version)

Mex extension powers !mthreads showing top frame/action performed by thread:

High-level overview of ongoing activities

Use case: High-level overview of ongoing operations in the snapshot

Group threads by call stacks

MEX !uniquestacks groups threads by operations they execute:

Threads grouped by call stacks

Use case: Locate repeatable patterns in one go.

Find currently executed ASP.NET requests

MEX !aspxpagesext gives stats for processed ASP.NET requests:

ASP.NET requests executed

Use case: Get the number of concurrent requests & how long they run for.

Tackling memory leak

In academia, there is no difference between academia & the real world.

In the real world, there is.

Nassim Nicholas Taleb

This post covers the real world case study on tackling memory leak.

Investigation strategy

Memory leak occurs if useless resources are not removed from memory – there has to be something rooting old data. Investigation plan:

  1. Collect memory snapshot once memory usage is beyond the expected range
  2. Collect another one in a minute or so
  3. Compare heap statistics: locate growing/weird types
  4. Find GC roots for these objects
  5. Determine construction mechanisms for these instances

Collecting memory snapshots

A few memory snapshots have been collected via Task Manager:

Collecting memory snapshot via Task Manager

Snapshot can be collected automatically once memory is higher than threshold.

Any anomalies in heap statistics?

Both snapshots contain a huge number of GlassMapper objects that contradicts the module usage pattern (create many short-lived objects):

We could either find !gcroots (who holds object in memory) for suspicious classes that have much higher count than expected or look for unexpectedly huge objects in the heap.

A few IDisposable[] arrays take as much space as 100K objects?! That is over 2200 elements in average (or ~18KB) inside array. There are over 700 huge arrays each having over two thousands disposable elements each, sounds as a code smell.

Finding bigger than average arrays with size over 20K bytes (via min param):

Huge array with over 2 million entries
Glass mapper objects stored inside

Two million elements long array (disposable GlassMapper objects inside) is rooted to ServiceProvider:

SitecorePerRequestScope module roots array in all snapshots

Same pattern is met in all the captured snapshots.

Hypothesis

GlassMapper disposable objects are resolved from global DI scope, hence getting disposed when application shuts down. Objects are stacked in memory until then.

Alternatively disposed scope is used to keep on resolving objects.

Who creates objects that are never disposed?

Although leaking classes can be modified to save birth call stack & ServiceProvider used to create them, not owned types cannot be modified to add that code.

Nevertheless, behavior could be simulated on a test disposable class and Sitecore DI mechanism.

Prediction

At least one way for creating disposable objects produces leak by rooting to either global DI scope (list of resolved IDisposable dependencies), or re-using disposed scope.

Verification steps

  1. Request disposable type via various Dependency Injection mechanisms
  2. Log object creation call stack
  3. Trigger full garbage collection a few times
  4. Attach to process with WinDBG and inspect alive instances
    • How where they created
    • Who roots them in memory

Demo code

The disposable dependency records its birth call stack and capture the ‘parent’ service provider:

using System;
using System.Threading;
using Sitecore.Abstractions;
using Sitecore.Diagnostics;
using Sitecore.Pipelines;

namespace Demo
{
    /// <summary>
    /// Registered in DI with transient scope.
    /// <para>Dispose is to be called upon scope end.</para>
    /// </summary>
    public class DisposableDependency : IDisposable
    {
        private readonly BaseLog _log;
        private readonly IServiceProvider _parent;
        private static int _instancesCount;
        private readonly string _birthCertificate;

        public int Number { get; }

        public DisposableDependency(BaseLog log, IServiceProvider parent)
        {
            Assert.ArgumentNotNull(log, nameof(log));
            _log = log;
            _parent = parent;
            Number = Interlocked.Increment(ref _instancesCount);
            _log.Warn($"Dummy processor was born: {Number} {Environment.NewLine} {Environment.StackTrace}", this);
            _birthCertificate = Environment.StackTrace;
        }

        public void Process(PipelineArgs args)
        {
            _log.Warn($"Dummy processor was executed: {Number} {Environment.NewLine} {Environment.StackTrace}", this);
        }

        void IDisposable.Dispose() => _log.Warn($"Dummy processor died: {Number} {Environment.NewLine} {Environment.StackTrace}", this);
    }
}

Injection to types created by Factory

Sitecore creates objects via DI if resolve=’true’ attribute set in config node.

New instance is created each time if reusable=’false’ attribute is set for processor:

<?xml version="1.0"?>

<configuration xmlns:patch="http://www.sitecore.net/xmlconfig/" xmlns:set="http://www.sitecore.net/xmlconfig/set/">
    <sitecore>
        <services>
            <!-- Register disposable service -->
            <register serviceType="Demo.DisposableDependency, Demo" implementationType="Demo.DisposableDependency, Demo" />
        </services>

        <pipelines>
            <initialize>
            <!-- Register controller route to test MVC constructor injection -->
                <processor type="Demo.RegisterRoute, Demo"/>
            </initialize>

            <disposableSample>
            <!-- Register processor to be created every time -->
                <processor type="Demo.DisposableDependency, Demo" resolve="true" reusable="false" />
            </disposableSample>
        </pipelines>
    </sitecore>
</configuration>

Define the disposableSample pipeline with non-reusable DisposableDependency so that a new instance is created for each call. Invoke it via dummy page:

<%@ Page Language="C#" AutoEventWireup="true" Inherits="Demo.PipelineCall" %>
using System;
using Sitecore.Abstractions;
using Sitecore.DependencyInjection;
using Sitecore.Diagnostics;
using Sitecore.Pipelines;

namespace Demo
{
    [AllowDependencyInjection]
    public class PipelineCall : System.Web.UI.Page
    {
        private readonly BaseCorePipelineManager _pipelineManager;

        protected PipelineCall()
        {
        }

        public PipelineCall(BaseCorePipelineManager pipelineManager)
        {
            Assert.ArgumentNotNull(pipelineManager, nameof(pipelineManager));
            _pipelineManager = pipelineManager;
        }

        protected void Page_Load(object sender, EventArgs e)
        {
            var pipeline = _pipelineManager.GetPipeline("disposableSample", string.Empty);
            pipeline.Run(new PipelineArgs());
        }
    }
}

Injection to WebForms and UserControls

ASP.NET ConstructorInjection.aspx form:

<%@ Page Language="C#" AutoEventWireup="true" Inherits="Demo.ConstructorInjection" %>
using System;
using System.Web;
using Sitecore.DependencyInjection;
using Sitecore.Diagnostics;

namespace Demo
{
    [AllowDependencyInjection]
    public partial class ConstructorInjection : System.Web.UI.Page
    {
        private readonly DisposableDependency _dependency;

        protected ConstructorInjection()
        {
        }

        public ConstructorInjection(DisposableDependency dependency)
        {
            Assert.ArgumentNotNull(dependency, nameof(dependency));
            _dependency = dependency;
        }

        protected void Page_Load(object sender, EventArgs e)
        {
            HttpContext.Current.Response.Write($"<h2>I was called {_dependency.Number} </h2>");
        }
    }
}

Injection and MVC

Controller that needs disposable dependency:

using System.Web.Mvc;
using Demo;
using Kerzner.Foundation.DependencyInjection;

namespace Kerzner.Project.BrandWebsites.Pipelines.ScScopeVerification
{
    [Controller]
    public class DummyController : Controller
    {
        private readonly DisposableDependency _dependency;

        public DummyController(DisposableDependency dependency)
        {
            _dependency = dependency;
        }

        public ActionResult Index()
        {
            return Content($"<h2>called {_dependency.Number} <h2/>");
        }
    }
}

Controller registration:

using System.Web.Mvc;
using System.Web.Routing;
using Sitecore.Pipelines;

namespace Demo
{
    public class RegisterRoute
    {
        public void Process(PipelineArgs args)
        {
            RouteTable.Routes.MapRoute(
                "DisposableDependency",
                "DummyController",
                new { controller = "Dummy", action = "Index" });
        }
    }
}

Test results

Non-disposed dependencies are created by Factory

Sitecore DefaultFactory (registered as singleton) captures scoped ServiceProvider. Any object is created from that service provider reuses that scope instead of one valid for request. Birth certificates proof objects created by Factory thereby leaking memory.

ASP.NET pages do not dispose some dependencies as well

AutowiredPageHandlerFactory creates ASPX pages with the respect to proper scope from the first sight. Nevertheless, it does not work as intended due to handler factory cache inside HttpApplication.

Even though correct service provider scope is used at first, it would still be re-used for further requests processed by the instance of HttpApplication.

Conclusion

The memory leak mystery was resolved thanks to a few memory snapshots. Once the cause is found, code adjustments could be done:

  • Do not resolve disposable objects from DI, prefer explicit creation (in case possible) to favor explicit dispose call
  • Consume per-request scope from Sitecore.DependencyInjection.SitecorePerRequestScopeModule.GetScope to resolve dependencies from request-bound scope so that disposed is called on EndRequest
  • Sitecore framework improvement to keep in mind potential nature of disposable dependencies

The behavior described in the article has been reported to Sitecore Support and accepted as 331542 bug report.

WinDBG basic commands, part 1

WinDBG debugger brings you behind the scenes to witness CLR magic from backstage. You’ll be able to see the hidden gems that turn magic into reality.

This post shows basic WinDBG commands to begin your journey. It is a good one to start exploring the world full of fascinating technical magic.

Snapshot creation time

Similar to picture capturing a single point in time, memory snapshots captures the process state in single moment.

.time command shows when the snapshot was taken or time of the debugging session (in case attaching to process)

.time command example
.time command example

Use case: Get the time diff between a few sequential memory snapshots.

The distance between SPECS cameras is known as well as speed limit. Hence the minimal legal journey time is known.Speeding fine shall be issued in case two cameras capture same car in shorter span.

Load extension

.load [path] command loads WinDBG extension into debugger

WinDDB extension load example
WinDDB extension load example

Anybody can create extension to automatize the sequence of re-occurring steps.

Use case: Extensions provide additional commands to execute, or better view for same data (like displaying object content !do vs !mdt).

List of loaded extensions into WinDBG

.chain command shows extensions currently loaded into debugger

Display WinDBG loaded extensions
Display WinDBG loaded extensions

Use case: Verify extensions powering commands are loaded (f.e. mex).

Unload extension

.unload [path] command unloads extension from debugger

Unloading extension from WinDBG on demand
Unloading extension from WinDBG on demand

Use case: Commands might overlap (sos and mex define !threadpool).

List threads

!thread lists threads in the process:

List threads from memory snapshot

Use case: Answer these questions:

  • Are there any exceptions being handled?
  • Are there any locks owned?
  • How many application domains are there?
  • Is the number of threads seem legit?

Hint: !threads -special would show threads with specific roles (GC, Finalizer, IOCompletion)

Switch to the thread

~[thread_number]s switches debugger to the thread:

Switching to GC thread

Use case: Investigate thread-specific data (like call stack or thread stack values).

Get unmanaged call stack

kb [number of frames] gets unmanaged thread call stack

Use case: Check the garbage collection phase.

Loading memory snapshot into debugger

Memory snapshot captures a picture of the process in time. It is a source of wonderful information about application. You can see on your own what operations are being executed, is there a bottleneck around locking expensive resource and so much more. The most important part to me is to see the application from the angle you’ve never seen it before.

This post shows how to unlock access to the data.

Pre-requirements

WinDbg is to be installed from Microsoft store:

WinDbg download screen

Alternatively, WinDbg could be installed as a part of Debugging Tools for Windows SDK.

Drag & Drop *.dmp file into WinDBG

Memory snapshot opened in WinDbg

Main bits to read snapshot data

The debugger must load data access component (DAC) (mscordacwks.dll) from the machine snapshot was created on.

Although in 99% of the cases debugger is able to load needed version from the web, you might need to copy it from ‘%WINDOWS%\Microsoft.NET\Framework64\[framework_version]\mscordacwks.dll‘ location.

WHAT IS ‘SOS’ ?

SOS Debugging Extension (SOS.dll) provides information about the internal Common Language Runtime (CLR) environment. In simple words – it translates data to human-understandable format

Automatically load needed assemblies

The .cordll -u -l -ve command attempts to automatically load core dll:

Core DLL for snapshot processing is loaded

Manually load needed assemblies

Should command fail to locate matching version, you’ll need to get the assembly from source machine and manually load it with .load:

Manually loaded mscordacwks.dll

Open local memory snapshot

Should the memory snapshot be collected from local machine, local core dll can be loaded via .loadby sos clr command:

Verify snapshot is loaded correctly

Execute any sos-driven command (f.e. !eestack -ee ) to verify snapshot loaded correctly:

Memory dumps intro

What ‘memory dump’ is in human language?

It is a snapshot of an application, similar to real-world picture – just an array of bytes:

How to open memory snapshot?

As you need software to open pictures you need WinDBG to open memory snapshots.

What is inside the snapshot?

Typical park picture

  • Trees, humans, birds
  • The timestamp it was taken
  • Clues about ongoing activities
    • Tree top bend hints wind
    • Sport outfit hints jogging
  • A queue to the coffee shop
  • Some fallen branches

Application picture

  • All objects
  • The timestamp it was collected
  • Thread call stacks
    • SQL – hints DB activity
    • IIS7Request – hints ASP.NET
  • How many entries in queue
  • No longer needed data

What cannot be answered from one snapshot?

Typical park picture

  • When the tree was planted?
  • What is the speed of the wind?
  • For how long the guy is running?
  • How fast the shop queue is being processed?
  • When did the branch fall?

Application picture

  • When was an object created?
  • How fast operation is executed?
  • For how long the request is processed?
  • Is the processing queue grows or shrinks?
  • When was the object last used?

MYTH: WHY SLOW FROM SINGLE SNAPSHOT

At least sequential 2 pictures depicting same activity are needed. The progress (f.e. number of records processed/(queue length)) is checked in both snapshots and correlated to time stamp difference.

CONFIRMED: CACHE STATS

Caching layer is typically implemented based on objects, that are captured in single snapshot.

ASP.NET cache summary
ASP.NET cache summary

CONFIRMED: ONGOING SQL COMMANDS

SQL commands are implemented as objects, hence visible in a single snapshot.

SQL commands captured in the memory snapshot
SQL commands captured in the snapshot

CONFIRMED: ANYBODY CAN OPEN SNAPSHOT

All you need is proper program to open it. Assistant file (translator) might be needed from exact machine in case not found in web automatically.

Update: I’ve published Loading memory snapshot into debugger post for you.

About blog

Have you ever caught yourself thinking how the computer works? I did.

People used to treat it as a black box. That is so true even for software developers!

I’ll guide you to the program backstage to let you witness coding from totally different angle. You’ll be able to see the flow from C# code into 0/1 data stored inside the process.

Threads, heaps, garbage collection, structures, registers would be seen as never before. Knowing how the software runs from inside will help building better software.

From GitHub to first-class blog

Github blog content is being migrated from KeepSitecoreSimple.

Contact me

Here are the channels I’m reachable: [LinkedIn][Twitter]