데이터베이스 개발자 Tip & 강좌

SQLER의 개발자들이 만들어가는 데이터베이스 사용자 Tip & 강좌 게시판입니다. SQL서버, Oracle, MySQL 등 여러 클라우드/오픈소스 기반 데이터베이스 개발 및 운영 관련 팁과 쿼리 노하우를 이곳에서 가장 먼저 접하실 수 있습니다. 많은 도움 되시길 바랍니다.

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]
No. Subject Author Date Views
2190 Azure에서 제공하는 데이터베이스 서비스 종류, AWS 및 GCP와 제품 비교 코난(김대우) 2020.12.25 277
2189 SQL Server 트랜잭션 로그 복원시 복원 시간이 오래 걸리는 현상 jevida(강성욱) 2020.02.28 1305
2188 SQL Server 2019 temp table을 사용한 워크로드에서 recompile 감소 jevida(강성욱) 2019.09.24 1637
2187 Azure SQL Managed Instance 및 SQL Server 2016 Later에서 대기 통계 분석 jevida(강성욱) 2019.09.24 1239
2186 SQL Server 2019에서 동기 통계 업데이트시 발생하는 쿼리 Blocking 확인 jevida(강성욱) 2019.09.21 1200
2185 SQL Server 2019 Log Writer Workers jevida(강성욱) 2019.09.21 1390
» SQL Server Login Timeout 디버깅 jevida(강성욱) 2019.09.19 1777
2183 SQL Server Worker Thread 기본 계산 jevida(강성욱) 2019.09.18 1305
2182 SQL Linux의 fsync 및 버퍼된 IO (버퍼된 쓰기중 오류가 발생하였을때 파일은 유효할까?) jevida(강성욱) 2019.09.17 1202
2181 SQL Server와 SQL Linux에서 인스턴스 파일 초기화 차이점 jevida(강성욱) 2019.09.14 1225
2180 BCP 실행시 동일 세션에서 여러개의 BULK INSERT 문으로 표시되는 이유 jevida(강성욱) 2019.09.13 1311
2179 삭제된 AD 그룹 계정으로 SQL Server 로그인 사례 (로그인 그룹 삭제 후 조치해야할 사항) jevida(강성욱) 2019.09.12 1114
2178 QPI(Query Performance Insights) 라이브러리를 사용하여 Azure SQL Managed Instance의 로그쓰기 사용량 확인 jevida(강성욱) 2019.09.11 1013
2177 ODBC 드라이버를 사용하여 SQL Server에서 Azure CosmosDB 쿼리 실행 jevida(강성욱) 2019.09.10 1075
2176 Azure SQL Managed Instance에서 로컬 스토리지 사용량 모니터링 jevida(강성욱) 2019.09.09 1090
2175 SQL Server Enterprise Edition 에서 CPU를 40 Core 이상 사용하지 못하는 현상 jevida(강성욱) 2019.09.04 1227
2174 SQL Server Agent Job에서 sysploicy_purge_history 작업실패 jevida(강성욱) 2019.09.04 1265
2173 where절 case관련... BGT051 2019.09.03 1318
2172 SQL Server에서 테이블 이름을 변경하지 않고 테이터만 교체하기 jevida(강성욱) 2019.05.03 1887
2171 SQL Server master 데이터베이스 정리 jevida(강성욱) 2019.04.23 4714





XE Login