Recolector de basura en Ruby 2.2 provoca CO inesperado

garbage-collection fork

Question

¿Cómo evito que el GC provoque copiado sobre escritura cuando doblo mi proceso? Recientemente, he estado analizando el comportamiento del recolector de basura en Ruby, debido a algunos problemas de memoria que encontré en mi programa (me quedo sin memoria en mi máquina 60core de 60 TB, incluso para tareas bastante pequeñas). Para mí, esto realmente limita la utilidad de ruby ​​para ejecutar programas en servidores multinúcleo. Me gustaría presentar mis experimentos y resultados aquí.

El problema surge cuando el recolector de basura se ejecuta durante la bifurcación. Investigué tres casos que ilustran el problema.

Caso 1: Asignamos una gran cantidad de objetos (cadenas de no más de 20 bytes) en la memoria usando una matriz. Las cadenas se crean usando un número aleatorio y un formato de cadena. Cuando el proceso se bifurca y obligamos al GC a ejecutarse en el niño, toda la memoria compartida se vuelve privada, lo que causa una duplicación de la memoria inicial.

Caso 2: Asignamos una gran cantidad de objetos (cadenas) en la memoria utilizando una matriz, pero la cadena se crea con la función rand.to_s, por lo tanto, eliminamos el formato de los datos en comparación con el caso anterior. Terminamos con una menor cantidad de memoria que se utiliza, presumiblemente debido a una menor cantidad de basura. Cuando el proceso se bifurca y obligamos al GC a ejecutarse en el niño, solo parte de la memoria se vuelve privada. Tenemos una duplicación de la memoria inicial, pero en menor medida.

Caso 3: Asignamos menos objetos en comparación con el anterior, pero los objetos son más grandes, de modo que la cantidad de memoria asignada permanece igual que en los casos anteriores. Cuando el proceso se bifurca y obligamos al GC a ejecutarse en el niño, toda la memoria permanece compartida, es decir, sin duplicación de memoria.

Aquí pego el código de Ruby que se ha usado para estos experimentos. Para alternar entre casos, solo necesita cambiar el valor de "opción" en la función memory_object. El código fue probado usando Ruby 2.2.2, 2.2.1, 2.1.3, 2.1.5 y 1.9.3 en una máquina Ubuntu 14.04.

Muestra de salida para el caso 1:

ruby version 2.2.2 
 proces   pid log                   priv_dirty   shared_dirty 
 Parent  3897 post alloc                   38            0 
 Parent  3897 4 fork                        0           37 
 Child   3937 4 initial                     0           37 
 Child   3937 8 empty GC                   35            5 

El mismo código ha sido escrito en Python y en todos los casos el CoW funciona perfectamente bien.

Muestra de salida para el caso 1:

python version 2.7.6 (default, Mar 22 2014, 22:59:56) 
[GCC 4.8.2] 
 proces   pid log                   priv_dirty shared_dirty 
 Parent  4308 post alloc                35             0 
 Parent  4308 4 fork                     0            35 
 Child   4309 4 initial                  0            35 
 Child   4309 10 empty GC                1            34 

Código Ruby

$start_time=Time.new

# Monitor use of Resident and Virtual memory.
class Memory

    shared_dirty = ''.+?Shared_Dirty:/s+(/d+)''
    priv_dirty = ''.+?Private_Dirty:/s+(/d+)''
    MEM_REGEXP = /#{shared_dirty}#{priv_dirty}/m

    # get memory usage
    def self.get_memory_map( pids)
        memory_map = {}
        memory_map[ :pids_found] = {}
        memory_map[ :shared_dirty] = 0
        memory_map[ :priv_dirty] = 0

        pids.each do |pid|
            begin
                lines = nil
                lines = File.read( "/proc/#{pid}/smaps")
            rescue
                lines = nil
            end
            if lines
                lines.scan(MEM_REGEXP) do |shared_dirty, priv_dirty|
                    memory_map[ :pids_found][pid] = true
                    memory_map[ :shared_dirty] += shared_dirty.to_i
                    memory_map[ :priv_dirty] += priv_dirty.to_i
                end
            end
        end
        memory_map[ :pids_found] = memory_map[ :pids_found].keys
        return memory_map
    end

    # get the processes and get the value of the memory usage
    def self.memory_usage( )
        pids   = [ $$]
        result = self.get_memory_map( pids)

        result[ :pids]   = pids
        return result
    end

    # print the values of the private and shared memories
    def self.log( process_name='''', log_tag="")
        if process_name == "header"
            puts " %-6s %5s %-12s %10s %10s/n" % ["proces", "pid", "log", "priv_dirty", "shared_dirty"]
        else
            time = Time.new - $start_time
            mem = Memory.memory_usage( )
            puts " %-6s %5d %-12s %10d %10d/n" % [process_name, $$, log_tag, mem[:priv_dirty]/1000, mem[:shared_dirty]/1000]
        end
    end
end

# function to delay the processes a bit
def time_step( n)
    while Time.new - $start_time < n
        sleep( 0.01)
    end
end

# create an object of specified size. The option argument can be changed from 0 to 2 to visualize the behavior of the GC in various cases
#
# case 0 (default) : we make a huge array of small objects by formatting a string
# case 1 : we make a huge array of small objects without formatting a string (we use the to_s function)
# case 2 : we make a smaller array of big objects
def memory_object( size, option=1)
    result = []
    count = size/20

    if option > 3 or option < 1
        count.times do
            result << "%20.18f" % rand
        end
    elsif option == 1
        count.times do
            result << rand.to_s
        end
    elsif option == 2
        count = count/10
        count.times do
            result << ("%20.18f" % rand)*30
        end
    end

    return result
end

##### main #####

puts "ruby version #{RUBY_VERSION}"

GC.disable

# print the column headers and first line
Memory.log( "header")

# Allocation of memory
big_memory = memory_object( 1000 * 1000 * 10)

Memory.log( "Parent", "post alloc")

lab_time = Time.new - $start_time
if lab_time < 3.9
    lab_time = 0
end

# start the forking
pid = fork do
    time = 4
    time_step( time + lab_time)
    Memory.log( "Child", "#{time} initial")

    # force GC when nothing happened
    GC.enable; GC.start; GC.disable

    time = 8
    time_step( time + lab_time)
    Memory.log( "Child", "#{time} empty GC")

    sleep( 1)
    STDOUT.flush
    exit!
end

time = 4
time_step( time + lab_time)
Memory.log( "Parent", "#{time} fork")

# wait for the child to finish
Process.wait( pid)

Código de Python

import re
import time
import os
import random
import sys
import gc

start_time=time.time()

# Monitor use of Resident and Virtual memory.
class Memory:   

    def __init__(self):
        self.shared_dirty = ''.+?Shared_Dirty:/s+(/d+)''
        self.priv_dirty = ''.+?Private_Dirty:/s+(/d+)''
        self.MEM_REGEXP = re.compile("{shared_dirty}{priv_dirty}".format(shared_dirty=self.shared_dirty, priv_dirty=self.priv_dirty), re.DOTALL)

    # get memory usage
    def get_memory_map(self, pids):
        memory_map = {}
        memory_map[ "pids_found" ] = {}
        memory_map[ "shared_dirty" ] = 0
        memory_map[ "priv_dirty" ] = 0

        for pid in pids:
            try:
                lines = None

                with open( "/proc/{pid}/smaps".format(pid=pid), "r" ) as infile:
                    lines = infile.read()
            except:
                lines = None

            if lines:
                for shared_dirty, priv_dirty in re.findall( self.MEM_REGEXP, lines ):
                    memory_map[ "pids_found" ][pid] = True
                    memory_map[ "shared_dirty" ] += int( shared_dirty )
                    memory_map[ "priv_dirty" ] += int( priv_dirty )     

        memory_map[ "pids_found" ] = memory_map[ "pids_found" ].keys()
        return memory_map

    # get the processes and get the value of the memory usage   
    def memory_usage( self):
        pids   = [ os.getpid() ]
        result = self.get_memory_map( pids)

        result[ "pids" ]   = pids

        return result

    # print the values of the private and shared memories
    def log( self, process_name='''', log_tag=""):
        if process_name == "header":
            print " %-6s %5s %-12s %10s %10s" % ("proces", "pid", "log", "priv_dirty", "shared_dirty")
        else:
            global start_time
            Time = time.time() - start_time
            mem = self.memory_usage( )
            print " %-6s %5d %-12s %10d %10d" % (process_name, os.getpid(), log_tag, mem["priv_dirty"]/1000, mem["shared_dirty"]/1000)

# function to delay the processes a bit
def time_step( n):
    global start_time
    while (time.time() - start_time) < n:
        time.sleep( 0.01)

# create an object of specified size. The option argument can be changed from 0 to 2 to visualize the behavior of the GC in various cases
#
# case 0 (default) : we make a huge array of small objects by formatting a string
# case 1 : we make a huge array of small objects without formatting a string (we use the to_s function)
# case 2 : we make a smaller array of big objects                                       
def memory_object( size, option=2):
    count = size/20

    if option > 3 or option < 1:
        result = [ "%20.18f"% random.random() for i in xrange(count) ]

    elif option == 1:
        result = [ str( random.random() ) for i in xrange(count) ]

    elif option == 2:
        count = count/10
        result = [ ("%20.18f"% random.random())*30 for i in xrange(count) ]

    return result

##### main #####

print "python version {version}".format(version=sys.version)

memory = Memory()

gc.disable()

# print the column headers and first line
memory.log( "header")   # Print the headers of the columns

# Allocation of memory
big_memory = memory_object( 1000 * 1000 * 10)   # Allocate memory

memory.log( "Parent", "post alloc")

lab_time = time.time() - start_time
if lab_time < 3.9:
    lab_time = 0

# start the forking
pid = os.fork()     # fork the process
if pid == 0:
    Time = 4
    time_step( Time + lab_time)
    memory.log( "Child", "{time} initial".format(time=Time))

    # force GC when nothing happened
    gc.enable(); gc.collect(); gc.disable();

    Time = 10
    time_step( Time + lab_time)
    memory.log( "Child", "{time} empty GC".format(time=Time))

    time.sleep( 1)

    sys.exit(0)

Time = 4
time_step( Time + lab_time)
memory.log( "Parent", "{time} fork".format(time=Time))

# Wait for child process to finish
os.waitpid( pid, 0)

EDITAR

De hecho, llamar al GC varias veces antes de hornear el proceso resuelve el problema y estoy bastante sorprendido. También he ejecutado el código usando Ruby 2.0.0 y el problema ni siquiera aparece, por lo que debe estar relacionado con este GC generacional tal como lo mencionó. Sin embargo, si llamo a la función memory_object sin asignar el resultado a ninguna variable (solo estoy creando basura), entonces la memoria está duplicada. La cantidad de memoria que se copia depende de la cantidad de basura que creo: cuanto más basura, más memoria se vuelve privada.

¿Alguna idea de cómo puedo prevenir esto?

Aquí hay algunos resultados

Ejecutando el GC en 2.0.0

ruby version 2.0.0
 proces   pid log          priv_dirty shared_dirty
 Parent  3664 post alloc           67          0
 Parent  3664 4 fork                1         69
 Child   3700 4 initial             1         69
 Child   3700 8 empty GC            6         65

Llamando a memory_object (1000 * 1000) en el niño

ruby version 2.0.0
 proces   pid log          priv_dirty shared_dirty
 Parent  3703 post alloc           67          0
 Parent  3703 4 fork                1         70
 Child   3739 4 initial             1         70
 Child   3739 8 empty GC           15         56

Llamar memory_object (1000 * 1000 * 10)

ruby version 2.0.0
 proces   pid log          priv_dirty shared_dirty
 Parent  3743 post alloc           67          0
 Parent  3743 4 fork                1         69
 Child   3779 4 initial             1         69
 Child   3779 8 empty GC           89          5

Answer 1

UPD2

De repente descubrió por qué toda la memoria se vuelve privada si formatea la cadena: genera basura durante el formateo, tiene GC inhabilitado, luego habilita GC, y tiene agujeros de objetos liberados en sus datos generados. Luego te bifurcas y la basura nueva comienza a ocupar estos agujeros, más basura, más páginas privadas.

Así que agregué una función de limpieza para ejecutar GC cada 2000 ciclos (solo habilitar el GC lento no ayudó):

count.times do |i|
  cleanup(i)
  result << "%20.18f" % rand
end

#......snip........#

def cleanup(i)
      if ((i%2000).zero?)
        GC.enable; GC.start; GC.disable
      end
end   

##### main #####

Que dio como resultado (con generación de memory_object( 1000 * 1000 * 10) después del tenedor):

RUBY_GC_HEAP_INIT_SLOTS=600000 ruby gc-test.rb 0
ruby version 2.2.0
 proces   pid log          priv_dirty shared_dirty
 Parent  2501 post alloc           35          0
 Parent  2501 4 fork                0         35
 Child   2503 4 initial             0         35
 Child   2503 8 empty GC           28         22

Sí, afecta el rendimiento, pero solo antes de bifurcar, es decir, aumentar el tiempo de carga en su caso.

UPD1

Acabo de encontrar los criterios por los cuales ruby ​​2.2 establece viejos bits de objetos, son 3 GC, por lo que si agrega los siguientes antes de bifurcar:

GC.enable; 3.times {GC.start}; GC.disable
# start the forking

obtendrá (la opción es 1 en la línea de comando):

$ RUBY_GC_HEAP_INIT_SLOTS=600000 ruby gc-test.rb 1
ruby version 2.2.0
 proces   pid log          priv_dirty shared_dirty
 Parent  2368 post alloc           31          0
 Parent  2368 4 fork                1         34
 Child   2370 4 initial             1         34
 Child   2370 8 empty GC            2         32

Pero esto necesita ser probado más con respecto al comportamiento de tales objetos en los futuros GC, al menos después de 100 GC :old_objects permanece constante, así que supongo que debería estar bien.

Iniciar sesión con GC.stat está aquí

Por cierto, también existe la opción RGENGC_OLD_NEWOBJ_CHECK para crear objetos antiguos desde el principio, pero dudo que sea una buena idea, pero puede ser útil para un caso particular.

Primera respuesta

Mi proposición en el comentario anterior era incorrecta, en realidad las tablas de mapas de bits son el salvador.

(option = 1)

ruby version 2.0.0
 proces   pid log          priv_dirty shared_dirty
 Parent 14807 post alloc           27          0
 Parent 14807 4 fork                0         27
 Child  14809 4 initial             0         27
 Child  14809 8 empty GC            6         25 # << almost everything stays shared <<

También tuve a mano y probé Ruby Enterprise Edition, es solo la mitad de mejor que los peores casos.

ruby version 1.8.7
 proces   pid log          priv_dirty shared_dirty
 Parent 15064 post alloc           86          0
 Parent 15064 4 fork                2         84
 Child  15065 4 initial             2         84
 Child  15065 8 empty GC           40         46

(Hice que el script se ejecutara estrictamente 1 GC, aumentando RUBY_GC_HEAP_INIT_SLOTS a 600k)