Anterior: Analizador Subir: Tabla de Contenido Siguiente: Cómos

Análisis de Memoria

This topic has missing or partial documentation. Please help us improve it.

See How-To - Write Documentation

Rubinius provee una interface que permite escribir el estado del heap actual a un archivo para hacer análisis posterior. Varios proyectos complementarios analizan estos dumps del heap y ayudan a descubrir fugas de memoria, colecciones muy grandes y problemas con el código que podrían generar desperdicio de memoria en tiempo de ejecución.

Un Programa de Ejemplo

El siguiente código (que no incluye chequeo de errores) servirá como base para un tour guiado a través del proceso de buscar una fuga de memoria en Ruby, y a la vez, para encontrar una fuga en el sistema subyacente que utiliza FFI.

Este código de ejemplo es un poco artificial pero sirve para ilustrar varios problemas del mundo real.

require 'rubygems'
require 'ffi-rzmq'

if ARGV.length < 3
  puts "usage: ruby leak.rb <connect-to> <message-size> <roundtrip-count>"
  exit
end

link = ARGV[0]
message_size = ARGV[1].to_i
roundtrip_count = ARGV[2].to_i

ctx = ZMQ::Context.new
request_socket = ctx.socket ZMQ::REQ
reply_socket = ctx.socket ZMQ::REP

request_socket.connect link
reply_socket.bind link

poller = ZMQ::Poller.new
poller.register_readable request_socket
poller.register_readable reply_socket

start_time = Time.now

message = ZMQ::Message.new("a" * message_size)
request_socket.send message, ZMQ::NOBLOCK
i = roundtrip_count
messages = []

until i.zero?
  i -= 1

  poller.poll_nonblock

  poller.readables.each do |socket|
    message = ZMQ::Message.new
    socket.recv message, ZMQ::NOBLOCK
    messages << message
    socket.send ZMQ::Message.new(message.copy_out_string), ZMQ::NOBLOCK
  end
end

elapsed_usecs = (Time.now.to_f - start_time.to_f) * 1_000_000
latency = elapsed_usecs / roundtrip_count / 2

puts "mean latency: %.3f [us]" % latency
puts "received #{messages.size} messages in #{elapsed_usecs / 1_000_000} seconds"

Vaya, este programa tiene más fugas que un cedazo. Veamos por qué.

Guardando un Head Dump

Rubinius provee acceso a la VM mediante una interfaz de agente. El agente abre un socket en la red y responde a comandos enviados desde el programa de consola. El agente debe ser iniciado con el programa.

rbx -Xagent.start <script name>

Ejecute el programa de prueba con el agente activado.

rbx -Xagent.start leak.rb

Conéctese al agente usando la consola de rbx. Este programa abre una sesión interactiva con el agente que se está ejecutando dentro de la VM. Los comandos son enviados al agente. En este caso, vamos a guardar un head dump para hacer un análisis posterior.

Al iniciar, el agente crea un archivo en $TMPDIR/rubinius-agent.\<pid> que contiene algunos detalles importantes para la consola de rbx. Al salir, el agente automáticamente elimina el archivo. Si existe un problema con el programa es posible que este archivo no sea eliminado, en este caso debe eliminarse manualmente.

$ rbx console
VM: rbx -Xagent.start leak.rb tcp://127.0.0.1:5549 1024 100000000
Connecting to VM on port 60544
Connected to localhost:60544, host type: x86_64-apple-darwin10.5.0
console> set system.memory.dump heap.dump
console> exit

El comando es set system.memory.dump <filename>. El archivo del head dump es creado en el directorio donde actualmente se está ejecutando el programa que corre el agente.

Analizando un Head Dump

El archivo de volcado del head dump es creado usando un formato bien documentado. A la fecha existen dos herramientas que son capaces de leer e interpretar este formato. Estos proyectos no forman parte de la distribución de Rubinius.

Puede encontrar head_dump en la página del proyecto.

Esta herramienta lee el archivo de volcado y devuelve información útil en 3 columnas que corresponden a el número de objetos visibles en el heap, la clase del objeto y el número total de bytes que fueron consumidos por todas las instancias de esta clase.

Al ejecutar esta herramienta, pasándole como parámetro el archivo de volcado que obtuvimos en nuestro programa leak.rb, podemos ver una pequeña pista de donde está la fuga de memoria. La siguiente salida ha sido editada para incluir solamente datos relevantes.

$ rbx -I /path/to/heap_dump/lib /path/to/heap_dump/bin/histo.rb heap.dump
    169350   Rubinius::CompactLookupTable 21676800
    168983             FFI::MemoryPointer 6759320
    168978                   ZMQ::Message 8110944
    168978                    LibZMQ::Msg 6759120
     27901                Rubinius::Tuple 6361528
     15615                         String 1124280
     13527            Rubinius::ByteArray 882560
      3010                          Array 168560
       825                    Hash::Entry 46200
       787       Rubinius::AccessVariable 62960
        87                           Time 4872
        41                           Hash 3280
        12                   FFI::Pointer 480
         2                    ZMQ::Socket 96

Aunque no se puede ver nada muy escandaloso en este ejemplo, algunos hechos son notables.

  1. La mayor cantidad de bytes es consumida por Rubinius::CompactLookupTable que es una clase que nuestro código nunca instancia directamente (y según los resultados de head_dump, consume alrededor de 20MB). Podemos ver entonces que algunas estructuras de Rubinius son reportadas en el archivo de volcado. Es interesante pero no nos ayuda a encontrar nuestra fuga.

  2. La clase ZMQ::Message en la línea 3 es la primera clase que nuestro código instancia directamente. Existen alrededor de 170k instancias, así que probablemente podremos encontrar nuestra fuga de memoria aquí.

Algunas veces una muestra única no es suficiente para hallar una fuga. En ese caso deberíamos tomar varias muestras del heap en tiempos diferentes y dejar que head_dump haga un análisis de diff. El diff muestra lo que ha cambiado en el heap en el antes y después.

$ rbx -I /path/to/heap_dump/lib /path/to/heap_dump/bin/histo.rb heap.dump heap2.dump
203110   Rubinius::CompactLookupTable 25998080
203110                   ZMQ::Message 9749280
203110                    LibZMQ::Msg 8124400
203110             FFI::MemoryPointer 8124400

Este diff muestra claramente la fuente del consumo de memoria. El código tiene 200k instancias adicionales de ZMG::Message entre el primer y el segundo volcado del heap así que es allí donde está sucediendo el crecimiento desmedido de memoria.

Examinando el código podemos ver que una de estas dos líneas es posiblemente la culpable.

messages << message
...
puts "received #{messages.size} messages in #{elapsed_usecs / 1_000_000} seconds"

Definitivamente no es necesario guardar cada mensaje para obtener el número total de mensajes al final de la ejecución. Al revisar el código podemos ver que usando una variable contadora podemos solucionar la fuga de memoria.

Herramientas Avanzados - Solamente OS X

Después de modificar el código Ruby para utilizar un contador (dejando así que el recolector de basura maneje todas las instancias de ZMQ::Message) vemos que el programa todavía tiene una fuga de memoria. Tomamos dos muestras y las analizamos, pero todavía no sabemos dónde puede estar el problema.

$ rbx -I /path/to/heap_dump/lib /path/to/heap_dump/bin/histo.rb heap3.dump heap4.dump
  -4                          Array -224
 -90                 Digest::SHA256 -4320
 -90          Rubinius::MethodTable -4320
 -90                   Digest::SHA2 -3600
 -90          Rubinius::LookupTable -4320
 -90                          Class -10080
-184                Rubinius::Tuple -29192

Este diff nos muestra que el número de algunas estructuras se encogió entre las dos muestras. Al parecer el problema ya no está en el código de Ruby ya que la VM es quien está consumiendo la memoria que se está fugando.

Afortunadamente existe una excelente herramienta en Mac OS X llamada leaks que puede ayudarnos a encontrar el problema. Adicionalmente, la página de man para malloc provee información sobre una variable de entorno llamada MallockStackLogging que podemos utilizar para incluir una traza de pila (stack trace) al final del archivo de volcado.

$ MallocStackLogging=1 rbx leak.rb tcp://127.0.0.1:5549 1024 10000000 &
$ leaks 36700 > leak.out
$ vi leak.out
leaks Report Version:  2.0
Process:         rbx [36700]
Path:            /Volumes/calvin/Users/cremes/.rvm/rubies/rbx-head/bin/rbx
Load Address:    0x100000000
Identifier:      rbx
Version:         ??? (???)
Code Type:       X86-64 (Native)
Parent Process:  bash [997]

Date/Time:       2010-12-22 11:34:35.225 -0600
OS Version:      Mac OS X 10.6.5 (10H574)
Report Version:  6

Process 36700: 274490 nodes malloced for 294357 KB
Process 36700: 171502 leaks for 263427072 total leaked bytes.
Leak: 0x101bb2400  size=1536  zone: DefaultMallocZone_0x100dea000
        0x01bb2428 0x00000001 0x00000400 0x00000000     ($..............
        0x00000000 0x00000000 0x00000000 0x00000000     ................
        0x00000000 0x00000000 0x61616161 0x61616161     ........aaaaaaaa
        0x61616161 0x61616161 0x61616161 0x61616161     aaaaaaaaaaaaaaaa
        0x61616161 0x61616161 0x61616161 0x61616161     aaaaaaaaaaaaaaaa
        0x61616161 0x61616161 0x61616161 0x61616161     aaaaaaaaaaaaaaaa
        0x61616161 0x61616161 0x61616161 0x61616161     aaaaaaaaaaaaaaaa
        0x61616161 0x61616161 0x61616161 0x61616161     aaaaaaaaaaaaaaaa
        ...
        Call stack: [thread 0x102f81000]: | thread_start | _pthread_start |
        thread_routine | zmq::kqueue_t::loop() | zmq::zmq_engine_t::in_event() |
        zmq::decoder_t::eight_byte_size_ready() | zmq_msg_init_size | malloc |
        malloc_zone_malloc

Podemos ver que en el momento de la muestra tenemos alrededor de 172k fugas. La salida de la pila de llamadas nos muestra que la fuga ocurre durante la llamada a zmq_msg_init_size, lo que no significa nada a menos de que decidamos leer el código fuente donde se implementa ZMQ::Message. Es aquí donde el conocimiento sobre el sistema subyacente es critico; sin más información donde esta llamada es hecha sería mucho más difícil encontrar el problema.

Resulta que la clase ZMQ::Message reserva memoria por medio de malloc sobre la cual no se hace seguimiento en el GC (Garbage Collector) de Rubinius. La de-asignación de esta memoria debe ser hecha manualmente.

Una llamada a ZMQ::Message#close resuelve el problema.

Anterior: Analizador Subir: Tabla de Contenido Siguiente: Cómos

Tweet at @rubinius on Twitter or email community@rubini.us. Please report Rubinius issues to our issue tracker.