[Ntdebugging]Event ID 2021, 2022가 기록된 서버 행

"이 문서는 http://blogs.msdn.com/ntdebugging blog 의 번역이며 원래의 자료가 통보 없이 변경될 수 있습니다. 이 자료는 법률적 보증이 없으며 의견을 주시기 위해 원래의 blog 를 방문하실 수 있습니다. (http://blogs.msdn.com/ntdebugging/archive/2007/06/19/server-hangs-with-event-id-2021-and-2022.aspx)

Event ID 2021, 2022 가 기록된 서버 행

안녕하세요. 저는 CPR 팀에서 일하고 있는 Tate 입니다. Server Service hang 증상과 가끔 두려움의 대상이 되는 Event ID: 2021 과 Event ID: 2022 에 대해서 설명 드리도록 하겠습니다. 두 이벤트에 대해 분석하는데 두려움을 가질 필요는 없고 적절한 방법으로 빠르게 디버그 할 수 있습니다.

이전에 일반적인 Server Service Event 2019 와 2020 에 대해서 말씀 드린 적이 있습니다. (Event ID: 20xx 는 Srv.sys 의 Event를 나타냅니다.) 또한, 지금부터 Server Service를 SRV 라고 하도록 하겠습니다.

이전에 이 이벤트들을 본적이 있다면 웹에서 아이디를 찾아 보았을 것이고 KB317249를 보았을 것 입니다. (이 문서는 오래된 것이지만 좋은 문서 입니다.)하지만 이 문서가 굉장히 방대하다는 것이 문제 입니다. 이 문서는 다양한 원인에 대해 설명되어 있고 또한 SRV의 동작을 이해할 수 있습니다. 그러나 실제로는 이중 몇 가지 문제만이 있을 뿐 입니다.

1) I/O 스택에서 블럭되어 일반적인 양의 SMB 요청이 적절한 시간에 처리되는 것을 막을 때 (이것이 가장 일반적인 것으로 SMB 처리가 실패하는 케이스 입니다.)

2) SRV에게 비정상적인 많은 요청이 전달될 때 (요청을 많이 하는 SMB 응용프로그램 또는 ChangeNotify 요청이 누적 될 때)

문제 발생시 이 두 가지 중 어떤 경우인지 확인하는 방법을 알려 드릴 것 입니다. 하지만 먼저 이벤트 메시지를 확인해 보도록 하겠습니다.

Event ID: 2022
Source: Srv
Description: Server was unable to find a free connection
n times in the last s seconds.

Event ID: 2021
Source: Srv
Description: Server was unable to create a work item %2 times in the last %3 seconds.

 

어떤 의미 인지?

먼저 Connection 과 Work Item에 대해서 설명 하겠습니다. 이 것들은 SRV에서 내부적으로 사용하는 구조체로 SRV에 대한 컨넥션과 워크아이템을 나타냅니다. 이해가 되시나요? SRV에 요청이 들어올 때 어떤 곳으로부터 요청이 들어왔는지, 하려는 작업이 무엇인지 그리고 어떻게 응답을 할 수 있는지 알기 위해 엔드포인트, 컨넥션, 워크아이템 그리고 다른 구조체들이 사용됩니다.

SRV의 핵심 내용으로 커널 모드 드라이버에서 SMB를 처리하는 것 입니다. 네트워크 SMB/CIFS 요청을 받아 로컬I/O로 변환한 후 처리하고 클라이언트에 돌려 줍니다. 하지만 문제는 I/O를 처리하는 도중 “찾을 수 없다” 또는 “생성할 수 없다” 라는 에러가 발생하는 것 입니다.

먼저 저장소에 대해 확인해 보도록 하겠습니다. 커널 메모리가 해제되지 않은 경우 다시 말하면 이전 블로그에서 이야기 한 것과 같이 커널 풀이 사용할 수 있는 메모리를 모두 사용하였거나 SRV의 제한( KB317249 에서 MaxWorkItems 확인)까지 사용하였을 경우가 있습니다. 이 두 가지 제한 중 하나라도 충족되면 이벤트가 기록 됩니다. 이전에 배운 것과 같이 페이지드 풀 또는 넌 페이지드 풀이 부족할 경우 행이 발생할 수 있고 SRV가 메모리를 할당할 수 없다는 이벤트를 기록할 수 있습니다. (Event ID: 2019 2020 블로그를 확인하여 정보와 해결 방법을 확인할 수 있습니다.) 워크아이템과 관련되어 블럭 되어 있거나 높은 부하가 걸릴 경우 EventID:2019, 2020 … 이 기록될 경우 어떤 일이 있을까요?( 풀을 많이 소모한 태그로 LSwn – LanmanWerverWorkItmes 가 기록될 경우) 이벤트 2021, 2022가 기록되는 것을 볼 수 있습니다. Event ID 2021, 2022가 SRV에서 기록될 경우 SRV가 커널 메모리 풀을 지나치게 사용하였는지 확인해 봐야 합니다.

 

KB317249 의 내용과 같이 \LanmanServer 의 모드 제한을 최대로 늘린다면 문제가 해결될까요?

문제가 발생할 때 얼마나 많이 블록 되어 있는지 그리고 얼마나 많은 부하가 걸리는지에 따라 해결될 수도 있고 아닐 수 도 있습니다. 만일 서버가 정상 상태가 된 후 이 문제를 확인하였다면 이미 문제의 증상이 사라진 후로 이 내용 만으로 문제가 해결되지 않고 추가 작업이 필요 할 것 입니다. 명심할 것은 이 문서에서 하는 것과 같이 레지스트리를 변경하여 최대 값까지 설정하면 풀 메모리의 사용이 최대치까지 늘어나는 시간이 빨라질 것 입니다. KB317249에 있는 값은 높지 않은 값으로 문제를 일으키지 않을 것 입니다. 하지만 문제를 완전히 해결해 주지도 않을 것 입니다. 또한 충분히 이해를 하기 전에 값을 변경하는 것을 원치 않는다면 계속 이 문서를 읽어 주십시오.

 

Event ID: 2021, 2020의 원인 #1

위에서 늘린다 라고 이야기 한 것은 Srv!WorkerThread 와 KQUEUE 구조 입니다. 요청이 들어올 때 상상하시는 것과 같이 KeInsertQueue를 사용해서 KQUEUEs 에 넣습니다. 이 큐를 처리하고 비우는 것은 Srv!WorkerThread(s) 에서 KeRemoveQueue 를 호출하는 것 입니다. 이 스레드들은 SRV 의 핵심이고 SMB 처리에서 멈추게 되는 원인이어서 해답을 찾기 위해 이 부분을 살펴 봅니다.

SRV 를 확인하기 위해 문제가 발생하였을 때 KB244139를 통해서 커널 메모리 덤프를 수집하거나 livekd(Sysinternals) 를 사용할 수 있습니다. 하지만 최선의 방법은 KB244139 나 커널 디버거를 사용하는 것 입니다. 덤프를 수집하기에 최적의 시간은 서버가 네트워크(SMB)에 응답하지 못하거나 2021/2022 이벤트가 계속 기록되고 있거나 장비가 이 이벤트 들이 기록된 후 멈춘 상태 입니다.

 

Memory.dmp 를 로드한 후 system 프로세스의 EPROCESS 구조체를 !process 0 0 system 명령을 통해 구할 수 있습니다.

0: kd> !process 0 0 system

PROCESS 89067520 SessionId: 0 Cid: 0008 Peb: 00000000 ParentCid: 0000

DirBase: 00030000 ObjectTable: 89067008 TableSize: 490.

Image: System

 

얻은 주소를 사용해서 .process /r /p <system EPROCESS 주소> 를 사용해서 프로세스 컨텍스트를 변경 합니다.

0: kd> .process /r /p 89067520

Implicit process is now 89067520

Loading User Symbols

 

!process <system EPROCESS 주소> 를 사용해서 모든 시스템 스레드를 출력 합니다.

0: kd> !process 89067520

PROCESS 89067520 SessionId: 0 Cid: 0008 Peb: 00000000 ParentCid: 0000

DirBase: 00030000 ObjectTable: 89067008 TableSize: 490.

Image: System

.

.

Dumping out the threads…

.

.

 

출력이 끝난 후 아래에서 위로 “Start Address srv!WorkerThread” 를 스택에서 검색 합니다.

참고 : Windows 2003 의 경우 “!stacks 2 Srv!WorkerThread” 명령으로 .process 명령을 사용하지 않고도 쉽게 결과를 얻을 수 있습니다.

 

요청이 들어오기를 KeRemoveQueue를 사용해서 기다리고 있는 “정상적인 스레드”가 있습니다.

THREAD 887c14e0 Cid 8.474 Teb: 00000000 Win32Thread: 00000000 WAIT: (WrEventPairLow) KernelMode Non-Alertable

be9fd324 Unknown

Not impersonating

Owning Process 89067520

Wait Start TickCount 160832116 Elapsed Ticks: 203335

Context Switch Count 134294

UserTime 0:00:00.0000

KernelTime 0:00:09.0343

Start Address srv!WorkerThread (0xbea06880)

Stack Init beb11000 Current beb10d3c Base beb11000 Limit beb0e000 Call 0

Priority 10 BasePriority 9 PriorityDecrement 0 DecrementCount 0

ChildEBP RetAddr Args to Child

beb10d54 8042ef5f 88a10eb8 be9fd320 00000001 nt!KiSwapThread+0x1b1

beb10d78 bea068ec 00000000 00000000 00000000 nt!KeRemoveQueue+0x197

beb10da8 804578c2 be9fd300 00000000 00000000 srv!WorkerThread+0x6c

beb10ddc 8046c966 bea06880 be9fd320 00000000 nt!PspSystemThreadStartup+0x54

00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

 

“비 정상적인 스레드” 는 어떻게 보일까요?

FindFirst SMB 를 처리 하기 위해 멈추어 있는 Srv!WorkerThread 를 가 아래에 있습니다.

THREAD 887dd4e0 Cid 8.45c Teb: 00000000 Win32Thread: 00000000 WAIT: (UserRequest) KernelMode Non-Alertable

88255db8 SynchronizationEvent

IRP List:

86941288: (0006,01fc) Flags: 00000884 Mdl: 00000000

Impersonation token: e5d56990 (Level Impersonation)

Owning Process 89067520

Wait Start TickCount 160783273 Elapsed Ticks: 252178

참고 : 이 스레드의 Tick 개수를 보면 오랫동안 기다리고 있는 좋지 않은 상태임을 알 수 있습니다.

 

Context Switch Count 12993

UserTime 0:00:00.0000

KernelTime 0:00:00.0843

Start Address srv!WorkerThread (0xbea06880)

Stack Init bec29000 Current bec284f4 Base bec29000 Limit bec26000 Call 0

Priority 10 BasePriority 9 PriorityDecrement 0 DecrementCount 0

ChildEBP RetAddr Args to Child

bec2850c 8042d893 00000000 882549c8 00000000 nt!KiSwapThread+0x1b1

bec28534 f5ae3408 88255db8 00000006 00000000 nt!KeWaitForSingleObject+0x1a3

bec285bc f5ae4066 bec285e4 00000000 00000000 SomeFiltr+0x3408<<<<<<<이 코드가 멈추게 한 것으로 보입니다.…

bec285fc f5ae19fb 884ce3a0 01941288 8041eecb SomeFiltr+0x4066

bec287a4 804c4994 884ce3a0 00000000 bec28894 SomeFiltr+0x19fb

bec287dc 804531c2 884766c8 00000000 bec28894 nt!IopParseFile+0x44

bec28854 804da4d8 0000051c bec28950 00000040 nt!ObpLookupObjectName+0xf8

bec28964 804a4495 00000000 00000000 00000000 nt!ObOpenObjectByName+0xc8

bec28a40 804a403a 8690d008 00000001 bec28b4c nt!IopCreateFile+0x407

bec28a88 bea0282c 8690d008 00000001 bec28b4c nt!IoCreateFile+0x36

bec28af8 bea050f6 88a0d2f8 8690d008 00000001 srv!SrvIoCreateFile+0x32a

bec28b8c bea0acdb 88a0d2f8 00000001 8046b000 srv!SrvQueryDirectoryFile+0x1c8

bec28c5c bea0936d 88a0d2f8 00000001 00000000 srv!SrvFind2Loop+0x171

bec28cd0 bea07d2f 88a0d201 bea0a9c8 88a0d2f8 srv!DoFindFirst2+0x373

bec28cd8 bea0a9c8 88a0d2f8 88a0d2f8 804636f0 srv!SrvSmbFindFirst2+0x31

bec28cf0 bea089b7 88994f38 88a0d2f8 00000000 srv!ExecuteTransaction+0xdc

bec28d68 be9f27ae 88a0d2f8 be9f2cde 88a0d300 srv!SrvSmbTransaction+0x5af

bec28d70 be9f2cde 88a0d300 88a144a0 bec28da8 srv!SrvProcessSmb+0x46

bec28d84 bea069a9 00000000 00000000 00000000 srv!SrvRestartReceive+0xa2

bec28da8 804578c2 88a14400 00000000 00000000 srv!WorkerThread+0x129

bec28ddc 8046c966 bea06880 88a144a0 00000000 nt!PspSystemThreadStartup+0x54

00000000 00000000 00000000 00000000 00000000 nt!KiThreadStartup+0x16

참고 : Tick count(Elapsed Ticks) 는 이전의 정상 상태의 Thread 보다 나빠 보이지는 않습니다. KeRemoveQuueu 에서 오랜 시간 대기 하면서 요청이 오기를 기다렸기 때문 입니다. 이 Queue 에 작업이 없다는 것은 문제가 아닙니다. 하지만 이 비 정상적인 스레드는 작업이 처리 되는 것을 오랜 시간 동안 막고 (1시간 5분) 있습니다.

무엇이 잘못되었는가?

Srv!WorkerThread 가 작업 스레드로 KQUEUE에 들어있는 작업을 비우는 역할을 하고 작업 스레드의 개수가 제한 적이라면 문제가 발생 합니다. 많은 요청이 srv로 들어오는 경우 다양한 트렌스포트 레이어 이벤트 핸들러가 KQUEUE 에 작업을 등록할 것 입니다. 하지만 작업을 처리할 작업 스레드가 없다면 (컨넥션과 작업이 풀에 저장되어 있고 풀 또한 한계가 있습니다.) 작업이 처리되지 않아 이벤트가 기록됩니다. KB317249 에서 이야기 하는 것과 같이 레지스트리를 수정하여 SRV, 넌 페이지드 풀등의 문제에서 벗어날 수 없습니다. 이 상태에서는 클라이언트에 정상적으로 응답을 할 수 없습니다.

 

만약 정상과 비 정상 스레드가 !process 명령의 결과에서 같이 보인다면?

두 개의 요청이 처리되고 있다고 할 수 있습니다. 블록 되어있는 큐와 블록되어 있지 않은 큐가 있고 KeRemoveQueue 를 호출하여 대기하고 있는 정상 스레드와 CreateFile, Find 등과 같은 요청에서 멈추어 있는 비 정상적인 스레드를 볼 수 있을 것 입니다. 일반적으로 Srv!WorkerThread 가 블록 되어 있고 KeRemoveQueue 가 오랜 시간 지연되었다면 비 정상 입니다.

해결방법은 무엇인가요?

SomeFiltr.sys 에 블록되어 있는 비 정상 스레드를 보면 필터 드라이버가 KeWaitForSingleObject를 호출하여 블록된 것을 볼 수 있습니다. 클라이언트가 FindFirst 요청을 하였으나 Srv!WorkerThread 에서 필터 드라이버가 어떠한 작업을 하기 위해 멈추었으므로 필터 드라이버에서 원인을 찾아야 합니다.

지금까지 설명한 것은 첫 번째 블록 문제로 Srv!WorkerThread 에서 오랜 시간 블록 되어 있는 것은 나쁜 결과를 가져올 수 있다는 것입니다. I/O 스택에 있는 어떠한 필터 또는 다바이스 드라이버가 다른 작업을 위해 멈추어 있다면 Srv 가 다른 모듈에 의존적인 문제가 발생할 수 있다는 것을 볼 수 있습니다.

다른 트릭은 다른 스레드 스택을 모두 확인하여 필터 드라이버 이름이 있는지 확인한 후 다른 커널 API 나 필터 등을 기다리고 있는지 확인하여 다른 것에 의해 블록 되어 있는 것인지 확인할 수 있습니다. 일반적인 경우 LSASS 에 LPC 를 사용하여 보안 확인 과정에 멈추어 있는 경우도 있습니다.

블록을 하고 있는 SomeFiltr.sys 를 확인할 수는 없고 다른 스택에서는 이 드라이버를 찾을 수 없다면 이 드라이버를 업데이트 하거나 제거 또는 SomeFilter.sys 를 만든 제작사에 연락하여 문제를 수정하도록 할 수 있습니다. “lmvm SomeFiltr.sys” 명령을 사용하여 시간/날짜 정보를 얻을 수 있습니다.

만약 모든 스레드가 정상 스레드 상태로 대기하고 있다면?

불행하게도 하나의 덤프만으로 문제를 찾을 수 없습니다. Ctrl+Scroll+Scroll 을 누르는 순간(Keyboard 로 덤프를 만드는 것) Srv!WorkerThread 의 블록이 풀릴 수 있습니다. 일시적으로 블록되는 문제에서는 무엇을 할 수 있을까요? 아니면 어 srv의 어떤 스택을 확인해야 할 까요?(아래 devstack 을 확인). 일반적으로 어떠한 필터 드라이버가 동작중인지 확인하고 해결방법 1과 같이 업데이트가 일반적으로 답이 될 수 있습니다. 일반적으로 동일 문제를 제작사에서 확인한 수 최신 버전에서 수정했을 수 있습니다.

그래서 디버깅을 하기 전에 필터 드라이버 업데이트를 요청하는 이유는 많은 경우 원인으로 확인 되었기 때문 입니다.

Srv.sys I/O를처리하는디바이스스택에서어떻게문제의필터드라이버를확인할수있을까요 ?

잘못된 스레드에 나열되어 있는 IRP들을 기억하십니까?

확인해 보면

0: kd> !irp 86941288

Irp is active with 11 stacks 11 is current (= 0x86941460)

No Mdl Thread 887dd4e0: Irp stack trace.

cmd flg cl Device File Completion-Context

[ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

[ 0, 0] 0 0 00000000 00000000 00000000-00000000

Args: 00000000 00000000 00000000 00000000

>[ 0, 0] 1 0 884ce3a0 878977a8 00000000-00000000

\FileSystem\SomeFitr

Args: bec28778 01000000 00070000 00000000

SomeFitr 로부터 Device Object 를 얻을 수 있습니다.

 

0: kd> !devstack 884ce3a0

!DevObj !DrvObj !DevExt ObjectName

> 884ce3a0 \FileSystem\SomeFiltr884ce458

88ba5c80 \Driver\InnocentDriver 88ba5d38

88ba5460 \FileSystem\Ntfs 88ba5518

이제는 어떻게 동작하는지 확인할 수 있습니다. Ntfs는 InnocentDriver 과 통신하고 이것은 다시 SomeFiltr 과 통신 합니다. 모든 드라이버 들이 정상적으로 동작 하여야 srv에 영향을 주지 않습니다.

 

IRP 를 모른다면… 문제 업습니다. 모든 행은 Ntfs를 가지고 확인하면 됩니다.

0: kd> !drvobj \FileSystem\Ntfs  <<<<!drvobj 명령으로 드라이버 오브젝트 확인

Driver object (88dd2710) is for:

\FileSystem\Ntfs

Driver Extension List: (id , addr)

Device Object list:

882b4120 8717a620  88b91800  88b981e0

88b9e600  88ba5460  88f583e0  88dd25f0

0: kd> !devstack 882b4120

  !DevObj   !DrvObj            !DevExt   ObjectName

  86576020  \FileSystem\SomeFiltr865760d8  <<<<<<SomeFiltr를 확인할 수 있습니다.

> 882b4120  \FileSystem\Ntfs   882b41d8 

0: kd> !devstack 8717a620

  !DevObj   !DrvObj            !DevExt   ObjectName

  8792ae00  \FileSystem\SomeFiltr8792aeb8  <<<<<<이곳에도 있습니다.

> 8717a620  \FileSystem\Ntfs   8717a6d8 

.

.etc…

.

0: kd> !devstack 88dd25f0

  !DevObj   !DrvObj            !DevExt   ObjectName

  886c9020  \FileSystem\SomeFiltr886c90d8  <<<<<<<이곳에도 있습니다.

  88f74f00  \FileSystem\DfsDriver88f74fb8 

  88f74020  \Driver\InnocentDriver       88f740d8 

> 88dd25f0  \FileSystem\Ntfs   00000000  Ntfs

스택에 있는 모든 드라이버를 업데이트해 본 후 메모리 덤프에서 Srv!WorkerThreads 를 디버깅해 본 결과 문제점을 확인할 수 없다면 ntfs 아래에서 동작하는 스토리지 드라이버를 신중하게 의심해야 합니다.

Event ID: 2021, 2020의 원인 #1

Event ID 2021, 2022 가 발생하는 문제가 공통적인 문제로 I/O 스택에 있는 필터 또는 기능 드라이버가 블록이라는 것일 앞에서 이야기 하였습니다. 또한 아주 많은 요청이 발생하거나 낮게 설정된 Srv(KB317249 에서 이야기한) 또는 많고 긴 요청이 시스템에 많이 있을 공유 발생할 수 있습니다. 예를 들면 ChangeNotify 를 들 수 있습니다. 어떻게 문제점을 찾을 수 있을 까요? 네트워크 트래픽을 확인해 보도록 하겠습니다.

네트워크 모니터링 툴로 SMB 트래픽이 서버로 얼마나 많이 유입되는지 확인할 수 있습니다. 저는 여기서 자세히 이야기 할 수 없지만 분석을 위해서는 SMB 명령을 잘 알아야 할 것 입니다. 정상적인 경우라면 SMB를 필터링 하여 어떤 클라이언트로부터 어떠한 요청이 들어왔는지 확인할 수 있습니다. 일반적으로 네트워크 응용프로그램이 비 정상적으로 동작하여 동일 파일에 대해 반복적으로 요청을 합니다. Srv!WorkerThreads 에서 높은 CPU 사용률이 기록될 경우에도 확인해 볼만한 내용 입니다.

ChangeNotifications 와 QueryFile 그리고 QueryPathInfo 요청의 부하를 줄일 수 있는 방법은 아래 KB 문서를 통해 클라이언트에서 설정해야 할 값을 확인할 수 있습니다.

 

클라이언트 측에서 SMB 쉘 수정 : NoRemoteChangeNotify

http://support.microsoft.com/kb/812669/ko

디렉터리 알림 SMB 요청을 해제하려면 Windows 업데이트를 사용할 수

 

클라이언트 측에서 (리다이렉터) 수정 : InfoCacheLevel

http://support.microsoft.com/kb/816375/ko

Windows XP 탐색기 창이 매핑된 네트워크 드라이브에서 깜박인다

 

이 글이 많은 도움이 되었기를 바라고 문제 해결에 도움이 되었기를 바랍니다.