Devel::MAT investigation into C - part 1

I have previously written about using Devel::MAT to find the cause of memory leaks in Perl programs. While it is often able to find the reasons for memory growth in a great number of cases, there are times when it cannot alone find the whole story, and we must combine other tools to finish our investigation. Here we'll look at one particular case that - like so many others - begins with the observation that a long-running Perl process slowly consumes ever-more memory from the host operating system, the longer it runs. We'd like to find out why, and fix it.

The process under investigation this time is a long-running script that regularly polls a number of sites over HTTP (well, HTTPS in fact) to collect up and aggregate some data from them. The rate of memory leak is observed to correlate with how often it performs this polling, so it suggests that the leak is likely caused by something that is done on every iteration of the program losing the same amount each time. The regular iteration of the program provides us a convenient point to attach some memory debugging to begin our investigation.

A slow increase of memory could be caused by a Perl-visible accumulation of SVs, or could be something only visible at the C layer. Before we start investigating with the heavy guns of Devel::MAT, we might do well to try to classify what's going on with something more lightweight. In this case, Devel::Gladiator provides us a simple way to count the total number of SVs on the Perl heap, to see if it's increasing. We keep a count of the previous total, so we can print the difference per iteration as well:

use Devel::Gladiator qw( arena_ref_counts );
use List::Util qw( sum );

my $lasttotal = 0;

...

    # per iteration:
    my $total = sum values %{ arena_ref_counts };
    printf "SVs %d (+%d)\n", $total, $lasttotal - $total;
    $lasttotal = $total;

We can now run this and get an initial idea of the growth of the Perl heap:

SVs 51940 (+51940)
SVs 60171 (+8231)
SVs 59655 (-516)
SVs 59652 (-3)
SVs 59655 (+3)
SVs 59657 (+2)
SVs 59660 (+3)
SVs 59663 (+3)
SVs 59665 (+2)
SVs 59668 (+3)

After a few iterations of initial startup and settling down, this program is clearly leaking actual Perl-visible SVs at around 2 or 3 per iteration, so it makes sense to get Devel::MAT involved. We can easily insert that into the iteration loop:

use Devel::MAT::Dumper;

my $iter = 0;
...

    # per iteration:
    $iter++;
    Devel::MAT::Dumper::dump( "perl-$iter.pmat" );

Now when we run this we get a sequence of numbered .pmat files, one per iteration, that we can throw into pmat-leakreport to look for leaked scalars. Because the first few files will contain a lot of noise from program startup, we'll skip those and take from, in this case, the 4th onwards:

$ pmat-leakreport -1 perl-{4,5,6,7,8}.pmat
LEAK[1] UNDEF() at 0x55efee189120
LEAK[1] UNDEF() at 0x55efee1ae1f8
LEAK[1] UNDEF() at 0x55efeda8c5e8
LEAK[1] UNDEF() at 0x55efee1acd30

This gives us four exciting candidates we can take more of a look at using the pmat shell:

$ pmat perl-8.pmat 
Perl memory dumpfile from perl 5.26.2
Heap contains 55890 objects
pmat> identify 0x55efee189120
UNDEF() at 0x55efee189120 is:
└─not found

pmat> identify 0x55efee1ae1f8
UNDEF() at 0x55efee1ae1f8 is:
└─not found

pmat> identify 0x55efeda8c5e8
UNDEF() at 0x55efeda8c5e8 is:
└─not found

pmat> identify 0x55efee1acd30
UNDEF() at 0x55efee1acd30 is:
└─not found

Well that's not very helpful. We have four scalars that contain no defined values, which aren't referenced by anywhere that Devel::MAT can see. In order to continue investigating this, we need to dig deeper with more tools. Perl itself provides an optional ability to write a more detailed log of memory allocation operations, controlled by a variable called PERL_MEM_LOG. According to perlhacktips(1):

PERL_MEM_LOG

If compiled with -DPERL_MEM_LOG (-Accflags=-DPERL_MEM_LOG), both memory and SV allocations go through logging functions, which is handy for breakpoint setting.

Now, we can't just set that environment variable on any normal perl binary, because the logging functions are sufficiently expensive at runtime that they are usually disabled on normal builds. We have to request them specifically with the use of some compile-time flags. To achieve this, it's easiest to use perlbrew to compile a custom binary for our purposes:

$ perlbrew install perl-5.26.2 --debug -Accflags=-DPERL_MEM_LOG

That'll take a while to build, but when it's ready we'll continue our investigation in part 2...

---

For another memory-leak investigation involving pmat-leakreport, see also the Binary.com tech blog post Differential Memory Leak Analysis with Devel::MAT.