José Manuel Tella Llop
jmtella@compuserve.com
¿QUE ESTÁ MATANDO MI CPU?
-------------------------Algunas veces, a pesar de ver el sistema ocioso e incluso ver en el Administrador de tareas que la CPU está desocupada en más de un 95%, tenemos la sensación que algo está "fallando", que el sistema no responde como debiera.
Estas "sensaciones" muchas veces son realidad. Un driver erróneo, un error hardware que está "friendo" a interrupciones la CPU (por ejemplo), quitan prestaciones a la máquina, e incluso pueden llegar a bloquearla o semibloquearla.
Actualmente, tenemos una herramienta de Microsoft, que a pesar de ser una herramienta para desarrolladores, también un usuario final puede mirar e investigar lo que le puede pasar a la máquina.
La herramienta está en: http://www.microsoft.com/download/en/details.aspx?DisplayLang=en&id=24853
Una vez instalada, la parte más interesante debe ejecutarse en una consola de comando (cmd.exe). En ella, vamos a la carpeta de instalación:
cd "c:\Archivos de Programa\KrView\Kernrates"
diry vemos tres archivos correspondientes a diferentes sistemas operativos:
Kernrate_i386_Win2000.exe
Kernrate_i386_XP.exe
Kernrate_ia64_XP.exeEn el caso de XP, debemos ejecutar el:
Kernrate_i386_XP.exe
Lo dejamos en ejecución un minuto para que recoja estadísticas y pulsaremos CTRL-C para pararlo.
Esperamos un minuto y lo paramos con CTRL-C./==============================\
< KERNRATE LOG >
\==============================/
Date: 2005/02/04 Time: 18:19:49
Machine Name: JETSABE
Number of Processors: 4
PROCESSOR_ARCHITECTURE: x86
PROCESSOR_LEVEL: 15
PROCESSOR_REVISION: 0205
Physical Memory: 3327 MB
Pagefile Total: 7264 MB
Virtual Total: 2047 MB
PageFile1: \??\J:\pagefile.sys, 4095MB
OS Version: 5.1 Build 2600 Service-Pack: 2.0
WinDir: K:\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:00.500 ( 9.6%) U 0:00:00.000 ( 0.0%) I 0:00:04.703 (90.4%) DPC 0:00:00.468 ( 9.0%) Interrupt 0:00:00.015 ( 0.3%)
Interrupts= 10188, Interrupt Rate= 1958/sec.
P1 K 0:00:00.046 ( 0.9%) U 0:00:00.000 ( 0.0%) I 0:00:05.156 (99.1%) DPC 0:00:00.000 ( 0.0%) Interrupt 0:00:00.000 ( 0.0%)
Interrupts= 2434, Interrupt Rate= 468/sec.
P2 K 0:00:00.031 ( 0.6%) U 0:00:00.015 ( 0.3%) I 0:00:05.156 (99.1%) DPC 0:00:00.000 ( 0.0%) Interrupt 0:00:00.015 ( 0.3%)
Interrupts= 2530, Interrupt Rate= 486/sec.
P3 K 0:00:00.296 ( 5.7%) U 0:00:00.046 ( 0.9%) I 0:00:04.859 (93.4%) DPC 0:00:00.031 ( 0.6%) Interrupt 0:00:00.000 ( 0.0%)
Interrupts= 2515, Interrupt Rate= 483/sec.
TOTAL K 0:00:00.875 ( 4.2%) U 0:00:00.062 ( 0.3%) I 0:00:19.875 (95.5%) DPC 0:00:00.500 ( 2.4%) Interrupt 0:00:00.031 ( 0.2%)
Total Interrupts= 17667, Total Interrupt Rate= 3395/sec.
Total Profile Time = 5203 msec
BytesStart BytesStop BytesDiff.
Available Physical Memory , 2675724288, 2674913280, -811008
Available Pagefile(s) , 7047180288, 7046549504, -630784
Available Virtual , 213262336 2131574784, -1048576
Available Extended Virtual , 0, 0, 0
Total Avg. Rate
Context Switches , 16507, 3173/sec.
System Calls , 180324, 34657/sec.
Page Faults , 1267, 244/sec.
I/O Read Operations , 215, 41/sec.
I/O Write Operations , 76, 15/sec.
I/O Other Operations , 1408, 271/sec.
I/O Read Bytes , 65260, 304/ I/O
I/O Write Bytes , 119602, 1574/ I/O
I/O Other Bytes , 384972, 273/ I/O
-----------------------------
Results for Kernel Mode:
-----------------------------
OutputResults: KernelModuleCount = 228
Percentage in the following table is based on the Total Hits for the Kernel
Time 8273 hits, 25000 events per hit --------
Module Hits msec %Total Events/Sec
intelppm 7817 5203 94 % 37560061
ntoskrnl 176 5203 2 % 845665
hal 168 5203 2 % 807226
win32k 53 5203 0 % 254660
USBPORT 43 5203 0 % 206611
usbohci 4 5203 0 % 19219
usbehci 3 5203 0 % 14414
dc21x4 2 5203 0 % 9609
NDIS 2 5203 0 % 9609
irstusb 1 5203 0 % 4804
tcpip6 1 5203 0 % 4804
STREAM 1 5203 0 % 4804
BT848 1 5203 0 % 4804
Ntfs 1 5203 0 % 4804
================================= END OF RUN ==================================
============================== NORMAL END OF RUN ==============================Esta es la salida típica en mi máquina, con 4 CPU's. No se ve nada anormal, ya que el máximo consumo corresponde al driver intelppm que es realmente el núcleo de multiprocesador.
Vemos a ver un caso posiblementa anómalo en otra máquina:
/==============================\
< KERNRATE LOG >
\==============================/
Date: 2004/12/21 Time: 15:33:21
Machine Name: AOSTOS
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 ==============================¿Qué observamos?....... primero un elevado (excesivo) número de interrupciones por segundo: 3022 (frente al ejemplo de mi máquina, 3395 - lo cual es normal por tener 19 discos, 1 controladora IDE, 2 SATA, y una SCSI, y tener mas de 30 dispositivos USB conectados).
Como segundo punto, vemos que el driver nv4_disp (correspondiente al driver de una tarjeta nVidia) se está llevando un 29%.
Esto puede empezar a darnos una pista. Ese driver posiblemente es incorrecto, o no está diseñado para ese modelo de tarjeta gr´sfica.... o la propia tarjeta gráfica está dañada.
------------------------------------
En la misma máquina, ejecutamos ahora de nuevo el programa con el parámetro que indico más abajo ,y antes de pararlo, en otra consola de comandos, ejecutamos un:
dir c:\ /S
y cuando termine, paramos con CTRL-C. De esta manera veremos los consumos durante la ejecución de dicho comando.
Vamos a investigar ahora el núcleo de Windows, ejecutando el mismo programa con un parámetro:
Kernrate_i386_XP.exe -z ntoskrnl
(y antes de parar, el dir c:\ /s comentado anteriormente).
La salida en este caso es:
/==============================\
< KERNRATE LOG >
\==============================/
Date: 2004/12/21 Time: 15:37:38
Machine Name: AOSTOS
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
==============================================================================
Son importantes las 4 primeras lineas:
CcUnpinDataForThread 32 5796 10 % 138026
KiDispatchInterrupt 27 5796 8 % 116459
ZwYieldExecution 18 5796 5 % 77639
FsRtlIsNameInExpression 14 5796 4 % 60386================================= END OF RUN ==================================
============================== NORMAL END OF RUN ==============================Esta vez no fue el driver de nVidia, y ha sido ntoskrnl.
Podemos ver aqui que KiDispatchInterrupt (el cual probablemne corresponde a interrupciones del disco disco duro: atapi!IdePortInterrup).
Vemos tambien a CcUnpinDataForThread, el cual parece ser el administrador de acceso a datos del caché de disco. Y vemos tambien a FsRtlIsNameInExpression, el cual corresponde a la rutina de búsqueda y coincidencia de nombres.Sorprende en este caso que se esté usando un 15% * 4% = 0,6% de tiempo de búsqueda cuando no hemos dado ningún patron de nombre en la orden dir.
Bien, hay análisis aquí que tienen más sentido para un programador de sistemas, pero espero que pueda ser de ayuda en la búsqueda de situaciones anómalas en la máquina.
--
|
|
4 - febrero - 2005