Debugging .NET Apps with Time Travel Debugging (TTD) aka Time Travel Tracing (TTT)

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

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 evident, and the symptoms appear moments later when the source of the problem is gone.

It also allows you to rewind and play how many times you want, helping you to isolate when the problem happened, and setting breakpoints as you are used in Windbg. Even when you don't need to rewind, TTD has some 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 should be used for less than a minute or the traces files can become very large (>5GB).

Setup

First, make sure you have WinDbg installed and the symbols are configured, below two ways to set it up:

  • Set via an environment variable (it will work for every debugger)
    Name: _NT_SYMBOL_PATH
    Value: srv*c:\symbols\public*http://msdl.microsoft.com/download/symbols
  • Set via Windbg. File -> Symbol File Path (Ctrl+S). Symbol Path: srv*c:\symbols\public*http://msdl.microsoft.com/download/symbols:

Download the Labs from GitHub and compile it, or download the compiled version: LabWindbgTTD.zip.

The machine where the traces will be recorded must be a Windows 10 >=1809 or a Windows Server 2019.

Demo Lab

The demo application is a simple Windows Forms bugged applications that writes a log file to disk.

Click on Save several times and after some seconds it doesn't work anymore:

Recording a trace

You can currently use WinDbg Preview to record the trace, but for this Lab, we'll use the builtin TTTracer.exe available in Windows 10 (1809 or newer) and Windows Server 2019 since many times we can't install tools in a production machine.

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

Now open a Command Line as admin and enter the following command, replacing <PID> with the PID of the process:

TTTracer -attach <PID>

The trace files will be created. Now click on Save several times until you receive the error. After the error, in a different Command Prompt, execute the following command to stop the trace:

TTTracer -stop <PID>

You will notice that the trace will stop in the first Command Prompt:

The traces will result in 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. Using WinDbg Preview, click File -> Open Trace File and select the ".run" file:

 

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

When stepping you can see the current Time Travel Position, 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 starts to get 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 mscordacwks

When debugging .NET applications in a different machine from where the dump or trace was created you need to copy the mscordacwks.dll and SOS.dll from C:\Windows\Microsoft.NET\Framework\v4.0.30319\ (or C:\Windows\Microsoft.NET\Framework64\v4.0.30319\ for 64 bits processes) and execute this command in WinDbg: 

.cordll -ve -u -lp <PATH>

Finding the problem (Spoiler alert)

Now that we know how to navigate 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 all of them 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 what 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 as well. The application is small and simple enough that looking the code you will easily find the problem, but let's continue the analysis using the WinDbg.

We know that at this point the root cause already happened, so go back to the beginning, !tt 0, and now we need to find out who is calling StreamWriter.Dispose, so set a breakpoint to this method and continue the execution, "!bpmd mscorlib.dll System.IO.StreamWriter.Dispose;g":

You'll break at Dispose method of StreamWriter, execute !clrstack to see the Stack Trace and find the method that is Disposing the StreamWriter:

 

Conclusion

TTD makes it viable to analyze many scenarios that would be extremally difficult to reproduce or to collect the right data. The possibility of going back and forth is powerful and certainly 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. 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]
public void Read_ResultSpan()
{
    int bufferSize = GetLineSize();
    char[] buffer = new char[bufferSize];
    ReadOnlySpan<char>[] result = new ReadOnlySpan<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++)
            {
                result[i] = new ReadOnlySpan<char>(buffer, lastIndex, positions[i]);
                lastIndex += positions[i];

                //int.TryParse(result[i], out int x);
            }
        }
    }
}

E o resultado final:

Method Mean Error StdDev Scaled ScaledSD Gen 0 Allocated
ReadLine_ResultSubstring 104.23 ms 2.883 ms 0.7488 ms 1.00 0.00 78700.0000 161229.46 KB
ReadLine_ResultCharArray 87.21 ms 1.725 ms 0.4482 ms 0.84 0.01 21500.0000 44043.26 KB
Read_ResultCharArray 70.48 ms 24.516 ms 6.3681 ms 0.68 0.05 - 9.6 KB
Read_ResultUseUnsafeCharPointer 107.08 ms 58.028 ms 15.0726 ms 1.03 0.13 - 9.6 KB
Read_ResultSpan 55.05 ms 4.291 ms 1.1146 ms 0.53 0.01 - 9.92 KB

O código está disponível em https://github.com/fujiy/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