SQL Server Scheduling and Yielding 트러블슈팅

 

·         Version : SQL Server

 

SQL Server 다중 스레드및 다중 태스크 시스템으로 SQLOS라고 불리는 자체 스레드 스케줄링 메커니즘을 가지고 있다. SQLOS 대한 내용은 아래 링크를 참조 한다.

·         A new platform layer in SQL Server 2005 to exploit new hardware capabilities and their trends : https://blogs.msdn.microsoft.com/slavao/2005/07/20/platform-layer-for-sql-server

·         Inside the SQL Server 2000 User Mode Scheduler : https://msdn.microsoft.com/library/aa175393.aspx

·         How To Diagnose and Correct Errors 17883, 17884, 17887, and 17888 : https://technet.microsoft.com/en-us/library/cc917684.aspx

 

SQL  Server 소스 코드에는 다중 스레드가 효율적이고 협조적으로 실행되도록 하는 많은 자발적인 Yield포인트(한국어로 번역하기엔 적당한 용어가 없어 양보하는정도로 해석할 있다.) 있다. SQL Server작업자 스레드가 자발적으로 양보하지 않으면 동일한 스레드에서 다른 스레드가 실행되지 않을 가능성이 높다. 스케줄러의 소유자가 60 이내에 결과를 보지 못하고 보류중인 요청(작업) 지연되면 SQL Server 다음과 같이 오류는 발생하지 않지만스케줄러 오류를 기록한다.

2018-03-10 21:16:35.89 Server      ***********************************************

2018-03-10 21:16:35.89 Server      *

2018-03-10 21:16:35.89 Server      * BEGIN STACK DUMP:

2018-03-10 21:16:35.89 Server      *   03/10/18 21:16:35 spid 22548

2018-03-10 21:16:35.89 Server      *

2018-03-10 21:16:35.89 Server      * Non-yielding Scheduler

2018-03-10 21:16:35.89 Server      *

2018-03-10 21:16:35.89 Server      ***********************************************

 

SQL Server 작업자는 4ms(밀리초) 퀀텀 타임으로 동작하지만 현실적으로 스케줄링은 매우 복잡하기 때문에 자발적인 양보를 하기전에 예기치 않게 스케줄이 실행되는 곳이 있을 수도 있다. 일반적으로 이러한 행동은 thread  실행할 thread 리스트에서  기아상태(굶주린 상태) 되지 않기 때문에 문제가 되지 않는다. 아래 그림은 스케줄러와 태스크가 어떻게 스케줄링 되는지 나타낸다.

 

다음 순서는 스케줄링이 작동하는 순서이다.

1.       작업이 실행중이면 “Running” 상태

2.       작업이 대기 상태가 되면 CPU 큐에 스케줄을 “Runnable” 등록

3.       작업이 무엇인가(lock, disk I/O ) 기다리고 있을때 그것은 “Suspended” 상태로 등록

4.       일시 중단 작업의 대기가 끝나고 실행할 준비가 되면 Runnable 큐의 부분에 등록

5.       실행중의 thread 자발적인 양보로 Runnable큐의 끝으로 이동한다.

6.       실행중인 스레드가 무엇인가를 기다려야할 경우 스케줄러에서”Suspended” 상태로 전환

7.       실행중의thread 끝나면 실행 가능한 큐의 최상단에  “Running”상태로 thread 등록된다.

 

SQL Server에서는 sys.dm_os_waiting_tasks또는 sys.dm_exec_requests  DMV 사용하여 wait_time, wait_resource등과 같은 대기 관련 정보를 확인할 있다.

SELECT session_id,status,wait_time,wait_type,wait_resource,last_wait_type

FROM sys.dm_exec_requests

WHERE session_id=52

 

 

sys.dm_os_wait_stats 실행하면 신호 대기 시간을 포함하여 대기 유형에 대한 전체 대기 시간을 확인할 있다. 특히 “signal_wailt_time_ms”라는 열의 값은 스레드가 스케줄러의 “Runnable”상태로 리스트에 머문 시간으로 CPU 올라가서 다시 실행될때 까지 기다린 시간이다.  개별 세션에 대한 신호 대기 시간의 자세한 정보를 확인하려면 XEvent wait_info wait_info_external 활용할 있다. 아래 링크는 wait_info 이벤트를 사용하여 REDO 대기 시간을 추적하는 방법이다.

·         Troubleshooting REDO queue build-up (data latency issues) on AlwaysOn Readable Secondary Replicas using the WAIT_INFO Extended Event : https://blogs.msdn.microsoft.com/alwaysonpro/2015/01/06/troubleshooting-redo-queue-build-up-data-latency-issues-on-alwayson-readable-secondary-replicas-using-the-wait_info-extended-event/

 

아래 실습을 통해서 신호 대기를 확인할 있다.

1.       실습할 테이블을 tempdb 생성한다.

USE tempdb

CREATE TABLE t1 (c1 int)

 

2.       SQL Server에서 사용할  CPU수를 조정한다. (절대 실서버에서 하지 말것)

EXEC SP_CONFIGURE  'affinity mask',2 --use only the second CPU of the system

RECONFIGURE WITH OVERRIDE

 

3.       XEvent 생성하고 실행한다.

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name LIKE 'SignalWaitDemo')

DROP EVENT SESSION [SignalWaitDemo] ON SERVER

GO

CREATE EVENT SESSION [SignalWaitDemo] ON SERVER

ADD EVENT sqlos.wait_info(

    ACTION(sqlos.scheduler_id,sqlserver.database_id,sqlserver.session_id)

    --Capture End event (opcode=1) only

WHERE ([package0].[equal_uint64]([opcode],(1))

--Only capture user sessions (session_id>=50)

AND [package0].[greater_than_equal_uint64]([sqlserver].[session_id],(50))

--You can change duration to bigger value, say, change below 10 ms to 3000ms

AND [duration]>=(10)))

ADD TARGET package0.event_file(SET filename=N'E:\temp\Wait_Info_Demo.xel')

WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30  SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=OFF)

 

GO

 

 ALTER EVENT SESSION [SignalWaitDemo] ON SERVER STATE=START;

 

4.       Ostress 도구를 사용하여 작업 부하를 시뮬레이션 한다.

 ostress -n1000 -r200 -S. –isignal_wait.sql (쿼리는 아래 박스

SET NOCOUNT ON

USE tempdb

DECLARE @I int=0,@k int=0

 

BEGIN

IF(rand()>0.9)update t1 set c1=c1+10*(rand()-0.5)

DECLARE @document varchar(64); 

SELECT @document = 'Reflectors are vital safety' + 

                   ' components of your bicycle.'; 

DECLARE @j int

SET @j=CHARINDEX('bicycle', @document);

SET @j=CHARINDEX('are', @document);

SET @j=CHARINDEX('vital', @document);

SET @j=CHARINDEX('dd', @document);

SET @j=CHARINDEX('your', @document);

END

 

ostress 실행 중일때 아래 스크립트를 실행하면  실행 가능한 스레드와 일시 중단된 스레드가 많은 것을 확인할 있다. 결과를 살펴보면 suspended스레드는 runnable 스레드가 스케줄러가 실행되기를 기다리는 동안 UPDATE 잠금을 대기중인 스레드이다.

select * from sys.dm_exec_requests where session_id>50

 

 

위에서 실행중인 XEvent 추적을 멈추고 확인하면 매우 duration세션이 있는 것을 확인할 있다. 실행 가능한 대기열에 있었음을 있다.

 


지금까지의 설명은 자원 대기 시간 신호 대기 시간을 확인하는 방법에 대해서 알아보았다. 이제 스레드가 주어진 스케줄러에서 양보하지 않고 얼마나 오랫동안 실행되었는지 확인하는(비정상  스케줄러) 방법에 대해서 알아본다. 응답하지(non-yielding)않은 스케줄러 시간은 스레드가 아무런 양보(yielding)없이 스케줄러를 점유하는 시간을 의미한다. 따라서 항상 CPU  실행 시간을 의미하는것은 아니다. 스케줄러를 점유하는 스레드는 다른 어플리케이션이 시점에서 동일한 CPU 사용하는 경우 운영체제에 의해 점유 있다.대부분의 경우 SQL Server 전용으로 운영되기 때문에 이러한 상황은 일반적이지 않다. 아래 스크립트를 실행하여 yield_count  컬럼에서 yield 횟수를 확인할 있다. 주기적으로 해당 스크립트를 실행하여 델타값을 산출하였을때  yield_count 변경되지 않으면 누군가 기간동안 스케줄러에서 실행중인 것을 있다.  

select yield_count, runnable_tasks_count, * from sys.dm_os_schedulers where scheduler_id<1024

 

 

 

아래 스크립트는 yield 횟수 관련 정보를 수집하여 저장하는 스크립트이다.

USE <yourdb>

 CREATE TABLE yields

 (runtime datetime, scheduler_id bigint,yield_count bigint,runnable int, session_id int,start_time datetime,command varchar(200),database_id int)

 

 GO  

 

 SET NOCOUNT ON

 WHILE(1=1)

 BEGIN

 INSERT INTO yields

 SELECT getdate() 'runtime', a.scheduler_id, a.yield_count, runnable_tasks_count, session_id,start_time, command,database_id

 FROM sys.dm_os_schedulers a

inner join sys.dm_os_workers b on a.active_worker_address=b.worker_address

left join sys.dm_exec_requests c on c.task_address=b.task_address

--Most system has less than 1024 cores, use this to ignore those HIDDEN schedulers

WHERE a.scheduler_id<1024

 --Monitor it every 5 seconds. you can change it to meet your needs

 WAITFOR DELAY '00:00:05'

 END

 

아래 스크립트는 저장된 yield 정보를 조회한다.

DECLARE scheduler_cur CURSOR 

FOR SELECT scheduler_id from yields group by scheduler_id order by scheduler_id

OPEN scheduler_cur

DECLARE @id bigint

FETCH NEXT  FROM scheduler_cur INTO @id

WHILE (@@FETCH_STATUS=0)

BEGIN

 DECLARE delta_cur CURSOR

 FOR SELECT runtime, yield_count,scheduler_id,runnable,session_id,start_time, command,database_id

 FROM yields WHERE scheduler_id=1  ORDER BY runtime ASC

 OPEN delta_cur

 DECLARE @runtime_previous datetime,@yieldcount_previous bigint

 DECLARE @runtime datetime,@yieldcount bigint,@scheduler_id bigint,@runnable int,@session_id int,@start_time datetime,@command varchar(200),@database_id int

 

 FETCH NEXT FROM delta_cur INTO  @runtime ,@yieldcount ,@scheduler_id,@runnable ,@session_id ,@start_time,@command,@database_id

 SET @runtime_previous=@runtime;SET @yieldcount_previous=@yieldcount

 FETCH NEXT FROM delta_cur INTO  @runtime ,@yieldcount ,@scheduler_id ,@runnable,@session_id ,@start_time,@command ,@database_id 

 

 WHILE(@@FETCH_STATUS=0)

 BEGIN

--We find one non-yielding scheduler during the runtime delta

IF(@yieldcount=@yieldcount_previous)

BEGIN

PRINT 'Non-yielding Scheduler Time delta found!'

  SELECT @runtime_previous 'runtime_previous', @runtime 'runtime', datediff(second, @runtime_previous,@runtime) 'non_yielding_scheduler_time_second', @yieldcount_previous 'yieldcount_previous',

  @yieldcount 'yieldcount' ,@scheduler_id 'scheduler_id',@runnable 'runnable_tasks' ,@session_id 'session_id' ,@start_time 'start_time',

 

  @command 'command' ,@database_id  'database_id'

END

 

-- print @id

SET @runtime_previous=@runtime;SET @yieldcount_previous=@yieldcount

FETCH NEXT FROM delta_cur INTO  @runtime ,@yieldcount ,@scheduler_id,@runnable ,@session_id ,@start_time,@command ,@database_id   

 

 END

 

 CLOSE delta_cur

 DEALLOCATE delta_cur

 FETCH NEXT  FROM scheduler_cur INTO @id

 

END

CLOSE scheduler_cur

DEALLOCATE scheduler_cur

 

 

이외에 응용프그램, 호스트명과 같은 사용자 세션에 대한 자세한 정보를 확인하려면 프로파일러 XEvent 동시에 실행하여 해당 이벤트를 캡처한다음 상관 관계를 분석 있다.

 

[참고자료]

https://blogs.msdn.microsoft.com/psssql/2018/04/05/troubleshooting-sql-server-scheduling-and-yielding/

 

 

2018-07-03 / Sungwook Kang / http://sqlmvp.kr

 

SQL Server, SQLOS, SQL Scheduler, yielding, non-yielding, MS SQL, CPU scheduler, CPU Quantum

+ Recent posts