Azure SQL Managed Instance SQL Server 2016 Later에서 대기 통계 분석

 

·       Version : Azure SQL, SQL Server 2016 Later

 

대기 통계(Wait Statistics)는데이터베이스 엔진에서 무언가를 기다리는 쿼리를 식별하는데 도움이 되며 쿼리 지속시간이 이유를 분석할 있는 정보를 나타낸다. 이번 포스트에서는 워크로드가 대기하는 이유와 일부 리소스에서 대기중인 쿼리를 식별하는 방법에 대해서 살펴본다.

 

Azure SQL Managed Instance 사용하면 아래 DMV 사용하여 쿼리가 리소스를 대기하는 이유를 찾을 있다.

·       sys.dm_os_wait_stats : 인스턴스 레벨에서  대기 정보 반환

·       sys.query_store_wait_stats : 데이터베이스 레벨에서 대기중인 쿼리의 실행계획 반환

 

이러한 정보는 DMO/Query Store 사용하여 찾을 있다. 그러나 분석을 쉽게 하기 위해 무료 오픈소스인 QPI 라이브러리를 사용할 있다.

·       QPI  : https://github.com/JocaPC/qpi

 

QPI 라이브러리를 설치하려면 아래 링크에서 SQL Server 버전에 대한 SQL 스크립트를 다운로드 있다. Query Store 의존하기 때문에 SQL Server 2016 이상, Azure SQL 에서 가능하다.

·       QPI Installation : https://github.com/JocaPC/qpi#installation

 

sys.dm_os_wait_stats 인스턴스 시작 이후 또는 통계를 마지막으로 재설정 이후에 대기 통계를 수집하므로 대기 통계의 스냅샷을 작성하거나 최소한 재설정을 해야한다. 아래 스크립트를 실행하여 QPI에서대기 통계를 재설정 있다.

exec qpi.snapshot_wait_stats

 

절차는 인스턴스의 대기 통계를 재설정하고 관리형 인스턴스는 대기 통계를 수집을  시작한다. 워크로드가 실행되는 동안 qpi.wait_stats보기에서 대기 통계 정보를 읽을 있다. 결과를 보면 인스턴스의 기본 대기 통계는 INSTANCE_LOG_RATE_GOVERNON이며 Log Rate Governor 분류 된다. 대기 유형의 영향을 받는 쿼리를 찾으려면 실제 대기 유형 이름이 아닌 쿼리 저정소에서 Category 사용해야 하므로 Category 중요하다. 쿼리 저장소의 대기 통계는 대기 유형별로 기록되지 않는다.

 

 

대기가 발생한 Category 영향을 받는 상위 쿼리를 보려면 qpi.db_query_wait_stats 보기를 사용하여 Category 해당하는 대기 통계를 필터링 있다.

 

예제의 경우 관리형 인스턴스에서 로그 속도 제한에 도달하고 있으며, 원인은 인덱스 재구축으로 인한것일 있다. 데이터베이스가 여러개인 경우 데이터베이스마다 쿼리 저장소가 구성되므로 데이터베이스에서 쿼리를 실행해야한다.

 

 

[참고자료]

https://blogs.msdn.microsoft.com/sqlserverstorageengine/2019/03/05/analyzing-wait-statistics-on-managed-instance/

 

 

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

 

 

Azure SQL, SQL Server Managed Instance, Query Store, QPI, sys.dm_os_wait_stats, sys.query_store_wait_stats

SQL Server 2019에서 동기 통계 업데이트시 발생하는 쿼리 Blocking 확인

 

·       Version : SQL Server 2019

 

SQL Server에서 통계정보는 옵티마이저가 실행 계획을 생성할 참고하는 중요한 지표이다. 통계 자동 업데이트가  true 설정된 경우, 데이터의 변경이 특정 임계치 이상되면 자동으로 통계 정보를 업데이트 한다.

·       SQL Server Statistics : http://sqlmvp.kr/140165557766

 

이때 통계 정보를 업데이트하면서 블럭킹이 발생하는데 이전까지는 블럭킹이 발생한것에 대해서 확인할 방법이 없었다. SQL Server 2019 부터는 이러한 문제를 해결하기 위해 새로운 진단 데이터가 도입되었다. 통계 업데이트시 블럭킹을 발생하는 것을 재현하기 위해 아래와 같은 시나리오를 만들었다.

·       자동 통계 업데이트를 트리거하는  SELECT 쿼리를 실행한다.

·       동기 통계 업데이트가 실행을 시작하고 통계가 생성될때 까지 쿼리가 대기한다. (기본적으로 차단됨)

·       동기 통계 업데이트 조작이 완료 까지 쿼리 컴파일 실행이 재개되지 않는다.

시간 동안 쿼리는 동기화 통계 업데이트 작업이 완료될 까지 대기하고 있으며, 문제를 확인하기 어려웠다. 대용량 테이블또는 사용량이 많은 시스템등 통계 업데이트에 시간이 오래 걸리는 경우 원인을 쉽게 확인할 있는 방법이 없다.

 

 

SQL Server 2019에서는 동기화 통계 업데이트로 인해 쿼리가 차단되면  sys.dm_exec_requests에서‘command’컬럼에 (STATMAN) 표시된다. 그리고 통계 업데이트 작업이 완료되면 초기 명령이름으로 돌아간다.

 

또한 새로운 WAIT_ON_SYNC_STATISTICS_REFRESH 대기 유형은 동기 통계 업데이트에서 집계된 대기 시간(블럭) 측정한다. 대기시간 누적은 sys.dm_os_wait_stats 동적 관리뷰에서 확인할 있다.

 

 

[참고자료]

https://blogs.msdn.microsoft.com/sqlserverstorageengine/2018/11/13/diagnostic-data-for-synchronous-statistics-update-blocking/

 

 

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

 

 

SQL Server2019, SQL Statistics, WAIT_ON_SYNC_STATISTICS_REFRESH, sys.dm_os_wait_stats, sys.dm_exec_requests

SQL Server 2019 Log Writer Workers

 

·       Version : SQL Server 2014, SQL Server 2016, SQL Server 2017, SQL Server 2019

 

SQL Server 2017 숨겨진 스케줄러에서 최대 4개의 Log Writer Worker 활용하여 트랜잭션 로그 처리 활동을 지원한다.

 

SQL Server 2019 버전부터는 하드웨어 성능에 따라 최대 Log Writer Worker 수가  최대 8개까지 증가한다.

;with kgroups AS

(SELECT kgroup_count = COUNT(DISTINCT processor_group)

 FROM sys.dm_os_nodes osn)

SELECT SQLServer_version = SERVERPROPERTY('ProductVersion'), sinfo.scheduler_count,

       sinfo.cpu_count, sinfo.softnuma_configuration_desc, sinfo.socket_count,

    sinfo.numa_node_count, kgroups.kgroup_count

FROM sys.dm_os_sys_info sinfo

CROSS JOIN kgroups;

 

SELECT req.session_id, req.command, sch.scheduler_id, sched_status = sch.[status],

       sch.cpu_id, sch.parent_node_id, osn.memory_node_id, osn.processor_group

FROM sys.dm_exec_requests req

JOIN sys.dm_os_schedulers sch ON req.scheduler_id = sch.scheduler_id

JOIN sys.dm_os_nodes osn ON sch.parent_node_id = osn.node_id

WHERE req.command = 'LOG WRITER';

 

 

 SQL Server 서비스 시작시 시스템 리소스 상태에 따라 Log Writer Worker수를 결정하며  아래 그림은 SQL Server 2019 2Core CP, 2GM RAM에서 실행 하였을때, Log Writer Worker 수를 SQL Server Error Log에서 확인한 것이다.

 

 

여러 Log Writer Worker 허용되지 않는 경우 단일 Log Writer Worker 사용한다. 그렇지 않으면 아래 공식을 사용하여 Log Writer Worker 수를 계산한다.

·       NUMA 노드 X 2

·       NUMA 노드에서 사용사능한 CPU 계산 (affinity mask 설정에 따라 CPU 카운트에 영향을 있음)

 

MAX_LOG_WRITERS 허용에 따라 4 또는 8개가 할당 된다.

 

[참고자료]

·       https://blogs.msdn.microsoft.com/bobsql/2019/02/11/sql-server-log-writer-workers/

·       http://sql-sasquatch.blogspot.com/2019/06/sql-server-2019-ctp-30-max-number-of.html

 

 

 

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

 

 

SQL Server2017, SQL Server 2019, Log Writer Worker, 로그 쓰기 워커, NUMA, OS NODE

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

+ Recent posts