Paul Williams's questions

Todos os dias, as lojas podem inserir informações de vendas em nosso aplicativo OLTP. O aplicativo chama um procedimento armazenado em SQL para salvar essas informações. Com base na atividade dos usuários, o aplicativo envia um código indicando se o proc deve realizar uma inserção, atualização ou exclusão.

Este procedimento armazenado de salvamento está recebendo concessões de memória de 60 GB para exclusões em uma linha. Para duplicar o problema, executei uma consulta de exclusão ad-hoc entre um begin trane rollbacke capturei o plano real abaixo:

https://www.brentozar.com/pastetheplan/?id=r189liBI4

O esquema é como segue:

Daily_Item_Sales_Headers -- ~100 million rows on this system
========================
DlyItmSlsHdr_Key decimal(15,0) primary key nonclustered,
DlyItmSlsHdr_PaperworkBatch_Key decimal(15,0), -- FK to parent batch of data that contains other types of data
UK_DlyItmSlsHdr_PaperworkBatchKey_Key clustered, unique, unique key located on PRIMARY (DlyItmSlsHdr_PaperworkBatch_Key, DlyItmSlsHdr_Key)

Daily_Item_Sales -- ~790 million rows on this system
================
DlyItmSls_Key decimal(15,0) primary key nonclustered,
DlyItmSls_DlyItmSlsHdr_Key decimal(15,0), -- FK to header table, cascade delete,
UK_DlyItmSls_DlyItmSlsHdrKey_Key clustered unique constraint on (DlyItmSls_DlyItmSlsHdr_Key, DlyItmSls_Key)
[columns about sales data]

A consulta que fiz é simples:

delete Daily_Item_Sales_Headers where DlyItmSlsHdr_Key = 1

O plano mostra que a exclusão do cabeçalho está em cascata corretamente para as linhas de vendas filhas. O plano também mostra uma busca de índice no índice clusterizado da tabela filha. No entanto, essa busca de índice clusterizado para a tabela filho tem uma estimativa de 790 milhões de linhas. O número real de linhas é ~100. As linhas estimadas altas estão causando uma concessão de memória de aproximadamente 60 GB.

Usando dbcc show_statisticsos índices da tabela filho, pude ver que as estatísticas foram atualizadas ontem à noite com um tamanho de amostra de 2%. O histograma mostra entre 1 e ~33.000 linhas estimadas por chave pai. Portanto, as estatísticas parecem mostrar que a estimativa deve ser muito menor.

Por que essa consulta de exclusão está gerando uma concessão de memória tão grande?

Eu vi esta pergunta sobre concessões excessivas de memória de classificação que parecem ser causadas por um bug, mas parece diferente para mim, porque não há classificações neste plano. Talvez seja o mesmo bug se aplicando aos carretéis da tabela ao cascatear para a tabela filho?

Concessão de memória de classificação excessiva

Por causa da cascata de chave estrangeira, não acho que possa contornar a concessão de memória excluindo as linhas filhas primeiro antes de excluir as linhas pai. Este é um sistema OLTP com até 10.000 lojas trabalhando ao mesmo tempo, então não posso descartar as chaves estrangeiras sob demanda para uma única exclusão.

EDITAR 28/02/2019 13:13 CST

A instância SQL tem cerca de 400 GB de memória alocada para ela.

O aplicativo tem os seguintes sinalizadores de rastreamento habilitados:

• 1222: rastreamento de impasse
• 4199: correções do processador de consultas
• 2312: use o estimador de cardinalidade de 2014
• 2453: cardinalidade da variável @Table

A desativação dos sinalizadores de rastreamento gera estimativas diferentes para a exclusão em cascata da tabela filha:

Trace Flag 2312    Trace Flag 4199   Row Estimate
===============    ===============   =============
      on                 on            790 million rows
      on                 off           608 rows (very accurate)
      off                on            1 row
      off                off           1 row

Adicionar um querytraceonpara o sinalizador 9130 mencionado na pergunta vinculada não faz diferença.

Um colega de trabalho encontrou este artigo interessante sobre um bug de memória no SQL 2014. A resolução vinculada era adicionar option (MAX_GRANT_PERCENT = 1)à consulta.

https://www.thereregister.co.uk/2016/02/09/microsoft_sql_server_2014_bug/

EDITAR

A versão exata do SQL Server é SQL Server 2014 SP2 CU 12.

O banco de dados é o nível de compatibilidade 110 - SQL Server 2012. Não podemos alterar o nível de compatibilidade por um tempo.

Eu tenho uma pergunta sobre este plano de consulta .

Temos uma tabela em um ambiente de teste, Order_Details_Taxes, que possui 11.225.799 linhas. Esta tabela tem uma coluna, OrdTax_PLTax_LoadDtl_Key, que é NULL em cada linha. Este ambiente de teste está configurado de forma que esta coluna seja sempre NULL. Há um índice nesta coluna.

Executei algumas consultas nessa tabela usando um valor NULL para uma coluna. Um NULL INNER JOIN nunca produzirá nenhum resultado.

declare @Keys table (KeyValue decimal(15,0))
insert into @Keys (KeyValue) values (null)

select OrdTax_PLTax_LoadDtl_Key
from @Keys
inner join Order_Details_Taxes
    on OrdTax_PLTax_LoadDtl_Key = KeyValue

select *
from @Keys
inner join Order_Details_Taxes
    on OrdTax_PLTax_LoadDtl_Key = KeyValue

Essas são as primeiras consultas no plano de consulta. O primeiro selectcomeça na tabela de cem milhões de linhas e se junta a @Keys. O segundo selectcomeça a partir de @Keys, mas faz uma varredura de índice clusterizado nesta tabela.

Eu sei que @Tables temporárias são questionáveis ​​na maioria dos casos, então mudei minha consulta para usar uma #Table temporária:

if object_id ('tempdb..#Keys') is not null
    drop table #Keys
create table #Keys (KeyValue decimal(15,0))
insert into #Keys (KeyValue) values (null)

select OrdTax_PLTax_LoadDtl_Key
from #Keys
inner join Order_Details_Taxes
    on OrdTax_PLTax_LoadDtl_Key = KeyValue

select *
from #Keys
inner join Order_Details_Taxes
    on OrdTax_PLTax_LoadDtl_Key = null

Essas consultas foram otimizadas e executadas exatamente como eu esperava - obtenha o valor #Keys NULL primeiro e procure por Order_Details_Taxes. São as últimas consultas no plano de consulta vinculadas.

Por que as consultas nas quais usei uma variável @Table executam varreduras de índice e tabela nessa tabela grande, quando estou unindo usando de uma tabela que tem um único valor NULL para uma tabela com apenas NULLs nesse valor de chave?

Suponho que a resposta seja limitações estatísticas e/ou de cardinalidade das variáveis ​​@Table, mas o plano de consulta resultante não foi intuitivo para mim.

ANSI_NULLsestá ativado para esta tabela e minha sessão SQL.

Estou executando o SQL Server 2014 Developer Edition no meu PC. Estou tentando visualizar os dados na sessão system_health. No SSMS, conectei ao banco de dados, expandi o servidor/gerenciamento/eventos estendidos/sessões. Vejo AlwaysON_health (parado) e system_health (em execução).

Quando clico com o botão direito do mouse na sessão system_health, recebo o seguinte erro:

O armazenamento falhou ao inicializar usando os parâmetros fornecidos. (Microsoft.SqlServer.XEventStorage) A sessão de Eventos Estendidos denominada "system_health" não pôde ser encontrada. Certifique-se de que a sessão existe e foi iniciada. (Microsoft SQL Server, erro: 25728)

Eu expando system_health e vejo os destinos package0.event_file e package0.ring_buffer. Se eu clicar com o botão direito do mouse em qualquer destino e escolher "Exibir dados do destino", recebo este erro:

O armazenamento falhou ao inicializar usando os parâmetros fornecidos. (Microsoft.SqlServer.XEventStorage) Não é possível visualizar a função 'fn_MSXe_read_event_stream', porque ela não existe ou você não tem permissão. (Microsoft SQL Server, erro: 15151)

A função existe. Eu posso executá-lo:

select * from fn_MSXe_read_event_stream('system_health', 0);

Quando eu faço, recebo este erro:

Msg 25728, Level 16, State 10, Line 6
The Extended Events session named "system_health" could not be found. Make  sure the session exists and is started.

Eu sei que a sessão system_health está lá. Eu vejo na lista de sessões:

select * from sys.dm_xe_sessions

address name       name
------------------ ------------- 
0x00000001FF6510C1 system_health

Eu tentei isso com minhas próprias sessões de eventos personalizados. Também não consigo assistir os dados ao vivo deles.

Posso consultar os dados de destino do buffer de anel system_health de sys.dm_xe_session_targets.

Por que não consigo assistir dados ao vivo para qualquer sessão de eventos estendida?

(Observe que há um item de feedback da Microsoft para esse problema.)

Estou vendo algum comportamento inesperado com colunas de carimbo de data/hora (rowversion). Criei uma tabela de teste:

create table Test
(
    Test_Key int identity(1,1) primary key clustered,
    Test_Value int,
    Test_Thread int,
    ts timestamp
)

create nonclustered index IX_Test_Value on Test (Test_Value) -- probably irrelevant

Comecei dois threads executando inserções nesta tabela ao mesmo tempo. O primeiro thread está executando o seguinte código:

declare @i int = 0
while @i < 100
begin
    insert into Test (Test_Value, Test_Thread) select n, 1 from dbo.fn_GenerateNumbers(10000)
    set @i = @i + 1
end

O segundo encadeamento está executando um código idêntico, exceto pelo fato de que está fazendo select n, 2a partir da função inserir seu ID de encadeamento.

Primeiro, uma palavra sobre a função. Isso usa uma série de expressões de tabela comuns cruzadas com um ROW_NUMBER() para retornar muitos números em sequência muito rapidamente. Aprendi esse truque com um artigo de Itzik Ben-Gan , então o crédito vai para ele. Não acho que a implementação da função seja importante, mas vou incluí-la de qualquer maneira:

CREATE FUNCTION dbo.fn_GenerateNumbers(@count int)
RETURNS TABLE WITH SCHEMABINDING
AS
RETURN
    WITH
        Nbrs_4( n ) AS ( SELECT 1 UNION SELECT 0 ),
        Nbrs_3( n ) AS ( SELECT 1 FROM Nbrs_4 n1 CROSS JOIN Nbrs_4 n2 ),
        Nbrs_2( n ) AS ( SELECT 1 FROM Nbrs_3 n1 CROSS JOIN Nbrs_3 n2 ),
        Nbrs_1( n ) AS ( SELECT 1 FROM Nbrs_2 n1 CROSS JOIN Nbrs_2 n2 ),
        Nbrs_0( n ) AS ( SELECT 1 FROM Nbrs_1 n1 CROSS JOIN Nbrs_1 n2 ),
        Nbrs  ( n ) AS ( SELECT 1 FROM Nbrs_0 n1 CROSS JOIN Nbrs_0 n2 )

    SELECT n
    FROM ( SELECT ROW_NUMBER() OVER (ORDER BY n) FROM Nbrs ) D ( n )
    WHERE n <= @count ; 

Esta tabela tem uma identitycoluna nela. Eu esperava que, quando selecionasse os valores da tabela por essa chave primária monotonicamente crescente, também veria os carimbos de data e hora na mesma ordem. Os timestamps podem não ser sequenciais, porque pode ter havido outras atualizações, mas pelo menos estariam em ordem.

No entanto, o que estou vendo é diferente. As inserções são intercaladas por chave primária, mas os timestamps são sequenciais por thread .

Test_Key Test_Value Test_Thread ts
-------- ---------- ----------- ------------------
20227    227        1           0x000000006EDF3BC5
20228    228        1           0x000000006EDF3BC6
20229    229        1           0x000000006EDF3BC7
20230    230        1           0x000000006EDF3BC8
20231    1          2           0x000000006EDF41E9 -- thread 2 starts with a new ts
20232    2          2           0x000000006EDF41EB
20233    3          2           0x000000006EDF41EC
20234    4          2           0x000000006EDF41ED
--<snip lots of thread 2 inserts>
21538    1308       2           0x000000006EDF4710
21539    1309       2           0x000000006EDF4711
21540    1310       2           0x000000006EDF4712
21541    1311       2           0x000000006EDF4713
21542    231        1           0x000000006EDF3BC9 -- This is less than the prior row!
21543    232        1           0x000000006EDF3BCA -- Thread 1 is inserting
21544    233        1           0x000000006EDF3BCB -- from its last ts value
21545    234        1           0x000000006EDF3BCC

Minha pergunta é:

1) Por que o timestamp nem sempre aumenta com inserções simultâneas?

Pontos de bônus se você puder responder a esta pergunta:

2) Por que as inserções simultâneas se sobrepõem à chave primária em vez de todas serem inseridas de uma vez? Cada inserção está executando sua própria transação implícita, portanto, esperava que as chaves primárias estivessem em ordem para a inserção de um único encadeamento. Eu não esperava que as chaves primárias fossem intercaladas.

Não sei o suficiente sobre replicação para responder a esta:

3) Ter timestamps fora de ordem causa um problema com a replicação? No exemplo acima, e se o thread 2 confirmar seus dados primeiro? Quando o thread 1 é concluído, seus timestamps são todos menores do que os registros inseridos pelo thread 2.

Examinei as solicitações em execução e verifiquei que elas não estão sendo executadas em paralelo, portanto, não acho que o paralelismo seja o problema.

Observe que esta consulta estava sendo executada no nível de isolamento padrão (READ COMMITTED). Se eu aumentar o nível de isolamento para SERIALIZABLE, ainda obterei carimbos de data/hora na ordem inversa quando os threads mudarem.

Estou testando isso no SQL Server 2008 R2.

Para verificar os pedidos de carimbo de data/hora, eu estava fazendo um select * from Test, e também estava usando as seguintes consultas:

-- find timestamps out of sequential order
select t1.*, t2.*
from Test t1
    inner join Test t2
        on t2.Test_Key = t1.Test_Key + 1
where
    t2.ts <> t1.ts + 1

-- find timestamps that are less than the prior timestamp
select t1.*, t2.*
from Test t1
    inner join Test t2
        on t2.Test_Key = t1.Test_Key + 1
where
    t2.ts < t1.ts

Um cliente nosso está passando por impasses frequentes. Os impasses estão principalmente na mesma UPDATEinstrução. Os bloqueios seguem um padrão no qual ambos os SPIDs adquiriram um bloqueio de atualização (U) em uma página e ambos tentam converter o bloqueio de página U em um bloqueio de intenção exclusivo (IX). Às vezes, há apenas uma página envolvida; às vezes vários.

Capturamos um rastreamento de deadlock usando o sinalizador de rastreamento 1222 . O log do SQL Server mostra muitos, muitos impasses com o seguinte padrão (na ordem de baixo para cima):

waiter id=processe0dc2088 mode=U requestType=convert
waiter id=process2f9db2478 mode=U requestType=convert
waiter-list
owner id=processe0dc2088 mode=IX
owner id=process2f9db2478 mode=IX
owner-list
pagelock fileid=1 pageid=5794 dbid=2 objectname=tempdb.dbo.Item_Package_Site_Costs_Work id=lock1b22de480 mode=IX associatedObjectId=72057594131775488
resource-list

Ambos os processos estão executando a mesma instrução UPDATE para definir um sinalizador nesta tabela tempdb. Essa tabela tempdb contém informações que precisam persistir entre as chamadas do cliente até que o cliente termine. A tabela tem um índice bastante longo que começa com um GUID que representa um ID de processo exclusivo.

Estou tendo dificuldade de entender e simular esse impasse. Eu tentei várias quantidades de registros com dados simulados.

Minhas perguntas:

Por que esses processos estão adquirindo bloqueios U e depois convertendo para IX? Eu esperaria que o DELETE adquirisse bloqueios IX para começar.

Como evitar o impasse?

A instrução que causa o impasse está abaixo. O processo acabou de fazer uma pesquisa de custos para uma lista de itens em uma única loja. É tentar observar que houve um custo encontrado.

Observe que há um obsoleto (NOLOCK) em uma instrução UPDATE . Isso seria um fator contribuinte?

UPDATE tempdb..Item_Package_Site_Costs_Work
SET ItemPkgSiteCost_VINCostFound = 1,
    ItemPkgSiteCost_VendCost_Key = SiteCosts_VendCost_Key
FROM tempdb..Item_Package_Site_Costs_Work (NOLOCK)
    INNER JOIN #SiteCosts
        ON ItemPkgSiteCost_GUID = @ProcGUID
        AND SiteCosts_Item_Type = 0 -- Standard
        AND ItemPkgSiteCost_Site_Key = SiteCosts_Input_Site_Key 
        AND ItemPkgSiteCost_Item_Key = SiteCosts_Item_Key
        AND ItemPkgSiteCost_ItemPkg_Key = SiteCosts_Input_Sel_ItemPkg_Key
        AND ItemPkgSiteCost_VendItem_Key = SiteCosts_VendItem_Key
        AND ISNULL(ItemPkgSiteCost_Qty_Recv, 1) = SiteCosts_Input_Qty_Recv

A @@versão do servidor do cliente é:

Microsoft SQL Server 2005 - 9.00.4035.00 (X64) 24 de novembro de 2008 16:17:31 Copyright (c) 1988-2005 Microsoft Corporation Standard Edition (64 bits) no Windows NT 6.1 (Build 7601: Service Pack 1)

Até agora não consegui capturar o plano de consulta usado no momento do impasse, e as formas normais que tento recuperar o plano de consulta não estão retornando nada ( sys.dm_exec_query_plan e sys.dm_exec_text_query_plan ambos retornam NULL).

ATUALIZAÇÃO 2013-08-29

O cliente instalou o SQL Server 2005 SP 4, mas ainda está vendo esse impasse. Vou tentar remover o obsoleto (NOLOCK) nas tabelas que estão sendo modificadas e ver se isso corrige os impasses.

Temos um processo que gera um relatório de inventário. No lado do cliente, o processo se divide em um número configurável de threads de trabalho para criar um bloco de dados para o relatório que corresponde a um armazenamento entre muitos (potencialmente milhares, geralmente dezenas). Cada thread de trabalho chama um serviço da Web que executa um procedimento armazenado.

O processo de banco de dados para processar cada bloco reúne um monte de dados em uma tabela #Temporary. No final de cada bloco de processamento, os dados são gravados em uma tabela permanente em tempdb. Por fim, ao final do processo, um thread do lado do cliente solicita todos os dados da tabela tempdb permanente.

Quanto mais usuários executam esse relatório, mais lento ele fica. Analisei a atividade no banco de dados. A certa altura, vi 35 solicitações separadas, todas bloqueadas em um ponto do processo. Todos esses SPIDs tiveram esperas da ordem de 50 ms do tipo LATCH_EXno recurso METADATA_SEQUENCE_GENERATOR (00000010E13CA1A8). Um SPID tem esse recurso e todos os outros estão bloqueando. Não encontrei nada sobre esse recurso de espera em uma pesquisa na web.

A tabela em tempdb que estamos usando tem uma IDENTITY(1,1)coluna. Esses SPIDs estão aguardando a coluna IDENTITY? Que métodos poderíamos usar para reduzir ou eliminar o bloqueio?

O servidor faz parte de um cluster. O servidor está executando o SQL Server 2012 Standard Edition SP1 de 64 bits no Windows 2008 R2 Enterprise de 64 bits. O servidor tem 64 GB de RAM e 48 processadores, mas o banco de dados só pode usar 16 por ser a edição padrão.

(Observe que não estou entusiasmado com o design de usar uma tabela permanente em tempdb para armazenar todos esses dados. Mudar isso seria um desafio técnico e político interessante, mas estou aberto a sugestões.)

ATUALIZAÇÃO 23/04/2013

Abrimos um caso de suporte com a Microsoft. Manterei esta pergunta atualizada à medida que aprendermos mais.

ATUALIZAÇÃO 10/05/2013

O engenheiro de suporte do SQL Server concordou que as esperas foram causadas pela coluna IDENTITY. A remoção da IDENTIDADE eliminou as esperas. Não foi possível duplicar o problema no SQL 2008 R2; ocorreu apenas no SQL 2012.

Tenho um script SQL que executo quando quero ver o que está acontecendo no banco de dados. O script tem muitas consultas que retornam informações dos DMVs, mas as duas que mais uso são "Requests" ( sys.dm_exec_requests , sys.dm_exec_sessions , etc.) e "Locks" ( sys.dm_tran_locks ). A saída é semelhante ao SQL Server Activity Monitor, mas exibe mais informações.

Às vezes, uma solicitação aparece na consulta Requests, mas é concluída antes da execução da consulta Locks. Por exemplo, a consulta Requests pode mostrar que o SPID 51 está aguardando um recurso de bloqueio, mas a consulta Locks não inclui nenhuma informação de bloqueio para SPID 51. (Eu sei sobre as colunas wait_typee de .)wait_resourcesys.dm_exec_requests

Existe uma maneira de garantir que essas duas consultas separadas exibam um instantâneo coerente da atividade do banco de dados?

Espero que os aplicativos comerciais de monitoramento de banco de dados encontrem o mesmo problema.

Eu experimentei executar essas consultas em simultaneidade SERIALIZABLE e adicionei dicas de bloqueio às junções DMV, mas as consultas não adquiriram bloqueios. Eu não gostaria de fazer isso na produção de qualquer maneira.

As melhores ideias que tenho até agora são:

1. Execute essas consultas simultaneamente em diferentes sessões.

2. Junte solicitações e bloqueios em uma consulta. Considerando que vi mais de 100.000 bloqueios de uma só vez, essa junção retornaria muitas solicitações duplicadas e dados de sessão, mas pode funcionar.

Não estou familiarizado o suficiente com eventos estendidos para saber se eles funcionariam melhor - emparelhamento de eventos, talvez?

Temos um trabalho do SQL Agent configurado para ser executado como usuário "dbo". Este trabalho obtém uma lista de bancos de dados definidos em sys.databases que correspondem a um esquema de nomenclatura. A tarefa então executa algum SQL dinâmico para limpar algumas tabelas de transações antigas. O trabalho começa em tempdb.

O trabalho do agente funciona bem em meu próprio banco de dados de desenvolvimento (SQL Server 2008 R2 Standard Edition 10.50.2500.0). A tarefa obtém corretamente a lista de bancos de dados. No entanto, em um sistema do cliente (SQL Server 2008 R2 Standard Edition 64 bits 10.50.1600.1), o trabalho não encontra nenhum banco de dados correspondente, apesar de existirem.

No sistema do cliente, uma simples select * from sys.databasesexecução no tempdb em uma janela de consulta retorna todos os 10 bancos de dados do sistema.

Usando o criador de perfil, vi a chamada do SQL Agent EXECUTE AS USER = N'dbo' WITH NO REVERTao executar este trabalho. Eu dupliquei o problema usando o seguinte SQL:

use tempdb

-- results: tempdb, <my SQL user>, dbo
select
    db_name() as [Current Database],
    suser_name() as [Current Context],
    user_name() as [Current User]

-- results: tempdb, 10 (which I expect)
select
    db_name() as [Current Database],
    count(*)
from sys.databases

execute as user = N'dbo'

-- results: tempdb, sa, dbo
select
    db_name() as [Current Database],
    suser_name() as [Current Context],
    user_name() as [Current User]

-- results: tempdb, 2 (?!?)
select
    db_name() as [Current Database],
    count(*)
from sys.databases

revert

Se eu alterar 'use tempdb' para 'use master', os resultados serão os 10 bancos de dados esperados para cada consulta.

Por que sys.databases retornaria resultados diferentes quando executado como o usuário dbo do banco de dados tempdb? E por que ele retorna todos os bancos de dados com use mastero usuário dbo?

Mais informações - Se eu executar este script no SQL Server Management Studio sem incluir o revertna parte inferior, minha lista de bancos de dados será reduzida para os mesmos dois que esta consulta retorna de sys.databases.

Encontrei um impasse que parece mostrar algo que eu pensava ser impossível. Existem dois processos envolvidos no impasse:

1. process8cf948 SPID 63

• Executando um ALTER TABLE na tabela temporária #PB_Cost_Excp_Process_Invoices_Work.

• Possui bloqueio IX na tabela #PB_Cost_Excp_Process_Invoices_Work com ID de objeto 455743580

2. process4cb3708 SPID 72

• Executando em UPDATE na tabela temporária #PB_Cost_Excp_Process_Invoices_Work, que deve ser sua própria cópia exclusiva da tabela.

• Possui bloqueio Sch-M em #PB_Cost_Excp_Process_Invoices_Work com o mesmo objeto ID 455743580 !

Isto é suposto ser impossível. Estou esquecendo de algo? Uma tabela #Temporary realmente foi reutilizada entre esses dois SPIDs?

Isso está no SQL Server 2008 R2 Service Pack 2 com atualização cumulativa 1 (versão 10.50.4260).

O rastreamento de impasse inalterado completo está abaixo. Observe como os dois processos estão operando no mesmo ID de objeto com o mesmo nome de tabela #PB_Cost_Excp_Process_Invoices_Work_SNIP_0000000D8519:

12/14/2012 13:46:03,spid23s,Unknown,waiter id=process8cf948 mode=X requestType=wait
12/14/2012 13:46:03,spid23s,Unknown,waiter-list
12/14/2012 13:46:03,spid23s,Unknown,owner id=process4cb3708 mode=Sch-M
12/14/2012 13:46:03,spid23s,Unknown,owner-list
12/14/2012 13:46:03,spid23s,Unknown,objectlock lockPartition=0 objid=455743580 subresource=FULL dbid=2 objectname=tempdb.dbo.#PB_Cost_Excp_Process_Invoices_Work_________________________________________________________________________________0000000D8519 id=lock371705d00 mode=Sch-M associatedObjectId=455743580
12/14/2012 13:46:03,spid23s,Unknown,waiter id=process4cb3708 mode=Sch-M requestType=wait
12/14/2012 13:46:03,spid23s,Unknown,waiter-list
12/14/2012 13:46:03,spid23s,Unknown,owner id=process8cf948 mode=IX
12/14/2012 13:46:03,spid23s,Unknown,owner-list
12/14/2012 13:46:03,spid23s,Unknown,objectlock lockPartition=3 objid=455743580 subresource=FULL dbid=2 objectname=tempdb.dbo.#PB_Cost_Excp_Process_Invoices_Work_________________________________________________________________________________0000000D8519 id=lock3139b4780 mode=IX associatedObjectId=455743580
12/14/2012 13:46:03,spid23s,Unknown,resource-list
12/14/2012 13:46:03,spid23s,Unknown,Proc [Database Id = 8 Object Id = 1857974987]
12/14/2012 13:46:03,spid23s,Unknown,inputbuf
12/14/2012 13:46:03,spid23s,Unknown,EXEC PB_ProcessExc_Costs_Submit_SP @SiteKey, @PWDate
12/14/2012 13:46:03,spid23s,Unknown,frame procname=PDICompany_218_01.dbo.DR_SubmitPaperwork_SP line=174 stmtstart=12912 stmtend=13018 sqlhandle=0x03000800cb72be6e500434018da000000100000000000000
12/14/2012 13:46:03,spid23s,Unknown,EXEC PB_ProcessExc_Costs_Create_SP
    
    -- Clean up work table
12/14/2012 13:46:03,spid23s,Unknown,frame procname=PDICompany_218_01.dbo.PB_ProcessExc_Costs_Submit_SP line=138 stmtstart=11890 stmtend=12012 sqlhandle=0x03000800428c1f1950f833018da000000100000000000000
12/14/2012 13:46:03,spid23s,Unknown,UPDATE #PB_Cost_Excp_Process_Invoices_Work
    SET PBCEPrcInv_RtlPkg_Item_Quantity = RtlPkg_Item_Quantity
    FROM #PB_Cost_Excp_Process_Invoices_Work
        INNER JOIN Item_Packages (NOLOCK)
            ON PBCEPrcInv_ItemPkg_Key = ItemPkg_Key
        INNER JOIN Retail_Packages (NOLOCK)
            ON ItemPkg_RtlPkg_Key = RtlPkg_Key
    
    -- Lookup pricebook cost
12/14/2012 13:46:03,spid23s,Unknown,frame procname=PDICompany_218_01.dbo.PB_ProcessExc_Costs_Create_SP line=25 stmtstart=2394 stmtend=3050 sqlhandle=0x030008003a082846321f46018da000000100000000000000
12/14/2012 13:46:03,spid23s,Unknown,executionStack
12/14/2012 13:46:03,spid23s,Unknown,process id=process8cf948 taskpriority=0 logused=0 waitresource=OBJECT: 2:455743580:0  waittime=3739 ownerId=707053534 transactionname=UPDATE lasttranstarted=2012-12-14T13:45:59.327 XDES=0x3c4502930 lockMode=X schedulerid=4 kpid=7276 status=suspended spid=72 sbid=0 ecid=0 priority=0 trancount=2 lastbatchstarted=2012-12-14T13:45:58.337 lastbatchcompleted=2012-12-14T13:45:58.337 clientapp=PDI WCF Services - pdidb01-PDIMaster.cfg hostname=PDIWEB01 hostpid=2084 loginname=pdiuser isolationlevel=read committed (2) xactid=707053534 currentdb=8 lockTimeout=4294967295 clientoption1=673316896 clientoption2=128568
12/14/2012 13:46:03,spid23s,Unknown,Proc [Database Id = 8 Object Id = 1857974987]
12/14/2012 13:46:03,spid23s,Unknown,inputbuf
12/14/2012 13:46:03,spid23s,Unknown,EXEC PB_ProcessExc_Costs_Submit_SP @SiteKey, @PWDate
12/14/2012 13:46:03,spid23s,Unknown,frame procname=PDICompany_218_01.dbo.DR_SubmitPaperwork_SP line=174 stmtstart=12912 stmtend=13018 sqlhandle=0x03000800cb72be6e500434018da000000100000000000000
12/14/2012 13:46:03,spid23s,Unknown,EXEC dbo.PB_ProcessExc_Costs_CreateInvoiceWorkTable_SP
12/14/2012 13:46:03,spid23s,Unknown,frame procname=PDICompany_218_01.dbo.PB_ProcessExc_Costs_Submit_SP line=58 stmtstart=5782 stmtend=5894 sqlhandle=0x03000800428c1f1950f833018da000000100000000000000
12/14/2012 13:46:03,spid23s,Unknown,ALTER TABLE #PB_Cost_Excp_Process_Invoices_Work DROP COLUMN PBCEPrcInv_Filler
12/14/2012 13:46:03,spid23s,Unknown,frame procname=PDICompany_218_01.dbo.PB_ProcessExc_Costs_CreateInvoiceWorkTable_SP line=50 stmtstart=5382 stmtend=5538 sqlhandle=0x0300080025d75a14ffff4701969f00000100000000000000
12/14/2012 13:46:03,spid23s,Unknown,executionStack
12/14/2012 13:46:03,spid23s,Unknown,process id=process4cb3708 taskpriority=0 logused=0 waitresource=OBJECT: 2:455743580:3  waittime=3739 ownerId=707052778 transactionname=ALTER TABLE lasttranstarted=2012-12-14T13:45:58.517 XDES=0x5f48bce80 lockMode=Sch-M schedulerid=6 kpid=7212 status=suspended spid=63 sbid=0 ecid=0 priority=0 trancount=1 lastbatchstarted=2012-12-14T13:45:58.513 lastbatchcompleted=2012-12-14T13:45:58.513 clientapp=PDI WCF Services - pdidb01-PDIMaster.cfg hostname=PDIWEB01 hostpid=2084 loginname=pdiuser isolationlevel=read committed (2) xactid=707052778 currentdb=2 lockTimeout=4294967295 clientoption1=673316896 clientoption2=128568
12/14/2012 13:46:03,spid23s,Unknown,process-list
12/14/2012 13:46:03,spid23s,Unknown,deadlock victim=process4cb3708
12/14/2012 13:46:03,spid23s,Unknown,deadlock-list

ATUALIZAR

A máquina em questão mostra 16 processadores no Gerenciador de Tarefas e no Gerenciador de Dispositivos, portanto, o particionamento de bloqueio está ativado e os dois bloqueios estão em diferentes partições de bloqueio. Não sei se o particionamento de bloqueio é uma causa contribuinte aqui ou não.

Também encontrei esta postagem intrigante no blog CSS SQL Server Engineers .

ATUALIZAÇÃO 2

As tabelas temporárias são descartadas no final de cada procedimento armazenado. Eles são criados com o padrão criar #tabela, modificar esquema, inserir, atualizar, selecionar e, em seguida, descartar. Existem vários pontos de entrada para um procedimento comum que usa essa #tabela temporária, portanto, temos um proc central que configura as colunas necessárias para chamar o proc comum. Caso contrário, teríamos que replicar a mesma definição #table em todos os procs do ponto de entrada.

O processo é chamado frequentemente de vários aplicativos clientes. Alguns dos aplicativos cliente chamam esse processo de vários encadeamentos. Outros executam um de cada vez. Pense em um software de inventário/contabilidade em que o escritório central está processando dados para milhares de lojas em paralelo, enquanto as próprias lojas também executam o mesmo processo. Portanto, se esse é um problema raro quando o particionamento de bloqueio está ativado, não será tão raro em nossos bancos de dados de clientes maiores.

ATUALIZAÇÃO 3 - 2012-12-19

Outro cliente está tendo o mesmo problema no SQL Server 2012 build 11.0.2100. Não vi nenhuma menção a uma correção para esse problema nas descrições de atualização cumulativa. Pesquisando.

ATUALIZAÇÃO 4 - 2013-02-13

A Microsoft lançou a correção para esse bug nas seguintes atualizações:

• Pacote de atualização cumulativa 4 para SQL Server 2008 R2 SP2
• Pacote de atualização cumulativa 2 para SQL Server 2012 SP1

Temos um processo que coleta dados das lojas e atualiza uma tabela de estoque de toda a empresa. Esta tabela possui linhas para cada loja por data e por item. Em clientes com muitas lojas, essa tabela pode ficar muito grande, da ordem de 500 milhões de linhas.

Esse processo de atualização de inventário geralmente é executado várias vezes ao dia conforme as lojas inserem dados. Essas execuções atualizam dados de apenas algumas lojas. No entanto, os clientes também podem executar isso para atualizar, digamos, todas as lojas nos últimos 30 dias. Nesse caso, o processo cria 10 threads e atualiza o estoque de cada loja em um thread separado.

O cliente está reclamando que o processo está demorando. Eu tracei o perfil do processo e descobri que uma consulta que INSERTs nesta tabela está consumindo muito mais tempo do que eu esperava. Às vezes, esse INSERT é concluído em 30 segundos.

Quando eu executo um comando SQL INSERT ad-hoc nesta tabela (limitada por BEGIN TRAN e ROLLBACK), o SQL ad-hoc é concluído na ordem de milissegundos.

A consulta de desempenho lento está abaixo. A ideia é INSERIR os registros que não existem e depois ATUALIZÁ-los à medida que calculamos vários bits de dados. Uma etapa anterior do processo identificou os itens que precisam ser atualizados, fez alguns cálculos e inseriu os resultados na tabela tempdb Update_Item_Work. Esse processo está sendo executado em 10 threads separados e cada thread tem seu próprio GUID em Update_Item_Work.

INSERT INTO Inventory
(
    Inv_Site_Key,
    Inv_Item_Key,
    Inv_Date,
    Inv_BusEnt_ID,
    Inv_End_WtAvg_Cost
)
SELECT DISTINCT
    UpdItemWrk_Site_Key,
    UpdItemWrk_Item_Key,
    UpdItemWrk_Date,
    UpdItemWrk_BusEnt_ID,
    (CASE UpdItemWrk_Set_WtAvg_Cost WHEN 1 THEN UpdItemWrk_WtAvg_Cost ELSE 0 END)
FROM tempdb..Update_Item_Work (NOLOCK)
WHERE UpdItemWrk_GUID = @GUID
AND NOT EXISTS
    -- Only insert for site/item/date combinations that don't exist
    (SELECT *
    FROM Inventory (NOLOCK)
    WHERE Inv_Site_Key = UpdItemWrk_Site_Key
    AND Inv_Item_Key = UpdItemWrk_Item_Key
    AND Inv_Date = UpdItemWrk_Date)

A tabela Estoque tem 42 colunas, a maioria das quais acompanha quantidades e contagens para vários ajustes de estoque. sys.dm_db_index_physical_stats diz que cada linha tem cerca de 242 bytes, então espero que cerca de 33 linhas caibam em uma única página de 8 KB.

A tabela é agrupada na restrição exclusiva (Inv_Site_Key, Inv_Item_Key, Inv_Date). Todas as chaves são DECIMAL(15,0) e a data é SMALLDATETIME. Há uma chave primária IDENTITY (não agrupada) e 4 outros índices. Todos os índices e a restrição clusterizada são definidos com um explícito (FILLFACTOR = 90, PAD_INDEX = ON).

Procurei no arquivo de log para contar as divisões de página. Eu medi cerca de 1.027 divisões no índice clusterizado e 1.724 divisões em outro índice, mas não registrei em que intervalo elas ocorreram. Uma hora e meia depois, medi 7.035 divisões de página no índice agrupado.

O plano de consulta que capturei no criador de perfil é assim:

Rows         Executes     StmtText                                                                                                                                             
----         --------     --------                                                                                                                                             
490          1            Sequence                                                                                                                                             
0            1              |--Index Update
0            1              |    |--Collapse
0            1              |         |--Sort
0            1              |              |--Filter
996          1              |                   |--Table Spool                                                                                                                 
996          1              |                        |--Split                                                                                                                  
498          1              |                             |--Assert
0            0              |                                  |--Compute Scalar
498          1              |                                       |--Clustered Index Update(UK_Inventory)
498          1              |                                            |--Compute Scalar
0            0              |                                                 |--Compute Scalar
0            0              |                                                      |--Compute Scalar
498          1              |                                                           |--Compute Scalar
498          1              |                                                                |--Top
498          1              |                                                                     |--Nested Loops
498          1              |                                                                          |--Stream Aggregate
0            0              |                                                                          |    |--Compute Scalar
498          1              |                                                                          |         |--Clustered Index Seek(tempdb..Update_Item_Work)
498          498            |                                                                          |--Clustered Index Seek(Inventory)
0            1              |--Index Update(UX_Inv_Exceptions_Date_Site_Item)
0            1              |    |--Collapse
0            1              |         |--Sort
0            1              |              |--Filter
996          1              |                   |--Table Spool
490          1              |--Index Update(UX_Inv_Date_Site_Item)
490          1                   |--Collapse
980          1                        |--Sort
980          1                             |--Filter
996          1                                  |--Table Spool                                                                                       

Olhando para as consultas versus vários dmvs, vejo que a consulta está aguardando em PAGEIOLATCH_EX por uma duração de 0 em uma página nesta tabela de inventário. Não vejo nenhuma espera ou bloqueio em bloqueios.

Esta máquina tem cerca de 32 GB de memória. Ele está executando o SQL Server 2005 Standard Edition, embora eles estejam atualizando em breve para o 2008 R2 Enterprise Edition. Não tenho números sobre o tamanho da tabela de inventário em termos de uso de disco, mas posso obter isso, se necessário. É uma das maiores mesas deste sistema.

Executei uma consulta em sys.dm_io_virtual_file_stats e vi que a média de esperas de gravação em tempdb era superior a 1,1 segundos . O banco de dados no qual essa tabela está armazenada tem esperas médias de gravação de aproximadamente 350 ms. Mas eles só reiniciam o servidor a cada 6 meses, então não tenho ideia se essa informação é relevante. tempdb está distribuído em 4 arquivos diferentes Eles têm 3 arquivos diferentes para o banco de dados que contém a tabela Inventário.

Por que essa consulta demoraria tanto para INSERT algumas linhas quando executada com muitos threads diferentes quando um único INSERT é muito rápido?

-- ATUALIZAR --

Aqui estão os números de latência por unidade, incluindo bytes lidos. Como você pode ver, o desempenho do tempdb é questionável. A tabela Inventory está em PDICompany_252_01.mdf, PDICompany_252_01_Second.ndf ou PDICompany_252_01_Third.ndf.

ReadLatencyWriteLatencyLatencyAvgBPerRead AvgBPerWriteAvgBPerTransferDriveDB                     physical_name
         42        1112    623       62171       67654          65147R:   tempdb                 R:\Microsoft SQL Server\Tempdb\tempdev1.mdf
         38        1101    615       62122       67626          65109S:   tempdb                 S:\Microsoft SQL Server\Tempdb\tempdev2.ndf
         38        1101    615       62136       67639          65123T:   tempdb                 T:\Microsoft SQL Server\Tempdb\tempdev3.ndf
         38        1101    615       62140       67629          65119U:   tempdb                 U:\Microsoft SQL Server\Tempdb\tempdev4.ndf
         25         341     71       92767       53288          87009X:   PDICompany             X:\Program Files\PDI\Enterprise\Databases\PDICompany_Third.ndf
         26         339     71       90902       52507          85345X:   PDICompany             X:\Program Files\PDI\Enterprise\Databases\PDICompany_Second.ndf
         10         231     90       98544       60191          84618W:   PDICompany_FRx         W:\Program Files\PDI\Enterprise\Databases\PDICompany_FRx.mdf
         61         137     68        9120        9181           9125W:   model                  W:\Microsoft SQL Server\MSSQL.3\MSSQL\Data\modeldev.mdf
         36         113     97        9376        5663           6419V:   model                  V:\Microsoft SQL Server\Logs\modellog.ldf
         22          99     34       92233       52112          86304W:   PDICompany             W:\Program Files\PDI\Enterprise\Databases\PDICompany.mdf
          9          20     10       25188        9120          23538W:   master                 W:\Microsoft SQL Server\MSSQL.3\MSSQL\Data\master.mdf
         20          18     19       53419       10759          40850W:   msdb                   W:\Microsoft SQL Server\MSSQL.3\MSSQL\Data\MSDBData.mdf
         23          18     19      947956       58304         110123V:   PDICompany_FRx         V:\Program Files\PDI\Enterprise\Databases\PDICompany_FRx_1.ldf
         20          17     17      828123       55295         104730V:   PDICompany             V:\Program Files\PDI\Enterprise\Databases\PDICompany.ldf
          5          13     13       12308        4868           5129V:   master                 V:\Microsoft SQL Server\Logs\mastlog.ldf
         11          13     13       22233        7598           8513V:   PDIMaster              V:\Program Files\PDI\Enterprise\Databases\PDIMaster.ldf
         14          11     13       13846        9540          12598W:   PDIMaster              W:\Program Files\PDI\Enterprise\Databases\PDIMaster.mdf
         13          11     11       22350        1107           1110V:   msdb                   V:\Microsoft SQL Server\Logs\MSDBLog.ldf
         17           9      9      745437       11821          23249V:   PDIFoundation          V:\Program Files\PDI\Enterprise\Databases\PDIFoundation.ldf
         34           8     31       29490       33725          30031W:   PDIFoundation          W:\Program Files\PDI\Enterprise\Databases\PDIFoundation.mdf
          5           8      8       61560       61236          61237V:   tempdb                 V:\Microsoft SQL Server\Logs\templog.ldf
         13           6     11        8370       35087          16785W:   SAHost_Company01       W:\Program Files\PDI\Enterprise\Databases\SAHostCompany.mdf
          2           6      5       56235       33667          38911W:   SAHost_Company01       W:\Program Files\PDI\Enterprise\Databases\SAHost_Company_01_log.LDF