[Articulo] ¿Qué está frenando a mi CPU?... depuracion de problemas.

¿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 mas de un 95%, tenemos la sensacion que
algo está "fallando", que el sistema no responde como debiera.

Estas "sensaciones" muchas veces son realidad. Un driver erroneo, un error hardware
que está "friendo" a interrupciones la CPU (por ejemplo), quitan prestaciones a la
maquina, e incluso pueden llegar a bloquearla o semibloquearla.

Actualmente, tenemos una herramienta de Microsoft, que a pesar de ser una
herramienta para desarroladores, tambien un usuario final puede mirar e investigar lo que le puede pasar a la maquina.

La herramienta está en: http://www.microsoft.com/downloads/...layLang=en

Una vez instalada, la parte mas interesante debe ejecutarse en una consola de
comando (cmd.exe). En ella, vamos a la carpeta de instalacion:

cd "c:\Archivos de Programa\KrView\Kernrates"
dir

y vemos tres archivos correspondientes a diferentes sistemas operativos:

Kernrate_i386_Win2000.exe
Kernrate_i386_XP.exe
Kernrate_ia64_XP.exe

En el caso de XP, debemos ejecutar el:

Kernrate_i386_XP.exe


Lo dejamos en ejecucion un minuto para que recoja estadisticas 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 tipica en mi maquina, con 4 CPU's. No se ve nada anormal,
ya que el maximo consumo corresponde al driver intelppm que es realmente el nucleo de multiprocesador.

Vemos a ver un caso posiblementa anomalo en otra maquina:


/\
< 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 ==

¿que observamos?... primero un elevado (excesivo) numero de interrupciones
por segundo: 3022 (frente al ejemplo de mi maquina, 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 grafica o la propia tarjeta
grafica está dañada.




En la misma maquina, ejecutamos ahora de nuevo el programa con el
parametro que indico mas 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 ejecucion de dicho comando.


Vamos a investigar ahora el nucleo de windows, ejecutando el mismo
programa con un parametro:


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\system32toskrnl.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...

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


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 cache de disco. Y vemos tambien a FsRtlIsNameInExpression
el cual corresponde a la rutina de busqueda y coincidencia de nombres.

Sorprende en este caso que se esté usando un 15% * 4% = 0,6% de tiempo
de busqueda cuando no hemos dado ningun patron de nombre en la orden dir.


Bien, hay analisis aquí, que tienen mas sentido a un programador de
sistemas, pero espero que pueda ser de ayuda en la busqueda de
situaciones anomalas en la maquina.



Jose Manuel Tella Llop
MVP - Windows
jmtella@XXXcompuserve.com (quitar XXX)
http://www.multingles.net/jmt.htm

Este mensaje se proporciona "como está" sin garantías de ninguna clase, y no otorga ningún derecho.

This posting is provided "AS IS" with no warranties, and confers no rights.
You assume all risk for your use.