Temos funções inline que reúnem dados em XML, passam esse XML derivado para outras funções, que então o fragmentam e o reformam como uma string.
(Seu "você não deveria fazer esse tipo de coisa em T-SQL" é uma discussão para outro dia.)
Isso funcionou bem por anos com 2005 e 2008 R2. Agora estamos atualizando para 2016 SP1. Uma consulta usando essas funções que é executada em menos de um segundo em nosso servidor de produção agora é ainda mais rápida no 2016 SP1. Isso seria ótimo, mas leva uma hora para compilar no 2016 SP1. Seriamente:
Ambiente de produção:
(Ambos são do SQL Sentry Plan Explorer.)
Tentamos com o banco de dados nos níveis de compatibilidade de 2008 (100) e 2016 (130) (mas ainda não jogamos com as configurações "Legacy Cardinality Estimation" e "Query Optimizer Fixes", que estão "OFF" atualmente). Tentamos usar QUERYTRACEON 9481, o que parece não ter efeito.
Novamente, não se trata dos planos resultantes, pois todos eles são executados em uma boa quantidade de tempo. É sobre o tempo que leva para fazer o plano.
Conseguimos reproduzir esse problema - até certo ponto - com um conjunto simplificado de código. Uma instrução que chama a função de nível superior do exemplo abaixo leva de 30 a 60 segundos para compilar no SQL Server 2016 (SP1-CU5), mas leva menos de um segundo para compilar e executar no SQL Server 2008 R2 (SP3).
Exemplo
/*
Create and populate table...
*/
CREATE TABLE TestXMLStuff (OrderID int, ProdLength int, ProdWidth int, ProdHeight int);
INSERT INTO TestXMLStuff (OrderID, ProdLength, ProdWidth, ProdHeight) VALUES
(1, 10, 15, 20),
(1, 15, 20, 25),
(2, 20, 25, 30),
(2, 25, 30, 35),
(2, 30, 35, 40);
GO
/*
Function which accepts XML, shreds it and reforms it as a string...
*/
CREATE FUNCTION TestCalc
(
@T varchar(8000),
@X xml
)
RETURNS TABLE
AS
RETURN
WITH p AS
(
SELECT
LF = CHAR(13) + CHAR(10),
Tab = CHAR(9),
T = isNull(@T,'')
), pid AS
(
SELECT
isNull(ProdInfoXMLTable.ProdInfoXML.query('(/ProdInfo)').value('(.)[1]','varchar(max)'),'') AS ProdInfoText
FROM (
SELECT
ProdInfoXML =
(
SELECT
ProdInfo =
CASE WHEN Products.ProdNum > 1 THEN '--' + p.LF ELSE '' END +
'Product Number: ' + CONVERT(varchar(50),Products.ProdNum) + p.LF +
CASE WHEN Products.ProdLength = '' THEN '' ELSE p.Tab + 'Length: ' + Products.ProdLength + p.LF END +
CASE WHEN Products.ProdWidth = '' THEN '' ELSE p.Tab + 'Width: ' + Products.ProdHeight + p.LF END +
CASE WHEN Products.ProdHeight = '' THEN '' ELSE p.Tab + 'Height: ' + Products.ProdHeight + p.LF END
FROM (
SELECT
ROW_NUMBER() OVER (ORDER BY (SELECT 1)) AS ProdNum,
isNull(P.X.value('(./Length)[1]','varchar(500)'),'') AS ProdLength,
isNull(P.X.value('(./Width)[1]','varchar(500)'),'') AS ProdWidth,
isNull(P.X.value('(./Height)[1]','varchar(500)'),'') AS ProdHeight
FROM @x.nodes('/Products/Product') AS P(X)
) AS Products
CROSS JOIN p
FOR XML PATH(''), TYPE
)
) AS ProdInfoXMLTable
)
SELECT
Final = p.T + p.LF + p.LF + pid.ProdInfoText
FROM p
CROSS JOIN pid;
GO
/*
Function to create XML in the format required for TestCalc...
*/
CREATE FUNCTION TestGetXML
(
@N int
)
RETURNS TABLE
AS
RETURN
WITH p AS
(
SELECT
N = isNull(@N,0)
)
SELECT
ProdInfoXML =
(
SELECT
[Length] = ProdData.ProdLength,
[Width] = ProdData.ProdWidth,
[Height] = ProdData.ProdHeight
FROM TestXMLStuff ProdData
WHERE ProdData.OrderID = @N
FOR XML PATH('Product'), ROOT('Products'), TYPE
);
GO
/*
Function to join the other two functions, gathering the XML and feeding it to the string creator which shreds and reforms it...
*/
CREATE FUNCTION TestGetFromTableUsingFunc
(
@N int
)
RETURNS TABLE
AS
RETURN
WITH p AS
(
SELECT
N = isNull(@N,0)
)
SELECT
FinalResult = 'This is a ' + TestCalcResults.Final
FROM p
CROSS APPLY TestGetXML
(
p.N
) AS x
CROSS APPLY TestCalc
(
'test',
x.ProdInfoXML
) AS TestCalcResults;
GO
/*
Code to call the function. This is what takes around 60 seconds to compile on our 2016 system but basically no time on the 2008 R2 system.
*/
SELECT *
FROM TestXMLStuff
CROSS APPLY TestGetFromTableUsingFunc
(
OrderID
)
OPTION (RECOMPILE);
GO
Produção @@versiononde a compilação não é um problema:
Microsoft SQL Server 2008 R2 (SP3) - 10.50.6000.34 (X64)
Teste @@versiononde a compilação leva "para sempre":
Microsoft SQL Server 2016 (SP1-CU5) (KB4040714) - 13.0.4451.0 (X64)
Perguntas
Por que há uma degradação no tempo de compilação indo para 2016 a partir de 2008 R2?
Essa resposta revela uma solução fácil para esse dilema além de mudar a maneira como tudo isso funciona? (Estou esperando por sinalizadores de rastreamento mágico ou uma próxima atualização da Microsoft.)
(Se isso fosse o SQL Server 2017, eu usaria JSON para coletar e passar os dados, o que parece ser mais rápido e com menor sobrecarga, e então usaria as funções JSON para fragmentar e STRING_AGGreformar em texto. Mas, infelizmente, isso ainda não é acessível.)
Com base em uma dica de Joe Obbish , reuni os resultados ao usar o sinalizador de rastreamento 8675 , usando este código:
DBCC TRACEON(3604)
SELECT *
FROM TestXMLStuff
CROSS APPLY TestGetFromTableUsingFunc
(
OrderID
)
OPTION (RECOMPILE, QUERYTRACEON 8675);
DBCC TRACEOFF(3604)
Em uma instância R2 de 2008, demorou muito menos de um segundo e produziu isto:
DBCC execution completed. If DBCC printed error messages, contact your system administrator. End of simplification, time: 0.008 net: 0.008 total: 0.008 net: 0.008
end exploration, tasks: 597 no total cost time: 0.005 net: 0.005 total: 0.014 net: 0.014
end search(0), cost: 2071.66 tasks: 2267 time: 0.005 net: 0.005 total: 0.02 net: 0.02
end exploration, tasks: 2703 Cost = 2071.66 time: 0.002 net: 0.002 total: 0.022 net: 0.022
end search(1), cost: 1731.11 tasks: 3362 time: 0.004 net: 0.004 total: 0.026 net: 0.026
end exploration, tasks: 3363 Cost = 1731.11 time: 0 net: 0 total:
0.026 net: 0.026
end search(1), cost: 1731.11 tasks: 3382 time: 0 net: 0 total: 0.026 net: 0.026
end exploration, tasks: 3413 Cost = 1731.11 time: 0 net: 0 total:
0.027 net: 0.027
end search(2), cost: 1731.11 tasks: 3515 time: 0 net: 0 total: 0.027 net: 0.027
End of post optimization rewrite, time: 0.001 net: 0.001 total: 0.029 net: 0.029
End of query plan compilation, time: 0.001 net: 0.001 total: 0.03 net:
0.03
(5 row(s) affected) DBCC execution completed. If DBCC printed error messages, contact your system administrator.
Em uma instância SP1-CU5 de 2016, levou 1 minuto e 11 segundos e produziu isto:
DBCC execution completed. If DBCC printed error messages, contact your system administrator. End of simplification, time: 0.004 net: 0.004 total: 0.004 net: 0.004
end exploration, tasks: 612 no total cost time: 0.003 net: 0.003 total: 0.008 net: 0.008
end exploration, tasks: 613 no total cost time: 0 net: 0 total: 0.008 net: 0.008
end exploration, tasks: 2305 no total cost time: 0.002 net: 0.002 total: 0.011 net: 0.011
end exploration, tasks: 2306 no total cost time: 0 net: 0 total: 0.011 net: 0.011
end search(0), cost: 4402.32 tasks: 2306 time: 0 net: 0 total: 0.011 net: 0.011
end exploration, tasks: 2738 Cost = 4402.32 time: 0.001 net: 0.001 total: 0.013 net: 0.013
end exploration, tasks: 2739 Cost = 4402.32 time: 0 net: 0 total:
0.013 net: 0.013
end exploration, tasks: 3466 Cost = 4402.32 time: 0.002 net: 0.002 total: 0.015 net: 0.015
end exploration, tasks: 3467 Cost = 4402.32 time: 0 net: 0 total:
0.015 net: 0.015
end search(1), cost: 3938.19 tasks: 3467 time: 0 net: 0 total: 0.015 net: 0.015
end exploration, tasks: 3468 Cost = 3938.19 time: 0 net: 0 total:
0.015 net: 0.015
end exploration, tasks: 3469 Cost = 3938.19 time: 0 net: 0 total:
0.015 net: 0.015
end exploration, tasks: 3489 Cost = 3938.19 time: 0 net: 0 total:
0.015 net: 0.015
end exploration, tasks: 3490 Cost = 3938.19 time: 0 net: 0 total:
0.015 net: 0.015
end search(1), cost: 3938.19 tasks: 3490 time: 0 net: 0 total: 0.015 net: 0.015
end exploration, tasks: 3521 Cost = 3938.19 time: 0 net: 0 total:
0.015 net: 0.015
end exploration, tasks: 3522 Cost = 3938.19 time: 0 net: 0 total:
0.015 net: 0.015
end exploration, tasks: 3625 Cost = 3938.19 time: 0 net: 0 total:
0.016 net: 0.016
end exploration, tasks: 3626 Cost = 3938.19 time: 0 net: 0 total:
0.016 net: 0.016
end search(2), cost: 3938.19 tasks: 3626 time: 0 net: 0 total: 0.016 net: 0.016
End of post optimization rewrite, time: 0 net: 0 total: 0.016 net:
0.016
End of query plan compilation, time: 0.001 net: 0.001 total: 0.018 net: 0.018
(5 row(s) affected) DBCC execution completed. If DBCC printed error messages, contact your system administrator.
Embora mais esteja acontecendo, parece que o tempo decorrido foi de apenas 0,018 (segundos?), que é menor que os 0,03 em 2008 R2. Então essa fase de compilação/otimização/execução não deve ser o que está demorando tanto. Mas algo definitivamente é.
Nossa eventual instância de produção de 2016 terá o mesmo "hardware" da produção atual de 2008 R2. As instâncias de teste/desenvolvimento 2016 têm especificações diferentes, portanto, essas comparações não são maçãs com maçãs. Prod é de 78 giga. Dev é de 16 GB. Mas testei em outra caixa R2 2008 com 20 giga e foi rápido. Também estamos falando de pequenas quantidades de dados bem indexadas. E durante a compilação pouco IO, mas muita CPU.
Eu pude ver as estatísticas sendo um problema com as funções reais que atingem tabelas reais (grandes), mas no meu exemplo simplificado e planejado, leva mais de 1 minuto para fazer alguma manipulação simples de XML/texto em 5 linhas carregadas de inteiros. Eu poderia digitar os resultados mais rápido. :) Acredito que temos estatísticas automáticas na produção e não vejo outros problemas de desempenho aparentemente relacionados a estatísticas. E outro ambiente de desenvolvimento/teste 2008 R2 de não produção (com cópia de produção obsoleta semelhante ao desenvolvimento/teste 2016) é lickety-split.
É possível que CU7 para SQL Server 2016 SP1 resolva seu problema. O artigo da base de conhecimento relevante parece ser KB 4056955 - CORREÇÃO: consultas que convertem dados de cadeia de caracteres ou binários para XML demoram muito tempo para compilar no SQL Server 2016 .
Executei seu código de reprodução no SQL Server 2016 SP1 CU6 e obtive o seguinte para tempos de compilação por
SET STATISTICS TIME ON:Veja como os tempos de compilação mudaram após a atualização para o SP1 CU7:
É cerca de 750 vezes mais rápido.
Não posso responder por que 2016 leva muito mais tempo, mas uma solução parece obscurecer algumas das operações do otimizador. Se você mascarar a parte de construção XML do processo colocando-a atrás de uma função escalar, o tempo de compilação cairá para cerca de um segundo. Ainda é significativamente mais lento do que em 2008 R2, mas pode ser rápido o suficiente.