Gargalo de memória direto das trincheiras

Olá,

 

Mais um caso de situação de problema direto das trincheiras do mundo corporativo.

O problema desta vez é contenção de memória. Todo o cenário, praticamente exatamente igual ao que presenciei, foi muito bem descrito em um artigo do Graham Kent. Veja em SQL Server Compilation Bottlenecks – Error: 8628, Severity: 17, State: 0. – Part 1

O que mudou no meu cenário:

  • CPU ficava em 100% somente quando as requisições chegavam no banco de dados (wait SOS_SCHEDULER_YIELD)
  • Gerou time-out de otimização de query (veja mais info abaixo), todas as requisições ficavam com wait RESOURCE_SEMAPHORE_QUERY_COMPILE
  • Meu gargalo foi em Medium Gateway, com 89 requisições em espera (Waiters) – Veja MemoryStatus

A mensagem de erro gerada pelo errorLog é:

2012-10-18 11:20:06.220 spid61       Error: 8628, Severity: 17, State: 1.
2012-10-18 11:20:06.220 spid61       A time out occurred while waiting to optimize the query. Rerun the query.

Outras referências:

How to use the DBCC MEMORYSTATUS command to monitor memory usage on SQL Server 2005

 

Bons Estudos. []’s

 

Anúncios

Corrupção de Dados direto das trincheiras

Olá,

Hoje venho com mais um caso de corrupção de dados extraído de um ambiente real, direto das “trincheiras”.

Tive um caso onde há alguns dias o SQL vinha gerando dumps de um problema até então não identificado. Como os dumps não vinham sendo verificados o problema ficou por alguns dias e só fomos “informados” dele quando um dia o SQL foi derrubado pelo erro. Vamos à investigação.

Primeiro erro crítico encontrado, que derrubou o SQL:

=====================================================================                                            
       BugCheck Dump                                                                                             
=====================================================================                                            
                                                                                                                 
This file is generated by Microsoft SQL Server                                                                   
version 9.00.5000.00                                                                                             
upon detection of fatal unexpected error. Please return this file,                                               
the query or program that produced the bugcheck, the database and                                                
the error log, and any other pertinent information with a Service Request.                                       
                                                                                                                 
                                                                                                                 
Computer type is AT/AT COMPATIBLE.                                                                               
Current time is 01:53:50 09/20/12.                                                                               
8 Unknown CPU 9., 3 Mhz processor (s).                                                                           
Windows NT 5.2 Build 3790 CSD Service Pack 2.                                                                    
                                     
Memory                               
MemoryLoad = 87%                     
Total Physical = 8189 MB             
Available Physical = 1048 MB         
Total Page File = 9779 MB            
Available Page File = 2785 MB        
Total Virtual = 8388607 MB           
Available Virtual = 8379991 MB       
***Stack Dump being sent to E:\MSSQL.1\MSSQL\LOG\SQLDump0129.txt                                                 
SqlDumpExceptionHandler: Process 63 generated fatal exception c0000005 EXCEPTION_ACCESS_VIOLATION. SQL Server is 
terminating this process.                                                                                        
* *******************************************************************************                                
*                                                                                                                
* BEGIN STACK DUMP:                                                                                              
*   09/20/12 01:53:50 spid 63                                                                                    
*                                                                                                                
*                                                                                                                
*   Exception Address = 0000000001D20C81 Module(sqlservr+0000000000D20C81)                                       
*   Exception Code    = c0000005 EXCEPTION_ACCESS_VIOLATION                                                      
*   Access Violation occurred writing address 0000000000000002

Destaquei os pontos que me chamaram a atenção. Pensei, provavelmente algo grave mas vamos continuar investigando… Este erro ocorreu ainda mais uma vez e depois começaram a surgir dumps com esta característica:

Begin transaction log dump for database 'dbcorporativo'; for Index maintenance - filter on ObjId.
              
                   Current LSN = 002907c7:000019ea:01da                                                          
                     Operation = LOP_MODIFY_ROW                                                                  
                       Context = LCX_CLUSTERED                                                                   
                Transaction ID = 0000:7241332b                                                                   
                      Tag Bits = 0000                                                                            
       Log Record Fixed Length = 62                                                                              
             Log Record Length = 116                                                                             
                  Previous LSN = 002907c7:000019ea:01d8                                                          
                     Flag Bits = 0200                                                                            
                   AllocUnitId = 372292930109440                                                                 
                 AllocUnitName = dbo.mk45_pf.pk_mk45_pf                                                          
                       Page ID = 0001:004cfa63                                                                   
                       Slot ID = 3                                                                               
             Previous Page LSN = 002907c6:00039c20:015a                                                          
               Number of Locks = 3                                                                               
              Lock Information = HoBt 372292930109440:ACQUIRE_LOCK_IX OBJECT: 6:1385771994:0 ;ACQUIRE_LOCK_IX PAG
E: 6:1:5044835;ACQUIRE_LOCK_X KEY: 6:372292930109440 (0f0088d0eb93)                                              
                   Description =                                                                                 
                    Log Record = 00003e00c7072900ea190000d80102002b3341720000040263fa4c0001000300da339952c6072900
209c03005a0101000000da33995201009c000100000004000100010008001a00cd00772ad18a2e48160fe84c020100000101000c0000da339
9520000010200040204000a0f0088d0eb939952                                                                          
                                                                                                                 
                   Current LSN = 002907c7:000019ea:01d9                                                          
                     Operation = LOP_MODIFY_COLUMNS                                                              
                       Context = LCX_CLUSTERED                                                                   
                Transaction ID = 0000:7241331c                                                                   
                      Tag Bits = 0000                                                                            
       Log Record Fixed Length = 62                                                                              
             Log Record Length = 144                                                                             
                  Previous LSN = 002907c7:000019ea:01d7                                                          
                     Flag Bits = 0200                                                                            
                   AllocUnitId = 372292930109440                                                                 
                 AllocUnitName = dbo.mk45_pf.pk_mk45_pf                                                          
                       Page ID = 0001:0059445a                                                                   
                       Slot ID = 3                                                                               
             Previous Page LSN = 002907c7:000019ea:01d7                                                          
               Number of Locks = 3                                                                               
              Lock Information = HoBt 372292930109440:ACQUIRE_LOCK_IX OBJECT: 6:1385771994:0 ;ACQUIRE_LOCK_IX PAG
E: 6:1:5850202;ACQUIRE_LOCK_X KEY: 6:372292930109440 (5200e0c454d0)                                              
                   Description =                                                                                 
                    Log Record = 00003e00c7072900ea190000d70102001c334172000006025a44590001000300da339952c7072900
ea190000d70101000000da339952010000000000000008000800040008001a000200020001000100330033009c009c000200010016521b530
20100000101000c0000da3399520000010200040204000a5200e0c454d04172530104020a004e00d0000100d1339952                  

E no final deste dump, a mensagem:

++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
                                                   
**Dump thread - spid = 63, PSS = 0x00000000BB17DEA0, EC = 0x00000000BB17DEB0                                     
***Stack Dump being sent to E:\MSSQL.1\MSSQL\LOG\SQLDump0131.txt                                                 
* *******************************************************************************                                
*                                                                                                                
* BEGIN STACK DUMP:                                                                                              
*   09/20/12 03:05:40 spid 63                                                                                    
*                                                                                                                
* CPerIndexMetaQS::ErrorAbort - Index corruption                                                                 

Já fiquei um pouco mais tranquilo. Trata-se de uma corrupção de índice. Ótimo! Algo relativamente simples de ser tratado. Restava ainda ter absoluta certeza de que se trava de uma corrupção de índice e tratá-la. Vamos ao DBCC CHECKDB. O resultado do CHECKDB na base em questão foi o seguinte (resumo):

Msg 8951, Level 16, State 1, Line 1
Table error: table 'mk45_pf' (ID 1385771994). Data row does not have a matching index row in the index 'IK_mk45_pf' (ID 24). Possible missing or invalid keys for the index row matching:
Msg 8955, Level 16, State 1, Line 1
Data row (1:4206449:9) identified by (cd_pes = 34916789) with index values 'cd_cpf_pes = 16614763254. and cd_sgm_pes_pri = '006' and cd_sgm_pes_sec = 'AKO' and cd_pes = 34916789'.
Msg 8951, Level 16, State 1, Line 1
Table error: table 'mk45_pf' (ID 1385771994). Data row does not have a matching index row in the index 'IK_mk45_pf' (ID 24). Possible missing or invalid keys for the index row matching:
Msg 8955, Level 16, State 1, Line 1
Data row (1:5060407:26) identified by (cd_pes = 38871114) with index values 'cd_cpf_pes = NULL and cd_sgm_pes_pri = '006' and cd_sgm_pes_sec = 'AKO' and cd_pes = 38871114'.
Msg 8951, Level 16, State 1, Line 1
Table error: table 'mk45_pf' (ID 1385771994). Data row does not have a matching index row in the index 'IK_mk45_pf' (ID 24). Possible missing or invalid keys for the index row matching:
Msg 8955, Level 16, State 1, Line 1
Data row (1:5061350:3) identified by (cd_pes = 38871291) with index values 'cd_cpf_pes = NULL and cd_sgm_pes_pri = '106' and cd_sgm_pes_sec = 'AUB' and cd_pes = 38871291'.
...
CHECKDB found 0 allocation errors and 28 consistency errors in table 'mk45_pf' (object ID 1385771994).
CHECKDB found 0 allocation errors and 28 consistency errors in database 'dbcorporativo'.
repair_rebuild is the minimum repair level for the errors found by DBCC CHECKDB (dbcorporativo).

No dump, ele gerou o resultado do DBCC CHECKDB desta forma:

<Dbcc ID="52" Error="8952" Severity="16" State="1">Table error: table 'mk45_pf' (ID 1385771994). Index row in ind
ex 'IK_mk45_pf' (ID 24) does not match any data row. Possible extra or invalid keys for:</Dbcc>                  
<Dbcc ID="53" Error="8956" Severity="16" State="1">Index row (1:15540904:69) with values (cd_cpf_pes = 9746759701
. and cd_sgm_pes_pri = '006' and cd_sgm_pes_sec = '080' and cd_pes = 46266481) pointing to the data row identifie
d by (cd_pes = 46266481).</Dbcc>                                                                                 
<Dbcc ID="54" Error="8952" Severity="16" State="1">Table error: table 'mk45_pf' (ID 1385771994). Index row in ind
ex 'IK_mk45_pf' (ID 24) does not match any data row. Possible extra or invalid keys for:</Dbcc>                  
<Dbcc ID="55" Error="8956" Severity="16" State="1">Index row (1:15577461:126) with values (cd_cpf_pes = 859179826
00. and cd_sgm_pes_pri = '106' and cd_sgm_pes_sec = '133' and cd_pes = 38872341) pointing to the data row identif
ied by (cd_pes = 38872341).</Dbcc>                                                                               
<Dbcc ID="56" Error="8990" Severity="10" State="1">CHECKDB found 0 allocation errors and 28 consistency errors in
 table 'mk45_pf' (object ID 1385771994).</Dbcc>                                                                  
<Dbcc ID="57" Error="8989" Severity="10" State="1">CHECKDB found 0 allocation errors and 28 consistency errors in
 database 'dbcorporativo'.</Dbcc>                                                                                
<Dbcc ID="58" Error="8957" Severity="-1" State="1">DBCC CHECKDB (dbcorporativo) WITH all_errormsgs, no_infomsgs e
xecuted by BSBR\dbadmin found 28 errors and repaired 0 errors. Elapsed time: 1 hours 9 minutes 23 seconds.</Dbcc>
<Dbcc ID="59" Error="8958" Severity="10" State="1">repair_rebuild is the minimum repair level for the errors foun
d by DBCC CHECKDB (dbcorporativo).</Dbcc>                                                                        
</DbccResults>                                                                                                   
**Dump thread - spid = 59, PSS = 0x0000000193777C00, EC = 0x0000000193777C10                                     
***Stack Dump being sent to E:\MSSQL.1\MSSQL\LOG\SQLDump0161.txt                                                 
* *******************************************************************************                                
*                                                                                                                
* BEGIN STACK DUMP:                                                                                              
*   10/05/12 15:08:22 spid 59                                                                                    
*                                                                                                                
* DBCC database corruption                                                                                       
*                                                                                                                
* Input Buffer 142 bytes -                                                                                       
*             dbcc checkdb(dbcorporativo)  with all_errormsgs, no_infomsgs                                       
*                                                                                                                
* *******************************************************************************                                

Problema diagnosticado com exatidão. Realmente trata-se de uma corrupção de índice. A minha suspeita seria de que este é um índice NON-CLUSTERED e alguma referência da PK foi corrompida, ou mesmo o próprio dado do índice. Não tive dúvidas, confirmei que se tratava de um índice NC (exec sp_helpindex ‘minha_tabela’), dropei o índice e o recriei logo em seguida.

Rodei o DBCC CHECKDB na sequência e, sucesso. Problema resolvido. Exp + 1. =)

 

Abraços e bons estudos.
Erickson Ricci

Non-yielding IOCP Listener

Olá,

Essa semana tive de realizar uma análise de performance em um de nossos servidores e me deparei com um Dump gerado pelo SQL com a seguinte descrição:

2012-09-18 00:21:43.110 Server       **Dump thread - spid = 0, EC = 0x0000000000000000
2012-09-18 00:21:43.130 Server       ***Stack Dump being sent to H:\MSSQL10.xxxxxxxxx\MSSQL\LOG\SQLDump0002.txt
2012-09-18 00:21:43.130 Server       * *******************************************************************************
2012-09-18 00:21:43.130 Server       *
2012-09-18 00:21:43.130 Server       * BEGIN STACK DUMP:
2012-09-18 00:21:43.130 Server       *   09/18/12 00:21:43 spid 9672
2012-09-18 00:21:43.130 Server       *
2012-09-18 00:21:43.130 Server       * Non-yielding IOCP Listener
2012-09-18 00:21:43.130 Server       *
2012-09-18 00:21:43.130 Server       * *******************************************************************************
2012-09-18 00:21:43.130 Server       * -------------------------------------------------------------------------------
2012-09-18 00:21:43.130 Server       * Short Stack Dump
2012-09-18 00:21:43.190 Server       Stack Signature for the dump is 0x0000000000000204
2012-09-18 00:21:46.460 Server       External dump process return code 0x20000001. External dump process returned no errors.

Seguido do Dump, foram identificados alguns erros como os abaixo:

2012-09-18 00:21:46.470 Server       IO Completion Listener (0x25f8) Worker 0x0000000007B8E1A0 appears to be non-yielding on Node 3. Approx CPU Used: kernel 0 ms, user 0 ms, Interval: 15048.
2012-09-19 00:07:26.230 Server       IO Completion Listener (0x25f8) Worker 0x0000000007B8E1A0 appears to be non-yielding on Node 3. Approx CPU Used: kernel 0 ms, user 0 ms, Interval: 15001.
2012-09-19 00:08:18.170 Server       IO Completion Listener (0x25f8) Worker 0x0000000007B8E1A0 appears to be non-yielding on Node 3. Approx CPU Used: kernel 0 ms, user 0 ms, Interval: 25002.

Depois de coletar dados através do Perfmon, aparentemente não havia problemas de consumo de CPU, ou memória… Pesquisando na internet cheguei ao KB2711549 que descreve o mesmo cenário que eu passei.

Este é um Cumulative Update para o SQL Server 2008 e SQL Server 2008 R2. No caso do SQL Server 2008 é o CU7 do SP. Para SQL Server 2008 R2, CU7 para o SP1.

Em breve irei aplicar este CU no ambiente e monitorar novamente para validar que o problema foi resolvido. Fica dica!

 

Bons Estudos!
Erickson Ricci

O que acontece quando se altera a configuração MAXDOP

Olá,
Um post rápido para evidenciar o que acontece quando nós alteramos a configuração de paralelismo do SQL Server.

A configuração a qual me refiro é a “Max Degree of Parallelism”, ou mais conhecida como MAXDOP.Esta configuração é utilizada para determinar quantos processadores serão utilizados para processar uma consulta quando esta necessitar de paralelização. Mais informações, acesse Degree of Parallelism

Para visualizar esta configuração, você pode executar a procedure sp_configure:

exec sp_configure

No entanto, com as configurações padrão, você deve ter um resultado como este:

name                                minimum     maximum     config_value run_value
----------------------------------- ----------- ----------- ------------ -----------
allow updates                       0           1           0            0
backup compression default          0           1           0            0
clr enabled                         0           1           0            0
cross db ownership chaining         0           1           0            0
default language                    0           9999        0            0
filestream access level             0           2           0            0
max text repl size (B)              -1          2147483647  65536        65536
nested triggers                     0           1           1            1
remote access                       0           1           1            1
remote admin connections            0           1           0            0
remote login timeout (s)            0           2147483647  20           20
remote proc trans                   0           1           0            0
remote query timeout (s)            0           2147483647  600          600
server trigger recursion            0           1           1            1
show advanced options               0           1           0            0
user options                        0           32767       0            0

Para visualizar o valor do MAXDOP, você deve antes habilitar a visão de opções avançadas (show advanced options):

sp_configure 'show advanced options', 1
reconfigure

Com isso, todas as opções são visualizadas, conforme abaixo. Em destaque a configuração do MAXDOP.

name                                minimum     maximum     config_value run_value
----------------------------------- ----------- ----------- ------------ -----------
access check cache bucket count     0           65536       0            0
access check cache quota            0           2147483647  0            0
Ad Hoc Distributed Queries          0           1           0            0
affinity I/O mask                   -2147483648 2147483647  0            0
affinity mask                       -2147483648 2147483647  0            0
affinity64 I/O mask                 -2147483648 2147483647  0            0
affinity64 mask                     -2147483648 2147483647  0            0
Agent XPs                           0           1           1            1
allow updates                       0           1           0            0
awe enabled                         0           1           0            0
backup compression default          0           1           0            0
blocked process threshold (s)       0           86400       0            0
c2 audit mode                       0           1           0            0
clr enabled                         0           1           0            0
common criteria compliance enabled  0           1           0            0
cost threshold for parallelism      0           32767       5            5
cross db ownership chaining         0           1           0            0
cursor threshold                    -1          2147483647  -1           -1
Database Mail XPs                   0           1           0            0
default full-text language          0           2147483647  1033         1033
default language                    0           9999        0            0
default trace enabled               0           1           1            1
disallow results from triggers      0           1           0            0
EKM provider enabled                0           1           0            0
filestream access level             0           2           0            0
fill factor (%)                     0           100         0            0
ft crawl bandwidth (max)            0           32767       100          100
ft crawl bandwidth (min)            0           32767       0            0
ft notify bandwidth (max)           0           32767       100          100
ft notify bandwidth (min)           0           32767       0            0
index create memory (KB)            704         2147483647  0            0
in-doubt xact resolution            0           2           0            0
lightweight pooling                 0           1           0            0
locks                               5000        2147483647  0            0
max degree of parallelism           0           1024        1            1
max full-text crawl range           0           256         4            4
max server memory (MB)              16          2147483647  26000        26000
max text repl size (B)              -1          2147483647  65536        65536
max worker threads                  128         32767       0            0
media retention                     0           365         0            0
min memory per query (KB)           512         2147483647  1024         1024
min server memory (MB)              0           2147483647  0            0
nested triggers                     0           1           1            1
network packet size (B)             512         32767       4096         4096
Ole Automation Procedures           0           1           0            0
open objects                        0           2147483647  0            0
optimize for ad hoc workloads       0           1           0            0
PH timeout (s)                      1           3600        60           60
precompute rank                     0           1           0            0
priority boost                      0           1           0            0
query governor cost limit           0           2147483647  0            0
query wait (s)                      -1          2147483647  -1           -1
recovery interval (min)             0           32767       0            0
remote access                       0           1           1            1
remote admin connections            0           1           0            0
remote login timeout (s)            0           2147483647  20           20
remote proc trans                   0           1           0            0
remote query timeout (s)            0           2147483647  600          600
Replication XPs                     0           1           0            0
scan for startup procs              0           1           0            0
server trigger recursion            0           1           1            1
set working set size                0           1           0            0
show advanced options               0           1           1            1
SMO and DMO XPs                     0           1           1            1
SQL Mail XPs                        0           1           0            0
transform noise words               0           1           0            0
two digit year cutoff               1753        9999        2049         2049
user connections                    0           32767       0            0
user options                        0           32767       0            0
xp_cmdshell                         0           1           0            0

Um efeito que alguns talvez desconheçam é o que acontece por trás dos bastidores quando esta configuração é alterada. Toda vez que o MAXDOP é alterado o cache do SQL é zerado. Como?!

Isso mesmo, o cache de procedures, queries e outros objetos compilados e zerado, fazendo com que todos os objetos tenham de ser recompilados novamente.

Como podemos comprovar isso? Dando uma olhada no errorlog. O resultado é este:

2012-09-27 15:57:59.320 spid80       Configuration option 'max degree of parallelism' changed from 1 to 0. Run the RECONFIGURE statement to install.
...
2012-09-27 15:57:59.360 spid80       SQL Server has encountered 2 occurrence(s) of cachestore flush for the 'Object Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2012-09-27 15:58:01.970 spid80       SQL Server has encountered 2 occurrence(s) of cachestore flush for the 'SQL Plans' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.
2012-09-27 15:58:01.980 spid80       SQL Server has encountered 2 occurrence(s) of cachestore flush for the 'Bound Trees' cachestore (part of plan cache) due to some database maintenance or reconfigure operations.

O SQL Server registrou ocorrências de “flush” das áreas de cache ‘Object Plans’, ‘SQL Plans’ e ‘Bound Trees’, que são as áreas onde são armazenados os planos de execução das consultas, procedures etc.

Obs: estou sendo bem simplista aqui ao descrever estas áreas de cache. Para mais informações vale a pena dar uma olhada na DMV sys.dm_os_memory_cache_counters , nos tipos para SQL Plans (CACHESTORE_SQLCP), Object Plans (CACHESTORE_OBJCP) e Bound Trees (CACHESTORE_PHDR).

Portanto, fica a dica. Caso você tenha que alterar esta configuração em um ambiente de produção, saiba que você terá consequências. Sabendo disso, você evitará uma análise equivocada do seu ambiente após alteração desta configuração.

 

Bons Estudos!
Erickson Ricci

Destination: Change

I have been asked a few times if there was a landing page for the 70-451 posts and figured that such a page would probably be more helpful than just the tags post.  So, without further ado, here is the listing:

Designing a Database Strategy (13 percent)

Ver o post original 765 mais palavras

iSQL Server - Um blog para falar de SQL Server

Tivemos hoje um webcast especial do grande amigo Erickson Ricci (blog | twitter) falando sobre a carreira de DBA. Pontos fundamentais de uma profissão extremamente importante e dando algumas dicas muito bem colocadas para não sermos apenas mais um DBA no mercado de trabalho.

Este webcast foi o primeiro de uma série de webcasts que serão realizados pelo grupo MTAC – Microsoft Technical Audience Contributor.

O webcast foi gravado e já esta disponível através do link de cadastramento do webcast.

Acessem e assistam agora mesmo!

https://msevents.microsoft.com/CUI/EventDetail.aspx?culture=pt-BR&EventID=1032527674&CountryCode=BR

Muito obrigado Erickson pelo ótimo webcast e aguardem novidades em breve!

Obrigado pela presença de todos e aguardo vocês nos próximos webcasts.

Ver o post original