How to debug a hanging action

Question

We have an MVC app that every know and then (anything from few times a day to once per 2-3 days) suffers a a site-wide hang (it doesn't respond to any requests and doesn't restart on its own either). We managed to reduce the number of suspects to a single page (whenever the site would suffer a hang this page would show up at the top of hanging requests). Knowing which page is the culprit doesn't help though, because we're unable to recreate the problem on development machine. In fact we can't even recreate the problem on the production machine (most of the time, simply opening the faulty page doesn't break anything).

What we know is that, sometimes when a user goes to this page (controller action) the site will hang and we know there isn't much in the way the request is being made that could contribute the the hang (from IIS logs we know how user got to the faulty page and that we're dealing with a simple GET with no query string params).

We would like to know where exactly in the code the hang happens, but we don't know how to get such information out of the app/worker thread/IIS/Windows Server. No exception is saved to Windows log, nor is our built into the app logger picking any exceptions (probably has something to do with the hang).

What are the ways to tell what exactly is an IIS worker thread doing at a given time (like get the corresponding file and line of code)?

---

P.S. I described the exact symptoms of the site-wide hang in another question, but those are irrelevant to this question. Plus the question ended up being too broad which only brought generic answers. P.S.2 We found the offending page by looking into Worker Processes\Requests in IIS.

Answer 1

In the past I've had the same issue and what really quickly helped me was the ability to inject a line of tracing code int the DLL(s) using Mono.Cecil. The code below injects tracing into the unsigned version of the DLL's and outputs a new DLL that can be used to create an "indented trace" into the code by injecting logging lines in the start (and end if needed...not shown below) of each method so that you can time the entry and exist of each call. There are a lot of third party tools but this is easy (a days work at best), gives full control to the developer, and as a bonus, is free.

You also need to create a DLL (IISStackTraceProvider below) that has the trace class and the static call "TraceStep" which can be used to log the data. To reconstruct that data across worker processes and threads, you associate a GUID and stopwatch with each BeginRequest/EndRequest using the "HttpContext.Items Property". Since your call hangs...you want to trace any call that "Begin" but never "End" or Ends with a time out and toss the rest away to keep things fast.

I've tested this against ~one million calls an hour/per server in a web farm in our production environment without affecting performance but be mindful of what requests you want to log and which requests get thrown away. Also, I used Redis to capture the logs since write times are insanely fast and also it's free, then just read the Redis data once I trap the issue.

class TraceInjection
{
    private ELogLevel logLevel;
    public enum ELogLevel
    {
        eLow,
        eMid,
        eHigh
    }

    public TraceInjection(ELogLevel logLevel)
    {
        this.logLevel = logLevel;
    }

    public bool InjectTracingLine(string assemblyPath, string outputDirectory)
    {
        CustomAttribute customAttr;
        AssemblyDefinition asmDef;

        // New assembly path
        string fileName = Path.GetFileName(assemblyPath);

        string newPath = outputDirectory + "\\" + fileName;

        // Check if Output directory already exists, if not, create one
        if (!Directory.Exists(outputDirectory))
        {
            Directory.CreateDirectory(outputDirectory);
        }

        ModuleDefinition modDefCopy = null;
        TypeDefinition typDefCopy = null;

        try
        {
            var resolver = new DefaultAssemblyResolver();
            resolver.AddSearchDirectory(System.IO.Path.GetDirectoryName(assemblyPath));

            var parameters = new ReaderParameters
            {
                AssemblyResolver = resolver,
            };

            // Load assembly
            asmDef = AssemblyDefinition.ReadAssembly(assemblyPath, parameters);

            String functionsFound = "";

            foreach (var modDef in asmDef.Modules)
            {
                modDefCopy = modDef;
                foreach (var typDef in modDef.Types)
                {
                    typDefCopy = typDef;                        
                    foreach (MethodDefinition metDef in typDef.Methods)
                    {
                        try
                        {
                            // Skipping things I personally don't want traced...
                            if (metDef.IsConstructor || 
                                metDef.IsAbstract ||
                                metDef.IsCompilerControlled ||
                                metDef.IsGetter ||
                                metDef.IsSetter
                                ) continue;

                            functionsFound += String.Format("{0}\r\n", metDef.Name.Trim());


                            // Get ILProcessor
                            ILProcessor ilProcessor = metDef.Body.GetILProcessor();

                            /*** Begin Method ******/
                            // Load fully qualified method name as string
                            Instruction i1 = ilProcessor.Create(
                                OpCodes.Ldstr,
                                String.Format(">,{0},{1}", metDef.Name.Replace(",", ""), asmDef.Name.Name)
                            );
                            ilProcessor.InsertBefore(metDef.Body.Instructions[0], i1);

                            // Call the method which would write tracing info
                            Instruction i2 = ilProcessor.Create(
                                OpCodes.Call,
                                metDef.Module.Import(
                                    typeof(IISStackTraceProvider).GetMethod("TraceStep", new[] { typeof(string) })
                                )
                            );
                            ilProcessor.InsertAfter(i1, i2);

                        }catch(Exception ex)
                        {
                            // ...
                        }
                    }
                }
            }

            Console.Write(functionsFound);
            Console.ReadKey();

            // Save modified assembly
            asmDef.Write(newPath, new WriterParameters() { WriteSymbols = true });
        }
        catch (Exception ex)
        {
            modDefCopy = null;
            typDefCopy = null;

            // Nothing to be done, just let the caller handle exception 
            // or do logging and so on
            throw;
        }

        return true;
    }

    public bool TryGetCustomAttribute(MethodDefinition type, string attributeType, out CustomAttribute result)
    {
        result = null;
        if (!type.HasCustomAttributes)
            return false;

        foreach (CustomAttribute attribute in type.CustomAttributes)
        {
            if (attribute.Constructor.DeclaringType.FullName != attributeType)
                continue;

            result = attribute;
            return true;
        }

        return false;
    }
}