SQL Server Scheduling and Yielding 트러블슈팅

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