cuellos de botella de CPU

Si vmstat ha mostrado que el sistema está enlazado con la CPU, el paso siguiente es determinar que proceso está utilizando más tiempo de CPU.

La herramienta recomendada es tprof:

> tprof -s -k -x sleep 60

outputs:

Mon Nov 28 12:40:11 2010
System: AIX 6.1 Node: voodoo Machine: 00455F1B4C00

Starting Command sleep 60 
stopping trace collection
Generating sleep.prof
> cat sleep.prof
Process                                Freq  Total Kernel   User Shared  Other
=======                                ====  ===== ======   ==== ======  =====
./java                                    5  59.39  24.28   0.00  35.11   0.00
wait                                      4  40.33  40.33   0.00   0.00   0.00
/usr/bin/tprof                            1   0.20   0.02   0.00   0.18   0.00
/etc/syncd                                3   0.05   0.05   0.00   0.00   0.00
/usr/bin/sh                               2   0.01   0.00   0.00   0.00   0.00
gil                                       2   0.01   0.01   0.00   0.00   0.00
afsd                                      1   0.00   0.00   0.00   0.00   0.00
rpc.lockd                                 1   0.00   0.00   0.00   0.00   0.00
swapper                                   1   0.00   0.00   0.00   0.00   0.00
=======                                ====  ===== ======   ==== ======  =====
Total                                    20 100.00  64.70   0.00  35.29   0.00

Process                   PID      TID  Total Kernel   User Shared  Other
=======                   ===      ===  ===== ======   ==== ======  =====
./java                 467018   819317  16.68   5.55   0.00  11.13   0.00
./java                 467018   766019  14.30   6.30   0.00   8.00   0.00
./java                 467018   725211  14.28   6.24   0.00   8.04   0.00
./java                 467018   712827  14.11   6.16   0.00   7.94   0.00
wait                    20490    20491  10.24  10.24   0.00   0.00   0.00
wait                     8196     8197  10.19  10.19   0.00   0.00   0.00
wait                    12294    12295   9.98   9.98   0.00   0.00   0.00
wait                    16392    16393   9.92   9.92   0.00   0.00   0.00
/usr/bin/tprof         421984   917717   0.20   0.02   0.00   0.18   0.00
/etc/syncd             118882   204949   0.04   0.04   0.00   0.00   0.00
./java                 467018   843785   0.03   0.02   0.00   0.00   0.00
gil                     53274    73765   0.00   0.00   0.00   0.00   0.00
gil                     53274    61471   0.00   0.00   0.00   0.00   0.00
/usr/bin/sh            397320   839883   0.00   0.00   0.00   0.00   0.00
rpc.lockd              249982   434389   0.00   0.00   0.00   0.00   0.00
/usr/bin/sh            397318   839881   0.00   0.00   0.00   0.00   0.00
swapper                     0        3   0.00   0.00   0.00   0.00   0.00
afsd                    65776   274495   0.00   0.00   0.00   0.00   0.00
/etc/syncd             118882   258175   0.00   0.00   0.00   0.00   0.00
/etc/syncd             118882   196839   0.00   0.00   0.00   0.00   0.00
=======                   ===      ===  ===== ======   ==== ======  =====
Total                                  100.00  64.70   0.00  35.29   0.00

	Total Samples = 24749	Total Elapsed Time = 61.88s

Esta salida muestra que el proceso Java™ con ID de proceso (PID) 467018 está utilizando la mayor parte del tiempo de CPU. También puede ver que el tiempo de CPU se comparte entre cuatro hebras dentro del proceso (ID de hebra 819317, 766019, 725211 y 712827).

Comprendiendo lo que representan las columnas, puede llegar a comprender lo que hacen las hebras:

Total: Porcentaje total de tiempo de CPU utilizado por esta hebra o este proceso.
Kernel: Porcentaje total de tiempo de CPU utilizado por esta hebra o este proceso en las rutinas de kernel (en nombre de una solicitud de la JVM u otro código nativo).
Usuario: Porcentaje total de tiempo de CPU utilizado para ejecutar rutinas del ejecutable. Puesto que el ejecutable Java es un derivador ligero que carga la JVM desde bibliotecas compartidas, se espera que este tiempo de CPU sea muy pequeño o cero.
Compartida: Porcentaje total de tiempo de CPU utilizado para ejecutar rutinas dentro de bibliotecas compartidas. El tiempo que se muestra en esta categoría abarca el trabajo realizado por la propia JVM, la compilación de JIT (pero no la ejecución del código posterior) y cualquier otro código JNI nativo.
Otros: Porcentaje total de tiempo de CPU no incluido en Kernel, Usuario y Comp. En el caso de un proceso Java, este tiempo de CPU cubre la ejecución de códigos de bytes Java y los propios métodos compilados por JIT.

En el ejemplo anterior, observe los valores Kernel y Shared: estos tienen en cuenta todo el tiempo de CPU utilizado por este proceso, lo que indica que el proceso Java está dedicando su tiempo a realizar trabajo dentro de la JVM (o algún otro código nativo).

Para comprender lo que se hace durante los tiempos de Kernel y Comp., se pueden analizar las secciones correspondientes de la salida tprof.

La sección de biblioteca compartida muestra qué bibliotecas compartidas se están invocando:

Shared Object                                                  %  
=============                                                          ======
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9gc26.so  17.42
/usr/lib/libc.a[shr.o]                                                   9.38
/usr/lib/libpthreads.a[shr_xpg5.o]                                       6.94
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9thr26.so   1.03
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9prt26.so   0.24
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9vm26.so   0.10
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9ute26.so   0.06
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9jit26.so   0.05
/usr/lib/libtrace.a[shr.o]                                               0.04
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9trc26.so   0.02
/work/JDK/inst.images/rios_aix32_8/sdk/jre/bin/libj9hookable26.so   0.01

Esta sección muestra que casi todo el tiempo se está empleando en una biblioteca compartida determinada, que forma parte de la instalación de JVM: libj9gc<vm_version>.so, donde < versión_vm> es la versión de la máquina virtual J9 (compruebe la salida del mandato java -version para confirmar el nivel de VM). Si comprende las funciones que realizan las bibliotecas de la JVM más habitualmente utilizadas, podrá obtener una imagen más precisa de lo que hacen las hebras:

libbcv<vm_version>.so: Verificador de código de byte
libdbg<vm_version>.so: Servidor de depuración (utilizado por la interfaz de depuración Java)
libj9gc<vm_version>.so: Recogida de basura
libj9jextract.so: El extractor de volcados, que utiliza el mandato jextract
libj9jit<vm_version>.so: El compilador JIT (Just In Time)
libj9jvmti<vm_version>.so: La interfaz JVMTI
libj9prt<vm_version>.so: La capa de puerto entre la JVM y el sistema operativo
libj9shr<vm_version>.so: La biblioteca de clases compartida
libj9thr<vm_version>.so: La biblioteca de hebras
libj9ute<vm_version>.so: El motor de rastreo
libj9vm<vm_version>.so: La máquina virtual de núcleo
libj9zlib<vm_version>.so: La biblioteca de programas de utilidad de archivos comprimidos
libjclscar_<vm_version>.so: Las rutinas de soporte de la biblioteca de clases Java (JCL)

En el ejemplo anterior, el tiempo de CPU se utiliza en la implementación de la recopilación de basura, lo que implica que hay un problema en la recopilación de basura o que la recopilación de basura se ejecuta casi continuamente.

De nuevo, puede obtener una comprensión más precisa de lo que ocurre dentro de la biblioteca de libj9gc<vm_version>.so durante el tiempo de CPU analizando la sección relevante de la salida de tprof :

Profile: /work/JDK/inst.images/rios_aix32_9/sdk/bin/
                                                      libj9gc26.so

  Total % For All Processes (/work/JDK/inst.images/rios_aix32_9/
                                 sdk/bin/libj9gc26.so) = 17.42

Subroutine                                            %   Source              
==========                                         ====== ======              
Scheme::scanMixedObject(MM_Environment*,J9Object*)   2.67 MarkingScheme.cpp   
MarkingScheme::scanClass(MM_Environment*,J9Class*)   2.54 MarkingScheme.cpp   
.GC_ConstantPoolObjectSlotIterator::nextSlot()       1.96 jectSlotIterator.cpp
lelTask::handleNextWorkUnit(MM_EnvironmentModron*)   1.05 ParallelTask.cpp    
orkPackets::getPacket(MM_Environment*,MM_Packet**)   0.70 WorkPackets.cpp     
cheme::fixupRegion(J9Object*,J9Object*,bool,long&)   0.67 CompactScheme.cpp   
WorkPackets::putPacket(MM_Environment*,MM_Packet*)   0.47 WorkPackets.cpp     
rkingScheme::scanObject(MM_Environment*,J9Object*)   0.43 MarkingScheme.cpp   
sweepChunk(MM_Environment*,MM_ParallelSweepChunk*)   0.42 allelSweepScheme.cpp
ment*,J9IndexableObject*,J9Object**,unsigned long)   0.38 MarkingScheme.cpp   
M_CompactScheme::getForwardingPtr(J9Object*) const   0.36 CompactScheme.cpp   
ObjectHeapIteratorAddressOrderedList::nextObject()   0.33 dressOrderedList.cpp
ckets::getInputPacketFromOverflow(MM_Environment*)   0.32 WorkPackets.cpp     
.MM_WorkStack::popNoWait(MM_Environment*)            0.31 WorkStack.cpp       
WorkPackets::getInputPacketNoWait(MM_Environment*)   0.29 WorkPackets.cpp     
canReferenceMixedObject(MM_Environment*,J9Object*)   0.29 MarkingScheme.cpp   
MarkingScheme::markClass(MM_Environment*,J9Class*)   0.27 MarkingScheme.cpp   
._ptrgl                                              0.26 ptrgl.s             
_MarkingScheme::initializeMarkMap(MM_Environment*)   0.25 MarkingScheme.cpp   
.MM_HeapVirtualMemory::getHeapBase()                 0.23 eapVirtualMemory.cpp

Esta salida muestra que las funciones más utilizadas son las siguientes:

MarkingScheme::scanMixedObject(MM_Environment*,J9Object*)   	
                                       2.67 MarkingScheme.cpp   
MarkingScheme::scanClass(MM_Environment*,J9Class*)   			
                                       2.54 MarkingScheme.cpp
ObjectSlotIterator.GC_ConstantPoolObjectSlotIterator::nextSlot()  
                                       1.96 ObjectSlotIterator.cpp
ParallelTask::handleNextWorkUnit(MM_EnvironmentModron*)   		
                                       1.05 ParallelTask.cpp

Los valores muestran el tiempo utilizado durante la fase de marca de la recopilación de basura. Debido a que la salida contiene también referencias a las fases de compactar y barrido, la recopilación de basura probablemente se está completando pero se está produciendo continuamente. Podría confirmar esa probabilidad ejecutando con -verbosegc habilitado.

La misma metodología que se ha mostrado anteriormente se puede utilizar para cualquier caso donde la mayor parte del tiempo de CPU se muestre que está en las columnas Kernel y Comp. Sin embargo, si el tiempo de CPU se clasifica comoOther, se necesita una metodología diferente porque tprof no contiene una sección que detalla correctamente qué métodos Java se están ejecutando.

En el caso de que el tiempo de CPU se atribuya aOther, puede utilizar un volcado Java para determinar el rastreo de pila para los TID que se muestra que están tomando el tiempo de CPU y, por lo tanto, proporcionar una idea del trabajo que está realizando. Correlacione el valor de TID que se muestra en la salida de tprof con la hebra correcta en el volcado Java tomando el TID de tprof, que se almacena en decimal, y convirtiéndolo a hexadecimal. El valor hexadecimal se muestra comonative IDen el volcado Java.

Para el ejemplo anterior:

Process            PID      TID  Total Kernel   User Shared  Other
=======            ===      ===  ===== ======   ==== ======  =====
./java            7018   819317  16.68   5.55   0.00  11.13   0.00

Esta hebra es la que utiliza más CPU; el TID en decimal es 819317. Este valor es C8075 en hexadecimal, lo que se puede ver en el volcado Java:

3XMTHREADINFO      "main" (TID:0x300E3500, sys_thread_t:0x30010734, 
                             state:R, native ID:0x000C8075) prio=5
4XESTACKTRACE          at java/lang/Runtime.gc(Native Method)
4XESTACKTRACE          at java/lang/System.gc(System.java:274)
4XESTACKTRACE          at GCTest.main(GCTest.java:5)

Estas entradas muestran que, en este caso, la hebra llama a la recogida de basura, y explica el tiempo utilizando en la biblioteca compartida de libj9gc<vm_version>.so.