Platform Engineer

시스템 행 현상이 발생 되었을때 원인 분석을 하는 방법에 대해서 글을 써보려고 하고 다음번 글에서는 행 덤프를 분석하는 방법을 쓰려고 합니다.

Windows나 ESXi 모두 커널 레벨에서 행이 발생하였을때 Reset을 해서 시스템을 재부팅하는 방법으로 문제를 해결하는 경우가 종종 있습니다. 하지만 문제가 빈번하게 재현되고 운영중인 Application이 중요한 역할을 하는 경우 원인 분석을 해야 하는 경우가 많이 있습니다. 행 현상이 발생하면 NMI를 이용해서 덤프를 수집하는 방법을 알아보겠습니다.

NMI란 무엇인가?

우선 NMI가 무엇인지 확인해보면 Wiki에 Non-maskable interrupt 라고 되어 있고 하드웨어가 발생시키는 인터럽트로 시스템이 ignore 할 수 없다고 되어 있습니다. 하지만 NMI는 하드웨어에서 발생시키는 경우만 있는 것이 아니라 행 분석을 위해서 시스템에 있는 NMI switch를 눌러(쇼트)서 수동으로 발생시키는 경우도 있습니다.

https://en.wikipedia.org/wiki/Non-maskable_interrupt

먼저 하드웨어로 인한 문제를 확인해 보겠습니다. 아래 HPE의 문서를 보면 하드웨어 이슈로 NMI가 호출되어 VMware의 ESXi에서 PSOD가 발생되었다고 합니다.

Advisory: (Revision) VMware - HPE ProLiant Gen8 Servers running VMware ESXi 5.5 Patch 10, VMware ESXi 6.0 Patch 4, Or VMware ESXi 6.5 May Experience Purple Screen Of Death (PSOD): LINT1 Motherboard Interrupt

https://support.hpe.com/hpsc/doc/public/display?docId=emr_na-c05392947

ESXi host fails with intermittent NMI purple diagnostic screen on HP servers (2085921)

https://kb.vmware.com/s/article/2085921

ESXi host fails with intermittent NMI PSOD on HP ProLiant Gen8 servers (2149043)

https://kb.vmware.com/s/article/2149043

VMware 환경에서 하드웨어로 인한 NMI 크래시에 대해서 설명하고 있습니다.

"LINT1 motherboard interrupt" error in an ESX/ESXi host (1804)

https://kb.vmware.com/s/article/1804

Windows 환경에서도 유사하가 하드웨어(Memory) 오류로 NMI가 호출되어 시스템이 BSOD가 발생된 것이 확인됩니다.

NMI Memory Parity error received during shutdown on Windows 7 and Windows Server 2008 R2

https://support.microsoft.com/en-au/help/2845432/nmi-memory-parity-error-received-during-shutdown-on-windows-7-and-wind

물리적인 하드웨어 뿐만 아니라 가상 하드웨어로 인해서 NMI가 발생할 수도 있습니다. 

VMware ESXi 5.5.x and 6.x hosts experiences a purple diagnostic screen mentioning ALERT: NMI: 709: NMI IPI received (2149704)

https://kb.vmware.com/s/article/2149704

하드웨어로 인한 NMI가 발생한 경우 하드웨어 업체에 연락을 해서 관련 이슈가 있는지 파악을 하고 하드웨어 점검, Firmware, Driver 업데이트 등을 진행할 수 있습니다. 문제가 계속 재현되는 경우 하드웨어를 교체해야할 수도 있습니다.

시스템 행 현상이 발생하였을 때 NMI를 이용한 행 덤프 수집

시스템 행 현상은 ESXi host에 ssh 접속이 안되거나 Windows 의 경우 RDP 등이 접속안되는 상태를 이야기 합니다. 결국 시스템의 중요 프로세스가 응답하지 못하는 상태가 되어 SSH 연결이나 RDP 연결을 받아주지 못하는 경우를 이야기 합니다. 이런 경우 우선 Ping을 해서 하드웨어 레벨에서 행이 걸렸는지 확인해볼 수 있습니다. Ping은 되는데 SSH나 RDP가 안되는 경우 하드웨어가 아닌 소프트웨어 이슈로 시스템이 응답하지 않는 것입니다.

시스템 행 현상이 발생하면 일반적으로 Reset 키를 눌러서 시스템을 재부팅을 하게 되는데 기술지원 계약이 되어 있는 경우 NMI를 이용해서 Dump를 수집하면 원인분석을 의뢰 할 수 있습니다.

-------------------------------------------------------- ESXi -----------------------------------------------------------

VMware는 KB문서를 통해서 시스템 행 현상이 있을 때 덤프를 수집하는 방법을 가이드 하고 있습니다.

ESXi host fails with intermittent NMI PSOD on HP ProLiant Gen8 servers (2149043)

https://kb.vmware.com/s/article/2149043https://kb.vmware.com/s/article/1014767

문서의 내용을 살펴보면 행 현상이 어떤 것인지 정의를 먼저 하고 있습니다. 행 현상은 vSphere client 에 응답하지 않거나, Ping에 응답하지 않거나, ESXi에서 실행중인 VM이 network에 응답하지 않거나, 콘솔 명령에 응답하지 않거나, Alt+F12를 콘솔에서 눌렀을때 VMkernel log가 화면에 출력되지 않는 경우를 이야기 합니다. 행 현상이 하드웨어에 의한 것인지 확인하기 위해 NumLock 키를 눌러 보거나 디스크나 네트워크에 워크로드가 있는지 확인, Ping으로 확인하는 등의 작업을 할 수 있지만 원인 분석을 위해서는 NMI를 이용해서 덤프를 수집해야 합니다.

Determining why an ESX/ESXi host does not respond to user interaction at the console (1017135)

https://kb.vmware.com/s/article/1017135?CoveoV2.CoveoLightningApex.getInitializationData=1&r=2&ui-communities-components-aura-components-forceCommunity-seoAssistant.SeoAssistant.getSeoData=1&other.KM_Utility.getArticleDetails=1&other.KM_Utility.getArticleMetadata=2&other.KM_Utility.getUrl=1&other.KM_Utility.getUser=1&other.KM_Utility.getAllTranslatedLanguages=2&ui-comm-runtime-components-aura-components-siteforce-qb.Quarterback.validateRoute=1

NMI를 사용해서 수동으로 덤프를 수집하기 위해서는 ESXi에 설정이 필요한데 ESXi 5.0 이후로는 별도의 설정 없이 NMI 버튼을 누르면 PSOD 덤프가 수집 됩니다.

KB의 마지막 부분에는 각 하드웨어 별로 NMI를 발생시키는 방법이 가이드 되어 있습니다.

Triggering the NMI

The NMI button or switch location varies depending on the hardware. A small set of examples are available:

IBM x3650 M2 – The NMI button is on the diagnostic panel. There may also be a Send NMI button in the RSA. For more information, see the x3650 M2 Installation and Users Guide.

HP Proliant – The NMI button or jumper is on the motherboard. There is also a Send NMI button in the iLO. For more information, see Performing an HP ProLiant server NMI crash dump.

Dell R900 – The NMI button is on the front panel. For more information, see the R900 Systems Hardware Owner's Manual.

Fujitsu PRIMERGY Servers (RX/TX) - The NMI button is on the front of the server. For more information, see the Operating Manual for your PRIMERGY Servers. The manual can be found at the Fujitsu website.

Click [Industry standard servers] - [PRIMERGY Servers]

Select your PRIMERGY Servers from the pulldown menu. For example, [PRIMERGY RX Servers] - [PRIMERGY RX300 Sriese] - [PRIMERGY RX300 S7]

Download the Operating Manual and check for the NMI button location.

Cisco UCS – The NMI can be sent via IPMI or the UCS Manager command-line interface:

IPMI command – ipmitool -I lan -H <RemoteServerBMCAddress> -U <Username> -a chassis power diag

UCSM command – diagnostic-interrupt.

For more information, see the Cisco UCS command-line reference documentation for the diagnostic-interrupt command.

The preceding links were correct as of November 6, 2013. If you find a link is broken, provide feedback and a VMware employee will update the link.

ESXi 호스트가 아닌 VM에 행 현상이 발생할 경우에도 NMI를 이용해서 덤프를 수집할 수 있습니다. ESXi 에서는 Snapshot을 이용해서 메모리 파일을 덤프 파일로 변환하는 방법으로 덤프를 수집할 수 도 있지만 VM에 NMI 인터럽트를 전달해서 행 덤프를 수집할 수도 있습니다. vCenter Web Clinet를 이용하거나 VM-support 명령 또는 vmdumper 명령을 사용해서 덥프를 수집할 수 있습니다.

How to send NMI to Guest OS on ESXi 6.x (2149185)

https://kb.vmware.com/s/article/2149185

How to capture a vmcore of hung Red Hat Enterprise Linux VMware® guest system using VMware® "vmss2core" tool ?

https://access.redhat.com/solutions/411653

아래 문서는 NMI로 인해 Windows VM이 크래시 된 것에 대한 설명을 하고 있습니다.

Windows virtual machines fails with a Stop Error: Hardware Malfunction - Call your hardware vendor for support (2105345)

https://kb.vmware.com/s/article/2105345

아래 문서에서는 Red Hat 리눅스가 행 현상이 있을때 ESXi 에서 NMI를 발생하는 방법을 설명하고 있습니다.

Red Hat Enterprise Linux - How to Force a Crash on a Hung Linux Virtual Machine Running on VMware ESXi Server

https://support.hpe.com/hpsc/doc/public/display?docId=mmr_kc-0105964

------------------------------------------------------ Windows ---------------------------------------------------------

Microsoft 에서는 아래 문서에서 행 현상이 있을때 덤프를 수집하는 방법을 설명하고 있습니다.

How to generate a kernel or a complete memory dump file in Windows Server

https://support.microsoft.com/en-us/help/969028/how-to-generate-a-kernel-or-a-complete-memory-dump-file-in-windows-ser

이 문서에서 별도로 행 현상에 대해서 설명을 하고 있지는 않지만 ESXi와 비슷하게 RDP 접속해보기, Numslock 눌러보기, Ping 해보기 등으로 행 현상이 있는지 확인해볼 수 있습니다.

Windows 는 커널 덤프, 전체 덤프와 같이 덤프의 유형이 있는데 각 유형에 따라서 적절한 페이지 파일 크기를 설정해 주어야 덤프파일이 정상적으로 수집됩니다. 커널 덤프의 경우 Windows 커널이 사용하는 메모리만 덤프 파일에 저장하는 것으로 커널의 메모리 사용량에 따라서 2 ~ 16GB 정도면 충분한 크기라고 할 수 있습니다. 전체 덤프의 경우 물리 메모리의 내용을 모두 덤프 파일에 저장하는 것으로 물리메모리 크기 + 1MB 이상의 페이지 파일이 있어야 덤프를 수집할 수 있습니다. Windows 커널의 행 현상에 대해서는 커널 덤프로 분석이 가능하지만 유저모드 프로세스의 행 현상은 전체 덤프를 수집해야 분석이 가능할 수 있습니다.

Windows 시스템에서는 일반적으로 키보드 (오른쪽 Ctrl 키를 누른 상태에서 Scroll Lock 를 두번 누르기)를 이용해서 덤프를 수집할 수 있는데 별도의 설정을 키보드에 해야하기 때문에 문제가 발생하기 전에 운영하는 시스템에 모두 키보드 덤프를 설정해 두어야 합니다. 덤프 생성을 위한 키를 변경할 수도 있으며 

Forcing a System Crash from the Keyboard

https://docs.microsoft.com/en-us/windows-hardware/drivers/debugger/forcing-a-system-crash-from-the-keyboard

Windows 시스템에서도 NMI를 이용해서 덤프를 수집할 수 있습니다. 

How to generate a complete crash dump file or a kernel crash dump file by using an NMI on a Windows-based system

https://support.microsoft.com/en-us/help/927069/how-to-generate-a-complete-crash-dump-file-or-a-kernel-crash-dump-file

PowerShell을 사용해서 Hyper-V 에서 VM에 NMI 인터럽트를 발생시키는 방법도 있습니다.

Debug-VM

https://docs.microsoft.com/en-us/powershell/module/hyper-v/debug-vm?view=win10-ps

Azure 환경에서 Serial console을 사용해서 Guest에 NMI를 보내는 방법도 있습니다. AWS에서는 어떻게 NMI를 보낼 수 있는지 찾지를 못했습니다.

Use Serial Console for SysRq and NMI calls

https://docs.microsoft.com/ko-kr/azure/virtual-machines/troubleshooting/serial-console-nmi-sysrq

다음 번에는 수집된 덤프를 분석하는 방법을 써보려고 합니다.

감사합니다.

VMware 에서 실행되는 Windows VM이 시스템 행 현상이 있다고 하여 분석을 진행해 보았습니다.

먼저 !vm 명령을 싱행해서 메모리 상태를 확인해 보았는데 별다른 문제가 확인되지 않았습니다.

0: kd> !vm

Page File: \??\C:\pagefile.sys

  Current:   1048576 Kb  Free Space:    807844 Kb

  Minimum:   1048576 Kb  Maximum:     10485500 Kb

Physical Memory:          4194156 (   16776624 Kb)

Available Pages:          3479978 (   13919912 Kb)

ResAvail Pages:           4063051 (   16252204 Kb)

Locked IO Pages:                0 (          0 Kb)

Free System PTEs:      4294989313 (17179957252 Kb)

Modified Pages:             13432 (      53728 Kb)

Modified PF Pages:          12747 (      50988 Kb)

Modified No Write Pages:        0 (          0 Kb)

NonPagedPool    0:             33 (        132 Kb)

NonPagedPoolNx  0:          32181 (     128724 Kb)

NonPagedPool    1:              0 (          0 Kb)

NonPagedPoolNx  1:              0 (          0 Kb)

NonPagedPool Usage:           168 (        672 Kb)

NonPagedPoolNx Usage:       40172 (     160688 Kb)

NonPagedPool Max:      4294967296 (17179869184 Kb)

PagedPool  0:               79908 (     319632 Kb)

PagedPool  1:               51553 (     206212 Kb)

PagedPool  2:                   0 (          0 Kb)

PagedPool Usage:           131461 (     525844 Kb)

PagedPool Maximum:     4160749568 (16642998272 Kb)

Processor Commit:             917 (       3668 Kb)

Session Commit:             16179 (      64716 Kb)

Syspart SharedCommit 0

Shared Commit:              51347 (     205388 Kb)

Special Pool:                   0 (          0 Kb)

Kernel Stacks:               8889 (      35556 Kb)

Pages For MDLs:               342 (       1368 Kb)

Pages For AWE:                  0 (          0 Kb)

NonPagedPool Commit:        38599 (     154396 Kb)

PagedPool Commit:          131461 (     525844 Kb)

Driver Commit:               9397 (      37588 Kb)

Boot Commit:                50253 (     201012 Kb)

System PageTables:            997 (       3988 Kb)

VAD/PageTable Bitmaps:       6871 (      27484 Kb)

ProcessLockedFilePages:        12 (         48 Kb)

Pagefile Hash Pages:          206 (        824 Kb)

Sum System Commit:         315470 (    1261880 Kb)

Total Private:             473164 (    1892656 Kb)

Misc/Transient Commit:       4291 (      17164 Kb)

Committed pages:           792925 (    3171700 Kb)

Commit limit:             4456300 (   17825200 Kb)

커널에서 동기화 객체를 기다리는 것이 있는지 확인해 보았지만 없었습니다.

0: kd> !locks

**** DUMP OF ALL RESOURCE OBJECTS ****

KD: Scanning for held locks.........

89274 total locks

그렇다면 CPU가 바빠서 발생하는 이슈일지 모른다고 생각해서 CPU의 상태를 확인해보았으니 IDLE 상태 였습니다.

0: kd> !cpuinfo

CP  F/M/S Manufacturer  MHz PRCB Signature    MSR 8B Signature Features

 0  6,79,1 GenuineIntel 2295 0b00002a00000000                   311b3fff

 1  6,79,1 GenuineIntel 2295 0b00002a00000000                   311b3fff

 2  6,79,1 GenuineIntel 2295 0b00002a00000000                   311b3fff

 3  6,79,1 GenuineIntel 2295 0b00002a00000000                   311b3fff

                      Cached Update Signature 0b00002a00000000

                     Initial Update Signature 0b00002a00000000

0: kd> !running

Process PID Thread           Id Pri Base Pri Next CPU CSwitches User          Kernel State              Time Reason

======= === ================ == === ======== ======== ========= ==== =============== ======= =============== ==============

Idle      0 fffff8035d3d5940  0   0        0        0  24448367    0   23h:56:06.250 Running 1d.00:48:53.796 Executive

Idle      0 ffffdf005f631000  0   0        0        1  20088217    0   23h:48:42.703 Running          3s.984 WrCalloutStack

Idle      0 ffffdf005f6b9000  0   0        0        2  18610602    0   23h:58:19.172 Running 1d.00:48:53.796 Executive

Idle      0 ffffdf005f741000  0   0        0        3  25365439    0 1d.00:00:03.219 Running 1d.00:48:53.796 Executive

Count: 4 | Show Unique Stacks

0: kd> !mex.us -cpu

4 threads: ffffdf005f6b9000 ffffdf005f741000 fffff8035d3d5940 ffffdf005f631000

    fffff8035d223ff1 nt!PpmIdleGuestExecute+0x15

    fffff8035d109eac nt!PpmIdleExecuteTransition+0xcbc

    fffff8035d10903a nt!PoIdle+0x33a

    fffff8035d17afac nt!KiIdleLoop+0x2c

1 stack(s) with 4 threads displayed (4 Total threads)

lpc의 상태를 확인해보니 svchost.exe가 explorer에 lpc message를 보내고 기다리는 것이 확인 됩니다.

0: kd> !lpcwait

Server Process ffffab06`b8137800  Connection Port ffffab06`b853c540  (\Device\HarddiskVolume1\Windows\explorer.exe)

    Client Thread        Client Wait Time     Client Message       Server Thread   

    =================    =================    =================    =================

    ffffab06`b1b28800           1:25.406      ffffce0e`5b04dcf0                                                          (\Device\HarddiskVolume1\Windows\System32\svchost.exe)

    1 thread waiting

svchost.exe의 Thread를 확인해보니 logoff를 처리하던 것으로 보입니다.

0: kd> kc

  *** Stack trace for last set context - .thread/.cxr resets it

 # Call Site

00 nt!KiSwapContext

01 nt!KiSwapThread

02 nt!KiCommitThreadWait

03 nt!KeWaitForSingleObject

04 nt!AlpcpSignalAndWait

05 nt!AlpcpReceiveSynchronousReply

06 nt!AlpcpProcessSynchronousRequest

07 nt!NtAlpcSendWaitReceivePort

08 nt!KiSystemServiceCopyEnd

09 ntdll!NtAlpcSendWaitReceivePort

0a RPCRT4!LRPC_BASE_CCALL::DoSendReceive

0b RPCRT4!I_RpcSendReceive

0c combase!CMessageCall::CallI_RpcSendReceive

0d combase!ThreadSendReceive

0e combase!CSyncClientCall::SwitchAptAndDispatchCall

0f combase!CSyncClientCall::SendReceive2

10 combase!SyncClientCallRetryContext::SendReceiveWithRetry

11 combase!CSyncClientCall::SendReceiveInRetryContext

12 combase!DefaultSendReceive

13 combase!CSyncClientCall::SendReceive

14 combase!CClientChannel::SendReceive

15 combase!NdrExtpProxySendReceive

16 RPCRT4!NdrpClientCall3

17 combase!ObjectStublessClient

18 combase!ObjectStubless

19 combase!RemoteReleaseRifRefHelper

1a combase!RemoteReleaseRifRef

1b combase!CStdMarshal::DisconnectCliIPIDs

1c combase!CStdMarshal::Disconnect

1d combase!CStdIdentity::{dtor}

1e combase!CStdIdentity::CInternalUnk::Release

1f netprofmsvc!ATL::IConnectionPointImpl<CImplINetworkListManager,&IID_INotifyNetworkGlobalCostEvents,ATL::CComDynamicUnkArray>::Unadvise

20 netprofmsvc!CImplINetworkListManager::UnadviseAndRemoveSessionCookie<&IID_INotifyNetworkGlobalCostEvents>

21 netprofmsvc!CImplINetworkListManager::PurgeClients

22 netprofmsvc!EnterPurgeClientsCallback

23 combase!EnterForCallback

24 combase!SwitchForCallback

25 combase!PerformCallback

26 combase!CObjectContext::InternalContextCallback

27 combase!CObjectContext::ContextCallback

28 combase!CContextSwitcher::ContextCallback

29 netprofmsvc!NetProfileManUserLogOff

2a ntdll!TppSimplepExecuteCallback

2b ntdll!TppWorkerThread

2c KERNEL32!BaseThreadInitThunk

2d ntdll!RtlUserThreadStart

Explorer는 파일을 닫는 중이었는데 백신 프로그램의 필터 드라이버인 TmXPFlt가 IO가 더 진행되지 못하게 막고 있었습니다.

0: kd> !us -p ffffab06b8137800

1 thread [stats]: ffffab06b8121080

    fffff8035d17e576 nt!KiSwapContext+0x76

    fffff8035d0d74fd nt!KiSwapThread+0x17d

    fffff8035d0d6f9f nt!KiCommitThreadWait+0x14f

    fffff8035d0d8d77 nt!KeWaitForSingleObject+0x377

    fffff8022e82bce3 TmXPFlt+0x1bce3

    fffff8022e814884 TmXPFlt+0x4884

    fffff8022e814d65 TmXPFlt+0x4d65

    fffff8022e814f65 TmXPFlt+0x4f65

    fffff8022e4b3f8d TmPreFlt!TmpQueryFullName+0x1e85

    fffff8022e4b40d8 TmPreFlt!TmpQueryFullName+0x1fd0

    fffff8022c603d15 FLTMGR!FltpPerformPostCallbacks+0x2a5

    fffff8022c603756 FLTMGR!FltpPassThroughCompletionWorker+0x76

    fffff8022c605299 FLTMGR!FltpLegacyProcessingAfterPreCallbacksCompleted+0x239

    fffff8022c603146 FLTMGR!FltpDispatch+0xb6

    fffff8035d4e75a0 nt!IopCloseFile+0x150

    fffff8035d5142c5 nt!ObCloseHandleTableEntry+0x245

    fffff8035d43098b nt!NtClose+0xcb

    fffff8035d187503 nt!KiSystemServiceCopyEnd+0x13

    00007ffe863c5ce4 ntdll!NtClose+0x14

    00007ffe83335aa2 KERNELBASE!CloseHandle+0x62

    00007ffe82f02560 SHCORE!CGenericFileHandle::Release+0x160

    00007ffe82f02082 SHCORE!CFileStream::~CFileStream+0xd2

    00007ffe82f00d35 SHCORE!CFileStream::Release+0x35

    00007ffe84b0d273 SHELL32!IconCacheSave+0x18965b

    00007ffe84983a05 SHELL32!SHDesktopMessageLoop+0x45

    00007ff694781468 Explorer!wWinMain+0x714

    00007ff694810727 Explorer!__wmainCRTStartup+0x1c7

    00007ffe83ce8364 KERNEL32!BaseThreadInitThunk+0x14

    00007ffe8638e851 ntdll!RtlUserThreadStart+0x21

1 stack(s) with 1 threads displayed (1 Total threads)

Windows Hang 관련 hotfix 입니다.

Windows Server 2012 and Windows Server 2012 R2
  System freezes during disk I/O in Windows
  https://support.microsoft.com/en-us/kb/2904100

The logon process hangs at the "Welcome" screen or the "Please wait for the User Profile Service" error message window
  https://support.microsoft.com/en-us/kb/3132080

  DNS server freezes and service restart fails during the service restart in Windows Server 2012 R2 or Windows Server 2012
  https://support.microsoft.com/en-us/kb/3134242