Debugging .NET Apps with Time Travel Debugging (TTD)

12/9/2018 6:24:16 PM By Felipe Pessoto

When you are debugging an application, there are many tools and techniques you can use, like logs, memory dumps and Event Tracing for Windows (ETW). In this post, we will talk about Time Travel Debugging, a tool used by Microsoft Support and product teams and more advanced users, but I encourage everyone to try this approach when diagnosing hard to find bugs.

Time Travel Debugging

Time Travel Debugging or TTD, is the process of recording and then replay the execution of a process, both forwards and backward, to understand what is happening during the execution. It is vital to fixing bugs when the root cause is not clear, and the symptoms appear moments later when the source of the problem is gone. In a way it's similar to Intellitrace (available in Visual Studio 2017 Enterprise), but while Intellitrace records specific events and associated data - call stack, function parameters and return value -, TTD embraces a more general approach and let you move at a single instruction level and access any process data (heap, registers, stack).

The same way you can debug a native or managed process, you can also use TTD in both cases, including .NET Core, but it is limited to Windows.
In the following sections, we'll describe particularities when debugging a managed process.

It also allows you to rewind and play how many times you want, helping you to isolate the problem when it happened, and setting breakpoints just as you usually do in Windbg. Even when you don't need to rewind, TTD has advantages over Live Debugging, since it doesn't interrupt the process, you can create a trace and analyze it offline, but be aware that TTD is very intrusive and ideally you shouldn't use it for more than a few minutes or the traces files can become very large (>5GB).

Demo Lab

The demo application is a simple Windows Forms bugged applications that writes a log file to disk. You can download the code from GitHub and compile it, or download the binaries. The machine where we'll record the traces must be a Windows 10 version 1809, Windows Server 2019 or newer.

Open the application and click on Save several times and after some seconds it doesn't work anymore:

Recording a trace

You can use WinDbg Preview to record the trace, but for this Lab, we'll use the built-in TTTracer.exe available on Windows 10 (1809 or newer) and Windows Server 2019, because sometimes it's impossible to install tools in a production environment.

1. Open the LabWindbgTTD.exe in the target machine and take a note of its PID:

2. Open a Command Line as admin and enter the following command, replacing <PID> with the PID of the process:

TTTracer -attach <PID>

Now, the TTD is recording the process execution.

3. Go to the LabWindbgTTD application and click on Save several times until you receive the error. After the error appears, in a different Command Prompt (with admin privileges), execute the following command to stop the trace:

TTTracer -stop <PID>

4. You are going to be notified about the trace stop in the first Command Prompt:

5. TTTracer will generate two files: LabWindbgTTD01.out and LabWindbgTTD01.run

Replay and Analyze

Copy both files to your machine, you can use WinDbg or WinDbg Preview to analyze it and don't forget to set up the symbols to be able to resolve the function names. We'll use WinDbg Preview, but the steps are similar in WinDbg, click File -> Open Trace File and select the ".run" file:

 

When debugging a TTD file, you can Step Into (t), Step Out and Step Over (p) like you do when Live Debugging:

You can see the current Time Travel Position when stepping through the application, like in the image above.

Using the !tt <POSITION> command you can navigate to a specific position:

 

The !positions command show the positions for all threads:

 

But it gets interesting when using the Step command contrariwise, instead of p, t, and g, you can execute p- (Step Back), t- (Trace Back), and g- (Go Back):

Loading Data Access Component and SOS debugging extension

When debugging .NET applications in a different machine from where the dump or trace was created, you need to copy the Data Access and SOS dlls:

  • For .NET Framework: mscordacwks.dll and SOS.dll in C:\Windows\Microsoft.NET\Framework\v4.0.30319\ (or C:\Windows\Microsoft.NET\Framework64\v4.0.30319\ for 64 bits processes)
  • For .NET Core: mscordaccore.dll and SOS.dll in C:\Program Files\dotnet\shared\Microsoft.NETCore.App\X.X.X\

And execute this command in WinDbg: 

.cordll -ve -u -lp <PATH>

.NET Framework

.NET Framework

 

.NET Core

Finding the problem

Now we know how to navigate into the TTD file, how can we find the bug?

Let's try to stop when the error occurs, to do this you could use "sxe clr;g" like you would do in a Live Debug, but the TTD extends the Session and Process data model objects, exposing events like Exceptions. To see them all, execute "dx @$curprocess.TTD" and "dx @$cursession.TTD":

 

We can take advantage of this feature and filter the Exception events, "dx -r2 @$curprocess.TTD.Events.Where(t => t.Type == "Exception").Select(e => e.Exception)":

Click on [Time Travel] to navigate to the moment when the Exception was thrown and execute !pe to see the System.ObjectDisposedException.

You can now execute !clrstack to see exactly which method is throwing the Exception, but it isn't helpful since the BtnSave_Click just call StreamWriter.WriteAsync and is not disposing the object.

In this case, a log containing the Stack Trace, or a Dump file wouldn't help. The application is small and simple enough that looking the code you would easily find the problem, but let's continue the analysis using the WinDbg.

Execute !dso (or !DumpStackObjects) to see the objects in the current stack and click on StreamWriter address.

Click the address to execute !do (or !DumpObj) that shows the details of the object, including its fields, where we can see the stream is null, which means it is disposed.

We know that at this point the StreamWrite.Dispose method has been called and we need to find out who called it. Set a breakpoint to this method and continue the execution in reverse, "!bpmd mscorlib.dll System.IO.StreamWriter.Dispose;g-":

You'll stop at Dispose method of StreamWriter. Execute !dso again, we can see a StreamWriter in the same address as before, let's inspect the object and the underlying stream to find more details about it.

 

 

The object address may be different because a Garbage Collection happened or just because we are looking at a different instance of StreamWriter. In this case, you would need to check if the object is the same.

Another option, to see if the object is the same, is to use !GCRoot to find references to the object, this way we can see if in both moments the StreamWriter object is the LogFile field in Form1.

If it is not the object you are looking for, execute g- again until you find it, then execute !clrstack to show the Stack Trace and find the method that is Disposing the StreamWriter:

 

 

Conclusion

TTD makes it viable to analyze many scenarios that would be extremely difficult to reproduce or to collect the right data. The possibility of going back and forth is powerful and has the potential to greatly reduce troubleshooting time.

Microsoft Docs has many more details about TTTracer and Windbg Preview.

[Update: Span<T>] - Evitando alocações de memória ao ler arquivos textos

12/4/2017 12:05:00 AM By Felipe Pessoto

Com o release de hoje do Visual Studio 15.5, fiz uma versão utilizando Span<T>, ainda não é possível ver suas vantagens pois muitas APIs ainda não aceitam o ReadOnlySpan<char> no lugar de strings, o que permitiria por exemplo chamar o int.TryParse diretamente (Update 2: Agora permitem, o codigo foi atualizado para refletir isso). Com isso o Span<T> traria o melhor de todas as soluções apresentadas, a simplicidade do Substring, com a performance dos ponteiros, sem utilizar o unsafe.

Ainda assim o Span<T> mostra que sua performance foi a melhor entre os métodos avaliados, sem alocar praticamente nenhuma memória:

[Benchmark]
private long Read_ResultSpan(bool stack)
{
    int bufferSize = GetLineSize();
    Span buffer = stack ? stackalloc char[bufferSize] : new char[bufferSize];
    long total = 0;

    TextReader sr = GetReader();
    {
        while (sr.Read(buffer) > 0)
        {
            int lastIndex = 0;

            for (int i = 0; i < positions.Length; i++)
            {
                ReadOnlySpan result = buffer.Slice(lastIndex, positions[i]);
                lastIndex += positions[i];
                total += int.Parse(result);
            }
        }
    }

    if (total != expected)
    {
        throw new Exception("Wrong result");
    }

    return total;
}

E o resultado final:

Method Mean Ratio Gen 0/1k Op Gen 1/1k Op Gen 2/1k Op Allocated Memory/Op
Minimum 1.522 ms 0.002 - - - 0 B
ReadLine_ResultSubstring 662.002 ms 1.000 78000.0000 - - 157 MB
ReadLine_ResultCharArray 649.625 ms 0.981 78000.0000 - - 157 MB
Read_ResultCharArray 443.691 ms 0.670 57000.0000 - - 114 MB
Read_ResultCharArraySpan 390.457 ms 0.590 - - - 440 B
Read_ResultUseUnsafeCharPointer 551.917 ms 0.834 - - - 1824 B
Read_ResultSpanStackAlloc 369.504 ms 0.558 - - - 0 B
Read_ResultSpanCharArray 397.005 ms 0.600 - - - 360 B
Read_ResultSpanNative 376.109 ms 0.568 - - - 0 B

 

 

O código está disponível em https://github.com/felipepessoto/AvoidingStringAllocation

O que há de novo no C# 7.0 - Pattern Matching

12/14/2016 2:40:00 AM By Felipe Pessoto

Pattern Matching é uma nova estrutura na linguagem que permite testar um valor contra um determinado formato enquanto atribui seu resultado.

Na versão 7.0 do C# são esperados três patterns:

  • Constant - Testa a expressão contra uma constante, isto é, literais, variável const, o valor de um enum ou typeof
  • Type - Testa se uma expressão é de um determinado tipo e em caso de sucesso faz o cast para o tipo, atribuindo o resultado em uma variável
  • Var - Esta expressão sempre é executada com sucesso, servindo apenas para atribuir o valor em uma nova variável

E mais estão por vir, no GitHub é possível ler o documento sobre Pattern Matching

Atualmente estes patterns podem ser utilizados nas expressões is e no case do bloco switch.

Is Expressions

 O principal uso nas expressões is será do Type Pattern, para atribuir uma variavel enquanto teste seu tipo. Por exemplo, quando é necessário executar um método de uma classe derivada, em vez de:

Dog dog = animal as Dog;
if(dog != null)
{
    dog.Bark();
}

//Ou

if (animal is Dog)
{
    Dog dog = (Dog)animal;
    dog.Bark();
}

É possível validar e atribuir em uma unica expressão:

if (animal is Dog dog)
{
    dog.Bark();
}

Como muitos dos recursos são apenas Syntactic Sugar, recomendo sempre avaliar qual a IL gerada, neste caso, é equivalente ao seguinte código C#:

Dog dog;
if ((dog = (animal as Dog)) != null)
{
    dog.Bark();
}

 Switch statements

 Com o switch fica ainda mais interessante ao combinar as condições, mantendo as regras separadas para cada caso e o código mais claro:

Animal animal = GetAnimal();

switch (animal)
{
    case Dog dog when dog.IsShortHaired:
        Console.WriteLine("Short Haired");
        break;
    case Dog dog:
        Console.WriteLine("Not Short Haired");
        break;
    case Cat cat:
        Console.WriteLine("Cat");
        break;
    case null:
        throw new ArgumentNullException();
    default:
        Console.WriteLine("Animal");
        break;
}

 O escopo de cada variavel atribuida no case é restrita ao bloco em que foi declarado e pode ser utilizado para validar outras regras, como no exemplo o IsShortHaired. Assim caso alguma validação não seja feita com sucesso, o bloco não é executado e o próximo case é avaliado.

Outra mudança importante é que agora o ordem dos case's é validada na compilação, impedindo que se use um case que inutilize os que estão abaixo dele, por exemplo:

E o case default será sempre executado por último, não importando o local em que foi declarado.

Evitando alocações de memória ao ler arquivos textos

12/2/2016 12:01:00 AM By Felipe Pessoto

Esta é uma tarefa comum, alguns processos de importação e exportação de dados usam colunas fixas, como alguns usados por bancos, por exemplos o CNAB.

O processo de leitura parece simples e realmente é. Só precisamos tomar alguns cuidados, como não ter ler todo o arquivo para a memória para então processar e guardar seu resultado, o que poderia causar um OutOfMemoryException.

De forma geral, bastaria algo como:

int[] positions = new int[] { 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10, 1, 2, 3, 4, 5, 6, 7, 8, 9, 10 };

string[] result = new string[positions.Length];

using (StreamReader sr = new StreamReader("Data.txt"))
{
    string line;
    while ((line = sr.ReadLine()) != null)
    {
        int lastIndex = 0;

        for (int i = 0; i < positions.Length; i++)
        {
            result[i] = line.Substring(lastIndex, positions[i]);
            lastIndex += positions[i];
        }
    }
}

 

Porém desta forma são alocadas diversas string para cada linha. Cada chamada ao método Substring, cria uma nova string.

Assim, ao ler 1.000.000 de linhas, são alocados cerca de 1121MB levando 1208ms.

Ao realizar o profiling da aplicação é possível ver que a praticamente todo o tempo é utilizado nos métodos ReadLine e Substring. (Não foi possível aguardar o fim da execução, com o profiler ativo ela fica muito mais lenta)

 

Assim podemos tentar otimizar estes dois pontos, o primeiro deles, o uso de Substring.

Neste exemplo criei duas soluções, utilizando char[], no caso como são diversas colunas, char[][]. A segunda opção com ponteiros.

Ambas tem resultados semelhantes, cada uma com seus pontos fortes e fracos. Ao utilizar ponteiro você obrigatoriamente utiliza código marcado como unsafe. E ao utilizar char[] não é possível utilizar as classes do .NET para fazer o Parse para int por exemplo, apesar de ser possível criar seu próprio método, como o método privado do .NET: https://referencesource.microsoft.com/#mscorlib/system/number.cs,04291cc3a0b10032,references

Ao executar o teste sem SubString diminuimos para 412MB alocados e 915ms de execução:

public void ReadLine_ResultCharArray()
{
    char[][] result = new char[positions.Length][];

    //Allocate char array of right size
    for (int i = 0; i < positions.Length; i++)
    {
        result[i] = new char[positions[i]];
    }

    using (TextReader sr = GetReader())
    {
        string line;
        while ((line = sr.ReadLine()) != null)
        {
            int lastIndex = 0;

            for (int i = 0; i < positions.Length; i++)
            {
                int fieldLength = positions[i];

                for (int j = 0; j < fieldLength; j++)
                {
                    result[i][j] = line[lastIndex + j];
                }

                lastIndex += fieldLength;
            }
        }
    }
}

 

 Desta vez o profiling é executado quase que de forma instantânea:

 

 

Agora nosso foco é o método ReadLine.

A classe TextReader possui um método Read que permite que seja utilizado um buffer de char[], assim podemos usar este método para evitar alocações, criando um buffer do tamanho de uma linha e reutilizando até o final do processamento:

public void Read_ResultCharArray()
{
    int bufferSize = GetLineSize();
    char[] buffer = new char[bufferSize];
    char[][] result = new char[positions.Length][];

    //Allocate char array of right size
    for (int i = 0; i < positions.Length; i++)
    {
        result[i] = new char[positions[i]];
    }

    using (TextReader sr = GetReader())
    {
        while (sr.Read(buffer, 0, bufferSize) > 0)
        {
            int lastIndex = 0;

            for (int i = 0; i < positions.Length; i++)
            {
                int fieldLength = positions[i];

                for (int j = 0; j < fieldLength; j++)
                {
                    result[i][j] = buffer[lastIndex + j];
                }

                lastIndex += fieldLength;
            }
        }
    }
}

 

 Diminuindo a alocação de memória para valores irrisórios:

 

Desta forma porém nosso resultado é um array de char e não string, impedindo o uso de alguns métodos como int.Parse. Para continuarmos com o resultado em string, é possível utilizando ponteiros, como no exemplo:

public void Read_ResultUseUnsafeCharPointer()
{
    int bufferSize = GetLineSize();
    char[] buffer = new char[bufferSize];
    string[] result = new string[positions.Length];

    //Allocate empty strings of right size
    for (int i = 0; i < positions.Length; i++)
    {
        result[i] = new string(' ', positions[i]);
    }

    using (TextReader sr = GetReader())
    {
        while (sr.Read(buffer, 0, bufferSize) > 0)
        {
            int lastIndex = 0;

            for (int i = 0; i < positions.Length; i++)
            {
                int fieldLength = positions[i];

                unsafe
                {
                    fixed (char* chars = result[i])
                    {
                        for (int j = 0; j < fieldLength; j++)
                        {
                            chars[j] = buffer[lastIndex + j];
                        }
                    }
                }

                lastIndex += fieldLength;
            }
        }
    }
}

 

O uso de memória e tempo de processamento é semelhante ao usar char[][].

Abaixo um sumário com todos os testes realizados com 100 mil linhas:

 

Method Mean StdErr StdDev Median Scaled Scaled-StdDev Gen 0 Bytes Allocated/Op
GoStraightReadLine 68.5477 ms 0.4298 ms 0.7444 ms 68.7090 ms 0.49 0.00 2,268.00 101,400,456.33
GoStraightRead 34.3965 ms 0.3196 ms 0.5535 ms 34.4998 ms 0.25 0.00 - 19,869.67
ReadLine_ResultSubstring 140.3299 ms 0.0818 ms 0.1416 ms 140.3629 ms 1.00 0.00 6,440.00 284,255,469.00
ReadLine_ResultCharArray 101.1819 ms 0.6428 ms 1.1134 ms 100.8166 ms 0.72 0.01 2,275.00 101,735,538.92
ReadLine_ResultUseUnsafeCharPointer 106.5311 ms 0.2403 ms 0.4162 ms 106.3192 ms 0.76 0.00 2,275.00 101,738,164.83
Read_ResultNewString 109.9989 ms 0.0806 ms 0.1395 ms 110.0615 ms 0.78 0.00 4,165.00 182,531,333.17
Read_ResultUseUnsafeCharPointer 80.7485 ms 0.2625 ms 0.4546 ms 80.7316 ms 0.58 0.00 - 24,451.50
Read_ResultCharArray 77.3640 ms 1.0972 ms 1.9004 ms 76.4365 ms 0.55 0.01 - 24,806.92

 

As duas primeiras linhas representam a leitura do arquivo, sem nenhum processamento. A terceira é o primeiro exemplo e a última o último exemplo

Application Insights ASP.NET Core SQL Dependency Track

10/1/2016 3:24:00 AM By Felipe Pessoto

Application Insights for ASP.NET Core doesn't support Dependency Tracking:

Dependency tracking and performance counter collection are by default enabled in ASP.NET Core on .NET Framework (currently not supported in .NET Core) https://github.com/Microsoft/ApplicationInsights-aspnetcore/wiki/Dependency-Tracking-and-Performance-Counter-Collection 

So I created this library to automatically track your SQL queries and send to Application Insights.

Setup:

1-) Add Fujiy.ApplicationInsights.AspNetCore.SqlTrack package

2-) On your Configure method, add TelemetryClient parameter and add AiEfCoreLoggerProvider to ILoggerFactory:

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory, TelemetryClient tc)
{
    loggerFactory.AddProvider(new AiEfCoreLoggerProvider(tc));
    ...

Then you can monitor the sql calls in each request and the most expensives:

 

GitHub: https://github.com/fujiy/Fujiy.ApplicationInsights.AspNetCore.SqlTrack