Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Memory leak: Bio::DB::HTS::Tabix - very reproducible #17

Closed
keiranmraine opened this issue May 18, 2016 · 20 comments
Closed

Memory leak: Bio::DB::HTS::Tabix - very reproducible #17

keiranmraine opened this issue May 18, 2016 · 20 comments
Assignees
Labels

Comments

@keiranmraine
Copy link
Contributor

Use the following small bit of code to reproduce with a tabix indexed BED file:

#!/usr/bin/perl
use strict;
use Bio::DB::HTS::Tabix;

my ($file, $search, $iterations) = @ARGV;

my $brass_np = Bio::DB::HTS::Tabix->new(filename => $file);

for(0..$iterations) {
  my $iter = $brass_np->query($search);
  while(my $record = $iter->next){ }
}

Example runs (coordinate must hit records):

$ /usr/bin/time -f '%Mk maxresident' perl htsTabix_mem.pl test.bed.gz 1:9551-10140 1
102848k maxresident
$ /usr/bin/time -f '%Mk maxresident' perl htsTabix_mem.pl test.bed.gz 1:9551-10140 10
108128k maxresident
$ /usr/bin/time -f '%Mk maxresident' perl htsTabix_mem.pl test.bed.gz 1:9551-10140 100
160880k maxresident
$ /usr/bin/time -f '%Mk maxresident' perl htsTabix_mem.pl test.bed.gz 1:9551-10140 1000
688240k maxresident

Seems a very similar problem to Bio::DB::HTS::Faidx

This is pretty critical as we've discovered this in the middle of a pre-release test cycle

@andrewyatz
Copy link
Member

andrewyatz commented May 18, 2016

Shoving a quick sv_2mortal() in there hasn't done the trick sorry. Seems like it's going to be a little bit harder

@rishidev
Copy link
Collaborator

OK - I'll have a look,

Cheers

Rishi

On 18/05/2016 15:55, Andrew Yates wrote:

Shoving a quick |sv_2mortal()| in there hasn't done the trick sorry. Seems like it's going to be a little bit harder :(


You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub #17 (comment)

@andrewyatz
Copy link
Member

Okay think I've got it. tabix_tbx_iter_next does not issue a free(str.s) after copying the value into a SVpv (line 1310). I'll open a branch quickly with the change on there. It's been tested on my local installation so it works for sure

@andrewyatz
Copy link
Member

Think this is solved by PR #18

@andrewyatz andrewyatz added the bug label May 18, 2016
@andrewyatz andrewyatz self-assigned this May 18, 2016
@keiranmraine
Copy link
Contributor Author

Problems in the cleanup code

/usr/bin/time -f '%Mk' perl ~/noddy/htsTabix_mem.pl /nfs/cancer_ref02/human/GRCh37d5/brass/brass_np_v4.groups.gz 1:9551-10140 1
    (in cleanup) Not a HASH reference at /nfs/users/nfs_k/kr2/newLocal/lib/perl5/x86_64-linux-thread-multi/Bio/DB/HTS/Tabix/Iterator.pm line 63.
    (in cleanup) Not a HASH reference at /nfs/users/nfs_k/kr2/newLocal/lib/perl5/x86_64-linux-thread-multi/Bio/DB/HTS/Tabix/Iterator.pm line 63.
    (in cleanup) Not a HASH reference at /nfs/users/nfs_k/kr2/newLocal/lib/perl5/x86_64-linux-thread-multi/Bio/DB/HTS/Tabix.pm line 113.

@keiranmraine
Copy link
Contributor Author

Looks good now 👍

@andrewyatz
Copy link
Member

Closing then

@keiranmraine
Copy link
Contributor Author

:( There's still something very tiny leaking.

It doesn't create a memory increase between 10 and 100 iterations so I didn't spot it, perl appears to use ~44MB itself. It isn't as critical as it's so much smaller (50MB@1000 iterations vs 600MB previously)

$ perl -le 'eval "require $ARGV[0]" and print $ARGV[0]->VERSION' Bio::DB::HTS::Tabix
1.13
$ /usr/bin/time -f '%Mk' perl ~/noddy/htsTabix_mem.pl groups.gz 1:9551-10140 1
102416k
$ /usr/bin/time -f '%Mk' perl ~/noddy/htsTabix_mem.pl groups.gz 1:9551-10140 10
102432k
$ /usr/bin/time -f '%Mk' perl ~/noddy/htsTabix_mem.pl groups.gz 1:9551-10140 100
102432k
$ /usr/bin/time -f '%Mk' perl ~/noddy/htsTabix_mem.pl groups.gz 1:9551-10140 1000
106032k
$ /usr/bin/time -f '%Mk' perl ~/noddy/htsTabix_mem.pl groups.gz 1:9551-10140 10000
142592k
$ /usr/bin/time -f '%Mk' perl ~/noddy/htsTabix_mem.pl groups.gz 1:9551-10140 100000
508224k

@rishidev
Copy link
Collaborator

It looks like there is the same string memory issue in the header function as well, I'll update.

@rishidev rishidev reopened this May 20, 2016
@rishidev
Copy link
Collaborator

This should be fixed in #21

@andrewyatz
Copy link
Member

There's still a leak somewhere but I think you've plugged another one @rishidev. My local using your code version shows a much smaller increase @keiranmraine had. But there is still an increase.

ayates@ebi-001:~/work/XS/Bio-HTS (master)$ /usr/bin/time -f '%Mk maxresident' perl -I /Users/ayates/Code/ensembl/bioperl-1.6.924/ -I blib/lib -I blib/arch/ -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/lib -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/arch/  htsTabix_mem.pl t/data/data.vcf.gz 1:9551-1014010 1
63648k maxresident
ayates@ebi-001:~/work/XS/Bio-HTS (master)$ /usr/bin/time -f '%Mk maxresident' perl -I /Users/ayates/Code/ensembl/bioperl-1.6.924/ -I blib/lib -I blib/arch/ -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/lib -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/arch/  htsTabix_mem.pl t/data/data.vcf.gz 1:9551-1014010 500
64240k maxresident
ayates@ebi-001:~/work/XS/Bio-HTS (master)$ /usr/bin/time -f '%Mk maxresident' perl -I /Users/ayates/Code/ensembl/bioperl-1.6.924/ -I blib/lib -I blib/arch/ -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/lib -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/arch/  htsTabix_mem.pl t/data/data.vcf.gz 1:9551-1014010 10000
78528k maxresident
ayates@ebi-001:~/work/XS/Bio-HTS (master)$ /usr/bin/time -f '%Mk maxresident' perl -I /Users/ayates/Code/ensembl/bioperl-1.6.924/ -I blib/lib -I blib/arch/ -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/lib -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/arch/  htsTabix_mem.pl t/data/data.vcf.gz 1:9551-1014010 20000
93600k maxresident

There's about a 14MB increase between 500 and 10,000 iterations and another 14MB going from 10k to 20k records. If I reduce the search space then there's still an increase but the amounts involved are much smaller (I did a smaller area over 500 iterations and then one that returns nothing 20K iterations).

ayates@ebi-001:~/work/XS/Bio-HTS (master)$ /usr/bin/time -f '%Mk maxresident' perl -I /Users/ayates/Code/ensembl/bioperl-1.6.924/ -I blib/lib -I blib/arch/ -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/lib -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/arch/  htsTabix_mem.pl t/data/data.vcf.gz 1:9551-10140 500
63728k maxresident
ayates@ebi-001:~/work/XS/Bio-HTS (master)$ /usr/bin/time -f '%Mk maxresident' perl -I /Users/ayates/Code/ensembl/bioperl-1.6.924/ -I blib/lib -I blib/arch/ -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/lib -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/arch/  htsTabix_mem.pl t/data/data.vcf.gz 1:9551-10140 20000
82000k maxresident
ayates@ebi-001:~/work/XS/Bio-HTS (master)$ /usr/bin/time -f '%Mk maxresident' perl -I /Users/ayates/Code/ensembl/bioperl-1.6.924/ -I blib/lib -I blib/arch/ -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/lib -I /homes/ayates/work/XS/Devel-LeakTrace-Fast-0.11/blib/arch/  htsTabix_mem.pl t/data/data.vcf.gz 1:1-10 20000
82000k maxresident

Altering the amount returned does have an effect. I've tried a few things to plug other possible leaks in the code including:

  • trying free(s) but it says no
  • cannot free anything else in the struct
  • mortalisation of the returning value has odd effects (seems XS decrements the ref count on RETVAL automatically)
  • code the example script to just use the exported subs and not the objects. No difference
  • have a bit of XS that does the script and convert the script into calling just that XS. That seems to plug the leak
  • replace the newSVpv(str.s, str.l) with newSVpv("ABC",3). No effect on memory
  • Sent the program through Devel::LeakTrace::Fast and valgrind with neither one reporting anything suspicious (well valgrind brought up a lot of Perl leaks but I think they're expected i.e. it's how Perl works).

@andrewyatz
Copy link
Member

andrewyatz commented May 20, 2016

Example XS code that I mentioned before that cuts out any internal Perl stuff (apart from XS). I assume it's easy enough to convert into a standalone C program if need be

void
hts_open(packname, filename, mode="r", region, repeats)
      char * packname
      char * filename
      char * mode
      char * region
      int repeats
      PREINIT:
        htsFile * htsfile;
        tbx_t * tabix;
        hts_itr_t * iter;
        kstring_t str = {0,0,0};
        char * mode = "r";
        SV * line;
      CODE:
        printf("%s | %s | %d\n", filename, region, repeats);
        htsfile = hts_open(filename,mode);
        tabix = tbx_index_load(filename);

        int i = 0;
        for( ; i <= repeats; i++) {
          iter = tbx_itr_querys(tabix, region);
          //printf("Iteration %d | ", i);
          int linecount = 0;
          while(tbx_itr_next(htsfile, tabix, iter, &str) >= 0) {
            //printf("\t%s\n", str.s);
            //line = newSVpvn(str.s, str.l);
            linecount++;
            //free(str.s);
          }
          //printf("Lines: %d\n", linecount);
          tbx_itr_destroy(iter);
          //free(str.s);
        }

        free(str.s);
        hts_close(htsfile);
        tbx_destroy(tabix);

@andrewyatz
Copy link
Member

And the C binary version of that code (I assume is actually doing the right thing).

#include <stdio.h>
#include <stdlib.h>
#include <string.h>

#include "config.h"

#include "htslib/kstring.h"
#include "htslib/hts.h"
#include "htslib/tbx.h"

int main(int argc, char *argv[])
{
  //parsing cmd line
  char *endptr, *file, *region;
  file = argv[1];
  region = argv[2];
  int repeats;
  repeats = (int)strtol(argv[3], &endptr, 10);

  // Start of local decs
  htsFile * htsfile;
  tbx_t * tabix;
  hts_itr_t * iter;
  kstring_t str = {0,0,0};
  char * mode = "r";

  printf("%s | %s | %d\n", file, region, repeats);
  htsfile = hts_open(file,mode);
  tabix = tbx_index_load(file);
  int i = 0;
  for( ; i <= repeats; i++) {
    iter = tbx_itr_querys(tabix, region);
    //printf("Iteration %d | ", i);
    int linecount = 0;
    while(tbx_itr_next(htsfile, tabix, iter, &str) >= 0) {
      //printf("\t%s\n", str.s);
      //line = newSVpvn(str.s, str.l);
      linecount++;
      //free(str.s);
    }
    //printf("Lines: %d\n", linecount);
    tbx_itr_destroy(iter);
    //free(str.s);
  }

  free(str.s);
  hts_close(htsfile);
  tbx_destroy(tabix);
  return 0;
}

Compiled in the libhts directory with gcc -g -O2 -I. -pthread -rdynamic -Wall tmptabix.c -o tmptabix libhts.a -lz. Output from using time looks like

ayates@ebi-001:~/work/XS/Bio-HTS/htslib ((1.3.1))$ /usr/bin/time -f '%Mk maxresident' ./tmptabix ../t/data/data.vcf.gz 1:9551-1014010 10000
../t/data/data.vcf.gz | 1:9551-1014010 | 10000
3568k maxresident
ayates@ebi-001:~/work/XS/Bio-HTS/htslib ((1.3.1))$ /usr/bin/time -f '%Mk maxresident' ./tmptabix ../t/data/data.vcf.gz 1:9551-1014010 40000
../t/data/data.vcf.gz | 1:9551-1014010 | 40000
3568k maxresident

There's no leak from htslib as far as I can tell. There's something in the XS layer that we're not understanding.

@andrewyatz
Copy link
Member

I believe PR #22 solves the issue. Seems we were returning from the subroutine too early. I've checked it on my test env and memory usage is pretty static. Fingers crossed!

@rishidev
Copy link
Collaborator

Thanks Andy

@andrewyatz
Copy link
Member

andrewyatz commented May 20, 2016

Going to mark as close. @keiranmraine if you find another memory leak please re-open (please please please don't otherwise I'm going to spend the entire weekend listening to The Smiths songs and being depressed)

@keiranmraine
Copy link
Contributor Author

Close, but hopefully easy to fix this time... Is it possible to add an automatic destroy for the query iterator?

There was still a leak evident when you pushed into high numbers:

Before adding a $iter->close

$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 1
102416k
$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 10
102384k
$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 100
102400k
$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 1000
103248k
$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 10000
115088k
$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 100000
233184k

After adding:

$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 1
102416k
$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 10
102416k
$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 100
102400k
$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 1000
102400k
$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 10000
102384k
$ /usr/bin/time -f '%Mk' perl htsTabix_mem.pl groups.gz 1:9551-10140 100000
102400k

This isn't in the docs so all code using the module would need an upgrade to correct if it can't be handled in the background. It would also be quite difficult to communicate.

@andrewyatz
Copy link
Member

andrewyatz commented May 20, 2016

It's already there ... https://github.com/Ensembl/Bio-HTS/blob/master/lib/Bio/DB/HTS/Tabix/Iterator.pm#L69. I'm sure it's called. Okay just taken the close() out and it's leaking again. I told you this would make me start playing Smiths songs.

@andrewyatz
Copy link
Member

andrewyatz commented May 20, 2016

Okay there's a fix. Using ref() will give back the blessed object string and not the underlying reference type it's pointing to. Scalar::Util::reftype() does what I need. Fix on #23

@andrewyatz andrewyatz reopened this May 20, 2016
@rishidev
Copy link
Collaborator

Thanks again!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

3 participants