tutorial - Java VisualVM proporciona resultados extraños para la creación de perfiles de CPU. ¿Alguien más se ha topado con esto?

visualvm remote

Question

He escrito esta clase pequeña (y brutalmente ineficiente) y quise perfilarla utilizando Java VisualVM.

public class Test {
public static void main(String[] args) throws IOException {
BufferedReader br = new BufferedReader(new InputStreamReader(System.in));
br.readLine();
int n = Integer.parseInt(args[0]);
int fib = fib(n);
System.out.println(fib);
}
private static int fib(int n) {
if (n < 2) {
return n;
}
return fib(n-1)+fib(n-2);
}
}

Los resultados son extraños. Los resultados están completamente dominados por las llamadas a ConnectionHandler.run ().

(98.2%) sun.rmi.transport.tcp.TCPTransport $ ConnectionHandler.run ()
(1.7%) java.lang.Thread.join (largo)
(0%) java.lang.String.equals (objeto)
etc ...

Probablemente hay alrededor de cien métodos perfilados y ninguno de ellos es fib (int).

Es inconcebible que mi programa realmente esté gastando todo su tiempo en estos métodos. Parecen ser el generador de perfiles que se conecta a mi jvm y hace su trabajo.

¿Qué estoy haciendo mal?

Editado para mayor claridad: si pasa 45 para el n, esta aplicación se ejecuta durante 20 segundos bien perfilados. El programa que estaba perfilando originalmente (no una calculadora de fibonacci) fija los cuatro núcleos en mi cpu al 100% y estaba haciendo ejecuciones de perfilado que duraron hasta 5 minutos. Estos tuvieron los mismos resultados y los métodos de mi aplicación no aparecieron en la lista de métodos de puntos calientes.

Varía de una ejecución a otra, pero ConnectionHandler.run () siempre está en la parte superior y generalmente representa alrededor del 99% del tiempo del perfil.

Segunda edición: He intentado usar la muestra y ahora estoy obteniendo resultados que son consistentes con lo que JProfiler está produciendo. La desventaja de esto es que no obtengo la información de seguimiento de pila que viene con el perfil. Pero para mis necesidades inmediatas esto es excelente.

Algo que descubrí mientras jugaba es que VisualVM cuenta el tiempo del reloj de pared para las llamadas de método mientras las perfila.

En mi caso específico, mi aplicación tiene un subproceso principal que inicia subprocesos de trabajo e inmediatamente bloquea la espera de un mensaje en una cola.

Esto significa que el método de bloqueo parecerá ocupar casi todo el tiempo en el generador de perfiles a pesar del hecho de que no es este el método que está consumiendo mi CPU.

Espero que suceda lo mismo con el método sun.rmi.transport.tcp.TCPTransport $ ConnectionHandler.run () que hace su trabajo muy bien, pero cuando termina, se convierte en uno de los métodos de ejecución más largos en mi aplicación, repetidamente .

Answer 1

Basándose en la respuesta de Ron, fue capaz de mejorar el resultado al detener la JVM justo después del inicio, luego se activó el generador de perfiles y, finalmente, se continuó la extracción (presionando Intro). Es crudo

class Foobar {
/* First line in Class */
static {
try {
System.in.read();
} catch (IOException e) {
throw new RuntimeException(e);
}
}
/* .. */
public static void main(..) {
doMagic()
}
} 

Answer 2

El perfil de jvisualvm probablemente teje los códigos de bytes en clases a medida que se cargan. Dado que su programa solo tiene una clase y ya está inicializado para cuando jvisualvm llega a la escena, supongo que no se puede instrumentar.

Mueva su método de fib en otra clase e intente perfilar nuevamente. Puede agregar una opción jvm "-verbose: class" para verificar que la clase no esté cargada antes de habilitar el perfil de la CPU en jvisualvm.

Edit: Gracias JB por el comentario. Olvídate de mi clase cargando tonterías. Mi intuición es que el método fib está demasiado unido al método principal, por lo que efectivamente se está ejecutando el bytecode.

Answer 3

Mi conjetura es que usted está pasando un valor demasiado pequeño a fib, y el programa simplemente no se ejecuta lo suficiente como para registrarse. Para obtener datos significativos para casi cualquier cosa al hacer un perfil (o una evaluación comparativa), generalmente necesita un tiempo transcurrido de al menos unos segundos.

Answer 4

No creo que eso sea inconcebible en absoluto. Tiene una aplicación donde la "carga útil" es bastante minúscula (aunque eso por supuesto depende del valor de n ), y tiene que aceptar que el esfuerzo adicional requerido (para conectar el generador de perfiles y transferir toda la información) será Pantano que carga útil.

Este no es el tipo de aplicación que estaría perfilando en primer lugar, ya que es bastante obvio que la gran cantidad de tiempo se gastaría en fib todos modos (para valores no triviales de n ), marcando eso como un objetivo obvio para la optimización.

Estaría más inclinado a usar el perfilador para aplicaciones más sustanciales donde:

• no es obvio dónde debe ir el esfuerzo de optimización; y
• Hay una cantidad sustancial de trabajo que hacer en la carga útil.

Si realmente desea probar ese código, probablemente necesite aumentar su efecto (por ejemplo) reemplazando:

int fib = fib(n);

con:

for (int i = 0; i < 100000; i++) {
int fib = fib(n);
)

Aunque te diré una cosa para tener cuidado. No conozco las partes internas de ninguna JVM en particular, pero usar una metodología recursiva en la que la reducción del argumento sea lenta suele ser una mala idea, lo que hace que el espacio de pila se agote con bastante rapidez.

Con eso, me refiero a que una búsqueda binaria es un buen candidato, ya que elimina la mitad del espacio de búsqueda restante con cada nivel de recursión (de modo que un espacio de búsqueda de mil millones de elementos es solo de 30 niveles).

Por otro lado, usar la recursión para una secuencia de Fibonacci en el número 1,000,000,000 tomaría alrededor de mil millones de niveles y la mayoría de las pilas tendrían dificultades para contener eso.

La optimización de la recursión del final de la cola puede evitar ese problema, pero debe tener cuidado en caso de que la optimización no se realice.