Buffer Latch Timeout的解析

作者: APGC DSD Team 發布時間: 2013-07-25 18:27 閱讀: 2720 次推薦: 1 原文鏈接 [收藏]

　　【問題描述】

　　我們可能會在數據庫的錯誤日志里，發現這么一條信息:

A time-out occurred while waiting for buffer latch -- type 4, bp 000000097BFDEDC0, page 1:19239, stat 0xc00009, database id: 5, allocation unit Id: 72057615247867904, task 0x0000000005E594C8 : 0, waittime 300, flags 0x1018, owning task 0x0000000000169DC8. Not continuing to wait.

　　我們的問題是，這個錯誤到底是什么含義，在什么情況下會報上面的錯誤，以及如何解決？

　　【背景介紹】

　　Latch是SQL Server內部用來同步資源訪問的一個數據結構。和操作系統的Critical Section或ReaderWriterLock類似。Latch保護了那些想保護的資源，使得訪問同步有序。比方說，當某個線程獲得某個資源的Latch的獨占使用權時候，別的線程如果也需要訪問這個Latch，則它必須等待。

　　從大的方面來講，有兩種Latch，一種叫Buffer Latch，另外一種叫I/O Latch。

　　我們先來簡短介紹一下I/O Latch。當SQL Server從硬盤上讀取一個頁時，會先在內存預留該頁的空間。并且在該預留空間的某一個位BUF_IO設為1。如果數據從硬盤讀寫完成，則該位設為0。從硬盤讀取頁的期間，其他也需要訪問該頁的線程當然要等待，等待類型為PAGEIOLATCH_SH，直到讀寫完成，BUF_IO被設為0為止。因此，如果我們看到大量PAGEIOLATCH_SH等待，則基本可以斷定問題是出在磁盤性能上面。

　　另外一種Latch則稱為Buffer Latch，用來保護內存里的數據結構，如Index, Data Pages, B樹中的Non-Leaf頁。當進程需要讀取一個內存里的數據頁時，該進程要先獲取該數據頁上的Buffer Latch。有各種類型的Latch，包括獨占Latch(PAGELATCH_EX)和共享Latch(PAGELATCH_SH)。

　　下面來演示，為什么我們需要Latch。如下圖所示，我們在頁面100上，已經存放了兩條記錄。

　　如果沒有Latch鎖的話，某進程在頁面100上，插入如下數據：INSERT VALUES(3, 300)，其結果如下：

　　這時，另外一個進程要在頁面100上，插入如下數據: INSERT VALUES(4, 400), 因為沒有Latch鎖，所以會覆蓋之前的數據。導致數據插入出問題。

　　正確的做法是，我們要在第一個線程進行操作時，加獨占Latch鎖。第二個線程必須要等待，直到第一個線程操作完成。如下圖所示:

　　開始第一條記錄插入，隨后修改m_freedata(值為141)以及Row的指針(值為126)，在此期間，第二條插入語句處于等待Latch狀態。第一條記錄插入完成后，釋放獨占Latch鎖。

　　第二條記錄開始插入，插入期間也會加獨占Latch鎖，以防止其他進程修改或讀取頁。完成后，也隨即釋放Latch鎖。最后結果如圖所示。由于有Latch鎖，所以數據的插入可以有序的進行。

　　【LATCH申請模式】

　　Latch在申請的時候有以下幾種模式，

KP – Keep Latch 保證引用的結構不能被破壞
SH – Shared Latch 讀數據頁的時候需要
UP – Update Latch 更改數據頁的時候需要
EX – Exclusive Latch 獨占模式，主要用于寫數據頁的時候需要
DT – Destroy Latch 在破壞引用的數據結構時所需要

　　下表顯示各種Latch申請的兼容模式：

　　Y表明是兼容的，如果兩個線程都去讀某頁，則他們都會去申請SH鎖，因為SH鎖是兼容的，則兩個線程都不會互相妨礙。而N表明是不兼容的，必須要等待。直到前面一個Latch被釋放為止。

　　【LATCH等待類型】

　　Latch的等待主要有三種。

Buffer (BUF) Latch 用來保護索引或數據頁，也包括PFS, GAM, SGAM和IAM數據頁，等待類型是PAGELATCH_*模式。
Non-buffer (Non-BUF) Latch 除了上述數據結構以外的其他內存結構，等待類型是LATCH_*模式。
IO Latch 保護數據從磁盤到頁面的讀寫過程，等待類型是PAGEIOLATCH_*模式。

　　我們可以查詢下面的語句了解一下具體的等待種類：

SELECT * FROM sys.dm_os_wait_stats WHERE wait_type like '%Latch%'

　　【信息解讀】

　　下面我們來解讀這段信息。

A time-out occurred while waiting for buffer latch -- type 4, bp 000000097BFDEDC0, page 1:19239, stat 0xc00009, database id: 5, allocation unit Id: 72057615247867904, task 0x0000000005E594C8 : 0, waittime 300, flags 0x1018, owning task 0x0000000000169DC8. Not continuing to wait.

　　這里，type 4 是等待的類型。通過下面的查詢，我們可以知道, type為4的Latch是EX模式。

SELECT * FROM sys.dm_xe_map_values where name = 'latch_mode'

　　bp 則是BUF結構的指針，如果沒有內存轉儲，我們沒有辦法通過這個指針獲取更有用的信息。Page (1:19239)則是等待的頁編號。Stat 0xc00009則是BUF結構的位信息。其中的0x000004位則是我們上面提到的BUF_IO位。0xc00009 & 0x000004 = 0, 說明該頁已經完全導入到內存里的BUF結構里了。Allocation unit id則是相對應的分配單元。一個數據庫的表可以有多個分配單元，通常分配單元的個數和這個表的索引個數相同。

　　使用以下一些列查詢，我們可以通過Allocation Unit ID得到其對應的表名。(當然我們也可以通過Page的具體信息來獲得表名，用DBCC PAGE命令)

--結果中的container_id就是partition_id。

SELECT * FROM sys.allocation_units where allocation_unit_id=’72057615247867904’

--得到object_id

SELECT * FROM sys.partitions where partition_id = xxxx

--得到name

SELECT * FROM sys.objects where object_id = yyyy

　　Waittime為300，單位是秒，也就是說，我們申請在頁(1:19239)上的一個獨占的Latch鎖，但是申請了300秒(5分鐘)，還是沒申請到。

　　這里flags用來判斷該latch是否是superLatch，對于分析latch等待用處不大，所以我們不進一步具體分析。

　　Task地址和owning task地址在內存轉儲分析中，非常重要。尤其是owning task, 是這個task阻塞了別的進程獲得Latch鎖。

　　【如何解決】

　　Latch申請不到，是由于被其他進程占用的緣故。所以我們需要找到哪個進程占用該Latch一直不釋放。然后采取相應的辦法進行解決。通常來講，都是由于磁盤性能所造成的，如果需要得知確切的原因，我們可能需要對內存轉儲進行分析。對于第一個Latch Timeout的錯誤，SQL Server會產生一個內存轉儲。而對于后續的Latch Timeout，則會在SQL Server的錯誤日志里，報告一個錯誤信息，但不會產生內存轉儲。如果要改變這個行為，即要求每次碰到Latch Timeout,都要生成一個內存轉儲，我們可以用traceflag 838，如下面的命令：

dbcc traceon(838, -1)

　　由于生成內存轉儲需要一點時間，有可能在生成內存轉儲的時候，Latch等待現象消失，在內存轉儲中，沒有足夠的信息。因此，我們可能要多次抓取內存轉儲，以對問題進行分析。

　　【案例分析】

　　下面是一個案例分析。我們在數據庫的錯誤日志里，發現有下面的錯誤，并且產生了一個內存轉儲。

A time-out occurred while waiting for buffer latch -- type 2, bp 0000000088FBFA40, page 1:153568, stat 0xc0010b, database id: 10, allocation unit Id: 72057594047758336, task 0x000000000C8E2988 : 0, waittime 300, flags 0x1a, owning task 0x0000000005A2F048. Not continuing to wait.

　　下面是對內存轉儲的的分析，為了簡單起見，不相關的調用堆棧被省略。我們可以看到，下面的這個進程在獲取Buffer Latch的時候，由于無法及時得到Latch鎖，產生了上述錯誤信息，并生成一個內存轉儲。

0a 00000026`ebe09350 00000000`0215d1b8 sqlservr!CDmpDump::Dump+0x7c

0b 00000026`ebe093a0 00000000`0215dd0c sqlservr!SQLDumperLibraryInvoke+0x1a0

0c 00000026`ebe093d0 00000000`021503f7 sqlservr!CImageHelper::DoMiniDump+0x3d4

0d 00000026`ebe095d0 00000000`0206af82 sqlservr!stackTrace+0x82b

0e 00000026`ebe0ab20 00000000`02069f69 sqlservr!LatchBase::DumpOnTimeoutIfNeeded+0x19a

0f 00000026`ebe0abf0 00000000`008e7bcc sqlservr!LatchBase::PrintWarning+0x205

10 00000026`ebe0ace0 00000000`000e7a29 sqlservr!LatchBase::Suspend+0xd12

11 00000026`ebe0b950 00000000`000a0689 sqlservr!LatchBase::AcquireInternal+0x1ff

12 00000026`ebe0b9f0 00000000`000a1792 sqlservr!BUF::AcquireLatch+0x8d

13 00000026`ebe0bd10 00000000`000a166c sqlservr!BPool::Get+0xc7

14 00000026`ebe0bd70 00000000`000a35a0 sqlservr!PageRef::Fix+0xbc

15 00000026`ebe0bdd0 00000000`000a320a sqlservr!BTreeMgr::Seek+0x44d

16 00000026`ebe0bff0 00000000`000a2e5d sqlservr!BTreeMgr::GetHPageIdWithKey+0x20a

17 00000026`ebe0c070 00000000`000a38e8 sqlservr!IndexPageManager::GetPageWithKey+0xbd

　　這時，錯誤信息中的owning task地址0x0000000005A2F048對于問題的分析就很重要了。我們通過owning task的地址，結合內存轉儲分析，可以找到對應于該owning task的進程編號。其調用堆棧如下:

0:175> kM

# Child-SP RetAddr Call Site

00 00000026`f027fa68 000007fe`fcd910dc ntdll!ZwWaitForSingleObject+0xa

01 00000026`f027fa70 00000000`00083b1a KERNELBASE!WaitForSingleObjectEx+0x79

02 00000026`f027fb10 00000000`00082d76 sqlservr!SOS_Scheduler::SwitchContext+0x26d

03 00000026`f027ffa0 00000000`00082700 sqlservr!SOS_Scheduler::SuspendNonPreemptive+0xca

04 00000026`f027ffe0 00000000`000829ac sqlservr!SOS_Scheduler::Suspend+0x2d

05 00000026`f0280010 00000000`000e7e46 sqlservr!EventInternal<Spinlock<153,1,0> >::Wait+0x1a8

06 00000026`f0280060 00000000`000e7a29 sqlservr!LatchBase::Suspend+0x599

07 00000026`f0280cd0 00000000`00645aac sqlservr!LatchBase::AcquireInternal+0x1ff

08 00000026`f0280d70 00000000`00646a49 sqlservr!SQLServerLogMgr::GrowAFile+0x7c

09 00000026`f0281150 00000000`000cb38b sqlservr!SQLServerLogMgr::ReserveAndAppend+0x1fb

0a 00000026`f0281290 00000000`000cbe89 sqlservr!XdesRMReadWrite::GenerateLogRec+0x567

0b 00000026`f02813d0 00000000`000cbc23 sqlservr!XdesRMReadWrite::LogBeginXact+0x243

0c 00000026`f0281530 00000000`000cbc3f sqlservr!XdesRMReadWrite::MakeActive+0x64

0d 00000026`f0281560 00000000`001746c1 sqlservr!XdesRMReadWrite::GenerateLogRec+0x87

0e 00000026`f02816a0 00000000`00174860 sqlservr!PageRef::ModifyRow+0xce0

0f 00000026`f02818f0 00000000`00176749 sqlservr!PageRef::ModifyColumnsInternal+0x1b3

10 00000026`f0281b50 00000000`00175f71 sqlservr!IndexPageRef::Modify+0x2fd3

　　上面的調用堆棧顯示，這是在增長數據庫日志文件。由于數據庫日志無法及時增長完成，因此導致了這個線程長時間擁有Latch鎖而不釋放，而其他進程無法及時獲取相應的Latch鎖。但查看該日志文件的增長設定，每次增長為300M。并不是以百分比增長。似乎沒有什么大的問題。

　　進一步查看數據庫的錯誤日志，在發生該警告之前，SQL Server已經有相關的磁盤性能警告：

SQL Server has encountered 18 occurrence(s) of I/O requests taking longer than 15 seconds to complete on file [F:\sqldata\logs\xxxx_log.ldf] in database [xxxx] (10). The OS file handle is 0x0000000000000A2C. The offset of the latest long I/O is: 0x000004e6511e00

　　通過收集磁盤性能信息，我們發現，在出問題的點上，Avg. Disk sec/Read達到了1.444. 通常這個值在0.03左右比較正常。而1.444這個值顯然偏差非常大。