Como as atualizações automáticas de estatísticas podem afetar o desempenho da consulta

Em minha postagem anterior, explorei diferentes métodos para rastrear atualizações automáticas de estatísticas para determinar se elas estavam afetando o desempenho da consulta. Na segunda metade do post, incluí opções, uma das quais era habilitar a configuração do banco de dados de atualização automática de estatísticas de forma assíncrona. Neste post, quero ver como o desempenho da consulta muda quando a atualização automática ocorre antes da execução da consulta e o que acontece com o desempenho se a atualização for assíncrona.

A configuração

Comecei com uma cópia do banco de dados AdventureWorks2012 e, em seguida, criei uma cópia da tabela SalesOrderHeader com mais de 200 milhões de linhas usando esse script. A tabela tem um índice clusterizado em SalesOrderID e um índice não clusterizado em CustomerID, OrderDate, SubTotal. [Nota:se você for fazer testes repetidos, faça um backup deste banco de dados neste momento para economizar algum tempo]. Depois de carregar os dados e criar o índice não clusterizado, verifiquei a contagem de linhas e calculei quantas linhas (aproximadamente) precisariam ser modificadas para invocar uma atualização automática.

SELECT
OBJECT_NAME([p].[object_id]) [TableName],
[si].[name] [IndexName],
[au].[type_desc] [Type],
[p].[rows] [RowCount],
([p].[rows]*.20) + 500 [UpdateThreshold],
[au].total_pages [PageCount],
(([au].[total_pages]*8)/1024)/1024 [TotalGB]
FROM [sys].[partitions] [p]
JOIN [sys].[allocation_units] [au] ON [p].[partition_id] = [au].[container_id]
JOIN [sys].[indexes] [si] on [p].[object_id] = [si].object_id and [p].[index_id] = [si].[index_id]
WHERE [p].[object_id] = OBJECT_ID(N'Sales.Big_SalesOrderHeader');

Big_SalesOrderHeader CIX e NCI Information

Também verifiquei o cabeçalho de estatísticas atual para o índice:

DBCC SHOW_STATISTICS ('Sales.Big_SalesOrderHeader',[IX_Big_SalesOrderHeader_CustomerID_OrderDate_SubTotal]);

Estatísticas do NCI:no início

Em seguida, criei o procedimento armazenado que usaria para teste. É um procedimento simples que consulta Sales.Big_SalesOrderHeader e agrega dados de vendas por CustomerID e OrderDate para análise:

CREATE PROCEDURE Sales.usp_GetCustomerStats
@CustomerID INT,
@StartDate DATETIME,
@EndDate DATETIME
AS
BEGIN
  SET NOCOUNT ON;
 
  SELECT CustomerID, DATEPART(YEAR, OrderDate), DATEPART(MONTH, OrderDate), COUNT([SalesOrderID]) as Computed
    FROM [Sales].[Big_SalesOrderHeader]
    WHERE CustomerID = @CustomerID
    AND OrderDate BETWEEN @StartDate and @EndDate
    GROUP BY CustomerID, DATEPART(YEAR, OrderDate), DATEPART(MONTH, OrderDate)
    ORDER BY DATEPART(YEAR, OrderDate), DATEPART(MONTH, OrderDate);
END

Por fim, antes de executar o procedimento armazenado, criei uma sessão de eventos estendidos para poder acompanhar a duração da consulta usando sp_statement_starting e sp_statement_completed. Eu também adicionei o evento auto_stats, porque mesmo que eu não esperasse que uma atualização ocorresse, eu queria usar essa mesma definição de sessão mais tarde.

CREATE EVENT SESSION [StatsUpdate_QueryPerf]
ON SERVER
ADD EVENT sqlserver.auto_stats,
ADD EVENT sqlserver.sp_statement_completed(
SET collect_statement=(1)
),
ADD EVENT sqlserver.sp_statement_starting
ADD TARGET package0.event_file(
SET filename=N'C:\temp\StatsUpdate_QueryPerf.xel'
)
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,
MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=ON,STARTUP_STATE=OFF);
GO

O Teste

Iniciei a sessão Extended Events e executei o procedimento armazenado várias vezes, usando diferentes CustomerIDs:

ALTER EVENT SESSION [StatsUpdate_QueryPerf]
ON SERVER
STATE = START;
GO
 
EXEC Sales.usp_GetCustomerStats 11331, '2012-08-01 00:00:00.000', '2012-08-31 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats 11330, '2013-01-01 00:00:00.000', '2013-01-31 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats 11506, '2012-11-01 00:00:00.000', '2012-11-30 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats 17061, '2013-01-01 00:00:00.000', '2013-01-31 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats 11711, '2013-03-01 00:00:00.000', '2013-03-31 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats 15131, '2013-02-01 00:00:00.000', '2013-02-28 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats 29837, '2012-10-01 00:00:00.000', '2012-10-31 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats 15750, '2013-03-01 00:00:00.000', '2013-03-31 23:59:59.997'
GO

Verifiquei a contagem de execução e o plano consultando o cache do procedimento:

SELECT
OBJECT_NAME([st].[objectid]),
[st].[text],
[qs].[execution_count],
[qs].[creation_time],
[qs].[last_execution_time],
[qs].[min_worker_time],
[qs].[max_worker_time],
[qs].[min_logical_reads],
[qs].[max_logical_reads],
[qs].[min_elapsed_time],
[qs].[max_elapsed_time],
[qp].[query_plan]
FROM [sys].[dm_exec_query_stats] [qs]
CROSS APPLY [sys].[dm_exec_sql_text]([qs].plan_handle) [st]
CROSS APPLY [sys].[dm_exec_query_plan]([qs].plan_handle) [qp]
WHERE [st].[text] LIKE '%usp_GetCustomerStats%'
AND OBJECT_NAME([st].[objectid]) IS NOT NULL;

Planejar cache:no início

Plano de consulta para procedimento armazenado, usando SQL Sentry Plan Explorer

Pude ver que o plano foi criado em 2014-04-08 18:59:39.850. Com o plano em cache, interrompi a sessão de Eventos Estendidos:

ALTER EVENT SESSION [StatsUpdate_QueryPerf]
ON SERVER
STATE = STOP;

Em seguida, adicionei cerca de 47 milhões de linhas de dados à tabela usando esse script, bem acima do limite necessário para invalidar as estatísticas atuais. Depois de adicionar os dados, verifiquei o número de linhas na tabela:

Big_SalesOrderHeader CI:após carregamento de dados

Antes de executar novamente meu procedimento armazenado, verifiquei o cache do plano para garantir que nada havia mudado e verifiquei se as estatísticas ainda não haviam sido atualizadas. Lembre-se, mesmo que as estatísticas tenham sido invalidadas neste momento, elas não serão atualizadas até que uma consulta que use a estatística seja executada (para referência:Entendendo quando as estatísticas serão atualizadas automaticamente). Para a etapa final, iniciei a sessão de eventos estendidos novamente e executei o procedimento armazenado várias vezes. Após essas execuções, verifiquei o cache do plano novamente:

Planejar cache:após carregamento de dados

O execution_count é 8 novamente, e se observarmos o create_time do plano, podemos ver que ele mudou para 2014-04-08 19:32:52.913. Se verificarmos o plano, podemos ver que é o mesmo, embora o plano tenha sido recompilado:

Plano de consulta para procedimento armazenado, usando SQL Sentry Plan Explorer

Análise da saída de eventos estendidos

Peguei o primeiro arquivo de eventos estendidos - antes que os dados fossem carregados - e o abri no SSMS, depois apliquei um filtro para que apenas as instruções do procedimento armazenado fossem listadas:

Saída de eventos estendidos:após a execução inicial do SP

Você pode ver que há oito (8) execuções do procedimento armazenado, com durações de consulta que variam um pouco.

Peguei o segundo arquivo de eventos estendidos - depois que os dados foram carregados - abri-o SSMS e filtrei novamente para que apenas as instruções do procedimento armazenado, bem como os eventos auto_stats, fossem listados:

Extended Events Output:SP Execution After Data Load

A saída é truncada, pois nem tudo é necessário para mostrar o resultado principal. As entradas realçadas em azul representam a primeira execução do procedimento armazenado e observe que há várias etapas – a atualização das estatísticas faz parte da execução. A instrução SELECT é iniciada (attach_activity_id.seq =3) e as atualizações das estatísticas são executadas. Em nosso exemplo, temos atualizações em três estatísticas. Assim que a última atualização for concluída (attach_activity_id.seq =11), o procedimento armazenado será iniciado e concluído (attach_activity_id.seq =13 e attach_activity_id.seq =14). Curiosamente, há um segundo evento sp_statement_starting para o procedimento armazenado (presumivelmente o primeiro é desconsiderado), portanto, a duração total do procedimento armazenado é calculada sem a atualização das estatísticas.

Nesse cenário, ter estatísticas atualizadas automaticamente imediatamente – ou seja, quando uma consulta que usa estatísticas invalidadas é executada – faz com que a consulta seja executada por mais tempo, mesmo que a duração da consulta com base no evento sp_statement_completed ainda seja menor que 14.000. O resultado final é que há não há benefício para o desempenho da consulta, pois o plano é exatamente o mesmo antes e depois da atualização das estatísticas. Nesse cenário, o plano de consulta e a duração da execução não mudam depois que mais dados são adicionados à tabela, portanto, a atualização das estatísticas apenas prejudica seu desempenho. Agora vamos ver o que acontece quando habilitamos a opção Auto Update Statistics Assynchronously.

O Teste, Versão 2

Começamos restaurando o backup que fiz antes de iniciarmos o primeiro teste. Eu recriei o procedimento armazenado e alterei a opção de banco de dados para atualizar as estatísticas de forma assíncrona:

USE [master];
GO
ALTER DATABASE [AdventureWorks2012_Big] SET AUTO_UPDATE_STATISTICS_ASYNC ON WITH NO_WAIT
GO

Iniciei a sessão Extended Events e executei novamente o procedimento armazenado várias vezes, usando diferentes CustomerIDs:

ALTER EVENT SESSION [StatsUpdate_QueryPerf]
ON SERVER
STATE = START;
GO
 
EXEC Sales.usp_GetCustomerStats11331, '2012-08-01 00:00:00.000', '2012-08-31 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats11330, '2013-01-01 00:00:00.000', '2013-01-31 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats11506, '2012-11-01 00:00:00.000', '2012-11-30 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats17061, '2013-01-01 00:00:00.000', '2013-01-31 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats11711, '2013-03-01 00:00:00.000', '2013-03-31 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats15131, '2013-02-01 00:00:00.000', '2013-02-28 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats29837, '2012-10-01 00:00:00.000', '2012-10-31 23:59:59.997'
GO
EXEC Sales.usp_GetCustomerStats15750, '2013-03-01 00:00:00.000', '2013-03-31 23:59:59.997'
GO

Verifiquei a contagem de execução e o plano consultando o cache do procedimento:

Planejar cache:no início, teste 2

Plano de consulta para procedimento armazenado, usando SQL Sentry Plan Explorer

Para este teste, o plano foi criado em 2014-04-08 21:15:55.490. Parei a sessão de eventos estendidos e adicionei novamente cerca de 47 milhões de linhas de dados à tabela, usando a mesma consulta de antes.

Depois que os dados foram adicionados, verifiquei o cache do plano para garantir que nada havia mudado e verifiquei se as estatísticas ainda não haviam sido atualizadas. Por fim, iniciei a sessão de eventos estendidos novamente e executei o procedimento armazenado mais oito vezes. Uma olhada final no cache do plano mostrou a execução_contagem em 16 e um tempo de criação de 2014-04-08 21:15:55.490. O execution_count e create_time demonstram que as estatísticas não foram atualizadas, pois o plano ainda não foi liberado do cache (se tivesse, teríamos um create_time posterior e um execution_count de 8).

Planejar cache:após o carregamento de dados, teste 2

Se abrirmos a saída de eventos estendidos após o carregamento de dados no SSMS e filtrar novamente para vermos apenas instruções do procedimento armazenado, bem como eventos auto_stats, encontramos isso (observe que a saída é dividida em duas capturas de tela):

Extended Events Output:Test 2, SP Execution After Data Load, parte I

Extended Events Output:Test 2, SP Execution After Data Load, parte II

Os eventos para a execução da primeira chamada do procedimento armazenado são destacados em azul – eles começam em 2014-04-08 21:54:14.9480607 e há sete (7) eventos. Observe que há três (3) eventos auto_stats, mas nenhum deles realmente é concluído, como vimos quando a opção Atualizar estatísticas automáticas de forma assíncrona foi desativada. Você notará que a atualização automática começa para uma das estatísticas quase imediatamente (2014-04-08 21:54:14.9481288), e seus três eventos têm o texto vermelho 'Stat Update #1' ao lado deles. Essa atualização de estatísticas termina em 2014-04-08 21:54:16.5392219, pouco menos de dois segundos após o início, mas após a conclusão de todas as outras execuções do procedimento. É por isso que o execution_count de sys.dm_exec_query_stats mostra 16. Na saída do XE, podemos ver que as outras atualizações de estatísticas são concluídas (Stat Update #2 e Stat Update #3). Todas as atualizações são assíncronas com a execução do procedimento armazenado inicial.

Resumo

Como você pode ver, as atualizações automáticas das estatísticas têm o potencial de afetar negativamente o desempenho da consulta. O grau de impacto dependerá da quantidade de dados que devem ser lidos para atualizar a estatística e dos recursos do sistema. Em alguns casos, o desempenho da consulta aumenta apenas em milissegundos e provavelmente é imperceptível para os usuários. Outras vezes, a duração pode aumentar drasticamente, o que afeta a experiência do usuário final. No caso em que o plano de consulta não muda após uma atualização das estatísticas, vale a pena considerar habilitar a opção Atualização automática de estatísticas de forma assíncrona, para mitigar o impacto no desempenho da consulta.