Como melhorar a performance de uma Azure Function usando SQL binding

This post has been republished via RSS; it originally appeared at: New blog articles in Microsoft Tech Community.

Há pouco tempo me deparei com um problema de desempenho em uma Azure Function. Não foi um troubleshooting complexo, porém a causa raiz desse problema foi muito interessante, por isso decidi abordá-lo aqui no blog.

Meu foco aqui não é explicar o que são Azure Functions, caso não esteja familiarizado com essa tecnologia, leia mais sobre Azure Functions em https://docs.microsoft.com/azure/azure-functions/functions-overview.

Azure Functions Triggers e Bindings

Azure Functions é um serviço do tipo PaaS (Platform as a Service). Elas permitem que sua aplicação seja implantada e executada sem a necessidade de provisionar e configurar a infraestrutura de servidores. Esse tipo de arquitetura é conhecida como Serverless. As Azure Functions podem ser escritas em várias linguagens, tais como:

C#
Java
JavaScript
TypeScript
Python

Triggers

A Trigger que dispara a execução de uma Azure Function, ela define como a função é invocada. Toda Azure Function tem exatamente uma Trigger.

No nosso caso usaremos uma HttpTrigger:

[HttpTrigger(AuthorizationLevel.Anonymous, "get")] HttpRequest req

Leia mais sobre Triggers em: https://docs.microsoft.com/azure/azure-functions/functions-triggers-bindings?tabs=csharp

Bindings

Os Bindings são formas declarativas de conexões com outros recursos do Azure a partir de uma função, existem dois tipos de bindings:

Entrada (Input).
Saída (Output).

Leia mais sobre bindings em: https://docs.microsoft.com/azure/azure-functions/functions-triggers-bindings?tabs=csharp

Problema no uso do SQL Binding

Os Bindings são extremamente relevantes, pois conseguimos deixar nossa função muito declarativa e limpa, facilitando consideravelmente sua manutenção. Imagine que uma função usa uma HttpTrigger e um SQL Input Binding, sua implementação ficaria assim:

[FunctionName("Blog")]
public IEnumerable<Blog> Run([HttpTrigger(AuthorizationLevel.Anonymous, "get")] HttpRequest req,
    [Sql(
        "exec BlogProc",
        CommandType = System.Data.CommandType.Text,
        ConnectionStringSetting = "SqlConnectionString"
    )] IEnumerable<Blog> blogs)
{
    return blogs;
}

Obs: Para usar o SQL Binding você precisa instalar o pacote Microsoft.Azure.WebJobs.Extensions.Sql

Fica bem intuitivo entender o que a função esta fazendo.

O trecho HttpTrigger(AuthorizationLevel.Anonymous, "get") declara que a função é ativada via HTTP, e aceitará apenas o verbo GET.

Agora a mágica: o trecho abaixo é responsável por configurar o SQL Input Binding, quando essa função for executada, automaticamente ela abrirá uma conexão com o banco de dados SQL Server, executará o comando exec BlogProc e retornará o resultado em um objeto que implementa a interface IEnumerable<Blog>:

[Sql(
    "exec BlogProc",
    CommandType = System.Data.CommandType.Text,
    ConnectionStringSetting = "SqlConnectionString"
)] IEnumerable<Blog> blogs

A procedure BlogProc executa um SELECT em uma tabela, e em seguida fará essa consulta ficar em estado de waiting por um segundo, com o objetivo de simular uma consulta mais demorada:

CREATE procedure BlogProc
AS
WAITFOR DELAY '00:00:01'
SELECT * FROM [dbo].[Blogs]

Naturalmente essa função demorará em torno de 1 segundo para responder.

Teste de carga

Agora a questão é: em um cenário de alta volume de requisições, como essa função irá se comportar?

Realizei um teste de carga simples, simulando 100 usuários simultâneos realizando requisições durante um minuto.

Para executar meu teste de carga iniciei o wsl através do comando:

wsl

Depois instalei a ferramenta siege, através do comando:

sudo apt-get install siege

Realizei o teste de carga através do comando:

host=$(grep nameserver /etc/resolv.conf | sed 's/nameserver //')
siege -t1 -c100  http://${host}:7071/api/Blog

O resultado obtido foi:

** SIEGE 4.0.4
** Preparing 100 concurrent users for battle.
The server is now under siege...
Lifting the server siege...
Transactions:                   2170 hits
Availability:                 100.00 %
Elapsed time:                  59.38 secs
Data transferred:               2.79 MB
Response time:                  2.68 secs
Transaction rate:              36.54 trans/sec
Throughput:                     0.05 MB/sec
Concurrency:                   97.84
Successful transactions:        2170
Failed transactions:               0
Longest transaction:           13.49
Shortest transaction:           1.04

O tempo de resposta médio foi de 2,68 segundos, e a requisição mais demorada foi de 13,49 segundos, isso significa que essa função está com desempenho ruim quando usada de forma concorrente.

O problema

Para entender mais detalhes sobre o porque deste comportamento, vou capturar um dump de memória.

Para capturar o dump vou instalar a ferramenta dotnet-dump, através do comando:

dotnet tool install -g dotnet-dump

Esse comando não funcionará caso você não tenha o .NET SDK instalado, mais informações em: https://dotnet.microsoft.com/download/visual-studio-sdks

Agora precisamos achar o PID da nossa função, podemos fazer isso através do comando:

dotnet-dump ps

No meu caso o resultado foi:

     18860 func       C:\Program Files\Microsoft\Azure Functions Core Tools\func.exe

Com o PID em mãos vamos capturar o Dump, mantenha em mente que precisamos realizar a captura durante o teste de carga, caso contrário não conseguiremos ter visibilidade do problema:

dotnet-dump collect -p 18860

Esse comando deve retornar algo parecido com:

Writing full to C:\dump_20220805_210149.dmp
Complete

Windbg

Para analisar o Dump usaremos o WindbgX.

Para entender o que está ocasionando a lentidão inspecione todas as pilhas das threads com o comando:

~*k

Agora basta olhar as pilhas de chamadas das threads e entender o porque elas estão sendo bloqueadas.

No meu caso, todas as threads estavam executando uma pilha parecida com:

      Child SP               IP Call Site
...
00000009FC07BD00 00007ff8157ac1be Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync()
00000009FC07BDA0 00007ff8157ac0ab Microsoft.Data.SqlClient.TdsParserStateObject.TryReadNetworkPacket()
00000009FC07BDE0 00007ff8157abfde Microsoft.Data.SqlClient.TdsParserStateObject.TryPrepareBuffer()
00000009FC07BE20 00007ff8157378ce Microsoft.Data.SqlClient.TdsParserStateObject.TryReadByte(Byte ByRef)
00000009FC07BE60 00007ff8152019b9 Microsoft.Data.SqlClient.TdsParser.TryRun(Microsoft.Data.SqlClient.RunBehavior, Microsoft.Data.SqlClient.SqlCommand, Microsoft.Data.SqlClient.SqlDataReader, Microsoft.Data.SqlClient.BulkCopySimpleResultSet, Microsoft.Data.SqlClient.TdsParserStateObject, Boolean ByRef)
00000009FC07BFF0 00007ff8156df296 Microsoft.Data.SqlClient.SqlDataReader.TryConsumeMetaData()
00000009FC07C040 00007ff815737c77 Microsoft.Data.SqlClient.SqlDataReader.get_MetaData()
00000009FC07C070 00007ff8157b013e Microsoft.Data.SqlClient.SqlCommand.FinishExecuteReader(Microsoft.Data.SqlClient.SqlDataReader, Microsoft.Data.SqlClient.RunBehavior, System.String, Boolean, Boolean, Boolean)
00000009FC07C0E0 00007ff8157ab569 Microsoft.Data.SqlClient.SqlCommand.RunExecuteReaderTds(System.Data.CommandBehavior, Microsoft.Data.SqlClient.RunBehavior, Boolean, Boolean, Int32, System.Threading.Tasks.Task ByRef, Boolean, Boolean, Microsoft.Data.SqlClient.SqlDataReader, Boolean)
00000009FC07C370 00007ff8156d8959 Microsoft.Data.SqlClient.SqlCommand.RunExecuteReader(System.Data.CommandBehavior, Microsoft.Data.SqlClient.RunBehavior, Boolean, System.Threading.Tasks.TaskCompletionSource`1, Int32, System.Threading.Tasks.Task ByRef, Boolean ByRef, Boolean, Boolean, System.String)
00000009FC07C440 00007ff8157af027 Microsoft.Data.SqlClient.SqlCommand.ExecuteReader(System.Data.CommandBehavior)
00000009FC07C540 00007ff8157aed06 Microsoft.Data.SqlClient.SqlCommand.ExecuteDbDataReader(System.Data.CommandBehavior)
00000009FC07C610 00007ff8157b2c73 System.Data.Common.DbDataAdapter.FillInternal(System.Data.DataSet, System.Data.DataTable[], Int32, Int32, System.String, System.Data.IDbCommand, System.Data.CommandBehavior)
00000009FC07C6A0 00007ff8157b29df System.Data.Common.DbDataAdapter.Fill(System.Data.DataTable[], Int32, Int32, System.Data.IDbCommand, System.Data.CommandBehavior)
...

Observe o primeiro método da pilha: Microsoft.Data.SqlClient.TdsParserStateObject.ReadSniSyncOverAsync(). Podemos perceber que todas as threads estavam bloqueadas esperando o resultado do banco de dados, pois essas consultas foram feitas de forma síncrona. O sincronismo está resultando na exaustão do ThreadPool e consequentemente gerando um efeito negativo no desempenho dessa aplicação.

Resolução

Nesse caso nos sabemos que a procedure que a aplicação está executando é a:

CREATE procedure BlogProc
AS
WAITFOR DELAY '00:00:01'
SELECT * FROM [dbo].[Blogs]

Para fazer isso vou refatorar a função que usava o SQL Binding com o modelo assíncrono:

[FunctionName("BlogAsync")]
    public async Task<List<Blog>> Run([HttpTrigger(AuthorizationLevel.Anonymous, "get")] HttpRequest req,
        [Sql(
            "exec BlogProc",
            CommandType = System.Data.CommandType.Text,
            ConnectionStringSetting = "SqlConnectionString"
        )] IAsyncEnumerable<Blog> blogs)
    {
        var enumerator = blogs.GetAsyncEnumerator();
        var blogList = new List<Blog>();
        while (await enumerator.MoveNextAsync())
        {
            blogList.Add(enumerator.Current);
        }
        await enumerator.DisposeAsync();

        return blogList;
    }

Executarei o mesmo teste de carga realizado anteriormente:

host=$(grep nameserver /etc/resolv.conf | sed 's/nameserver //')
siege -t1 -c100  http://${host}:7071/api/Blog

O resultado do teste depois da refatoração, foi:

** SIEGE 4.0.4
** Preparing 100 concurrent users for battle.
The server is now under siege...
Lifting the server siege...
Transactions:                   3665 hits
Availability:                  99.16 %
Elapsed time:                  59.14 secs
Data transferred:               4.71 MB
Response time:                  1.36 secs
Transaction rate:              61.97 trans/sec
Throughput:                     0.08 MB/sec
Concurrency:                   84.36
Successful transactions:        3665
Failed transactions:              31
Longest transaction:            2.87
Shortest transaction:           1.02

Para facilitar a comparação, vou colocar aqui o resultado do teste que fizemos anteriormente:

** SIEGE 4.0.4
** Preparing 100 concurrent users for battle.
The server is now under siege...
Lifting the server siege...
Transactions:                   2170 hits
Availability:                 100.00 %
Elapsed time:                  59.38 secs
Data transferred:               2.79 MB
Response time:                  2.68 secs
Transaction rate:              36.54 trans/sec
Throughput:                     0.05 MB/sec
Concurrency:                   97.84
Successful transactions:        2170
Failed transactions:               0
Longest transaction:           13.49
Shortest transaction:           1.04

Olhando rapidamente podemos identificar de forma bem clara o efeito da nossa refatoração.

Conclusão

No primeiro exemplo, conseguimos identificar através da inspeção da fila global do pool que 99 requisições estavam aguardando por uma thread, isso demostra um problema de exaustão do ThreadPool, justificado posteriormente pelas chamadas síncronas ao banco de dados, cujo bloqueará a thread em execução.

Para entender melhor esse problema, sugiro dar uma olhada nesse artigo que escrevi: Como melhorar a performance de uma Web Api ASP.NET Core usando async/await.

Podemos ver claramente os benefícios do uso do modelo assíncrono, o tempo de resposta da função sofre consideravelmente menos alteração em um cenário concorrente, onde com a carga que fizemos ficou em 1,36 segundos, aproximadamente um tempo de resposta 90% melhor em comparação ao código síncrono 2,68 segundos.

Outra diferença impressionante entre as duas estratégias é a Longest transaction (Requisição que mais demorou), onde no primeiro exemplo ficou em 13,49 segundos, já no código assíncrono foi de 2,87 segundos.

A ponto mais interessante é se compararmos as duas funções em termos de quantidade de código, mesmo que com algumas nuances, o segundo exemplo não foge muita da esfera de complexidade do primeiro.