Cuidado com dados enganosos do SET STATISTICS IO

Meu colega de trabalho Steve Wright (blog | @SQL_Steve) me cutucou com uma pergunta recentemente sobre um resultado estranho que ele estava vendo. Para testar algumas funcionalidades em nossa ferramenta mais recente, SQL Sentry Plan Explorer PRO, ele fabricou uma tabela ampla e grande e estava executando uma variedade de consultas nela. Em um caso, ele estava retornando muitos dados, mas STATISTICS IO estava mostrando que muito poucas leituras estavam ocorrendo. Fiz um ping em algumas pessoas no #sqlhelp e, como parecia que ninguém tinha visto esse problema, pensei em blogar sobre isso.

TL;Versão DR

Resumindo, esteja muito ciente de que existem alguns cenários em que você não pode confiar em STATISTICS IO para te dizer a verdade. Em alguns casos (este envolvendo TOP e paralelismo), ele subestimará amplamente as leituras lógicas. Isso pode levar você a acreditar que tem uma consulta muito amigável para E/S quando não tem. Existem outros casos mais óbvios – como quando você tem um monte de E/S escondida pelo uso de funções escalares definidas pelo usuário. Achamos que o Plan Explorer torna esses casos mais óbvios; este, no entanto, é um pouco mais complicado.

A consulta do problema

A tabela tem 37 milhões de linhas, até 250 bytes por linha, cerca de 1 milhão de páginas e fragmentação muito baixa (0,42% no nível 0, 15% no nível 1 e 0 além disso). Não há colunas computadas, UDFs em jogo e índices, exceto uma chave primária agrupada no INT inicial coluna. Uma consulta simples retornando 500.000 linhas, todas as colunas, usando TOP e SELECT * :

SET STATISTICS IO ON;
 
SELECT TOP 500000 * FROM dbo.OrderHistory 
WHERE OrderDate < (SELECT '19961029');

(E sim, eu percebo que estou violando minhas próprias regras e usando SELECT * e TOP sem ORDER BY , mas por uma questão de simplicidade, estou tentando o meu melhor para minimizar minha influência no otimizador.)

Resultados:
(500.000 linhas afetadas)
Tabela 'OrderHistory'. Contagem de varredura 1, leituras lógicas 23, leituras físicas 0, leituras antecipadas 0, leituras lógicas lob 0, leituras físicas lob 0, leituras antecipadas lob 0.
Estamos retornando 500.000 linhas e leva cerca de 10 segundos. Eu imediatamente sei que algo está errado com o número de leituras lógicas. Mesmo que eu ainda não soubesse sobre os dados subjacentes, posso dizer pelos resultados da grade no Management Studio que isso está puxando mais de 23 páginas de dados, sejam elas da memória ou do cache, e isso deve ser refletido em algum lugar em STATISTICS IO . Olhando para o plano...

…vemos que há paralelismo lá, e que examinamos toda a tabela. Então, como é possível que existam apenas 23 leituras lógicas?

Outra consulta "idêntica"

Uma das minhas primeiras perguntas para Steve foi:"O que acontece se você eliminar o paralelismo?" Então eu tentei. Peguei a versão original da subconsulta e adicionei MAXDOP 1 :

SET STATISTICS IO ON;
 
SELECT TOP 500000 * FROM dbo.OrderHistory 
WHERE OrderDate < (SELECT '19961029') OPTION (MAXDOP 1);

Resultados e plano:
(500.000 linhas afetadas)
Tabela 'OrderHistory'. Contagem de varredura 1, leituras lógicas 149589, leituras físicas 0, leituras antecipadas 0, leituras lógicas lob 0, leituras físicas lob 0, leituras antecipadas lob 0.

Temos um plano um pouco menos complexo, e sem o paralelismo (por motivos óbvios), STATISTICS IO está nos mostrando números muito mais críveis para contagens lógicas de leitura.

Qual é a verdade?

Não é difícil ver que uma dessas consultas não está dizendo toda a verdade. Enquanto STATISTICS IO pode não nos contar toda a história, talvez o rastreamento conte. Se recuperarmos as métricas de tempo de execução gerando um plano de execução real no Plan Explorer, veremos que a consulta mágica de baixa leitura está, de fato, puxando os dados da memória ou do disco, e não de uma nuvem mágica de pó mágico. Na verdade, tem *mais* leituras do que a outra versão:

Portanto, está claro que as leituras estão acontecendo, elas apenas não estão aparecendo corretamente no STATISTICS IO saída.

Qual é o problema?

Bem, vou ser bem honesto:não sei, além do fato de que o paralelismo está definitivamente desempenhando um papel, e parece ser algum tipo de condição de corrida. STATISTICS IO (e, como é onde obtemos os dados, nossa guia Table I/O) mostra um número muito enganoso de leituras. Está claro que a consulta retorna todos os dados que estamos procurando e está claro nos resultados do rastreamento que ela usa leituras e não osmose para fazer isso. Perguntei a Paul White (blog | @SQL_Kiwi) sobre isso e ele sugeriu que apenas algumas das contagens de E/S pré-thread estão sendo incluídas no total (e concorda que isso é um bug).

Se você quiser experimentar isso em casa, tudo o que você precisa é do AdventureWorks (isso deve ser reproduzido nas versões 2008, 2008 R2 e 2012) e a seguinte consulta:

SET STATISTICS IO ON;
DBCC SETCPUWEIGHT(1000) WITH NO_INFOMSGS;
GO
 
SELECT TOP (15000) * 
FROM Sales.SalesOrderHeader 
WHERE OrderDate < (SELECT '20080101');
 
SELECT TOP (15000) * 
FROM Sales.SalesOrderHeader 
WHERE OrderDate < (SELECT '20080101') 
OPTION (MAXDOP 1);
 
DBCC SETCPUWEIGHT(1) WITH NO_INFOMSGS;

(Observe que SETCPUWEIGHT é usado apenas para persuadir o paralelismo. Para obter mais informações, consulte a postagem do blog de Paul White sobre Plan Costing.)

Resultados:
Tabela 'SalesOrderHeader'. Contagem de varredura 1, leituras lógicas 4, leituras físicas 0, leituras antecipadas 0, leituras lógicas lob 0, leituras físicas lob 0, leituras antecipadas lob 0.
Tabela 'SalesOrderHeader'. Contagem de varredura 1, leituras lógicas 333, leituras físicas 0, leituras antecipadas 0, leituras lógicas lob 0, leituras físicas lob 0, leituras antecipadas lob 0.
Paul apontou uma reprodução ainda mais simples:

SET STATISTICS IO ON;
GO
 
SELECT TOP (15000) *
FROM Production.TransactionHistory
WHERE TransactionDate < (SELECT '20080101')
OPTION (QUERYTRACEON 8649, MAXDOP 4);
 
SELECT TOP (15000) *
FROM Production.TransactionHistory AS th
WHERE TransactionDate < (SELECT '20080101');

Resultados:
Tabela 'Histórico de Transações'. Contagem de varredura 1, leituras lógicas 5, leituras físicas 0, leituras antecipadas 0, leituras lógicas lob 0, leituras físicas lob 0, leituras antecipadas lob 0.
Tabela 'TransactionHistory'. Contagem de varredura 1, leituras lógicas 110, leituras físicas 0, leituras antecipadas 0, leituras lógicas lob 0, leituras físicas lob 0, leituras antecipadas lob 0.
Então parece que podemos facilmente reproduzir isso à vontade com um TOP operador e um DOP baixo o suficiente. Eu registrei um bug:

STATISTICS IO relata leituras lógicas insuficientes para planos paralelos

E Paul apresentou dois outros bugs relacionados envolvendo paralelismo, o primeiro como resultado de nossa conversa:

Erro de estimativa de cardinalidade com predicado enviado em uma pesquisa [ postagem de blog relacionada ]
Desempenho ruim com paralelismo e principal [ postagem de blog relacionada ]

(Para os nostálgicos, aqui estão seis outros bugs de paralelismo que apontei alguns anos atrás.)

Qual é a lição?

Tenha cuidado ao confiar em uma única fonte. Se você olhar apenas para STATISTICS IO depois de alterar uma consulta como essa, você pode ficar tentado a se concentrar na queda milagrosa nas leituras em vez do aumento na duração. Nesse ponto, você pode se dar um tapinha nas costas, sair do trabalho mais cedo e aproveitar seu fim de semana, pensando que acabou de causar um tremendo impacto no desempenho de sua consulta. Quando é claro que nada poderia estar mais longe da verdade.