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 호출에 멈춘 경우 일반적으로 찾기 고르인 시간이 누적된다.

·       로그인이 스케줄러에 대기된 경우 로그인 실패 이벤트에 대해 또는 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



출처: https://sqlmvp.tistory.com/1342 [Database Lab]




profile

강성욱 / jevida@naver.com
Microsoft SQL Server MVP
Blog : http://sqlmvp.kr
Facebook : http://facebook.com/sqlmvp

Kakao Talk : SQLMVP

Line : jevida


현재 LA에 거주하고 있으며 SQL에 관심있는 분이면 언제든 친추 환영합니다.