SQL Server Login Timeout 디버깅

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