Wstecz: Profiler Do góry: Spis treści Dalej: Jak

Analiza pamięci

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

See How-To - Write Documentation

Rubinius udostępnia interfejs do wykonywania zrzutu pamięci (sterty - heap) do pliku w celu analizy. Istnieje kilka narzędzi umożliwiających wykrycie wycieków pamięci, dużych kolekcji obiektów oraz potencjalnych problemów z kodem mogących prowadzić do problemów z pamięcią.

Przykładowy program

Poniższy program będzie służył jako przykład do analizy wycieku pamięci w kodzie Ruby jak również w kodzie korzystającym z podsystemu FFI.

Kod został sztucznie spreparowany jednak posłuży jako dobry przykład problemów z jakimi możemy się spotkać pisząc rzeczywiste programy.

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"

Ten program cieknie jak z durszlaka :). Sprawdźmy dlaczego:

Zapisanie sterty

Rubinius umożliwia dostęp do swojej maszyny wirtualnej poprzez interfejs agenta. Agent otwiera gniazdo sieciowe i odpowiada na polecenia wydawane przez program w konsoli. Agenta uruchamiamy wraz z programem w poniższy sposób.

rbx -Xagent.start <program>

Korzystając z powyższego polecenia uruchomimy zarówno program jak i agenta.

rbx -Xagent.start leak.rb

Teraz możemy nawiązać połączenie z agentem za pomocą konsoli rbx (rbx console). Polecenia wywoływane w konsoli są przekazywane do agenta który działa w tym samym procesie co maszyna wirtualna. Teraz wydamy kilka poleceń które służą do zrzutu pamięci do późniejszej analizy.

Podczas startu agent tworzy plik w katalogu $TMPDIR/rubinius-agent.\<pid> zawierający kilka przydatnych informacji z których korzysta konsola rbx. Kiedy zamkniemy agenta ten plik zostaje przez niego usunięty. W pewnych przypadkach (np. segfault) ten plik może nie zostać usunięty i konieczne będzie jego ręczne usunięcie.

$ 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

Polecenie którym wykonujemy zrzut pamięci to set system.memory.dump <filename>. Plik z zapisem stanu pamięci jest tworzony w katalogu w którym działa program z uruchomionym agentem.

Analiza sterty

Plik ze stertą zostaje zapisany w udokumentowanym formacie. Do tej pory znane nam są 2 narzędzia, które potrafią zinterpretować ten format. Są to projekty odrębne do projektu Rubinius.

Jednym z tych narzędzi jest heap_dump strona domowa projektu.

Heap dump czyta plik ze stertą i wyświetla kilka przydatnych informacji w 3 kolumnach. Informacje te odnoszą się do liczby obiektów widocznych na stercie, ich klas oraz sumy bajtów zajętych przez wszystkie instancje tego obiektu.

Jeśli uruchomimy to narzędzie przekazując mu plik ze stertą z naszego programu leak.rb uzyskamy kilka wskazówek odnośnie tego, gdzie znajduje się wyciek pamięci.

$ 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

Na pierwszy rzut oka nic nie wydaję się być podejrzane. Możemy jednak zauważyć kilka rzeczy.

  1. Najwięcej pamięci (20MB) zajmują obiekty klasy Rubinius::CompactLookupTable. Jest to klasa której nasz kod bezpośrednio nie wywołuje. Dowiadujemy się więc o pewnych wewnętrznych strukturach Rubiniusa. Jest to ciekawe lecz nie pomaga nam w diagnozie problemu.

  2. Klasa ZMQ::Message w linii 3 jest pierwszą klasą, do której nasz kod bezpośrednio się odwołuje. Istnieje 168987 instancji tej klasy więc to jest zapewne nasz wyciek.

Czasami aby lepiej zdiagnozować wyciek nie wystarczy jeden zrzut sterty. W takim wypadku powinniśmy wykonać kilka zrzutów w różnym czasie działania programu i pozwolić programowi "heap dump" wykonać analizę różnic. Analiza różnic pokazuje które obiekty zmieniły się na stercie przed i po.

$ 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

Wynik wyraźnie pokazuje źródło znacznego wzrostu zużycia pamięci. Sterta zyskała 203110 nowych obiektów klasy ZMQ::Message pomiędzy pierwszym i drugim zrzutem.

Badając nasz kod zauważamy 2 podejrzane linie:

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

Z pewnością przechowywanie każdej wiadomości nie jest konieczne aby na końcu uzyskać liczbę wszystkich wiadomości. Zmiana kodu tak aby korzystał z prostej zmiennej zliczającej wiadomości powinno naprawić wyciek.

Zaawansowane narzędzia - tylko OSX

Po naszych modyfikacjach (użycie zmiennej zliczającej) odśmiecacz (GC) zajmuje się poprawnie usunięciem wszystkich instancji ZMQ::Message. Jednak nasz program wciąż cieknie. Wykonanie 2 zrzutów nie pomaga.

$ 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

Powyższa analiza róznicowa pokazuje, że kilka struktur skurczyło się pomiędzy zrzutami a nie powiększyło. Najwyraźniej wyciek nie jest już w kodzie Ruby ponieważ maszyna wirtualna nie jest w stanie wskazać co zajmuje tą pamięć.

Na szczęście jeśli mamy dostęp do systemu Mac OS X mamy również dostęp do programu o nazwie leaks który pomoże nam w wykryciu problemu. Dodatkowo czytając manual do malloc (man malloc) dowiemy się o ustawieniu zmiennej środowiskowej która umożliwi programowi leaks dostęp do aktualnego stanu stosu w miejscu każdego wycieku.

$ 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

Wynik wykonania programu leaks pokazuje, że w momencie zrzutu mieliśmy prawie 172000 wyciekających obiektów. Obraz stosu pokazuje, że wyciek nastąpił podczas wywołania zmq_msg_init_size co nabierze sensu dopiero gdy zagłebimy się w szczegóły implementacji klasy `ZMQ::Message``. W tym miejscu przydaje się znajomość szegółów naszego systemu; bez tej znajomości byłoby trudno namierzyć ten problem.

Okazuje się, że ZMQ::Message alokuje pamięć przy pomocy malloc która to pamięć nie jest kontrolowania przez odśmiecacz Rubiniusa. Pamięć ta musi zostać ręcznie zwolniona.

Zmiana kodu aby wywołał ZMQ::Message#close poprawia ten wyciek.

Wstecz: Profiler Do góry: Spis treści Dalej: Jak

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