Nosso trabalho Ola Hallengren IntegrityCheck falhou devido a um tempo limite de trava de buffer durante a execução de DBCC CHECKDB em um banco de dados de usuário.
No entanto, o tempo limite de trava do buffer relatado estava em TempDB (ID do banco de dados 2).
Saída do trabalho:
Date and time: 2022-01-22 09:04:15 [SQLSTATE 01000]
Database context: [master] [SQLSTATE 01000]
Command: SET LOCK_TIMEOUT 600000; DBCC CHECKDB ([SentryOne]) WITH NO_INFOMSGS, ALL_ERRORMSGS, MAXDOP = 4 [SQLSTATE 01000]
Msg 845, Sev 17, State 1, Line 1 : Time-out occurred while waiting for buffer latch type 2 for page (6:222), database ID 2. [SQLSTATE 42000]
Outcome: Failed [SQLSTATE 01000]
Duration: 12:40:32 [SQLSTATE 01000]
Date and time: 2022-01-22 21:44:47 [SQLSTATE 01000]
Mensagens no log de erros do SQL:
Date 1/22/2022 9:35:22 PM
Log SQL Server (Archive #1 - 1/23/2022 12:00:00 AM)
Source spid777
Message
A time-out occurred while waiting for buffer latch -- type 2, bp 0000016D7A1DE340, page 6:222, stat 0x40d, database id: 2, allocation unit Id: 536870912/281475513581568, task 0x0000016CD624E4E8 : 2, waittime 300 seconds, flags 0x1a, owning task 0x0000016CD624E4E8. Not continuing to wait.
BobMgr::GetBuf: Sort Big Output Buffer write not complete after 60 seconds.
DBCC CHECKDB (SentryOne) WITH all_errormsgs, no_infomsgs, maxdop = 4 executed by NT SERVICE\SQLSERVERAGENT terminated abnormally due to error state 6. Elapsed time: 12 hours 39 minutes 57 seconds.
[INFO] Database ID: [12]. Cleaning up StorageArray. LastClosedCheckpointEndTs: '1225176490'
[WARNING] ALTER or DROP TABLE could not clean up root row within 10 seconds.
A página em questão é uma página do IAM no TempDB. Saída DBCC PAGE para ele:
PAGE: (6:222)
BUFFER:
BUF @0x0000016D6B622C40
bpage = 0x00000161A6C52000 bPmmpage = 0x0000000000000000 bsort_r_nextbP = 0x0000016D6B622AD0
bsort_r_prevbP = 0x0000016D6B622B80 bhash = 0x0000000000000000 bpageno = (6:222)
bpart = 4 ckptGen = 0x0000000000000000 bDirtyRefCount = 0
bstat = 0x9 breferences = 3 berrcode = 0
bUse1 = 19321 bstat2 = 0x0 blog = 0x215a215a
bsampleCount = 1 bIoCount = 0 resPoolId = 0
bcputicks = 330 bReadMicroSec = 848 bDirtyContext = 0x0000000000000000
bDbPageBroker = 0x0000000000000000 bdbid = 2 bpru = 0x0000016D3A170040
PAGE HEADER:
Page @0x00000161A6C52000
m_pageId = (6:222) m_headerVersion = 1 m_type = 10
m_typeFlagBits = 0x0 m_level = 0 m_flagBits = 0x200
m_objId (AllocUnitId.idObj) = 1837007664 m_indexId (AllocUnitId.idInd) = 28675
Metadata: AllocUnitId = 8071415347312328704
Metadata: PartitionId = 2162691495132069888 Metadata: IndexId = 0
Metadata: ObjectId = -1083263203 m_prevPage = (0:0) m_nextPage = (0:0)
pminlen = 90 m_slotCnt = 2 m_freeCnt = 6
m_freeData = 8182 m_reservedCnt = 0 m_lsn = (324:1435184:42)
m_xactReserved = 0 m_xdesId = (0:0) m_ghostRecCnt = 0
m_tornBits = -551517712 DB Frag ID = 1
Allocation Status
GAM (6:2) = ALLOCATED SGAM (6:3) = ALLOCATED
PFS (6:1) = 0x70 IAM_PG MIXED_EXT ALLOCATED 0_PCT_FULL DIFF (6:6) = NOT CHANGED
ML (6:7) = NOT MIN_LOGGED
IAM: Header @0x00000036C4278064 Slot 0, Offset 96
sequenceNumber = 0 status = 0x0 objectId = 0
indexId = 0 page_count = 0 start_pg = (8:511232)
IAM: Single Page Allocations @0x00000036C427808E
Slot 0 = (0:0) Slot 1 = (0:0) Slot 2 = (0:0)
Slot 3 = (0:0) Slot 4 = (0:0) Slot 5 = (0:0)
Slot 6 = (0:0) Slot 7 = (0:0)
IAM: Extent Alloc Status Slot 1 @0x00000036C42780C2
(8:511232) - (8:592656) = NOT ALLOCATED
(8:592664) - = ALLOCATED
(8:592672) - (8:770424) = NOT ALLOCATED
Encontrei esta pergunta do DBA StackExchange que parece ser mais relevante: Obtendo o erro "Ocorreu o tempo limite enquanto aguardava o tipo de trava de buffer 2 para a página (1:3564879), ID do banco de dados 7". Mas um banco de dados com Id 7 NÃO existe
No entanto, nesse cenário, a página expirada relatada está em um banco de dados do usuário e não no TempDB.
Além disso, estamos na versão mais recente do SQL Server (2019-CU14 Enterprise), portanto, isso não deve acontecer de qualquer maneira.
Percebi que havia latência muito alta nos arquivos de dados TempDB por volta das 18h e 21h40. Não tenho certeza se está relacionado, no entanto, porque o pico de latência às 18h é maior e, no entanto, o trabalho falhou apenas por volta das 21h44.
Esses picos de latência não se correlacionam com nenhum pico nas métricas do Azure Monitor VM Cached IOPS Consumed Percentagee VM Cached Bandwidth Consumed Percentage.
Informação adicional:
- O servidor está instalado em uma VM do Azure:
Standard E8s v3 (8 vcpus, 64 GiB memory) - O banco de dados do usuário em questão (SentryOne) possui tabelas com otimização de memória.
- Os metadados com otimização de memória TempDB estão DESATIVADOS.
- A inicialização instantânea do arquivo está ATIVADA.
- Bloquear Páginas na Memória está DESATIVADO.
Alguma idéia de por que isso aconteceu e como evitá-lo no futuro?
Obrigado!
TempDB é usado com CheckDB , provavelmente havia um conjunto de itens esperando na trava (ou um único item, não posso dizer com os dados fornecidos) e houve uma ocorrência de comboio devido a algo lento (por exemplo, IO ou alocações de memória) ou houve uma única ocorrência disso.
De acordo com o seu anúncio de captura de tela, a saída do trabalho:
Isso se correlaciona muito bem, parece ser algum disco lento no momento com base nos dados disponíveis.