Kernrate 를 이용한 성능 분석

안녕하세요 오늘은 Kernrate 라는 성능분석 툴에 대해서 설명을 해보려고 합니다.
필터 드라이버들을 개발 하다 보면 성능 문제를 만나는 경우가 많이 있습니다. Filesystem Filter Driver 를 작성하였는데 Load 해보니 system 이 느려지더라 등의 문제가 있을 수 있는데 이때 어디가 병목지점인지 찾기가 힘듭니다. 왜냐하면 Filesystem Filter 의 경우 1초에도 수천개의 I/O 가 지나고 있기 때문에 전부를 비교할 수 없습니다. 그리고 어떤 지점에서 얼마의 시간이 걸렸는지는 알수 없습니다. 무식하게 작성한다면 모든 함수에 시간을 출력하게 해서 각 시간을 비교해 보는 방법이 있을 수 있겠지만 수 많은 (수만개)의 I/O 를 분석한다는 것은 정말 힘든 일 입니다.
이럴때 사용하기 좋은 툴이 Kernrate 입니다. 이 툴은 MS 사이트에서 공짜로 받을 수 있는 좋은 툴 입니다. MS 는 정말로 많은 툴을 만들어 놓네요 (참고로 Compuware 에 TrueTime 이라는 툴도 있습니다. 이것은 상용이고 좀더 보기좋은 GUI 를 가진 결과를 보여 줍니다.)
다음은 dir /s c: 를 하고 난 후 Kernrate 를 실행 시켜본 결과 입니다.

 

C:\KrView\Kernrates>Kernrate_i386_XP.exe
/==============================\
<         KERNRATE LOG           >
\==============================/
Date: 2004/12/21   Time: 15:33:21
Machine Name: AOLTEAN-H4
Number of Processors: 1
PROCESSOR_ARCHITECTURE: x86
PROCESSOR_LEVEL: 6
PROCESSOR_REVISION: 0800
Physical Memory: 480 MB
Pagefile Total: 1125 MB
Virtual Total: 2047 MB
PageFile1: \??\E:\pagefile.sys, 720MB
OS Version: 5.1 Build 2600 Service-Pack: 2.0
WinDir: E:\WINDOWS

Kernrate User-Specified Command Line:
Kernrate_i386_XP.exe

Kernel Profile (PID = 0): Source= Time,
Using Kernrate Default Rate of 25000 events/hit
Starting to collect profile data

***> Press ctrl-c to finish collecting profile data
===> Finished Collecting Data, Starting to Process Results

------------Overall Summary:--------------

P0     K 0:00:13.656 (38.2%)  U 0:00:02.484 ( 7.0%)  I 0:00:19.578 (54.8%)  DPC 0:00:00.312 ( 0.9%)  Interrupt 0:00:00.296 ( 0.8%)
       Interrupts= 107928, Interrupt Rate= 3022/sec.

Total Profile Time = 35718 msec

                                       BytesStart          BytesStop         BytesDiff.
    Available Physical Memory   ,       107065344,       112259072,         5193728
    Available Pagefile(s)       ,       374460416,       371945472,        -2514944
    Available Virtual           ,      2132889600,      2131841024,        -1048576
    Available Extended Virtual  ,               0,               0,               0

                                  Total      Avg. Rate
    Context Switches     ,       395167,         11063/sec.
    System Calls         ,      1106131,         30968/sec.
    Page Faults          ,        20595,         577/sec.
    I/O Read Operations  ,         2346,         66/sec.
    I/O Write Operations ,         1102,         31/sec.
    I/O Other Operations ,        32185,         901/sec.
    I/O Read Bytes       ,       346338,         148/ I/O
    I/O Write Bytes      ,        83614,         76/ I/O
    I/O Other Bytes      ,      5832690,         181/ I/O

-----------------------------

Results for Kernel Mode:
-----------------------------

OutputResults: KernelModuleCount = 135
Percentage in the following table is based on the Total Hits for the Kernel

Time   13080 hits, 25000 events per hit --------
Module                                Hits   msec  %Total  Events/Sec
amdk7                                  7381      35718    56 %     5166162
nv4_disp                               3834      35718    29 %     2683520
ntoskrnl                                819      35718     6 %      573240
win32k                                  341      35718     2 %      238675
hal                                     288      35718     2 %      201579
Ntfs                                    180      35718     1 %      125986
NVENET                                   64      35718     0 %       44795
USBPORT                                  38      35718     0 %       26597
atapi                                    20      35718     0 %       13998
ino_fltr                                 19      35718     0 %       13298
nv4_mini                                 17      35718     0 %       11898
usbohci                                  11      35718     0 %        7699
watchdog                                  9      35718     0 %        6299
tcpip                                     7      35718     0 %        4899
HIDPARSE                                  7      35718     0 %        4899
Npfs                                      5      35718     0 %        3499
HIDCLASS                                  4      35718     0 %        2799
NDIS                                      4      35718     0 %        2799
sr                                        4      35718     0 %        2799
ftdisk                                    4      35718     0 %        2799
usbhub                                    3      35718     0 %        2099
PCIIDEX                                   3      35718     0 %        2099
ACPI                                      3      35718     0 %        2099
mouhid                                    2      35718     0 %        1399
hidusb                                    2      35718     0 %        1399
mouclass                                  2      35718     0 %        1399
TDI                                       2      35718     0 %        1399
PartMgr                                   2      35718     0 %        1399
rdbss                                     1      35718     0 %         699
psched                                    1      35718     0 %         699
VIDEOPRT                                  1      35718     0 %         699
imapi                                     1      35718     0 %         699
CLASSPNP                                  1      35718     0 %         699

================================= END OF RUN ==================================
============================== NORMAL END OF RUN ==============================

결과를 보면 nv4_disp.sys 라는 드라이버가 29% 의 시간을 소모하고 있는 것을 볼 수 있습니다.(NVidia chipset 과 관련된 드라이버 입니다.)
명령을 추가하여 Module 의 내부 함수에 대해서 알고 싶다면 아래와 같은 명령을 실행하면 됩니다.

 

C:\KrView\Kernrates>Kernrate_i386_XP.exe -z ntoskrnl
/==============================\
<         KERNRATE LOG           >
\==============================/
Date: 2004/12/21   Time: 15:37:38
Machine Name: AOLTEAN-H4
Number of Processors: 1
PROCESSOR_ARCHITECTURE: x86
PROCESSOR_LEVEL: 6
PROCESSOR_REVISION: 0800
Physical Memory: 480 MB
Pagefile Total: 1125 MB
Virtual Total: 2047 MB
PageFile1: \??\E:\pagefile.sys, 720MB
OS Version: 5.1 Build 2600 Service-Pack: 2.0
WinDir: E:\WINDOWS

Kernrate User-Specified Command Line:
Kernrate_i386_XP.exe -z ntoskrnl

Kernel Profile (PID = 0): Source= Time,
Using Kernrate Default Rate of 25000 events/hit
CallBack: Finished Attempt to Load symbols for 804d7000 \WINDOWS\system32\ntoskrnl.exe

Starting to collect profile data

***> Press ctrl-c to finish collecting profile data
===> Finished Collecting Data, Starting to Process Results

------------Overall Summary:--------------

P0     K 0:00:01.406 (24.3%)  U 0:00:00.859 (14.8%)  I 0:00:03.531 (60.9%)  DPC 0:00:00.031 ( 0.5%)  Interrupt 0:00:00.062 ( 1.1%)
       Interrupts= 23804, Interrupt Rate= 4106/sec.

Total Profile Time = 5796 msec

                                       BytesStart          BytesStop         BytesDiff.
    Available Physical Memory   ,       117850112,       114122752,        -3727360
    Available Pagefile(s)       ,       370819072,       368578560,        -2240512
    Available Virtual           ,      2132889600,      2130681856,        -2207744
    Available Extended Virtual  ,               0,               0,               0

                                  Total      Avg. Rate
    Context Switches     ,       206440,         35612/sec.
    System Calls         ,       372915,         64330/sec.
    Page Faults          ,        14872,         2566/sec.
    I/O Read Operations  ,          186,         32/sec.
    I/O Write Operations ,          180,         31/sec.
    I/O Other Operations ,        19183,         3309/sec.
    I/O Read Bytes       ,        39296,         211/ I/O
    I/O Write Bytes      ,        11940,         66/ I/O
    I/O Other Bytes      ,      3000748,         156/ I/O

-----------------------------

Results for Kernel Mode:
-----------------------------

OutputResults: KernelModuleCount = 135
Percentage in the following table is based on the Total Hits for the Kernel

Time   1893 hits, 25000 events per hit --------
Module                                Hits   msec  %Total  Events/Sec
amdk7                                  1309       5796    69 %     5646135
ntoskrnl                                292       5796    15 %     1259489
hal                                      91       5796     4 %      392512
Ntfs                                     79       5796     4 %      340752
win32k                                   56       5796     2 %      241545
NVENET                                   28       5796     1 %      120772
ino_fltr                                  8       5796     0 %       34506
atapi                                     6       5796     0 %       25879
CLASSPNP                                  4       5796     0 %       17253
Npfs                                      3       5796     0 %       12939
PCIIDEX                                   3       5796     0 %       12939
watchdog                                  2       5796     0 %        8626
nv4_mini                                  2       5796     0 %        8626
sr                                        2       5796     0 %        8626
PartMgr                                   2       5796     0 %        8626
ftdisk                                    2       5796     0 %        8626
nv4_disp                                  1       5796     0 %        4313
tcpip                                     1       5796     0 %        4313
USBPORT                                   1       5796     0 %        4313
NDIS                                      1       5796     0 %        4313

===> Processing Zoomed Module ntoskrnl.exe...

----- Zoomed module ntoskrnl.exe (Bucket size = 16 bytes, Rounding Down) --------
Percentage in the following table is based on the Total Hits for this Zoom Module

Time   292 hits, 25000 events per hit --------
Module                                Hits   msec  %Total  Events/Sec
CcUnpinDataForThread                     32       5796    10 %      138026
KiDispatchInterrupt                      27       5796     8 %      116459
ZwYieldExecution                         18       5796     5 %       77639
FsRtlIsNameInExpression                  14       5796     4 %       60386
KiIpiServiceRoutine                      13       5796     4 %       56073
SeUnlockSubjectContext                    9       5796     2 %       38819
NtAllocateVirtualMemory                   8       5796     2 %       34506
ObReferenceObjectByHandle                 8       5796     2 %       34506
ExAllocatePoolWithTag                     8       5796     2 %       34506
NtRequestWaitReplyPort                    7       5796     2 %       30193
ExInterlockedPopEntrySList                7       5796     2 %       30193
SeDeleteAccessState                       6       5796     1 %       25879
ExAcquireResourceExclusiveLite            6       5796     1 %       25879
ExReleaseResourceLite                     6       5796     1 %       25879
NtOpenProcessTokenEx                      5       5796     1 %       21566
ObCreateObject                            5       5796     1 %       21566
ObfDereferenceObject                      5       5796     1 %       21566
wcstombs                                  4       5796     1 %       17253
MmMapLockedPagesSpecifyCache              4       5796     1 %       17253
IoBuildPartialMdl                         4       5796     1 %       17253
RtlCopyUnicodeString                      4       5796     1 %       17253

 

마지막으로 자신이 만든 모듈의 내부를 알고 싶다면
kernrate -z module -j module의 심볼 패스
명령을 수행한다면 내부 모듈중 어떤 것에서 병목 현상이 발생하고 있는지 확인할 수 있을 것입니다.
http://www.microsoft.com/downloads/details.aspx?FamilyID=d6e95259-8d9d-4c22-89c4-fad382eddcd1&DisplayLang=en