Note
Access to this page requires authorization. You can try signing in or changing directories.
Access to this page requires authorization. You can try changing directories.
안녕하세요 오늘은 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의 심볼 패스
명령을 수행한다면 내부 모듈중 어떤 것에서 병목 현상이 발생하고 있는지 확인할 수 있을 것입니다.
https://www.microsoft.com/downloads/details.aspx?FamilyID=d6e95259-8d9d-4c22-89c4-fad382eddcd1&DisplayLang=en