SQL Server Login Timeout 디버깅

 

·       Version : SQL Server, SQL Server Linux

 

SQL Server 2017 SQL Linux에서 로그인시 랜덤하게 연결이 실패하는 경우가있다. 이번 포스트는 SQL Server Login Timeout 발생하는 원인을 분석하기 위한 디버깅 과정을 소개한다.

 

[Report Symptoms]

·       SQL 인증 AD 기반 로그인 모두에서 무작위 연결 실패

·       서버의 원격 클라이언트 또는 sqlcmd 실행시 디렉토리(/opt/mssql-tools/bin)에서 오류가 발생

·       장애 발생시 예측 없음

·       Non-yielding 스케줄러 보고서

·       SQL Server 2017 CU10 동작이 표시되지 않음

·       SQL Server 2017 CU12 동작을 나타냄

·       서버는 많은 CPU RAM 가진Superdome 상태

 

 

[Health Session Information]

문제를 디버깅하는 방법 하나는 /var/opt/mssql/log/system_health*.xel 파일에 있는 SQL Server 상태 세션을 추적하는 것이다. SSMS (SQL Server Management Studio)에서 XEvent 상태 세션을 보고 조정할 있다.

-          실시간 데이터 시청

-          마우스 오른쪽 ->세션을 조정

-          마우스 오른쪽 -> 스크립트 세션

상태 세션에서는 여러 이벤트 유형이 포함되며, 일부 이벤트 유형에서는 시스템 상태 세션에서 노이즈를 제거하기 위한 조건자가 포함된다.

sqlclr.clr_allocation_failure

sqlclr.clr_virtual_alloc_failure

sqlos.memory_broker_ring_buffer_recorded

sqlos.memory_node_oom_ring_buffer_recorded

sqlos.process_killed

sqlos.scheduler_monitor_deadlock_ring_buffer_recorded

sqlos.scheduler_monitor_non_yielding_iocp_ring_buffer_recorded

sqlos.scheduler_monitor_non_yielding_ring_buffer_recorded

sqlos.scheduler_monitor_non_yielding_rm_ring_buffer_recorded

sqlos.scheduler_monitor_stalled_dispatcher_ring_buffer_recorded

sqlos.scheduler_monitor_system_health_ring_buffer_recorded

sqlos.wait_info

sqlos.wait_info_external

sqlserver.connectivity_ring_buffer_recorded

sqlserver.error_reported

sqlserver.security_error_ring_buffer_recorded

sqlserver.sp_server_diagnostics_component_result

sqlserver.sql_exit_invoked

sqlserver.xml_deadlock_report

 

Non-yielding, wait_info* 연결 이벤트는 문제에 필요한 정보를 제공한다. health record 보면 다음과 같은 패턴이 반복적으로 나타난다.

 

시스템 상태에 기록된 이벤트는 Non-yielding 시작, 로그인 타임아웃 종료 Non-yielding 종료를 표시한다.

 

 

[connectivity_ring_buffer_record]

connectivity_ring_buffer_record에서는 세부 정보가 표시된다.

 

연결시도가 실패하면 type=LoginTimers 레코드가 기록되어 로그인 활동에 대한 타이밍을 제공한다. total_login_time_ms = 23309 실패한 로그인 시도가 23.3초임을 표시한다. SSL 교환 시간은 낮았지만 login_trigger_and_resouce_governor_ms 값은 대부분의 시간을 소비했다. find_login_ms 이벤트는 다른 이용자였으며 login_trigger_and_resouce_governor_ms 하위이다. 아래 스크립트를 실행하여 버퍼 항목 관계를 통해서 LoginTimer 대해서 어떤 타이밍에 대한 부모 또는 자식 값인지 확인할 있다.

Select

       *

from sys.dm_os_ring_buffers

where ring_buffer_type = 'RING_BUFFER_CONNECTIVITY'

 

버퍼 xml 형식은 상위 하위 관계를 출력한다. LoginTimer  항목은 타이밍 정보를 표시한다. (전체 레코드에서 SSL, SSPI, 읽기, 쓰기 등에 대한 추가 정보가 포함됨)

<Record id="2" type="RING_BUFFER_CONNECTIVITY" time="591262106">

 

  <ConnectivityTraceRecord>

 

    <RecordType>LoginTimers</RecordType>

 

    <LoginTimersInMilliseconds>

 

      <TotalTime>23309</TotalTime>

 

      <EnqueueTime>0</EnqueueTime>

 

      <NetWritesTime>0</NetWritesTime>

 

      <NetReadsTime>0</NetReadsTime>

 

       <TriggerAndResGovTime>

 

        <TotalTime>23266</TotalTime>

 

        <FindLogin>23265</FindLogin>

 

        <LogonTriggers>0</LogonTriggers>

 

        <ExecClassifier>0</ExecClassifier>

 

        <SessionRecover>0</SessionRecover>

 

      </TriggerAndResGovTime>

 

    </LoginTimersInMilliseconds>

 

  </ConnectivityTraceRecord>

 

이름에서 있듯이 SQL Server 로그인 유효성 검사의 일부로 로그인 정보를 검색하고 필요한 경우 AD 연결한다. , 마스터에서 데이터베이스 페이지를 읽고 잠금을 획득하며 도메인 컨트롤러(DC/KDC) 호출한다.

 

 

[waint_info *]

다른 관찰은 시스템 상태 세션이 5초보다 wait_info* 이벤트를 포함하지 않는다는 것이다. 데이터베이스 읽기, 잠금 또는 선제적외부 호출을 5 이상 기다리는 경우 이벤트가 기록되었기 때문에 waint_info* 이벤트의 부족이 드러난다. 이는 데이터베이스 읽기, 잠금 또는 preemptive, 외부 호출에 문제가 발생하지 않을 것임을 의미한다.

 

 

[Network Trace]

네트워크 추적을 살펴보면 문제를 이해하는데 도움이 된다.

 

 

[Normal SQL Login, execute select @@VERSION and logout]

다음은 유요한 SQL Server 로그인의 예이다.

 

1.       ODBC CLIENT에서 LINUX SQL Server(SYN)로의 TCP 연결 설정

2.       TDS 사전 로그인 교환

3.       512 바이트 응답 (데이터베이스 컨텍스트 XXXX, 기본언어 XXXX, 테스트 크기 XXXX 사용)

4.       SQL Batch (@@VERSION 선택)

5.       FIN-TCP 연결종료 분리

 

 

[Failing Login]

다음은 실패한 SQL Server 로그인의 예이다.

1.       ODBC CLIENT에서 LINUX SQL Server(SYN) TCP 연결 설정

2.       TDS 사전 로그인 교환

3.       로그인 응답

4.       연결 끊김 상태를 유지하면서 다른 활동 없이 시간이 경과하기를 시작

5.       RST-클라이언트가 TCP연결을 재설정함(OS오류 : 10054)

가지 실패 변형이 있었지만 로그인 응답을 처리하는 가장 일반적인 대기가 발생.

 

 

[Network Layer Overloaded]

실패한 SQL Server 로그인과 달리 네트워크 계층이 오버로드 되어 SQL Server 대한 요청을 완료하지 않은 경우 네트워크 추적이 나타난다. 일반적으로 SYN 재전송이 시작된다.

 

 

[Attempting A Reproduction]

이제 패턴에 대한 아이디어를 얻었다.  문제를 재현하는 것은 문제를 추적하고 올바르게 해결되도록 하는데 도움이 된다. Ostress툴을 사용해서 재현할 있다.

"C:\Program Files\Microsoft Corporation\RMLUtils\ostress" -Usa -Pxxxxxxx  -Q"--" -Stcp:10.193.17.114 -q -n64 -r99999999 -cc:\temp\sample.ini -T146 -oc:\temp\output

 

-          Use -U and -P for SQL authentication

 

-          Use -E for AD authentication

 

-          -q ignores query results

 

-          -S target server name forcing tcp protocol

 

-          -Q with a query of --  (comment only to do nothing)

 

-          -n controls the number of threads

 

-          -r controls the number of loops for each thread

 

-          -c the control file

 

-          -T146 disable encrypted TDS

 

-          -o output location

 

설정 파일에서 DisconnectPct=100.0 설정한다. 이를 통해 ostress 연결, 쿼리 실행,연결 끊기에 대해서 -n 스레드에 대해서 -r 반복하도록 지시한다. XEvent에서  로그인 로그 아웃 이벤트를 추적하면 연결 연결 끊기 활동을 있다. 다음은 테스트가 수행하는 로그인 로그아웃 비율을 확인하기 위한 간단한 쿼리이다.

drop table #before

go

drop table #after

go

 

select * into #before

from sys.dm_os_performance_counters where counter_name in ('Logins/sec', 'Logouts/sec')

 

waitfor delay '00:00:10'

 

select * into #after       from sys.dm_os_performance_counters where counter_name in ('Logins/sec', 'Logouts/sec')

 

select b.object_name, a.cntr_value - b.cntr_value as , (a.cntr_value - b.cntr_value) / 10.0 as [Rate/sec]

       from #before b

              inner join #after a on a.counter_name = b.counter_name

 

연결 경로를 연습하는 cmd 파일 스크립트로 시작했다.

start "ostress" "C:\Program Files\Microsoft Corporation\RMLUtils\ostress" -E -Q"--" -Stcp:xxxxxxx -q -n32 -r99999999 -cc:\temp\sample.ini -T146 -oc:\temp\output

 

start "ostress" "C:\Program Files\Microsoft Corporation\RMLUtils\ostress" -E -Q"--" -Stcp:xxxxxxx -q -n32 -r99999999 -cc:\temp\sample.ini -T146 -oc:\temp\output2

 

:top

 

       sqlcmd -E -Stcp:xxxxxxx -Q"select @@VERSION"

 

       ping -n 10 xxxxxxxx

 

goto top

 

 

[Windows TCP Settings]

2TB, 144CPU 시스템에서 스트레스 수준을 높이면서 TCP 문제가 발생했다. 동안 SQL Server에서 트래픽이 발생하지 않고 갑자기 실행된 스트레스가 발생했다. 활동이 중단되는 동안, local /opt/mssql-tools/bin/sqlcmd 연결이 계속 작동했다. Linux SQL Server시스템에서 로컬로 실행되는 아래 bash 스크립트를 사용하여 원격 연결이 실패한 동안 성공적인 연결을 확인했다.

while [ 1 -gt 0 ]

 

do

 

        echo

 

        echo $(date)

 

 

 

        ./sqlcmd -Usa -Pxxxxxxx -Q"select @@VERSION" -Stcp:.

 

        sleep 2

 

done

 

Windows 클라이언트 TCP 포트가 부족하여 중단 연결 동작이 발생했다.

netsh int ipv4 show dynamicport tcp

netsh int ipv6 show dynamicport tcp

 

netsh int ipv4 set dynamicport tcp start=10000 num=50000

netsh int ipv6 set dynamicport tcp start=10000 num=50000

 

이제 네트워크 포화 상태 (재전송이 있는 SYN) 보기 시작할 까지 높은 수준의 연결 연결 끊기 작업을 시작했지만 Non-yielding 패턴은 보이지 않았다.

 

[Disrupt The Domain Controller (Keytab)]

FindLogin 도메인 컨트롤러 호출을 수행한다는 것을 알면 다음에 도메인 컨트롤러 VM 일시 중지하여 연결시간 초과로 인해 Non-yielding 발생하여 FindLogin 많이 기록되도록 하였다.  KDC/DC 쿼리 동작을 나태나는 키탭 파일(잘못된 DC 대상) 항목을 추가할 있다. 그런 다음 FindLogin에서 Linux, AD 활동을 위해 SSSD 또는 LDAP 호출하기 전에 preemptive으로 전환되지 않는 가지 코드 경로를 찾았다. SQL Server preemptive으로 전환하지 않았기 때문에 시스템 상태 로그에 wait_type * 레코드가 없다.

 

[Non-Yielding Scheduler]

Non-Yielding 문제와 관련된 주요 행동이다. 아래 다이어그램은 발생한 문제를 강조하는데 도움이 된다.

 

 

소유한 작업자가 SQL Server 스케줄러를 끄지 않고 도메인 컨트롤러를 호출(preemptive)했다. 사전 로그인 시퀀스를 통해 SQL  인증 AD 인증 작업자가 일부 생성되어 있다. 소유 작업자가 yield일때 실행 가능한 목록은 다음에 실행할 작업자를 결정하는데 사용된다. 실행 가능 목록이 스케줄러의 최대 작업자 수에 도달하면 요청이 큐에 대기된다.

KDC/DC 쿼리가 5초이상 걸리고 Scheduler Monitor(NUMA노드당 하나) non-yielding condition (BEGIN) 보고한다. SchedulerMonitor 5초마다 진행률을 확인하여 통과 횟수를 증가 시킨다. 통과 횟수가 한계(12, 60) 도달하면 non-yielding 상황이 보고된다.

테스트의 경우 non-yielding 일반적으로 5~15 동안 지속되었으며 시스템 상태 세션에서 non-yielding BEGIN END 이벤트가 브라켓 연결시간 종료 이벤트와 함께 보고되었다. 그런 다음 다양한 로그인 시간 초과가 트리거 된다. 클라이언트가 연결을 감지하면 시간 초과에 도달하면 TCP 연결을 닫기 위해 FIN 전송된다. 일반적으로 오류 10054 SQL Server 버블링-연결이 닫힌다.

·       로그인이 사전 로그인을 처리하는 중이라면 버퍼 항목에 SSL 읽기 등의 시간과 연결 끊김이 표시될 있다.

·       로그인이 DC 호출에 멈춘 경우 일반적으로 찾기 고르인 시간이 누적된다.

·       로그인이 스케줄러에 대기된 경우 로그인 실패 이벤트에 대해 1 또는 0ms 경과 시간이 표시된다. 작업자가 작업을 받을수 있을 때까지 클라이언트는 이미 10054 보냈으며 SQL Server 로그인을 처리하려고 하면 연결이 닫히고 실패한것으로 감지된다.

 

[SQL Authentication Impact]

이제 AD 인증이 어떻게 SQL 인증, 로그인 시간 초과로 이어질 있는지 있다. SQL 인증 요청이 지연된 KDC/DC 쿼리와 동일한 스케줄러에 있는 경우 리퀘스트에 영향을 준다.

 

[Other Scheduler Impacted]

코드 경로는 많은 SQL 잠금에 관여하지 않으므로 KDC/DC 쿼리를 실행하는 정지된 사용자는 일반적으로 다른 스케줄러 해당 스케줄러와 관련된 로그인에 영향을 미치지 않는다. 다른 스케줄러는 가지 방식으로 KDC/DC쿼리의 영향을 받는다.

1.       다른 스케줄러가 AD로그인을 처리하려고 시도하고 KDC/DC 쿼리가 느리면 쿼리에 동일한 동작이 발생할 있다.

2.       non-yielding 감지되면 덤프가 호출된다. 덤프는 SQL Server 프로세스를 일시 중단한다. 덤프 시간이 로그인 시간 초과를 초과하면 클라이언트가 연결을 닫고 일반적으로 SQL Server 스케줄러에서 10054 TCP 오류가 발생한다.

 

[Recap]

버그는 도메인 컨트롤러를 쿼리하기 전에 FindLogin 코드가 preemptive되지 않아 지연 로그인 시간 초과를 초래한다. 수정된 경우 KDC/DC 쿼리에서 지연이 발생한 경우 개별 AD 로그인 시도에 여전히 로그인 시간 초과가 발생하지만 다른 로그인 쿼리는 이상 영향을 받지 않는다.

 

 

[참고자료]

https://blogs.msdn.microsoft.com/bobsql/2019/02/10/sql-mysteries-sql-server-login-timeouts-a-debugging-story/

 

 

 

 

2019-09-18/ Sungwook Kang / http://sungwookkang.com

 

 

SQL Server2017, XEvent, Login TimeOut, SQL Authentication Impact, FindLogin, Non-Yielding Scheduler, SQL Login, SQL TimeOut, SQL Logout

XEvent 사용하여 Auto tuning 작업 모니터링

 

·         Version : SQL Server 2017

 

SQL Server 2017 부터 Auto tuning 기능이 도입되어 사용자 쿼리에 대해 SQL plan change regression방식으로 쿼리의 플랜이 변경되었을때 변경 사항을 감지하고 나은 플랜을 사용하도록 자동 조정한다. SQL Server 쿼리에 대해 마지막으로 성공한 플랜을 추적하고 기존의 플랜과 비교하여 마지막 실행 플랜이 좋다고 판단되는 경우 강제로 마지막 플랜으로  변경 한다. 이번 포스트에서는 XEvent  활용하여 Auto tuning 적용되어 강제로 플랜이 변경 되었을때 추적하는 방법에 대해서 알아본다.  

 

Automatic tuning process 변경된 플랜을 감지하지만 마지막으로 실행된 플랜이 기존의 플랜과 비교하여 성능 차이가 충분히 높지 않으면 마지막으로 사용된 플랜을 강제로 적용하지 않는다. Auto tuning 프로스세가 현재의 플랜과 마지막에 실행된 플랜과 비교할때XEvent qds.automatic_tuning_plan_regression_detection_check_completed 이벤트가 실행되어 추적할 있다.

CREATE EVENT SESSION [APC - plans that are not corrected] ON SERVER

 

ADD EVENT qds.automatic_tuning_plan_regression_detection_check_completed(

WHERE ((([is_regression_detected]=(1))

  AND ([is_regression_corrected]=(0)))

  AND ([option_id]=(0))))

ADD TARGET package0.event_file(SET filename=N'plans_that_are_not_corrected')

WITH (STARTUP_STATE=ON);

GO

 

ALTER EVENT SESSION [APC - plans that are not corrected] ON SERVER STATE = start;

GO

 

·         is_regression_detected : SQL Server 플랜 변경을 감지 했음을 의미

·         is_regression_corrected : 플랜이 수정 되었음을 의미

·         option_id : 항상 0 (FORCE_LAST_GOOD_PLAN SQL Server2017 첫번째 자동 튜닝 옵션임)

 

 XEvent 다른 중요한 필드는 cpu_gain으로 권장되는 플랜이 기존의 플랜을 대신하게 경우 향상되는 CPU 예상비용이10.000.000 마이크로 세컨드( 10 CPU second)보다 작으면 새로운 플랜이 강제로 적용되지 않을 있다.

 

새로운 플랜이 강제로 적용되면 Auto tuning 지속적으로 강제 적용된 플랜을 모니터링하고 성능이 저하되지 않는지 확인한다. 성능 저하가 발생하면 Query Optimized 새로운 계획을 생성할지(recompile) 기존 계획을 유지할지 결정한다. SQL Server 플랜 검증을 완료할 때마다 XEvent  qds.automatic_tuning_plan_regression_verification_check_completed  이벤트가 실행된다.

  

CREATE EVENT SESSION [APC - Reverted plan corrections] ON SERVER

 

ADD EVENT qds.automatic_tuning_plan_regression_verification_check_completed(

    WHERE ((([is_regression_detected]=(1))

      AND ([is_regression_corrected]=(1)))

      AND ([option_id]=(0))))

ADD TARGET package0.event_file(SET filename=N'reverted_plan_corrections')

WITH (STARTUP_STATE=ON);

GO

 

ALTER EVENT SESSION [APC - Reverted plan corrections] ON SERVER STATE = start;

GO

 

·         is_regression_detected : SQL Server 강제 플랜을 감지하면 1 설정

·         is_regression_corrected : SQL Server Query Optimized 새로운 계획을 만들면 1 설정됨

 

SQL Server 강제로 새로 적용된 플랜이 기존 플랜보다 좋지 않은 경우 새로운 플랜은 적용되지 않으며 데이터베이스 엔진은 컴파일과정을 통해 새로운 플랜을 생성한다.  SQL 엔진에서 강제된 플랜이 기존의 플랜보다 우수하다고 확인되면 다시 컴파일 되기 전까지 강제된 플랜이 유지 된다.

 

 

[참고자료]

·         https://docs.microsoft.com/en-us/sql/relational-databases/automatic-tuning/automatic-tuning?view=sql-server-2017

·         https://blogs.msdn.microsoft.com/sqlserverstorageengine/2017/07/18/monitoring-automatic-tuning-actions-using-xevents/

 

 

 

2018-06-19 / Sungwook Kang / http://sqlmvp.kr

 

SQL Server, MS SQL, SQL 2017, SQL Auto Tuning, Query Optimized, XEvent, Monitoring automatic tuning actions using XEvents


SQL Server 2016 쿼리 실행에 대한 스레드(오퍼레이터) 성능 통계

 

·         Version : SQL Server 2014 SP2, 2016

 

SQL Server 2016에서 쿼리 성능 문제를 해결할 참고 있는 가지 정보가 추가 되었다. 대표적인 것이 라이브 쿼리 통계 이다.

·         SQL Server 2016 라이브 쿼리 통계 : http://sqlmvp.kr/220453033961

 

하지만 아직도 많은 쿼리 성능 문제를 해결하기 위한 메트릭은 부족한 편이다. 이번에 소개하는 기능은 showplan XML을 활성화하고 쿼리를 실행하였을때 각 스레드(오퍼레이터)에서 실행한 결과를 확인할 수 있는 기능이다. 예를 들어 SQL Server2014까지는 쿼리 실행결과 행결과를 반환하지만 스캔 성능에 관해 자세한 정보를 제공하지는 않았다.

<RunTimeInformation>

    <RunTimeCountersPerThread Thread = "0"ActualRows = "8001"ActualEndOfScans = "1"ActualExecutions = "1"/>

 </ RunTimeInfo

 

SQL Server 2016 부터는 실제 행 수를 포함하여 I/O read, CPU 시간 등의 내용이 스레드 별로 표시 된다.

<RunTimeInformation>

   <RunTimeCountersPerThread Thread="0" ActualRows="8001" ActualRowsRead="10000000" Batches="0" ActualEndOfScans="1" ActualExecutions="1" ActualExecutionMode="Row" ActualElapsedms="965" ActualCPUms="965" ActualScans="1" ActualLogicalReads="26073" ActualPhysicalReads="0" ActualReadAheads="0" ActualLobLogicalReads="0" ActualLobPhysicalReads="0" ActualLobReadAheads="0" />

</RunTimeInformation>

 

퀴리가 병렬로 수행되는 경우 아래와 같이 각 스레드의 실행 내용이 표시된다.

<RunTimeInformation>

    <RunTimeCountersPerThread Thread = "6"ActualRows = "0"ActualRowsRead = "932085"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "160"ActualCPUms = "158"ActualScans = "1" 1 "ActualLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLockReadAheads ="0 "ActualLogicalReads ="0 "

    <RunTimeCountersPerThread Thread = "8"ActualRows = "0"ActualRowsRead = "886279"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "138"ActualCPUms = "137"ActualScans = "1" 1 "ActualLogicalReads ="2341 "ActualPhysicalReads ="0 "ActualReadAheads ="0 "ActualLobLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLobReadAheads ="0 "

    <RunTimeCountersPerThread Thread = "10"ActualRows = "0"ActualRowsRead = "828520"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "121"ActualCPUms = "120"ActualScans = "1" 1 "ActualLogicalReads ="2192 "ActualPhysicalReads ="0 "ActualReadAheads ="0 "ActualLobLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLobReadAheads ="0 "

    <RunTimeCountersPerThread Thread = "12"ActualRows = "0"ActualRowsRead = "932085"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "155"ActualCPUms = "155"ActualScans = "1" 1 "ActualLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLockReadAheads ="0 "ActualLogicalReads ="0 "

    <RunTimeCountersPerThread Thread = "11"ActualRows = "0"ActualRowsRead = "828520"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "133"ActualCPUms = "132"ActualScans = "1" 1 "ActualLogicalReads ="2192 "ActualPhysicalReads ="0 "ActualReadAheads ="0 "ActualLobLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLobReadAheads ="0 "

    <RunTimeCountersPerThread Thread = "9"ActualRows = "0"ActualRowsRead = "724955"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "124"ActualCPUms = "124"ActualScans = "1" 1 "ActualLogicalReads ="1918 "ActualPhysicalReads ="0 "ActualReadAheads ="0 "ActualLobLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLobReadAheads ="0 "

    <RunTimeCountersPerThread Thread = "1"ActualRows = "0"ActualRowsRead = "724955"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "121"ActualCPUms = "120"ActualScans = "1" 1 "ActualLogicalReads ="1918 "ActualPhysicalReads ="0 "ActualReadAheads ="0 "ActualLobLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLobReadAheads ="0 "

    <RunTimeCountersPerThread Thread = "7"ActualRows = "0"ActualRowsRead = "414260"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "111"ActualCPUms = "109"ActualScans = "1" 1 "ActualLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLockReadAheads ="0 "ActualLogicalReads ="0 "

    <RunTimeCountersPerThread Thread = "5"ActualRows = "0"ActualRowsRead = "1035650"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "168"ActualCPUms = "165"ActualScans = "1" 1 "ActualLogicalReads ="2740 "ActualPhysicalReads ="0 "ActualReadAheads ="0 "ActualLobLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLobReadAheads ="0 "/>

    <RunTimeCountersPerThread Thread = "4"ActualRows = "8001"ActualRowsRead = "932086"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "160"ActualCPUms = "158"ActualScans = "1" 1 "ActualLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLockReadAheads ="0 "ActualLogicalReads ="0 "

    <RunTimeCountersPerThread Thread = "2"ActualRows = "0"ActualRowsRead = "828520"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "156"ActualCPUms = "130"ActualScans = "1" 1 "ActualLogicalReads ="2192 "ActualPhysicalReads ="0 "ActualReadAheads ="0 "ActualLobLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLobReadAheads ="0 "

    <RunTimeCountersPerThread Thread = "3"ActualRows = "0"ActualRowsRead = "932085"Batches = "0"ActualEndOfScans = "1"ActualExecutionMode = " "ActualElapsedms = "159"ActualCPUms = "158"ActualScans = "1" 1 "ActualLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLockReadAheads ="0 "ActualLogicalReads ="0 "

    <RunTimeCountersPerThread Thread = "0"ActualRows = "0"Batches = "0"ActualEndOfScans = "0"ActualExecutionMode = " "ActualElapsedms = "0"ActualCPUms = "0"ActualLogicalReads = 2 "ActualPhysicalReads ="0 "ActualReadAheads ="0 "ActualLobLogicalReads ="0 "ActualLobPhysicalReads ="0 "ActualLobReadAheads ="0 "/>

 </ RunTimeInformation>

 

또한 새로운 확장이벤트(query_thread_profiler)를 도입하여 각 노드 및 스레드의 성능에 대한 통찰력을 제공한다. 아래 스크립트는 이벤트를 생성하는 예제이다.

CREATE EVENT SESSION [PerfStats_XE] ON SERVER

ADD EVENT sqlserver.query_thread_profile(

ACTION(sqlos.scheduler_id,sqlserver.database_id,sqlserver.is_system,sqlserver.plan_handle,sqlserver.query_hash_signed,sqlserver.query_plan_hash_signed,sqlserver.server_instance_name,sqlserver.session_id,sqlserver.session_nt_username,sqlserver.sql_text))

ADD TARGET package0.ring_buffer(SET max_memory=(25600))

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

 

 

 

 

[참고자료]

https://blogs.msdn.microsoft.com/sql_server_team/added-per-operator-level-performance-stats-for-query-processing/

 

 

2017-08-21 / 강성욱 / http://sqlmvp.kr

 

SQL SQL Server 2016, Live query stats, operator level performance stat, DBA, SQL Tuning, DB Tuning, xEvent, MS SQL


확장이벤트 사용시 주의사항

 

  • Version : SQL Server 2012, 2014, 2016

 

SQL Serve Extended Event (xevent, 확장이벤트)는 다양한 이슈 및 성능을 해결하기 위한 매우 좋은 도구이다. 하지만 확장이벤트는 사용방법에 따라 오버헤드가 발생하기 때문에 주의하여야 한다.

 

아래 사례는 Microsoft CSS SQL Server Engineers 공식 블로그에 게시된 내용으로 고객 사례를 바탕으로 주의점을 설명하였다. 자세한 내용은 원문을 참고 한다.

 

고객 사례는 간단한 쿼리를 실행하는데 오랜 시간이 걸리데, 덤프 및 호출 스택을 분석한 결과 xevent가 포함된 것을 확인하였고 높은 오버헤드를 일으킬 수 있는 활성화된 이벤트를 발견하였다. 확장이벤트에는 scan_start, scan_stop, wait_info등 다양한 이벤트가 매분마다 수백만 이벤트가 캡처되고 있었다. 특히 모든 이벤트에 대해 SQL_TEXT를 수집하여 높은 오버헤드를 유발 하였다. (아래 그림 참고)

 

 

 

 

위에 언급된 이벤트(scan_started, scan_stopped, wait_info)는 장시간 캡처에는 적합하지 않다. 특히 SQL_TEXT를 포함한 wait_info 캡처는 스케줄러 대기가 발생할때마다 생성되므로 매우 빈번하게 이벤트가 발생하여 이번 오버헤드의 주요 원인 이었다. 이처럼 대규모 작업에서는 SQL_TEXT를 배제하는 것이 좋다.

 

확장이벤트는 다양한 문제를 해결하는데 좋은 도구이지만 무분별한 사용은 많은 오버헤드를 발생시키므로 필터를 잘 적용하여 오버헤드가 발생하지 않도록 설정해서 사용해야 한다.

 

[참고자료]

https://blogs.msdn.microsoft.com/psssql/2016/02/24/not-every-extended-event-is-suited-for-all-situations/

 

 

2016-05-13 / 강성욱 / http://sqlmvp.kr

 

 

MS SQL, SQL Server, 확장이벤트, Xevent, Extended Event, DB 튜닝, DB 성능, DB 트러블슈팅, DB 모니터링

+ Recent posts