Jüngst versuche ich mal wieder ein wenig Memory Leaks in unserer Applikation zu finden. Es ist zwar nicht so, dass die Server “explodieren”, aber bei einem der beiden ist letzthin über 24Std doch schon ein starker Anstieg (~75%) des RAM Verbrauchs nach Start der Prozesse zu verzeichnen. Das lasse ich nun schon seit einigen Wochen schleifen..

Da die Applikationen inzwischen relativ groß sind (~80 Controller Module, ~110 Model Module, so ~400++ Module gesamt) ist das wichtigste erst einmal raus zu finden, welche Aufrufe leaken.  Auf CPAN gibt es (natürlich;)) hierfür schon vorgefertigtige Lösungen, aber leider hat das bei mir nicht geholfen – abgesehen davon, dass es nicht einfach unter Perl 5.8.8 (debian) zu installieren war, scheint es hier eher um die Rückferfolgung eines einzelnen Aufrufes (Controller::Module::method) zu gehen, als um das auffinden selber.

Wie auch immer, der Ansatz ist ganz einfach: Tracken wieviel RAM vor dem Aufruf von dem Prozess verwendet wird, tracken wieviel danach, Differnz bilden und gucken ob diese beim nächste Aufruf wieder freigegeben wurde. Wenn nicht: könnte ein Leak sein.

Da ich – wie wohl die meisten Programmierer – eher ein fauler Mensch bin, möchte ich das alles schön automatisiert im Hintergrund passiert. Daher lasse ich diese Infos einfach über die Catalyst-Debug-Logs ausgeben und parse sie später mit einem anderen kleinen Perl Script.

Mein erster Ansatz war über Devel::Size die größe der “$c”-Varible zu tracken und bestenfalls noch gleich den “$c->stash” davon abzuziehen. Leider hat das zu überaus strangen Seiteneffekten geführt (wirklich sehr strange.. wie das “foreach my $k(keys %hash)” über ein nicht leeres hash nachvollziehbar nicht mehr funktioniert hat), so dass ich mich nach einer anderen Lösung umsehen musste. Die habe ich auch schnelle in Proc::ProcessTable gefunden. Mit diesem Modul von D. Urist kann mein einfach auf die laufenden Prozesse des Systems zugreifen. Da natürlich über $$ die eigene PID bekannt ist findet man schnell den Speicherverbrauch .. das ganze habe ich in ein kleines Plugin gepackt:

package Catalyst::Plugin::MyApp::TrackLeaks;

=head1 NAME

Catalyst::Plugin::MyApp::TrackLeaks

=head1 DESCRIPTION

trace the leaks in my app!

=head1 SYNOPSIS

    use Catalyst qw/ ... MyApp::TrackLeaks ... /;

    # reads value
    my $value = $c->mish_config( $name ); 

    # write
    $c->mish_config( $name, $value );

    package MyApp::Controller::Root;

    # ..

    sub begin : Private {
        my ( $self, $c ) = @_;
        # ..
        $c->start_proc_size_in_memory;
        # ..
    }

    # ...

    sub end : ActionClass('RenderView') {
        my ( $self, $c ) = @_;
        # ..
        $c->log->debug( $c->req->path .": ". $c->end_proc_size_in_memory );
        return ;
    }

=cut

use strict;
use warnings;

use Proc::ProcessTable;
use Number::Format;

=head1 METHODS

=head2 proc_size_in_memory

returns the size in memory of the current running process 

=cut

sub proc_size_in_memory {
    my ( $c ) = @_;
    my $pt = Proc::ProcessTable->new;
    my $pid = $$;
    foreach my $proc( @{ $pt->table } ) {
        if ( $proc->pid == $pid ) {
            my $size = $proc->size;
            undef $pt;
            return $size;
        }
    }

    return 0;
}

=head2 start_proc_size_in_memory

measures process size in memory and writes it to stash for later usage ..

=cut

sub start_proc_size_in_memory {
    my ( $c ) = @_;
    return $c->stash->{ _start_proc_size_in_memory } = $c->proc_size_in_memory;
}

=head2 end_proc_size_in_memory

returns formatted string with the size of bytes in memory  .. and the differene between start 

=cut

sub end_proc_size_in_memory {
    my ( $c ) = @_;

    my $end = $c->proc_size_in_memory;
    my $n = Number::Format->new( thousands_sep => ',', decimal_point => '.' );

    if ( defined ( my $start = $c->stash->{ _start_proc_size_in_memory } ) ) {
        return sprintf( '%s: Memory: from %s (%d) to %s (%d) diff %s (%d) [pid=%d]',
            $c->req->path ."",
            $n->format_bytes( $start ), $start,
            $n->format_bytes( $end ), $end,
            $n->format_bytes( $end - $start ), $end - $start,
            $$
        );
    }
    return sprintf( '%s: Memory: no start, but current %s (%d) [pid=%d]',
        $c->req->path. "", $n->format_bytes( $end ), $end, $$
    );
}

1;

Das ganze verwende ich wie in der Synopsis beschrieben im Root-Controller meiner Applikationen. Später dann in zwei Schritten:

grep "Memory: from" | /var/log/path/to/your-app.log > /tmp/memory-leaks.log

Und as ganze dann durch ein Perl-Script laufen lassen:

#!/usr/bin/perl

# track-down-leaks.pl

use strict;
use warnings;

use FindBin qw( $Bin );
use Number::Format;

my ( %pid, %action, %last_pid, %leak_action ) = ();

die "$0 /path/to/logs.." unless @ARGV;
my $f = shift @ARGV;
my $n = Number::Format->new( thousands_sep => '.', decimal_point => ',' );

open my $fh, "<", $f or die "Cannot open '$f' for read! $@";
while( my $line = <$fh> ) {
    chomp $line;
    if ( $line =~ /^\[debug\] ([^:]+): Memory: from \d+(?:.\d+)?[KMG]? \((\d+)\) to \d+(?:.\d+)?[KMG]? \((\d+)\) diff \d+(?:.\d+)?[KMG]? \((\d+)\) \[pid=(\d+)\]/ ) {
        my ( $action, $before, $after, $diff, $pid ) = ( $1, $2, $3, $4, $5 );
        $pid{ $pid } += $diff;
        $action{ $action } += $diff;

        if( defined $last_pid{ $pid } && $last_pid{ $pid }->{ before } < $before ) {
            my $leak = $before - $last_pid{ $pid }->{ before };
            print "Leak in ". $last_pid{ $pid }->{ action }. " .. gestartet bei ". $n->format_bytes( $last_pid{ $pid }->{ before } ) . " und geendet bei ". $n->format_bytes( $last_pid{ $pid }->{ after } ). " .. nächster Start der PID ($pid) bei ". $n->format_bytes( $before ). "\n\t->LEAK ". $n->format_bytes( $leak ) . "\n";
            $leak_action{ $last_pid{ $pid }->{ action } } += $leak;
        }
        $last_pid{ $pid } = {
            before => $before,
            after  => $after,
            action => $action
        };
    }
    else {
        #print "ERR '$line'\n";
    }
    #print "ACTION $action, $before -> $after ($diff) for $pid\n";
}
close $fh;

print "\n\n";
print join( "\n", map {
    sprintf( '%40s : %5s', $_, $n->format_bytes( $leak_action{ $_ } ) );
} sort {
    return $leak_action{ $b } <=> $leak_action{ $a }
} keys %leak_action );
print "\n\n\n";

1;

perl track-down-leaks.pl /tmp/memory-leaks.log

Und so in etwa sieht die Ausgabe aus:

Leak in module1/method1 .. gestartet bei 318,52M und geendet bei 318,52M .. nächster Start der PID (11212) bei 318,64M
	->LEAK 128K
# ..
Leak in module33/method1 .. gestartet bei 352,28M und geendet bei 352,39M .. nächster Start der PID (11211) bei 352,5M
	->LEAK 228K

                         module1/method1 : 124,33M
                         module2/method4 : 59,91M
                                       # ...
                        module33/method1 : 5,54M

Damit habe ich dann meine Memory leaks gefunden. Zumindest die Methoden wo ich suchen kann!

Hier nochmal alles zum download

• MemoryLeaks.pm
• track-down-leaks.pl