查看語句運行時間異常的原因(SQLServer)


    經常有開發同事反映如下情況:我有一條語句或者一個JOB昨天跑半個小時就完成了,今天怎么跑了兩個小時還沒有完成?

是不是數據庫出現問題了?

    數據庫語句運行時間異常,其實是一個比較復雜的情況,因為數據是不斷變動的,今天好好的一條語句,有可能明天運行就

不在預計的時間內了,這個場景是沒辦法完全重溯的,即便有當時的備份數據,但是當時的服務器壓力是沒有辦法知道和營造

的;但是好在現在不是要調查昨天語句跑時間異常的原因,而是要找到現在語句運行異常的原因,現在的情況還正在進行着呢,

所以我們可以根據語句目前的情況,初步來排查一下;

    其實要考慮的問題比較多:

    1. 索引是否正常(索引是否損壞、有沒有人刪除索引等);

    2. 統計信息是否過時;

    3. 語句執行計划是否發生偏移(和索引、統計信息以及數據量都有關系);

    4. 語句是否有bug;

    5. 是否發生的阻塞;

    6. 系統資源是否遇到瓶頸;

    .........

    這么多的情況都考慮的話我們很難下手,一般解決這個問題我們都需要采用比較快的方式來做排查,以下方法主要針對5和6兩

個方面進行,因為這兩個方面是最常見的情況。

我們來簡單模擬一下排查過程:

1. 創建測試表和數據

USE [master]
GO

/****** Object: Table [dbo].[a] Script Date: 01/17/2012 16:46:34 ******/
SET ANSI_NULLS ON
GO

SET QUOTED_IDENTIFIER ON
GO

SET ANSI_PADDING ON
GO

CREATE TABLE [dbo].[a](
[id] [int] IDENTITY(1,1) NOT NULL,
[name] [varchar](100) NULL
) ON [PRIMARY]

GO

SET ANSI_PADDING OFF
GO


insert into a values('aa'),('bb'),('cc')

2. 制造阻塞:開兩個session,分別運行下面的語句

--Session 1
use master
go
begin tran
update A set name='abc' where id=2

--rollback


--Session 2
select * from a

因為Session1 的Update語句沒有能夠提交,所以此時Session2 過程會被阻塞


3. 分析排查:

  我們首先需要查詢下此時數據庫中是否存在阻塞:

--Blocked
select * from sys.sysprocesses with(nolock) where blocked<>0


 我們看到了阻塞的記錄,53阻塞了56,被阻塞的資源是:dbid 1 file 1 page 307;

 接下來我們需要知道阻塞和被阻塞的是什么語句,有兩種方式:

 a. dbcc inputbuffer

 b. sys.dm_exec_sql_text

 方法一與方法二相比:

   優點:方法一能顯示非活動session的語句,方法二只能查活動的session(通過sp_who2 active 能顯示是否活動);

   缺點:方法一只能一個一個查詢,方法二可以多個一起查詢;

方法一:

--No1:
dbcc inputbuffer(53)
go
dbcc inputbuffer(56)

方法二:

--No2:
SELECT
S.session_id, R.blocking_session_id,
S.host_name, S.login_name,
databaseName=DB_NAME(R.database_id),R.command, R.status,
current_execute_sql = SUBSTRING(T.text,
R.statement_start_offset / 2 + 1,
CASE
WHEN statement_end_offset = -1 THEN LEN(T.text)
ELSE (R.statement_end_offset - statement_start_offset) / 2+1
END),
S.program_name,
S.status,
S.cpu_time, memory_usage_kb = S.memory_usage * 8, S.reads, S.writes,
S.transaction_isolation_level,
C.connect_time, C.last_read, C.last_write,
C.net_transport, C.client_net_address, C.client_tcp_port, C.local_tcp_port,
R.start_time,
R.wait_time, R.wait_type, R.last_wait_type, R.wait_resource,
R.open_transaction_count, R.transaction_id

FROM sys.dm_exec_sessions S
LEFT JOIN sys.dm_exec_connections C
ON S.session_id = C.session_id
LEFT JOIN sys.dm_exec_requests R
ON S.session_id = R.session_id
AND C.connection_id = R.connection_id
OUTER APPLY sys.dm_exec_sql_text(R.sql_handle) T
WHERE S.is_user_process = 1 -- 如果不限制此條件,則查詢所有進程(系統和用戶進程)
and s.session_id in(53,56)

我們看到方法一兩條語句都能查出來,而方法二只能查出一個語句;

到這里,我們已經能判斷語句運行慢的原因是被阻塞了,我們再來查查阻塞的原因是什么,可以通過以下語句查看:

select request_session_id,resource_type,db_name(resource_database_id) as DBName,resource_description,
request_mode,request_type,request_status from sys.dm_tran_locks where request_session_id in(56,53)
order by request_session_id

可以看到,56處於WAIT狀態,它在等待獲取1:307:1 上的一個共享鎖,但是1:307:1上被53的一個排他鎖占據了(GRANT代表

已獲得資源,正在運行),因此56必須等待53上的排他鎖釋放后才能繼續運行;於是我們轉而調查53排他鎖沒有釋放的原因;可能是

53需要的其他資源被其他進程占有了,在等待其他進程釋放鎖;也可能是因為Update語句更新的數據量過多,需要的時間比較長,不

能夠及時的釋放鎖;還有就是我們現在的情況,沒有提交事物了(語句中可以直接看到);阻塞的排查方法都是類似的。

 

如果語句並沒有被其他語句blocked呢? 那我們需要再進一步查找的原因就是Wait了,前面已經有wait的相關查詢,下面我們來查下

更具體的信息:

-- wait & lock
select lo.request_session_id as [Session],
DB_NAME(lo.resource_database_id) as Dbname,
lo.resource_type as [Type],
lo.resource_description,
lo.request_mode,
lo.request_owner_type,
lo.request_status,
case when lo.resource_type='OBJECT' then OBJECT_NAME(lo.resource_associated_entity_id)
when lo.resource_associated_entity_id IS NULL OR lo.resource_associated_entity_id=0
then NULL
else OBJECT_NAME(p.object_id)
end as Associated_Entity,
wt.blocking_session_id,wt.resource_description
from
sys.dm_tran_locks lo with(nolock)
left join sys.partitions p with(nolock)
on lo.resource_associated_entity_id=p.partition_id
left join sys.dm_os_waiting_tasks wt with(nolock)
on lo.lock_owner_address=wt.resource_address
where lo.request_session_id>50
and lo.request_session_id=56
order by [Session] ,[TYPE]

上面可以看到,56在獲取共享資源1:307:1時,遇到了等待,當然這里的等待還是被53阻塞了,但是等待會有多種原因的等待,我們查

一下當前的等待信息:

--current wait info
select wait_type,COUNT(0) as num_waiting_tasks,
SUM(wait_duration_ms) as total_wait_time_ms
from sys.dm_os_waiting_tasks with(nolock)
where session_id>50
group by wait_type
order by wait_type

這里可以看到是鎖等待(Wait_Type),還有很多資源類型的等待,值的重點關注的有:
  Memory:CMEMTHREAD ,RESOURCE_SEMAPHORE
     CMEMTHREAD:
       說明和原因:計划緩存出現問題的標志(大量計划加入或者移出);
       解決:     使用參數化的查詢或者設置數據庫強制參數化(forced parameterization)

     RESOURCE_SEMAPHORE:
       說明和原因:內存密集型查詢無法獲得請求的內存;其他進程消耗了太多的內存;
       解決:     為數據庫添加合適的索引或者增加內存

  IO:IO_COMPLETION,ASYNC_IO_COMPLETION,WRITELOG,PAGEIOLATCH_*

  CPU: CXPACKET,SOS_SCHEDULER_YIELD
       CXPACKET:
          說明和原因:並行處理等待類型,並行同步等待;
          解決:     可以通過修改並行度的值(或者禁用)解決;
       SOS_SCHEDULER_YIELD:
          說明和原因:任務執行到時間片尾,讓出調度器給其他任務運行;
          解決:     需要處理能力更好的CPU
 
  Network:ASYNC_NETWORK_IO,DBMIRROR_SEND
       ASYNC_NETWORK_IO: 網卡帶寬飽和或者客戶端不能及時把結果取走;
       DBMIRROR_SEND:  網絡帶寬不足以支持鏡像事務量或者鏡像數據庫超出限額;

  鎖阻塞:LCK_*    


我們可以統計下,我們數據庫最多的20種等待類型:

--total wait info
select top 20 wait_type,SUM(waiting_tasks_count) waiting_tasks_count,
SUM(wait_time_ms)as total_wait_time_ms,
SUM(signal_wait_time_ms) as total_signal_wait_time_ms
from sys.dm_os_wait_stats with(nolock)
where wait_type not in
--system wait type
('LAZYWRITER_SLEEP','REQUEST_FOR_DEADLOCK_SEARCH','SQLTRACE_BUFFER_FLUSH',
'XE_TIMER_EVENT','FT_IFTS_SCHEDULER_IDLE_WAIT','LOGMGR_QUEUE','CHECKPOINT_QUEUE',
'SLEEP_TASK','BROKER_IO_FLUSH','BROKER_TASK_STOP','BROKER_TO_FLUSH','BROKER_EVENTHANDLER')
group by wait_type
order by total_wait_time_ms desc

通過這個我們可以從中看出DB等待主要集中在哪些方面,如果是在CPU、IO、Memory、Lock等上面等待時間很長,說明我們

的數據庫需要做某些方面的優化了。

    以上就是從阻塞和等待方面,對運行時間異常的語句做初步排查的過程,歡迎大家拍磚。

 


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM